Introduce JSON logging

- add JSON log format cmd flag
- format apply output as a map of object/operation
- add apply logs to docs

README.md

@@ -154,13 +154,26 @@ You can wait for the kustomize controller to apply the manifest corresponding to
 kubectl wait kustomization/podinfo-dev --for=condition=ready
 ```
 
-When the controller finishes the reconciliation, the following objects will be created on your cluster:
+When the controller finishes the reconciliation, it will log the applied objects:
 
-```text
-namespace/dev created
-service/podinfo created
-deployment.apps/podinfo created
-horizontalpodautoscaler.autoscaling/podinfo created
+```bash
+kubectl -n kustomize-system logs deploy/kustomize-controller | jq .
+```
+
+```json
+{
+  "level": "info",
+  "ts": 1587195448.071468,
+  "logger": "controllers.Kustomization",
+  "msg": "Kustomization applied in 1.436096591s",
+  "kustomization": "default/podinfo-dev",
+  "output": {
+    "namespace/dev": "created",
+    "service/podinfo": "created",
+    "deployment.apps/podinfo": "created",
+    "horizontalpodautoscaler.autoscaling/podinfo": "created"
+  }
+}
 ```
 
 You can trigger a kustomize build and apply any time with:
@@ -185,7 +198,10 @@ status:
 ``` 
 
 ```json
-{"Kustomization": "default/podinfo-dev", "error": "kubectl apply: Error from server (NotFound): error when creating \"podinfo-dev.yaml\": namespaces \"dev\" not found\n"}
+{
+  "kustomization": "default/podinfo-dev",
+  "error": "Error from server (NotFound): error when creating \"podinfo-dev.yaml\": namespaces \"dev\" not found\n"
+}
 ```
 
 ### Deploy releases to production

config/manager/deployment.yaml

@@ -27,6 +27,7 @@ spec:
             name: http-prom
         args:
         - --enable-leader-election
+        - --log-json
         resources:
           limits:
             cpu: 1000m

controllers/gitrepository_controller.go

@@ -18,6 +18,7 @@ package controllers
 
 import (
 	"context"
+	"strings"
 	"time"
 
 	"github.com/go-logr/logr"
@@ -49,7 +50,7 @@ func (r *GitRepositoryWatcher) Reconcile(req ctrl.Request) (ctrl.Result, error)
 		return ctrl.Result{}, client.IgnoreNotFound(err)
 	}
 
-	log := r.Log.WithValues(repo.Kind, req.NamespacedName)
+	log := r.Log.WithValues(strings.ToLower(repo.Kind), req.NamespacedName)
 	log.Info("New artifact detected")
 
 	// get the list of kustomizations that are using this Git repository

controllers/kustomization_controller.go

@@ -23,6 +23,7 @@ import (
 	"os"
 	"os/exec"
 	"path"
+	"strings"
 	"time"
 
 	"github.com/go-logr/logr"
@@ -55,7 +56,7 @@ func (r *KustomizationReconciler) Reconcile(req ctrl.Request) (ctrl.Result, erro
 		return ctrl.Result{}, client.IgnoreNotFound(err)
 	}
 
-	log := r.Log.WithValues(kustomization.Kind, req.NamespacedName)
+	log := r.Log.WithValues(strings.ToLower(kustomization.Kind), req.NamespacedName)
 
 	var source sourcev1.Source
 
@@ -103,7 +104,7 @@ func (r *KustomizationReconciler) Reconcile(req ctrl.Request) (ctrl.Result, erro
 		return ctrl.Result{Requeue: true}, err
 	}
 
-	log.Info("Kustomization sync finished", "msg", kustomizev1.KustomizationReadyMessage(syncedKustomization))
+	log.Info("Kustomization sync finished, next run in " + kustomization.Spec.Interval.Duration.String())
 
 	// requeue kustomization
 	return ctrl.Result{RequeueAfter: kustomization.Spec.Interval.Duration}, nil
@@ -181,6 +182,8 @@ func (r *KustomizationReconciler) sync(
 	ctxApply, cancel := context.WithTimeout(context.Background(), timeout)
 	defer cancel()
 
+	applyStart := time.Now()
+
 	// run apply with timeout
 	cmd = fmt.Sprintf("cd %s && kubectl apply -f %s.yaml --timeout=%s",
 		tmpDir, kustomization.GetName(), kustomization.Spec.Interval.Duration.String())
@@ -199,7 +202,11 @@ func (r *KustomizationReconciler) sync(
 	}
 
 	// log apply output
-	fmt.Println(string(output))
+	applyDuration := fmt.Sprintf("Kustomization applied in %s", time.Now().Sub(applyStart).String())
+	r.Log.WithValues(
+		strings.ToLower(kustomization.Kind),
+		fmt.Sprintf("%s/%s", kustomization.GetNamespace(), kustomization.GetName()),
+	).Info(applyDuration, "output", r.parseApplyOutput(output))
 
 	return kustomizev1.KustomizationReady(
 		kustomization,
@@ -213,3 +220,24 @@ func (r *KustomizationReconciler) lock(name string) (unlock func(), err error) {
 	mutex := lockedfile.MutexAt(lockFile)
 	return mutex.Lock()
 }
+
+func (r *KustomizationReconciler) parseApplyOutput(in []byte) map[string]string {
+	result := make(map[string]string)
+	input := strings.Split(string(in), "\n")
+	if len(input) == 0 {
+		return result
+	}
+	var parts []string
+	for _, str := range input {
+		if str != "" {
+			parts = append(parts, str)
+		}
+	}
+	for _, str := range parts {
+		kv := strings.Split(str, " ")
+		if len(kv) > 1 {
+			result[kv[0]] = kv[1]
+		}
+	}
+	return result
+}

controllers/kustomization_predicate.go

@@ -19,6 +19,7 @@ package controllers
 import (
 	"fmt"
 	"os/exec"
+	"strings"
 
 	"github.com/go-logr/logr"
 	"sigs.k8s.io/controller-runtime/pkg/event"
@@ -70,11 +71,11 @@ func (gc KustomizationGarbageCollectPredicate) Delete(e event.DeleteEvent) bool
 			if output, err := command.CombinedOutput(); err != nil {
 				gc.Log.Error(err, "Garbage collection failed",
 					"output", string(output),
-					"Kustomization", fmt.Sprintf("%s/%s", k.GetNamespace(), k.GetName()))
+					strings.ToLower(k.Kind), fmt.Sprintf("%s/%s", k.GetNamespace(), k.GetName()))
 			} else {
 				gc.Log.Info("Garbage collection completed",
 					"output", string(output),
-					"Kustomization", fmt.Sprintf("%s/%s", k.GetNamespace(), k.GetName()))
+					strings.ToLower(k.Kind), fmt.Sprintf("%s/%s", k.GetNamespace(), k.GetName()))
 			}
 		}
 	}

main.go

@@ -48,13 +48,15 @@ func init() {
 func main() {
 	var metricsAddr string
 	var enableLeaderElection bool
+	var logJSON bool
 	flag.StringVar(&metricsAddr, "metrics-addr", ":8282", "The address the metric endpoint binds to.")
 	flag.BoolVar(&enableLeaderElection, "enable-leader-election", false,
 		"Enable leader election for controller manager. "+
 			"Enabling this will ensure there is only one active controller manager.")
+	flag.BoolVar(&logJSON, "log-json", false, "Set logging to JSON format.")
 	flag.Parse()
 
-	ctrl.SetLogger(zap.New(zap.UseDevMode(true)))
+	ctrl.SetLogger(zap.New(zap.UseDevMode(!logJSON)))
 
 	mgr, err := ctrl.NewManager(ctrl.GetConfigOrDie(), ctrl.Options{
 		Scheme:             scheme,