CHAOS-326: Make logging changes (#572)

* Set log level to DEBUG

* Only log starting injection when we are actually creating new pods

* chaos pods not being ready immediately is very normal, should be DEBUG

* Dont update targets if we did not change them

* Pods can take minutes to become Ready or Terminated, dont retry every 5s

* log tc commands at DEBUG by default

* Dont give error on safe to retry finalizer removals

* Log host resolution for user clarity

* The linter was angry

* Restore update logic

* We fixed this feature, put the test back

* Remove unused argument from assertion function

* Remove comment saying test is broken

Author: ptnapoleon

api/v1beta1/disruption_webhook.go

@@ -13,7 +13,6 @@ import (
 	"time"
 
 	"github.com/DataDog/chaos-controller/ddmark"
-	"github.com/DataDog/chaos-controller/types"
 	"github.com/DataDog/chaos-controller/utils"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 
@@ -43,7 +42,7 @@ var handlerEnabled bool
 var defaultDuration time.Duration
 
 func (r *Disruption) SetupWebhookWithManager(setupWebhookConfig utils.SetupWebhookWithManagerConfig) error {
-	if err := ddmark.InitLibrary(EmbeddedChaosAPI, types.DDMarkChaoslibPrefix); err != nil {
+	if err := ddmark.InitLibrary(EmbeddedChaosAPI, chaostypes.DDMarkChaoslibPrefix); err != nil {
 		return err
 	}
 
@@ -108,7 +107,7 @@ func (r *Disruption) ValidateCreate() error {
 		return err
 	}
 
-	multiErr := ddmark.ValidateStructMultierror(r.Spec, "validation_webhook", types.DDMarkChaoslibPrefix)
+	multiErr := ddmark.ValidateStructMultierror(r.Spec, "validation_webhook", chaostypes.DDMarkChaoslibPrefix)
 	if multiErr.ErrorOrNil() != nil {
 		return multierror.Prefix(multiErr, "ddmark: ")
 	}

controllers/disruption_controller.go

@@ -149,10 +149,10 @@ func (r *DisruptionReconciler) Reconcile(ctx context.Context, req ctrl.Request)
 				return ctrl.Result{}, err
 			}
 
-			// if not cleaned yet, requeue and reconcile again in 5s-10s
+			// if not cleaned yet, requeue and reconcile again in 15s-20s
 			// the reason why we don't rely on the exponential backoff here is that it retries too fast at the beginning
 			if !isCleaned {
-				requeueAfter := time.Duration(rand.Intn(5)+5) * time.Second //nolint:gosec
+				requeueAfter := time.Duration(rand.Intn(5)+15) * time.Second //nolint:gosec
 
 				r.log.Infow(fmt.Sprintf("disruption has not been fully cleaned yet, re-queuing in %v", requeueAfter))
 
@@ -281,8 +281,8 @@ func (r *DisruptionReconciler) Reconcile(ctx context.Context, req ctrl.Request)
 
 			return ctrl.Result{}, fmt.Errorf("error updating disruption injection status: %w", err)
 		} else if !injected {
-			// requeue after 5-10 seconds, as default 1ms is too quick here
-			requeueAfter := time.Duration(rand.Intn(5)+5) * time.Second //nolint:gosec
+			// requeue after 15-20 seconds, as default 1ms is too quick here
+			requeueAfter := time.Duration(rand.Intn(5)+15) * time.Second //nolint:gosec
 			r.log.Infow("disruption is not fully injected yet, requeuing", "injectionStatus", instance.Status.InjectionStatus)
 
 			return ctrl.Result{
@@ -346,7 +346,7 @@ func (r *DisruptionReconciler) updateInjectionStatus(instance *chaosv1beta1.Disr
 
 			// consider the disruption as not fully injected if at least one not ready pod is found
 			if !podReady {
-				r.log.Infow("chaos pod is not ready yet", "chaosPod", chaosPod.Name)
+				r.log.Debugw("chaos pod is not ready yet", "chaosPod", chaosPod.Name)
 			}
 		}
 
@@ -383,10 +383,6 @@ func (r *DisruptionReconciler) updateInjectionStatus(instance *chaosv1beta1.Disr
 
 // startInjection creates non-existing chaos pod for the given disruption
 func (r *DisruptionReconciler) startInjection(instance *chaosv1beta1.Disruption) error {
-	if len(instance.Status.Targets) > 0 {
-		r.log.Infow("starting targets injection", "targets", instance.Status.Targets)
-	}
-
 	// chaosPodsMap is used to check if a target's chaos pods already exist or not
 	chaosPodsMap := make(map[string]map[string]bool, len(instance.Status.Targets))
 
@@ -408,6 +404,10 @@ func (r *DisruptionReconciler) startInjection(instance *chaosv1beta1.Disruption)
 		}
 	}
 
+	if len(instance.Status.Targets) > 0 && (len(instance.Status.Targets) != len(chaosPodsMap)) {
+		r.log.Infow("starting targets injection", "targets", instance.Status.Targets)
+	}
+
 	// iterate through target + existing disruption kind -- to ensure all chaos pods exist
 	for _, target := range instance.Status.Targets {
 		for _, disKind := range chaostypes.DisruptionKindNames {
@@ -623,6 +623,7 @@ func (r *DisruptionReconciler) handleOrphanedChaosPods(req ctrl.Request) error {
 //   - the pod is pending
 //   - the pod is succeeded (exit code == 0)
 //   - the pod target is not healthy (not existing anymore for instance)
+//
 // if a finalizer can't be removed because none of the conditions above are fulfilled, the instance is flagged
 // as stuck on removal and the pod finalizer won't be removed unless someone does it manually
 // the pod target will be moved to ignored targets, so it is not picked up by the next reconcile loop
@@ -725,7 +726,11 @@ func (r *DisruptionReconciler) handleChaosPodTermination(instance *chaosv1beta1.
 		controllerutil.RemoveFinalizer(&chaosPod, chaostypes.ChaosPodFinalizer)
 
 		if err := r.Client.Update(context.Background(), &chaosPod); err != nil {
-			r.log.Errorw("error removing chaos pod finalizer", "error", err, "chaosPod", chaosPod.Name)
+			if strings.Contains(err.Error(), "latest version and try again") {
+				r.log.Debugw("cannot remove chaos pod finalizer, need to re-reconcile", "error", err)
+			} else {
+				r.log.Errorw("error removing chaos pod finalizer", "error", err, "chaosPod", chaosPod.Name)
+			}
 
 			return
 		}
@@ -807,7 +812,7 @@ func (r *DisruptionReconciler) selectTargets(instance *chaosv1beta1.Disruption)
 		instance.Status.RemoveTargets(cTargetsCount - dTargetsCount)
 	}
 
-	r.log.Infow("updating instance status with targets selected for injection")
+	r.log.Debugw("updating instance status with targets selected for injection")
 
 	instance.Status.SelectedTargetsCount = len(instance.Status.Targets)
 	instance.Status.IgnoredTargetsCount = totalAvailableTargetsCount - targetsCount

controllers/disruption_controller_test.go

@@ -23,6 +23,7 @@ import (
 
 	. "github.com/onsi/ginkgo"
 	. "github.com/onsi/gomega"
+	"k8s.io/apimachinery/pkg/types"
 	"sigs.k8s.io/controller-runtime/pkg/client"
 
 	chaosv1beta1 "github.com/DataDog/chaos-controller/api/v1beta1"
@@ -127,24 +128,24 @@ func expectChaosInjectors(instance *chaosv1beta1.Disruption, count int) error {
 	return nil
 }
 
-func expectDisruptionStatus(instance *chaosv1beta1.Disruption, desiredTargetsCount int, ignoredTargetsCount int, selectedTargetsCount int, injectedTargetsCount int) error {
+func expectDisruptionStatus(desiredTargetsCount int, ignoredTargetsCount int, selectedTargetsCount int, injectedTargetsCount int) error {
 	updatedInstance := &chaosv1beta1.Disruption{}
 
 	if err := k8sClient.Get(context.Background(), instanceKey, updatedInstance); err != nil {
 		return err
 	}
 
 	if desiredTargetsCount != updatedInstance.Status.DesiredTargetsCount {
-		return fmt.Errorf("incorred number of desired targets: expected %d, found %d", desiredTargetsCount, updatedInstance.Status.DesiredTargetsCount)
+		return fmt.Errorf("incorrect number of desired targets: expected %d, found %d", desiredTargetsCount, updatedInstance.Status.DesiredTargetsCount)
 	}
 	if ignoredTargetsCount != updatedInstance.Status.IgnoredTargetsCount {
-		return fmt.Errorf("incorred number of ignored targets: expected %d, found %d", ignoredTargetsCount, updatedInstance.Status.IgnoredTargetsCount)
+		return fmt.Errorf("incorrect number of ignored targets: expected %d, found %d", ignoredTargetsCount, updatedInstance.Status.IgnoredTargetsCount)
 	}
 	if injectedTargetsCount != updatedInstance.Status.InjectedTargetsCount {
-		return fmt.Errorf("incorred number of injected targets: expected %d, found %d", injectedTargetsCount, updatedInstance.Status.InjectedTargetsCount)
+		return fmt.Errorf("incorrect number of injected targets: expected %d, found %d", injectedTargetsCount, updatedInstance.Status.InjectedTargetsCount)
 	}
 	if selectedTargetsCount != updatedInstance.Status.SelectedTargetsCount {
-		return fmt.Errorf("incorred number of selected targets: expected %d, found %d", selectedTargetsCount, updatedInstance.Status.SelectedTargetsCount)
+		return fmt.Errorf("incorrect number of selected targets: expected %d, found %d", selectedTargetsCount, updatedInstance.Status.SelectedTargetsCount)
 	}
 
 	return nil
@@ -413,7 +414,7 @@ var _ = Describe("Disruption Controller", func() {
 			Expect(expectChaosInjectors(disruption, 2)).To(BeNil())
 
 			By("Ensuring that the disruption status is displaying the right number of targets")
-			Eventually(func() error { return expectDisruptionStatus(disruption, 2, 0, 2, 2) }, timeout).Should(Succeed())
+			Eventually(func() error { return expectDisruptionStatus(2, 0, 2, 2) }, timeout).Should(Succeed())
 
 			By("Adding an extra target")
 			Expect(k8sClient.Create(context.Background(), targetPodA2)).To(BeNil())
@@ -422,7 +423,7 @@ var _ = Describe("Disruption Controller", func() {
 			Eventually(func() error { return expectChaosPod(disruption, 3) }, timeout).Should(Succeed())
 
 			By("Ensuring that the disruption status is displaying the right number of targets")
-			Eventually(func() error { return expectDisruptionStatus(disruption, 3, 0, 3, 3) }, timeout).Should(Succeed())
+			Eventually(func() error { return expectDisruptionStatus(3, 0, 3, 3) }, timeout).Should(Succeed())
 
 			By("Deleting the extra target")
 			Expect(k8sClient.Delete(context.Background(), targetPodA2)).To(BeNil())
@@ -431,7 +432,7 @@ var _ = Describe("Disruption Controller", func() {
 			Eventually(func() error { return expectChaosPod(disruption, 2) }, timeout).Should(Succeed())
 
 			By("Ensuring that the disruption status is displaying the right number of targets")
-			Eventually(func() error { return expectDisruptionStatus(disruption, 2, 0, 2, 2) }, timeout).Should(Succeed())
+			Eventually(func() error { return expectDisruptionStatus(2, 0, 2, 2) }, timeout).Should(Succeed())
 		})
 	})
 
@@ -463,7 +464,7 @@ var _ = Describe("Disruption Controller", func() {
 
 		It("should scale up then down with the right number of targets count", func() {
 			By("Ensuring that the disruption status is displaying the right number of targets")
-			Eventually(func() error { return expectDisruptionStatus(disruption, 3, 0, 2, 2) }, timeout).Should(Succeed())
+			Eventually(func() error { return expectDisruptionStatus(3, 0, 2, 2) }, timeout).Should(Succeed())
 
 			By("Adding an extra target")
 			Expect(k8sClient.Create(context.Background(), targetPodA3)).To(BeNil())
@@ -472,7 +473,7 @@ var _ = Describe("Disruption Controller", func() {
 			Expect(k8sClient.Create(context.Background(), targetPodA4)).To(BeNil())
 
 			By("Ensuring that the disruption status is displaying the right number of targets")
-			Eventually(func() error { return expectDisruptionStatus(disruption, 3, 1, 3, 3) }, timeout).Should(Succeed())
+			Eventually(func() error { return expectDisruptionStatus(3, 1, 3, 3) }, timeout).Should(Succeed())
 
 			By("Deleting the extra target")
 			Expect(k8sClient.Delete(context.Background(), targetPodA3)).To(BeNil())
@@ -482,26 +483,22 @@ var _ = Describe("Disruption Controller", func() {
 		})
 	})
 
-	// NOTE: disabled until fixed
-	// the feature is broken now that we moved all chaos pods into the same namespace
-	// because we had to remove the owner reference on those pods, meaning that
-	// the reconcile loop does not automatically trigger anymore on chaos pods events like a delete
-	// Context("manually delete a chaos pod", func() {
-	// 	It("should properly handle the chaos pod finalizer", func() {
-	// 		By("Ensuring that the chaos pods have been created")
-	// 		Eventually(func() error { return expectChaosPod(disruption, 5) }, timeout).Should(Succeed())
-
-	// 		By("Listing chaos pods to pick one to delete")
-	// 		chaosPods, err := listChaosPods(disruption)
-	// 		Expect(err).To(BeNil())
-	// 		chaosPod := chaosPods.Items[0]
-	// 		chaosPodKey := types.NamespacedName{Namespace: chaosPod.Namespace, Name: chaosPod.Name}
-
-	// 		By("Deleting one of the chaos pod")
-	// 		Expect(k8sClient.Delete(context.Background(), &chaosPod)).To(BeNil())
-
-	// 		By("Waiting for the chaos pod finalizer to be removed")
-	// 		Eventually(func() error { return k8sClient.Get(context.Background(), chaosPodKey, &chaosPod) }, timeout).Should(MatchError(fmt.Sprintf("Pod \"%s\" not found", chaosPod.Name)))
-	// 	})
-	// })
+	Context("manually delete a chaos pod", func() {
+		It("should properly handle the chaos pod finalizer", func() {
+			By("Ensuring that the chaos pods have been created")
+			Eventually(func() error { return expectChaosPod(disruption, 4) }, timeout).Should(Succeed())
+
+			By("Listing chaos pods to pick one to delete")
+			chaosPods, err := listChaosPods(disruption)
+			Expect(err).To(BeNil())
+			chaosPod := chaosPods.Items[0]
+			chaosPodKey := types.NamespacedName{Namespace: chaosPod.Namespace, Name: chaosPod.Name}
+
+			By("Deleting one of the chaos pod")
+			Expect(k8sClient.Delete(context.Background(), &chaosPod)).To(BeNil())
+
+			By("Waiting for the chaos pod finalizer to be removed")
+			Eventually(func() error { return k8sClient.Get(context.Background(), chaosPodKey, &chaosPod) }, timeout).Should(MatchError(fmt.Sprintf("Pod \"%s\" not found", chaosPod.Name)))
+		})
+	})
 })

injector/network_disruption.go

@@ -165,7 +165,7 @@ func (i *networkDisruptionInjector) Inject() error {
 			return fmt.Errorf("error applying tc operations: %w", err)
 		}
 
-		i.config.Log.Info("operations applied successfully")
+		i.config.Log.Debug("operations applied successfully")
 	}
 
 	i.config.Log.Info("editing pod net_cls cgroup to apply a classid to target container packets")
@@ -847,6 +847,8 @@ func (i *networkDisruptionInjector) addFiltersForHosts(interfaces []string, host
 			return fmt.Errorf("error resolving given host %s: %w", host.Host, err)
 		}
 
+		i.config.Log.Infof("resolved %s as %s", host.Host, ips)
+
 		for _, ip := range ips {
 			// handle flow direction
 			var (

log/log.go

@@ -14,7 +14,7 @@ import (
 func NewZapLogger() (*zap.SugaredLogger, error) {
 	// configure logger
 	loggerConfig := zap.NewProductionConfig()
-	loggerConfig.Level.SetLevel(zapcore.InfoLevel)
+	loggerConfig.Level.SetLevel(zapcore.DebugLevel)
 	loggerConfig.EncoderConfig.MessageKey = "message"
 	loggerConfig.EncoderConfig.EncodeTime = zapcore.EpochMillisTimeEncoder
 

network/tc.go

@@ -61,7 +61,7 @@ func (e defaultTcExecuter) Run(args ...string) (int, string, error) {
 	cmd.Stderr = stderr
 
 	// run command
-	e.log.Infof("running tc command: %v", cmd.String())
+	e.log.Debugf("running tc command: %v", cmd.String())
 
 	// early exit if dry-run mode is enabled
 	if e.dryRun {