Update logging in our deployment controllers

pkg/deploy/controller/deployment/controller.go

@@ -39,7 +39,7 @@ const maxRetryCount = 15
 // fatalError is an error which can't be retried.
 type fatalError string
 
-func (e fatalError) Error() string { return "fatal error handling deployment: " + string(e) }
+func (e fatalError) Error() string { return "fatal error handling rollout: " + string(e) }
 
 // actionableError is an error on which users can act.
 type actionableError string
@@ -131,17 +131,17 @@ func (c *DeploymentController) handle(deployment *kapi.ReplicationController, wi
 			// Generate a deployer pod spec.
 			deployerPod, err := c.makeDeployerPod(deployment)
 			if err != nil {
-				return fatalError(fmt.Sprintf("couldn't make deployer pod for %s: %v", deployutil.LabelForDeployment(deployment), err))
+				return fatalError(fmt.Sprintf("couldn't make deployer pod for %q: %v", deployutil.LabelForDeployment(deployment), err))
 			}
 			// Create the deployer pod.
 			deploymentPod, err := c.pn.Pods(deployment.Namespace).Create(deployerPod)
 			// Retry on error.
 			if err != nil {
-				return actionableError(fmt.Sprintf("couldn't create deployer pod for %s: %v", deployutil.LabelForDeployment(deployment), err))
+				return actionableError(fmt.Sprintf("couldn't create deployer pod for %q: %v", deployutil.LabelForDeployment(deployment), err))
 			}
 			updatedAnnotations[deployapi.DeploymentPodAnnotation] = deploymentPod.Name
 			nextStatus = deployapi.DeploymentStatusPending
-			glog.V(4).Infof("Created deployer pod %s for deployment %s", deploymentPod.Name, deployutil.LabelForDeployment(deployment))
+			glog.V(4).Infof("Created deployer pod %q for %q", deploymentPod.Name, deployutil.LabelForDeployment(deployment))
 
 		// Most likely dead code since we never get an error different from 404 back from the cache.
 		case deployerErr != nil:
@@ -164,12 +164,10 @@ func (c *DeploymentController) handle(deployment *kapi.ReplicationController, wi
 				nextStatus = deployapi.DeploymentStatusFailed
 				updatedAnnotations[deployapi.DeploymentStatusReasonAnnotation] = deployapi.DeploymentFailedUnrelatedDeploymentExists
 				c.emitDeploymentEvent(deployment, kapi.EventTypeWarning, "FailedCreate", fmt.Sprintf("Error creating deployer pod since another pod with the same name (%q) exists", deployer.Name))
-				glog.V(2).Infof("Couldn't create deployer pod for %s since an unrelated pod with the same name (%q) exists", deployutil.LabelForDeployment(deployment), deployer.Name)
 			} else {
 				// Update to pending or to the appropriate status relative to the existing validated deployer pod.
 				updatedAnnotations[deployapi.DeploymentPodAnnotation] = deployer.Name
 				nextStatus = nextStatusComp(nextStatus, deployapi.DeploymentStatusPending)
-				glog.V(4).Infof("Detected existing deployer pod %s for deployment %s", deployer.Name, deployutil.LabelForDeployment(deployment))
 			}
 		}
 
@@ -187,13 +185,14 @@ func (c *DeploymentController) handle(deployment *kapi.ReplicationController, wi
 				}
 				updatedAnnotations[deployapi.DeploymentStatusReasonAnnotation] = deployapi.DeploymentFailedDeployerPodNoLongerExists
 				c.emitDeploymentEvent(deployment, kapi.EventTypeWarning, "Failed", fmt.Sprintf("Deployer pod %q has gone missing", deployerPodName))
-				deployerErr = fmt.Errorf("Failing deployment %q because its deployer pod %q disappeared", deployutil.LabelForDeployment(deployment), deployerPodName)
+				deployerErr = fmt.Errorf("Failing rollout for %q because its deployer pod %q disappeared", deployutil.LabelForDeployment(deployment), deployerPodName)
 				utilruntime.HandleError(deployerErr)
 			}
 
+		// Most likely dead code since we never get an error different from 404 back from the cache.
 		case deployerErr != nil:
 			// We'll try again later on resync. Continue to process cancellations.
-			deployerErr = fmt.Errorf("Error getting deployer pod %q for deployment %q: %v", deployerPodName, deployutil.LabelForDeployment(deployment), deployerErr)
+			deployerErr = fmt.Errorf("Error getting deployer pod %q for %q: %v", deployerPodName, deployutil.LabelForDeployment(deployment), deployerErr)
 			utilruntime.HandleError(deployerErr)
 
 		default: /* err == nil */
@@ -242,12 +241,12 @@ func (c *DeploymentController) handle(deployment *kapi.ReplicationController, wi
 		}
 
 		if _, err := c.rn.ReplicationControllers(deployment.Namespace).Update(deployment); err != nil {
-			return fmt.Errorf("couldn't update deployment %s to status %s: %v", deployutil.LabelForDeployment(deployment), nextStatus, err)
+			return fmt.Errorf("couldn't update rollout status for %q to %s: %v", deployutil.LabelForDeployment(deployment), nextStatus, err)
 		}
-		glog.V(4).Infof("Updated deployment %s status from %s to %s (scale: %d)", deployutil.LabelForDeployment(deployment), currentStatus, nextStatus, deployment.Spec.Replicas)
+		glog.V(4).Infof("Updated rollout status for %q from %s to %s (scale: %d)", deployutil.LabelForDeployment(deployment), currentStatus, nextStatus, deployment.Spec.Replicas)
 
 		if deployutil.IsDeploymentCancelled(deployment) && deployutil.IsFailedDeployment(deployment) {
-			c.emitDeploymentEvent(deployment, kapi.EventTypeNormal, "DeploymentCancelled", fmt.Sprintf("Deployment %q cancelled", deployutil.LabelForDeployment(deployment)))
+			c.emitDeploymentEvent(deployment, kapi.EventTypeNormal, "RolloutCancelled", fmt.Sprintf("Rollout for %q cancelled", deployutil.LabelForDeployment(deployment)))
 		}
 	}
 	return nil
@@ -425,13 +424,13 @@ func (c *DeploymentController) cleanupDeployerPods(deployment *kapi.ReplicationC
 		if err := c.pn.Pods(deployerPod.Namespace).Delete(deployerPod.Name, &kapi.DeleteOptions{}); err != nil && !kerrors.IsNotFound(err) {
 			// if the pod deletion failed, then log the error and continue
 			// we will try to delete any remaining deployer pods and return an error later
-			utilruntime.HandleError(fmt.Errorf("couldn't delete completed deployer pod %q for deployment %q: %v", deployerPod.Name, deployutil.LabelForDeployment(deployment), err))
+			utilruntime.HandleError(fmt.Errorf("couldn't delete completed deployer pod %q for %q: %v", deployerPod.Name, deployutil.LabelForDeployment(deployment), err))
 			cleanedAll = false
 		}
 	}
 
 	if !cleanedAll {
-		return actionableError(fmt.Sprintf("couldn't clean up all deployer pods for %s", deployment.Name))
+		return actionableError(fmt.Sprintf("couldn't clean up all deployer pods for %q", deployutil.LabelForDeployment(deployment)))
 	}
 	return nil
 }

pkg/deploy/controller/deployment/factory.go

@@ -1,6 +1,7 @@
 package deployment
 
 import (
+	"fmt"
 	"time"
 
 	"github.com/golang/glog"
@@ -29,7 +30,7 @@ const (
 func NewDeploymentController(rcInformer, podInformer cache.SharedIndexInformer, kc kclientset.Interface, sa, image string, env []kapi.EnvVar, codec runtime.Codec) *DeploymentController {
 	eventBroadcaster := record.NewBroadcaster()
 	eventBroadcaster.StartRecordingToSink(&kcoreclient.EventSinkImpl{Interface: kc.Core().Events("")})
-	recorder := eventBroadcaster.NewRecorder(kapi.EventSource{Component: "deployments-controller"})
+	recorder := eventBroadcaster.NewRecorder(kapi.EventSource{Component: "deployer-controller"})
 
 	c := &DeploymentController{
 		rn: kc.Core(),
@@ -79,15 +80,15 @@ func (c *DeploymentController) Run(workers int, stopCh <-chan struct{}) {
 		go wait.Until(c.worker, time.Second, stopCh)
 	}
 	<-stopCh
-	glog.Infof("Shutting down deployment controller")
+	glog.Infof("Shutting down deployer controller")
 	c.queue.ShutDown()
 }
 
 func (c *DeploymentController) waitForSyncedStores(ready chan<- struct{}, stopCh <-chan struct{}) {
 	defer utilruntime.HandleCrash()
 
 	for !c.rcStoreSynced() || !c.podStoreSynced() {
-		glog.V(4).Infof("Waiting for the rc and pod caches to sync before starting the deployment controller workers")
+		glog.V(4).Infof("Waiting for the rc and pod caches to sync before starting the deployer controller workers")
 		select {
 		case <-time.After(storeSyncedPollPeriod):
 		case <-stopCh:
@@ -141,12 +142,12 @@ func (c *DeploymentController) deletePod(obj interface{}) {
 	if !ok {
 		tombstone, ok := obj.(cache.DeletedFinalStateUnknown)
 		if !ok {
-			glog.Errorf("Couldn't get object from tombstone: %+v", obj)
+			utilruntime.HandleError(fmt.Errorf("Couldn't get object from tombstone: %+v", obj))
 			return
 		}
 		pod, ok = tombstone.Obj.(*kapi.Pod)
 		if !ok {
-			glog.Errorf("Tombstone contained object that is not a pod: %+v", obj)
+			utilruntime.HandleError(fmt.Errorf("Tombstone contained object that is not a pod: %+v", obj))
 			return
 		}
 	}
@@ -159,14 +160,19 @@ func (c *DeploymentController) deletePod(obj interface{}) {
 func (c *DeploymentController) enqueueReplicationController(rc *kapi.ReplicationController) {
 	key, err := kcontroller.KeyFunc(rc)
 	if err != nil {
-		glog.Errorf("Couldn't get key for object %#v: %v", rc, err)
+		utilruntime.HandleError(fmt.Errorf("Couldn't get key for object %#v: %v", rc, err))
 		return
 	}
 	c.queue.Add(key)
 }
 
 func (c *DeploymentController) rcForDeployerPod(pod *kapi.Pod) (*kapi.ReplicationController, error) {
-	key := pod.Namespace + "/" + deployutil.DeploymentNameFor(pod)
+	rcName := deployutil.DeploymentNameFor(pod)
+	if len(rcName) == 0 {
+		// Not a deployer pod, so don't bother with it.
+		return nil, nil
+	}
+	key := pod.Namespace + "/" + rcName
 	return c.getByKey(key)
 }
 
@@ -187,7 +193,7 @@ func (c *DeploymentController) work() bool {
 
 	rc, err := c.getByKey(key.(string))
 	if err != nil {
-		glog.Error(err.Error())
+		utilruntime.HandleError(err)
 	}
 
 	if rc == nil {
@@ -207,12 +213,11 @@ func (c *DeploymentController) work() bool {
 func (c *DeploymentController) getByKey(key string) (*kapi.ReplicationController, error) {
 	obj, exists, err := c.rcStore.Indexer.GetByKey(key)
 	if err != nil {
-		glog.Infof("Unable to retrieve replication controller %q from store: %v", key, err)
-		c.queue.Add(key)
+		c.queue.AddRateLimited(key)
 		return nil, err
 	}
 	if !exists {
-		glog.Infof("Replication controller %q has been deleted", key)
+		glog.V(4).Infof("Replication controller %q has been deleted", key)
 		return nil, nil
 	}
 

pkg/deploy/controller/deploymentconfig/controller.go

@@ -246,7 +246,6 @@ func (c *DeploymentConfigController) reconcileDeployments(existingDeployments []
 				}
 				copied, err = deployutil.DeploymentDeepCopy(rc)
 				if err != nil {
-					glog.V(2).Infof("Deep copy of deployment %q failed: %v", rc.Name, err)
 					return err
 				}
 				copied.Spec.Replicas = newReplicaCount
@@ -279,7 +278,6 @@ func (c *DeploymentConfigController) reconcileDeployments(existingDeployments []
 func (c *DeploymentConfigController) updateStatus(config *deployapi.DeploymentConfig, deployments []*kapi.ReplicationController, additional ...deployapi.DeploymentCondition) error {
 	newStatus, err := c.calculateStatus(*config, deployments, additional...)
 	if err != nil {
-		glog.V(2).Infof("Cannot calculate the status for %q: %v", deployutil.LabelForDeploymentConfig(config), err)
 		return err
 	}
 
@@ -297,10 +295,14 @@ func (c *DeploymentConfigController) updateStatus(config *deployapi.DeploymentCo
 	copied.Status = newStatus
 	// TODO: Retry update conficts
 	if _, err := c.dn.DeploymentConfigs(copied.Namespace).UpdateStatus(copied); err != nil {
-		glog.V(2).Infof("Cannot update the status for %q: %v", deployutil.LabelForDeploymentConfig(copied), err)
 		return err
 	}
-	glog.V(4).Infof("Updated the status for %q (observed generation: %d)", deployutil.LabelForDeploymentConfig(copied), copied.Status.ObservedGeneration)
+	glog.V(4).Infof(fmt.Sprintf("Updated status for DeploymentConfig: %s, ", deployutil.LabelForDeploymentConfig(config)) +
+		fmt.Sprintf("replicas %d->%d (need %d), ", config.Status.Replicas, newStatus.Replicas, config.Spec.Replicas) +
+		fmt.Sprintf("readyReplicas %d->%d, ", config.Status.ReadyReplicas, newStatus.ReadyReplicas) +
+		fmt.Sprintf("availableReplicas %d->%d, ", config.Status.AvailableReplicas, newStatus.AvailableReplicas) +
+		fmt.Sprintf("unavailableReplicas %d->%d, ", config.Status.UnavailableReplicas, newStatus.UnavailableReplicas) +
+		fmt.Sprintf("sequence No: %v->%v", config.Status.ObservedGeneration, newStatus.ObservedGeneration))
 	return nil
 }
 
@@ -430,7 +432,6 @@ func (c *DeploymentConfigController) cleanupOldDeployments(existingDeployments [
 
 		err := c.rn.ReplicationControllers(deployment.Namespace).Delete(deployment.Name, nil)
 		if err != nil && !kapierrors.IsNotFound(err) {
-			glog.V(2).Infof("Failed deleting old Replication Controller %q for Deployment Config %q: %v", deployment.Name, deploymentConfig.Name, err)
 			deletionErrors = append(deletionErrors, err)
 		}
 	}

pkg/deploy/controller/deploymentconfig/factory.go

@@ -1,6 +1,7 @@
 package deploymentconfig
 
 import (
+	"fmt"
 	"time"
 
 	"github.com/golang/glog"
@@ -125,12 +126,12 @@ func (c *DeploymentConfigController) deleteDeploymentConfig(obj interface{}) {
 	if !ok {
 		tombstone, ok := obj.(cache.DeletedFinalStateUnknown)
 		if !ok {
-			glog.Errorf("Couldn't get object from tombstone %+v", obj)
+			utilruntime.HandleError(fmt.Errorf("Couldn't get object from tombstone %+v", obj))
 			return
 		}
 		dc, ok = tombstone.Obj.(*deployapi.DeploymentConfig)
 		if !ok {
-			glog.Errorf("Tombstone contained object that is not a deployment config: %+v", obj)
+			utilruntime.HandleError(fmt.Errorf("Tombstone contained object that is not a deployment config: %+v", obj))
 			return
 		}
 	}
@@ -148,7 +149,6 @@ func (c *DeploymentConfigController) updateReplicationController(old, cur interf
 		return
 	}
 
-	glog.V(4).Infof("Replication controller %q updated.", curRC.Name)
 	if dc, err := c.dcStore.GetConfigForController(curRC); err == nil && dc != nil {
 		c.enqueueDeploymentConfig(dc)
 	}
@@ -166,16 +166,15 @@ func (c *DeploymentConfigController) deleteReplicationController(obj interface{}
 	if !ok {
 		tombstone, ok := obj.(cache.DeletedFinalStateUnknown)
 		if !ok {
-			glog.Errorf("Couldn't get object from tombstone %#v", obj)
+			utilruntime.HandleError(fmt.Errorf("Couldn't get object from tombstone %#v", obj))
 			return
 		}
 		rc, ok = tombstone.Obj.(*kapi.ReplicationController)
 		if !ok {
-			glog.Errorf("Tombstone contained object that is not a replication controller %#v", obj)
+			utilruntime.HandleError(fmt.Errorf("Tombstone contained object that is not a replication controller %#v", obj))
 			return
 		}
 	}
-	glog.V(4).Infof("Replication controller %q deleted.", rc.Name)
 	if dc, err := c.dcStore.GetConfigForController(rc); err == nil && dc != nil {
 		c.enqueueDeploymentConfig(dc)
 	}
@@ -198,12 +197,12 @@ func (c *DeploymentConfigController) deletePod(obj interface{}) {
 	if !ok {
 		tombstone, ok := obj.(cache.DeletedFinalStateUnknown)
 		if !ok {
-			glog.Errorf("Couldn't get object from tombstone %+v", obj)
+			utilruntime.HandleError(fmt.Errorf("Couldn't get object from tombstone %+v", obj))
 			return
 		}
 		pod, ok = tombstone.Obj.(*kapi.Pod)
 		if !ok {
-			glog.Errorf("Tombstone contained object that is not a pod: %+v", obj)
+			utilruntime.HandleError(fmt.Errorf("Tombstone contained object that is not a pod: %+v", obj))
 			return
 		}
 	}
@@ -215,7 +214,7 @@ func (c *DeploymentConfigController) deletePod(obj interface{}) {
 func (c *DeploymentConfigController) enqueueDeploymentConfig(dc *deployapi.DeploymentConfig) {
 	key, err := kcontroller.KeyFunc(dc)
 	if err != nil {
-		glog.Errorf("Couldn't get key for object %#v: %v", dc, err)
+		utilruntime.HandleError(fmt.Errorf("Couldn't get key for object %#v: %v", dc, err))
 		return
 	}
 	c.queue.Add(key)
@@ -238,7 +237,7 @@ func (c *DeploymentConfigController) work() bool {
 
 	dc, err := c.getByKey(key.(string))
 	if err != nil {
-		glog.Error(err.Error())
+		utilruntime.HandleError(err)
 	}
 
 	if dc == nil {
@@ -254,7 +253,6 @@ func (c *DeploymentConfigController) work() bool {
 func (c *DeploymentConfigController) getByKey(key string) (*deployapi.DeploymentConfig, error) {
 	obj, exists, err := c.dcStore.Indexer.GetByKey(key)
 	if err != nil {
-		glog.V(2).Infof("Unable to retrieve deployment config %q from store: %v", key, err)
 		c.queue.AddRateLimited(key)
 		return nil, err
 	}

pkg/deploy/controller/generictrigger/factory.go

@@ -1,6 +1,7 @@
 package generictrigger
 
 import (
+	"fmt"
 	"reflect"
 	"time"
 
@@ -135,7 +136,7 @@ func (c *DeploymentTriggerController) updateDeploymentConfig(old, cur interface{
 	if err != nil {
 		// If we get an error here it may be due to the rc cache lagging behind. In such a case
 		// just defer to the api server (instantiate REST) where we will retry this.
-		glog.V(2).Infof("Cannot get latest rc for dc %s:%d (%v) - will defer to instantiate", deployutil.LabelForDeploymentConfig(newDc), newDc.Status.LatestVersion, err)
+		glog.V(4).Infof("Cannot get latest rc for dc %s:%d (%v) - will defer to instantiate", deployutil.LabelForDeploymentConfig(newDc), newDc.Status.LatestVersion, err)
 	} else {
 		initial, err := deployutil.DecodeDeploymentConfig(latestRc, c.codec)
 		if err != nil {
@@ -190,7 +191,7 @@ func (c *DeploymentTriggerController) updateImageStream(old, cur interface{}) {
 func (c *DeploymentTriggerController) enqueueDeploymentConfig(dc *deployapi.DeploymentConfig) {
 	key, err := kcontroller.KeyFunc(dc)
 	if err != nil {
-		glog.Errorf("Couldn't get key for object %+v: %v", dc, err)
+		utilruntime.HandleError(fmt.Errorf("Couldn't get key for object %+v: %v", dc, err))
 		return
 	}
 	c.queue.Add(key)
@@ -213,7 +214,7 @@ func (c *DeploymentTriggerController) work() bool {
 
 	dc, err := c.getByKey(key.(string))
 	if err != nil {
-		glog.Error(err.Error())
+		utilruntime.HandleError(err)
 	}
 
 	if dc == nil {
@@ -229,12 +230,11 @@ func (c *DeploymentTriggerController) work() bool {
 func (c *DeploymentTriggerController) getByKey(key string) (*deployapi.DeploymentConfig, error) {
 	obj, exists, err := c.dcLister.Indexer.GetByKey(key)
 	if err != nil {
-		glog.Infof("Unable to retrieve deployment config %q from store: %v", key, err)
-		c.queue.Add(key)
+		c.queue.AddRateLimited(key)
 		return nil, err
 	}
 	if !exists {
-		glog.Infof("Deployment config %q has been deleted", key)
+		glog.V(4).Infof("Deployment config %q has been deleted", key)
 		return nil, nil
 	}