Improve reporting about rolling updates

Sergey Dudoladov · Sergey Dudoladov · commit ee6a61a26d93 · 2018-09-19T15:32:41.000+02:00
diff --git a/docs/administrator.md b/docs/administrator.md
@@ -219,4 +219,8 @@ The operator is capable of maintaining roles of multiple kinds within a Postgres
 
 3. **Per-cluster robot users** are also roles for processes originating from external systems but defined for an individual Postgres cluster in its manifest. A typical example is a role for connections from an application that uses the database.
 
-4. **Human users** originate from the Teams API that returns list of the team members given a team id. Operator differentiates between (a) product teams that own a particular Postgres cluster and are granted admin rights to maintain it, and (b) Postgres superuser teams that get the superuser access to all PG databases running in a k8s cluster for the purposes of maintaining and troubleshooting.
+4. **Human users** originate from the Teams API that returns list of the team members given a team id. Operator differentiates between (a) product teams that own a particular Postgres cluster and are granted admin rights to maintain it, and (b) Postgres superuser teams that get the superuser access to all PG databases running in a k8s cluster for the purposes of maintaining and troubleshooting.
+
+## Understanding rolling update of Spilo pods
+
+The operator logs reasons for a rolling update with the `info` level and a diff between the old and new StatefulSet specs with the `debug` level. To benefit from numerous escape characters in the latter log entry, view it in CLI with `echo -e`. Note that the resultant message will contain some noise because the `PodTemplate` used by the operator is yet to be updated with the default values used internally in Kubernetes.
diff --git a/pkg/cluster/cluster.go b/pkg/cluster/cluster.go
@@ -321,15 +321,16 @@ func (c *Cluster) compareStatefulSetWith(statefulSet *v1beta1.StatefulSet) *comp
 		needsRollUpdate = true
 		reasons = append(reasons, "new statefulset's container specification doesn't match the current one")
 	} else {
-		needsRollUpdate, reasons = c.compareContainers(c.Statefulset, statefulSet)
+		var containerReasons []string
+		needsRollUpdate, containerReasons = c.compareContainers(c.Statefulset, statefulSet)
+		reasons = append(reasons, containerReasons...)
 	}
 	if len(c.Statefulset.Spec.Template.Spec.Containers) == 0 {
 		c.logger.Warningf("statefulset %q has no container", util.NameFromMeta(c.Statefulset.ObjectMeta))
 		return &compareStatefulsetResult{}
 	}
 	// In the comparisons below, the needsReplace and needsRollUpdate flags are never reset, since checks fall through
 	// and the combined effect of all the changes should be applied.
-	// TODO: log all reasons for changing the statefulset, not just the last one.
 	// TODO: make sure this is in sync with generatePodTemplate, ideally by using the same list of fields to generate
 	// the template and the diff
 	if c.Statefulset.Spec.Template.Spec.ServiceAccountName != statefulSet.Spec.Template.Spec.ServiceAccountName {
@@ -340,7 +341,7 @@ func (c *Cluster) compareStatefulSetWith(statefulSet *v1beta1.StatefulSet) *comp
 	if *c.Statefulset.Spec.Template.Spec.TerminationGracePeriodSeconds != *statefulSet.Spec.Template.Spec.TerminationGracePeriodSeconds {
 		needsReplace = true
 		needsRollUpdate = true
-		reasons = append(reasons, "new statefulset's terminationGracePeriodSeconds  doesn't match the current one")
+		reasons = append(reasons, "new statefulset's terminationGracePeriodSeconds doesn't match the current one")
 	}
 	if !reflect.DeepEqual(c.Statefulset.Spec.Template.Spec.Affinity, statefulSet.Spec.Template.Spec.Affinity) {
 		needsReplace = true
@@ -416,23 +417,23 @@ func newCheck(msg string, cond containerCondition) containerCheck {
 
 // compareContainers: compare containers from two stateful sets
 // and return:
-// * whether or not roll update is needed
+// * whether or not a rolling update is needed
 // * a list of reasons in a human readable format
 func (c *Cluster) compareContainers(setA, setB *v1beta1.StatefulSet) (bool, []string) {
 	reasons := make([]string, 0)
 	needsRollUpdate := false
 	checks := []containerCheck{
-		newCheck("new statefulset's container %d name doesn't match the current one",
+		newCheck("new statefulset's container %s (index %d) name doesn't match the current one",
 			func(a, b v1.Container) bool { return a.Name != b.Name }),
-		newCheck("new statefulset's container %d image doesn't match the current one",
+		newCheck("new statefulset's container %s (index %d) image doesn't match the current one",
 			func(a, b v1.Container) bool { return a.Image != b.Image }),
-		newCheck("new statefulset's container %d ports don't match the current one",
+		newCheck("new statefulset's container %s (index %d) ports don't match the current one",
 			func(a, b v1.Container) bool { return !reflect.DeepEqual(a.Ports, b.Ports) }),
-		newCheck("new statefulset's container %d resources don't match the current ones",
+		newCheck("new statefulset's container %s (index %d) resources don't match the current ones",
 			func(a, b v1.Container) bool { return !compareResources(&a.Resources, &b.Resources) }),
-		newCheck("new statefulset's container %d environment doesn't match the current one",
+		newCheck("new statefulset's container %s (index %d) environment doesn't match the current one",
 			func(a, b v1.Container) bool { return !reflect.DeepEqual(a.Env, b.Env) }),
-		newCheck("new statefulset's container %d environment sources don't match the current one",
+		newCheck("new statefulset's container %s (index %d) environment sources don't match the current one",
 			func(a, b v1.Container) bool { return !reflect.DeepEqual(a.EnvFrom, b.EnvFrom) }),
 	}
 
@@ -441,7 +442,7 @@ func (c *Cluster) compareContainers(setA, setB *v1beta1.StatefulSet) (bool, []st
 		for _, check := range checks {
 			if check.condition(containerA, containerB) {
 				needsRollUpdate = true
-				reasons = append(reasons, fmt.Sprintf(check.reason, index))
+				reasons = append(reasons, fmt.Sprintf(check.reason, containerA.Name, index))
 			}
 		}
 	}
diff --git a/pkg/cluster/resources.go b/pkg/cluster/resources.go
@@ -132,16 +132,17 @@ func (c *Cluster) preScaleDown(newStatefulSet *v1beta1.StatefulSet) error {
 	return nil
 }
 
-// setRollingUpdateFlagForStatefulSet sets the indicator or the rolling upgrade requirement
+// setRollingUpdateFlagForStatefulSet sets the indicator or the rolling update requirement
 // in the StatefulSet annotation.
 func (c *Cluster) setRollingUpdateFlagForStatefulSet(sset *v1beta1.StatefulSet, val bool) {
 	anno := sset.GetAnnotations()
-	c.logger.Debugf("rolling upgrade flag has been set to %t", val)
 	if anno == nil {
 		anno = make(map[string]string)
 	}
+
 	anno[rollingUpdateStatefulsetAnnotationKey] = strconv.FormatBool(val)
 	sset.SetAnnotations(anno)
+	c.logger.Debugf("statefulset's rolling update annotation has been set to %t", val)
 }
 
 // applyRollingUpdateFlagforStatefulSet sets the rolling update flag for the cluster's StatefulSet
@@ -176,9 +177,9 @@ func (c *Cluster) getRollingUpdateFlagFromStatefulSet(sset *v1beta1.StatefulSet,
 	return flag
 }
 
-// mergeRollingUpdateFlagUsingCache return the value of the rollingUpdate flag from the passed
+// mergeRollingUpdateFlagUsingCache returns the value of the rollingUpdate flag from the passed
 // statefulset, however, the value can be cleared if there is a cached flag in the cluster that
-// is set to false (the disrepancy could be a result of a failed StatefulSet update).s
+// is set to false (the discrepancy could be a result of a failed StatefulSet update)
 func (c *Cluster) mergeRollingUpdateFlagUsingCache(runningStatefulSet *v1beta1.StatefulSet) bool {
 	var (
 		cachedStatefulsetExists, clearRollingUpdateFromCache, podsRollingUpdateRequired bool
@@ -198,7 +199,7 @@ func (c *Cluster) mergeRollingUpdateFlagUsingCache(runningStatefulSet *v1beta1.S
 			c.logger.Infof("clearing the rolling update flag based on the cached information")
 			podsRollingUpdateRequired = false
 		} else {
-			c.logger.Infof("found a statefulset with an unfinished pods rolling update")
+			c.logger.Infof("found a statefulset with an unfinished rolling update of the pods")
 
 		}
 	}
diff --git a/pkg/cluster/sync.go b/pkg/cluster/sync.go
@@ -2,6 +2,7 @@ package cluster
 
 import (
 	"fmt"
+
 	"k8s.io/api/core/v1"
 	policybeta1 "k8s.io/api/policy/v1beta1"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
@@ -280,6 +281,7 @@ func (c *Cluster) syncStatefulSet() error {
 				podsRollingUpdateRequired = true
 				c.setRollingUpdateFlagForStatefulSet(desiredSS, podsRollingUpdateRequired)
 			}
+
 			c.logStatefulSetChanges(c.Statefulset, desiredSS, false, cmp.reasons)
 
 			if !cmp.replace {
diff --git a/pkg/cluster/util.go b/pkg/cluster/util.go
@@ -179,7 +179,7 @@ func (c *Cluster) logStatefulSetChanges(old, new *v1beta1.StatefulSet, isUpdate
 	if !reflect.DeepEqual(old.Annotations, new.Annotations) {
 		c.logger.Debugf("metadata.annotation diff\n%s\n", util.PrettyDiff(old.Annotations, new.Annotations))
 	}
-	c.logger.Debugf("spec diff\n%s\n", util.PrettyDiff(old.Spec, new.Spec))
+	c.logger.Debugf("spec diff between old and new statefulsets: \n%s\n", util.PrettyDiff(old.Spec, new.Spec))
 
 	if len(reasons) > 0 {
 		for _, reason := range reasons {

Original file line number	Diff line number	Diff line change
`@@ -179,7 +179,7 @@ func (c Cluster) logStatefulSetChanges(old, new v1beta1.StatefulSet, isUpdate`
`179`	`179`	`if !reflect.DeepEqual(old.Annotations, new.Annotations) {`
`180`	`180`	`c.logger.Debugf("metadata.annotation diff\n%s\n", util.PrettyDiff(old.Annotations, new.Annotations))`
`181`	`181`	`}`
`182`		`- c.logger.Debugf("spec diff\n%s\n", util.PrettyDiff(old.Spec, new.Spec))`
	`182`	`+ c.logger.Debugf("spec diff between old and new statefulsets: \n%s\n", util.PrettyDiff(old.Spec, new.Spec))`
`183`	`183`
`184`	`184`	`if len(reasons) > 0 {`
`185`	`185`	`for _, reason := range reasons {`