feat: additional logs for rollout controller

rollout/context.go

@@ -3,6 +3,8 @@ package rollout
 import (
 	"time"
 
+	logutil "github.com/argoproj/argo-rollouts/utils/log"
+
 	log "github.com/sirupsen/logrus"
 	appsv1 "k8s.io/api/apps/v1"
 	"k8s.io/apimachinery/pkg/util/validation/field"
@@ -56,6 +58,8 @@ func (c *rolloutContext) reconcile() error {
 	err := c.getRolloutValidationErrors()
 	if err != nil {
 		if vErr, ok := err.(*field.Error); ok {
+			logCtx := logutil.WithRollout(c.rollout)
+			logCtx.Info("rollout enqueue due reconcile error")
 			// We want to frequently requeue rollouts with InvalidSpec errors, because the error
 			// condition might be timing related (e.g. the Rollout was applied before the Service).
 			c.enqueueRolloutAfter(c.rollout, 20*time.Second)

rollout/controller.go

@@ -174,6 +174,11 @@
 		client:       cfg.KubeClientSet,
 		resyncPeriod: cfg.ResyncPeriod,
 		enqueueAfter: func(obj interface{}, duration time.Duration) {
+			ro := unstructuredutil.ObjectToRollout(obj)
+			if ro != nil {
+				logCtx := logutil.WithRollout(ro)
+				logCtx.Info("rollout enqueue due to pod restart")
+			}
 			controllerutil.EnqueueAfter(obj, duration, cfg.RolloutWorkQueue)
 		},
 	}
@@ -234,6 +239,8 @@
 			controller.enqueueRollout(obj)
 			ro := unstructuredutil.ObjectToRollout(obj)
 			if ro != nil {
+				logCtx := logutil.WithRollout(ro)
+				logCtx.Info("rollout enqueue due to add event")
 				if cfg.Recorder != nil {
 					cfg.Recorder.Eventf(ro, record.EventOptions{
 						EventType:   corev1.EventTypeNormal,
@@ -258,12 +265,16 @@
 					controller.IstioController.EnqueueDestinationRule(key)
 				}
 			}
+			if newRollout != nil {
+				logCtx := logutil.WithRollout(newRollout)
+				logCtx.Info("rollout enqueue due to update event")
+			}
 			controller.enqueueRollout(new)
 		},
 		DeleteFunc: func(obj interface{}) {
 			if ro := unstructuredutil.ObjectToRollout(obj); ro != nil {
 				logCtx := logutil.WithRollout(ro)
-				logCtx.Info("rollout deleted")
+				logCtx.Info("rollout enqueue due to delete event")
 				controller.metricsServer.Remove(ro.Namespace, ro.Name, logutil.RolloutKey)
 				// Rollout is deleted, queue up the referenced Service and/or DestinationRules so
 				// that the rollouts-pod-template-hash can be cleared from each

rollout/pause.go

@@ -3,6 +3,8 @@ package rollout
 import (
 	"time"
 
+	logutil "github.com/argoproj/argo-rollouts/utils/log"
+
 	log "github.com/sirupsen/logrus"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 
@@ -209,6 +211,10 @@ func (c *rolloutContext) checkEnqueueRolloutDuringWait(startTime metav1.Time, du
 	if nextResync.After(expiredTime) && expiredTime.After(now.Time) {
 		timeRemaining := expiredTime.Sub(now.Time)
 		c.log.Infof("Enqueueing Rollout in %s seconds", timeRemaining.String())
+
+		logCtx := logutil.WithRollout(c.rollout)
+		logCtx.Info("rollout enqueue during wait")
+
 		c.enqueueRolloutAfter(c.rollout, timeRemaining)
 	}
 }

rollout/replicaset.go

@@ -6,6 +6,8 @@
 	"sort"
 	"time"
 
+	logutil "github.com/argoproj/argo-rollouts/utils/log"
+
 	appsv1 "k8s.io/api/apps/v1"
 	k8serrors "k8s.io/apimachinery/pkg/api/errors"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
@@ -150,6 +152,8 @@
 					c.log.Infof("RS '%s' has not reached the scaleDownTime", c.newRS.Name)
 					remainingTime := scaleDownAt.Sub(now.Time)
 					if remainingTime < c.resyncPeriod {
+						logCtx := logutil.WithRollout(c.rollout)
+						logCtx.Info("rollout enqueue due to scaleDownDelay")
 						c.enqueueRolloutAfter(c.rollout, remainingTime)
 						return false, nil
 					}
@@ -284,6 +288,8 @@
 			if err != nil {
 				return annotationedRSs, desiredReplicaCount, err
 			}
+			logCtx := logutil.WithRollout(c.rollout)
+			logCtx.Info("rollout enqueue due to scaleDownDelay v2")
 			c.enqueueRolloutAfter(c.rollout, scaleDownDelaySeconds)
 		}
 	} else if replicasetutil.HasScaleDownDeadline(rs) {
@@ -297,6 +303,8 @@
 			} else if remainingTime != nil {
 				c.log.Infof("RS '%s' has not reached the scaleDownTime", rs.Name)
 				if *remainingTime < c.resyncPeriod {
+					logCtx := logutil.WithRollout(c.rollout)
+					logCtx.Info("rollout enqueue due to scaleDownDelay v3")
 					c.enqueueRolloutAfter(c.rollout, *remainingTime)
 				}
 				desiredReplicaCount = rolloutReplicas

rollout/service.go

@@ -172,6 +172,8 @@ func (c *rolloutContext) awsVerifyTargetGroups(svc *corev1.Service) error {
 		}
 		if !verifyRes.Verified {
 			c.recorder.Warnf(c.rollout, record.EventOptions{EventReason: conditions.TargetGroupUnverifiedReason}, conditions.TargetGroupUnverifiedRegistrationMessage, svc.Name, tgb.Spec.TargetGroupARN, verifyRes.EndpointsRegistered, verifyRes.EndpointsTotal)
+			logCtx := logutil.WithRollout(c.rollout)
+			logCtx.Info("rollout enqueue due to awsVerifyTargetGroups")
 			c.enqueueRolloutAfter(c.rollout, defaults.GetRolloutVerifyRetryInterval())
 			return nil
 		}

rollout/sync.go

@@ -828,11 +828,13 @@ func (c *rolloutContext) requeueStuckRollout(newStatus v1alpha1.RolloutStatus) t
 	// Make it ratelimited so we stay on the safe side, eventually the Deployment should
 	// transition either to a Complete or to a TimedOut condition.
 	if after < time.Second {
-		c.log.Infof("Queueing up Rollout for a progress check now")
+		logCtx := logutil.WithRollout(c.rollout)
+		logCtx.Info("rollout enqueue due to stuck event")
 		c.enqueueRollout(c.rollout)
 		return time.Duration(0)
 	}
-	c.log.Infof("Queueing up rollout for a progress after %ds", int(after.Seconds()))
+	logCtx := logutil.WithRollout(c.rollout)
+	logCtx.Infof("Queueing up rollout for a progress after %ds", int(after.Seconds()))
 	// Add a second to avoid milliseconds skew in AddAfter.
 	// See https://github.com/kubernetes/kubernetes/issues/39785#issuecomment-279959133 for more info.
 	c.enqueueRolloutAfter(c.rollout, after+time.Second)

rollout/trafficrouting.go

@@ -6,6 +6,8 @@ import (
 	"strconv"
 	"strings"
 
+	logutil "github.com/argoproj/argo-rollouts/utils/log"
+
 	"github.com/argoproj/argo-rollouts/utils/annotations"
 
 	"github.com/argoproj/argo-rollouts/rollout/trafficrouting/plugin"
@@ -283,6 +285,8 @@ func (c *rolloutContext) reconcileTrafficRouting() error {
 				c.log.Infof("Desired weight (stepIdx: %s) %d verified", indexString, desiredWeight)
 			} else {
 				c.log.Infof("Desired weight (stepIdx: %s) %d not yet verified", indexString, desiredWeight)
+				logCtx := logutil.WithRollout(c.rollout)
+				logCtx.Info("rollout enqueue due to trafficrouting")
 				c.enqueueRolloutAfter(c.rollout, defaults.GetRolloutVerifyRetryInterval())
 			}
 		}