Increase log verbosity, namely for object updates.

- add a new environment variable for triggering debug log level
- show both new, old object and diff during syncs and updates
- use pretty package to pretty-print go structures
-

pkg/cluster/cluster.go

@@ -177,25 +177,42 @@ func (c *Cluster) Create() error {
 	return nil
 }
 
-func (c Cluster) sameServiceWith(service *v1.Service) bool {
+func (c Cluster) sameServiceWith(service *v1.Service) (match bool, reason string) {
 	//TODO: improve comparison
-	return reflect.DeepEqual(c.Service.Spec.LoadBalancerSourceRanges, service.Spec.LoadBalancerSourceRanges)
+	reason = ""
+	match = false
+	if !reflect.DeepEqual(c.Service.Spec.LoadBalancerSourceRanges, service.Spec.LoadBalancerSourceRanges) {
+		reason = "new service's LoadBalancerSourceRange doesn't match the current one"
+	} else {
+		match = true
+	}
+	return
 }
 
-func (c Cluster) sameVolumeWith(volume spec.Volume) bool {
-	return reflect.DeepEqual(c.Spec.Volume, volume)
+func (c Cluster) sameVolumeWith(volume spec.Volume) (match bool, reason string) {
+	reason = ""
+	match = false
+	if !reflect.DeepEqual(c.Spec.Volume, volume) {
+		reason = "new volume's specification doesn't match the current one"
+	} else {
+		match = true
+	}
+	return
 }
 
-func (c Cluster) compareStatefulSetWith(statefulSet *v1beta1.StatefulSet) (equal, needsRollUpdate bool) {
-	equal = true
+func (c Cluster) compareStatefulSetWith(statefulSet *v1beta1.StatefulSet) (match, needsRollUpdate bool, reason string) {
+	match = true
 	needsRollUpdate = false
+	reason = ""
 	//TODO: improve me
 	if *c.Statefulset.Spec.Replicas != *statefulSet.Spec.Replicas {
-		equal = false
+		match = false
+		reason = "new statefulset's number of replicas doesn't match the current one"
 	}
 	if len(c.Statefulset.Spec.Template.Spec.Containers) != len(statefulSet.Spec.Template.Spec.Containers) {
-		equal = false
+		match = false
 		needsRollUpdate = true
+		reason = "new statefulset's container specification doesn't match the current one"
 		return
 	}
 	if len(c.Statefulset.Spec.Template.Spec.Containers) == 0 {
@@ -206,25 +223,29 @@ func (c Cluster) compareStatefulSetWith(statefulSet *v1beta1.StatefulSet) (equal
 	container1 := c.Statefulset.Spec.Template.Spec.Containers[0]
 	container2 := statefulSet.Spec.Template.Spec.Containers[0]
 	if container1.Image != container2.Image {
-		equal = false
+		match = false
 		needsRollUpdate = true
+		reason = "new statefulset's container image doesn't match the current one"
 		return
 	}
 
 	if !reflect.DeepEqual(container1.Ports, container2.Ports) {
-		equal = false
+		match = false
 		needsRollUpdate = true
+		reason = "new statefulset's container ports don't match the current one"
 		return
 	}
 
 	if !reflect.DeepEqual(container1.Resources, container2.Resources) {
-		equal = false
+		match = false
 		needsRollUpdate = true
+		reason = "new statefulset's container resources don't match the current ones"
 		return
 	}
 	if !reflect.DeepEqual(container1.Env, container2.Env) {
-		equal = false
+		match = false
 		needsRollUpdate = true
+		reason = "new statefulset's container environment doesn't match the current one"
 	}
 
 	return
@@ -235,11 +256,8 @@ func (c *Cluster) Update(newSpec *spec.Postgresql) error {
 		c.Metadata.ResourceVersion, newSpec.Metadata.ResourceVersion)
 
 	newService := c.genService(newSpec.Spec.AllowedSourceRanges)
-	if !c.sameServiceWith(newService) {
-		c.logger.Infof("LoadBalancer configuration has changed for Service '%s': %+v -> %+v",
-			util.NameFromMeta(c.Service.ObjectMeta),
-			c.Service.Spec.LoadBalancerSourceRanges, newService.Spec.LoadBalancerSourceRanges,
-		)
+	if match, reason := c.sameServiceWith(newService); !match {
+		c.logServiceChanges(c.Service, newService, true, reason)
 		if err := c.updateService(newService); err != nil {
 			return fmt.Errorf("Can't update Service: %s", err)
 		} else {
@@ -247,19 +265,16 @@ func (c *Cluster) Update(newSpec *spec.Postgresql) error {
 		}
 	}
 
-	if !c.sameVolumeWith(newSpec.Spec.Volume) {
-		c.logger.Infof("Volume specification has been changed")
+	if match, reason := c.sameVolumeWith(newSpec.Spec.Volume); !match {
+		c.logVolumeChanges(c.Spec.Volume, newSpec.Spec.Volume, reason)
 		//TODO: update PVC
 	}
 
 	newStatefulSet := c.genStatefulSet(newSpec.Spec)
-	sameSS, rollingUpdate := c.compareStatefulSetWith(newStatefulSet)
+	sameSS, rollingUpdate, reason := c.compareStatefulSetWith(newStatefulSet)
 
 	if !sameSS {
-		c.logger.Infof("StatefulSet '%s' has been changed: %+v -> %+v",
-			util.NameFromMeta(c.Statefulset.ObjectMeta),
-			c.Statefulset.Spec, newStatefulSet.Spec,
-		)
+		c.logStatefulSetChanges(c.Statefulset, newStatefulSet, true, reason)
 		//TODO: mind the case of updating allowedSourceRanges
 		if err := c.updateStatefulSet(newStatefulSet); err != nil {
 			return fmt.Errorf("Can't upate StatefulSet: %s", err)

pkg/cluster/resources.go

@@ -15,7 +15,6 @@ var (
 	orphanDependents = false
 )
 
-
 func (c *Cluster) LoadResources() error {
 	ns := c.Metadata.Namespace
 	listOptions := v1.ListOptions{

pkg/cluster/sync.go

@@ -55,10 +55,11 @@ func (c *Cluster) syncService() error {
 	}
 
 	desiredSvc := c.genService(cSpec.AllowedSourceRanges)
-	if c.sameServiceWith(desiredSvc) {
+	if match, reason := c.sameServiceWith(desiredSvc); match {
 		return nil
+	} else {
+		c.logServiceChanges(c.Service, desiredSvc, false, reason)
 	}
-	c.logger.Infof("Service '%s' needs to be updated", util.NameFromMeta(desiredSvc.ObjectMeta))
 
 	if err := c.updateService(desiredSvc); err != nil {
 		return fmt.Errorf("Can't update Service to match desired state: %s", err)
@@ -99,11 +100,11 @@ func (c *Cluster) syncStatefulSet() error {
 	}
 
 	desiredSS := c.genStatefulSet(cSpec)
-	equalSS, rollUpdate := c.compareStatefulSetWith(desiredSS)
-	if equalSS {
+	match, rollUpdate, reason := c.compareStatefulSetWith(desiredSS)
+	if match {
 		return nil
 	}
-	c.logger.Infof("StatefulSet '%s' is not in the desired state", util.NameFromMeta(c.Statefulset.ObjectMeta))
+	c.logStatefulSetChanges(c.Statefulset, desiredSS, false, reason)
 
 	if err := c.updateStatefulSet(desiredSS); err != nil {
 		return fmt.Errorf("Can't update StatefulSet: %s", err)
@@ -147,8 +148,8 @@ func (c *Cluster) syncPods() error {
 			Namespace: pod.Namespace,
 			Name:      pod.Name,
 		}
-
-		if podMatchesTemplate(&pod, curSs) && pod.Status.Phase == v1.PodPending {
+		match, _ := podMatchesTemplate(&pod, curSs)
+		if match && pod.Status.Phase == v1.PodPending {
 			c.logger.Infof("Waiting for left over Pod '%s'", podName)
 			ch := c.registerPodSubscriber(podName)
 			c.waitForPodLabel(ch, podRole)
@@ -157,11 +158,11 @@ func (c *Cluster) syncPods() error {
 	}
 
 	for _, pod := range pods.Items {
-		if podMatchesTemplate(&pod, curSs) {
+		if match, reason := podMatchesTemplate(&pod, curSs); match {
 			c.logger.Infof("Pod '%s' matches StatefulSet pod template", util.NameFromMeta(pod.ObjectMeta))
 			continue
 		} else {
-			c.logger.Infof("Pod '%s' does not match StatefulSet pod template. Pod needs to be recreated", util.NameFromMeta(pod.ObjectMeta))
+			c.logPodChanges(&pod, curSs, reason)
 		}
 
 		if util.PodSpiloRole(&pod) == "master" {

pkg/cluster/util.go

@@ -45,28 +45,93 @@ func normalizeUserFlags(userFlags []string) (flags []string, err error) {
 	return
 }
 
-func podMatchesTemplate(pod *v1.Pod, ss *v1beta1.StatefulSet) bool {
+func podMatchesTemplate(pod *v1.Pod, ss *v1beta1.StatefulSet) (match bool, reason string) {
 	//TODO: improve me
+	match = false
+	reason = ""
 	if len(pod.Spec.Containers) != 1 {
-		return false
+		reason = "new pod defines more than one container"
+		return
 	}
 	container := pod.Spec.Containers[0]
 	ssContainer := ss.Spec.Template.Spec.Containers[0]
 
-	if container.Image != ssContainer.Image {
-		return false
-	}
-	if !reflect.DeepEqual(container.Env, ssContainer.Env) {
-		return false
-	}
-	if !reflect.DeepEqual(container.Ports, ssContainer.Ports) {
-		return false
-	}
-	if !reflect.DeepEqual(container.Resources, ssContainer.Resources) {
-		return false
+	switch {
+	case container.Image != ssContainer.Image:
+		{
+			reason = "new pod's container image doesn't match the current one"
+		}
+	case !reflect.DeepEqual(container.Env, ssContainer.Env):
+		{
+			reason = "new pod's container environment doesn't match the current one"
+		}
+	case !reflect.DeepEqual(container.Ports, ssContainer.Ports):
+		{
+			reason = "new pod's container ports don't match the current ones"
+		}
+	case !reflect.DeepEqual(container.Resources, ssContainer.Resources):
+		{
+			reason = "new pod's container resources don't match the current ones"
+		}
+	default:
+		match = true
 	}
+	return
+}
 
-	return true
+func (c *Cluster) logStatefulSetChanges(old, new *v1beta1.StatefulSet, isUpdate bool, reason string) {
+	if isUpdate {
+		c.logger.Infof("StatefulSet '%s' has been changed",
+			util.NameFromMeta(old.ObjectMeta),
+		)
+	} else {
+		c.logger.Infof("StatefulSet '%s' is not in the desired state and needs to be updated",
+			util.NameFromMeta(old.ObjectMeta),
+		)
+	}
+	c.logger.Debugf("Current %# v\nnew %# v\ndiff %s\n",
+		util.Pretty(old.Spec), util.Pretty(new.Spec), util.PrettyDiff(old.Spec, new.Spec))
+
+	if reason != "" {
+		c.logger.Infof("Reason: %s", reason)
+	}
+}
+
+func (c *Cluster) logServiceChanges(old, new *v1.Service, isUpdate bool, reason string) {
+	if isUpdate {
+		c.logger.Infof("Service '%s' has been changed",
+			util.NameFromMeta(old.ObjectMeta),
+		)
+	} else {
+		c.logger.Infof("Service '%s  is not in the desired state and needs to be updated",
+			util.NameFromMeta(old.ObjectMeta),
+		)
+	}
+	c.logger.Debugf("Current %# v\nnew %# v\ndiff %s\n",
+		util.Pretty(old.Spec), util.Pretty(new.Spec), util.PrettyDiff(old.Spec, new.Spec))
+
+	if reason != "" {
+		c.logger.Infof("Reason: %s", reason)
+	}
+}
+
+func (c *Cluster) logVolumeChanges(old, new spec.Volume, reason string) {
+	c.logger.Infof("Volume specification has been changed")
+	c.logger.Debugf("Current %# v\nnew %# v\ndiff %s\n",
+		util.Pretty(old), util.Pretty(new), util.PrettyDiff(old, new))
+	if reason != "" {
+		c.logger.Infof("Reason: %s", reason)
+	}
+}
+
+func (c *Cluster) logPodChanges(pod *v1.Pod, statefulset *v1beta1.StatefulSet, reason string) {
+	c.logger.Infof("Pod'%s does not match StatefulSet pod template and needs to be recreated",
+		util.NameFromMeta(pod.ObjectMeta),
+	)
+	c.logger.Debugf("Pod: %# v\nstatefulset %# v\n", util.Pretty(pod.Spec), util.Pretty(statefulset.Spec))
+	if reason != "" {
+		c.logger.Infof("Reason: %s", reason)
+	}
 }
 
 func (c *Cluster) getTeamMembers() ([]string, error) {

pkg/controller/controller.go

@@ -39,10 +39,15 @@ type Controller struct {
 }
 
 func New(controllerConfig *Config, operatorConfig *config.Config) *Controller {
+	if operatorConfig.DebugLogging {
+		logrus.SetLevel(logrus.DebugLevel)
+	}
+	logger := logrus.WithField("pkg", "controller")
+	logger.Debugf("Debug output enabled")
 	return &Controller{
 		Config:    *controllerConfig,
 		opConfig:  operatorConfig,
-		logger:    logrus.WithField("pkg", "controller"),
+		logger:    logger,
 		clusters:  make(map[spec.ClusterName]*cluster.Cluster),
 		stopChMap: make(map[spec.ClusterName]chan struct{}),
 		podCh:     make(chan spec.PodEvent),

pkg/util/config/config.go

@@ -38,6 +38,7 @@ type Config struct {
 	DockerImage        string `split_words:"true",default:"registry.opensource.zalan.do/acid/spilo-9.6:1.2-p12"`
 	ServiceAccountName string `split_words:"true",default:"operator"`
 	DbHostedZone       string `split_words:"true",default:"db.example.com"`
+	DebugLogging       bool   `split_words:"true",default:"false"`
 }
 
 func LoadFromEnv() *Config {

pkg/util/util.go

@@ -3,10 +3,13 @@ package util
 import (
 	"crypto/md5"
 	"encoding/hex"
+	"encoding/json"
 	"fmt"
 	"math/rand"
 	"time"
 
+	"github.com/kr/pretty"
+
 	"github.bus.zalan.do/acid/postgres-operator/pkg/spec"
 	"k8s.io/client-go/pkg/api/v1"
 	"k8s.io/client-go/pkg/types"
@@ -60,3 +63,18 @@ func PGUserPassword(user spec.PgUser) string {
 
 	return "md5" + hex.EncodeToString(s[:])
 }
+
+func Pretty(x interface {}) (f fmt.Formatter) {
+	return pretty.Formatter(x)
+}
+
+func PrettyDiff(a, b interface{}) (result string) {
+	diff := pretty.Diff(a, b)
+	json, err := json.MarshalIndent(diff, "", " ")
+	if err != nil {
+		result = fmt.Sprintf("%v", diff)
+	} else {
+		result = string(json)
+	}
+	return
+}