use zap for logging, previous log never outputted to kubectl logs

Author: eatwithforks

go.mod

@@ -2,13 +2,15 @@ module github.com/open-policy-agent/cert-controller
 
 go 1.14
 
-require (
-	github.com/onsi/gomega v1.10.1
-	github.com/pkg/errors v0.9.1
-	go.uber.org/atomic v1.4.0
-	go.uber.org/zap v1.10.0
-	k8s.io/api v0.18.6
-	k8s.io/apimachinery v0.18.6
-	k8s.io/client-go v0.18.6
-	sigs.k8s.io/controller-runtime v0.6.3
-)
+ require (
+ 	github.com/go-logr/zapr v0.1.0
+ 	github.com/onsi/gomega v1.10.1
+ 	github.com/open-policy-agent/cert-controller v0.1.0
+ 	github.com/pkg/errors v0.9.1
+ 	go.uber.org/atomic v1.4.0
+ 	go.uber.org/zap v1.10.0
+ 	k8s.io/api v0.18.6
+ 	k8s.io/apimachinery v0.18.6
+ 	k8s.io/client-go v0.18.6
+ 	sigs.k8s.io/controller-runtime v0.6.3
+ )

main.go

@@ -12,6 +12,8 @@ import (
 	"k8s.io/client-go/tools/clientcmd/api"
 	"os"
 	ctrl "sigs.k8s.io/controller-runtime"
+	logf "sigs.k8s.io/controller-runtime/pkg/log"
+	"github.com/go-logr/zapr"
 	"sigs.k8s.io/controller-runtime/pkg/client/apiutil"
 	"time"
 )
@@ -27,6 +29,21 @@ var (
 	webhookName    = flag.String("webhook-name", "", "Your webhook name")
 )
 
+func buildLogger() (*zap.Logger, error) {
+	// build a logger:
+	// - without timestamps because docker already logs with timestamps
+	// - use "message" instead of "msg" for consistency with other services / datadog parsing
+	// - remove caller since it points to shared methods most of the time anyway
+	loggerConfig := zap.NewProductionConfig()
+	loggerConfig.EncoderConfig.TimeKey = ""
+	loggerConfig.EncoderConfig.MessageKey = "message"
+	loggerConfig.DisableCaller = true
+	if os.Getenv("DEBUG") == "1" {
+		loggerConfig.Level.SetLevel(zap.DebugLevel)
+	}
+	return loggerConfig.Build()
+}
+
 func main() {
 	flag.Parse()
 
@@ -38,7 +55,9 @@ func main() {
 	}
 
 	// configure logging.
-	logger, _ := zap.NewDevelopment()
+	logger, _ := buildLogger()
+	defer logger.Sync() // flush buffer
+	logf.SetLogger(zapr.NewLogger(logger)) // Set logger for cert-controller or it sends to /dev/null
 
 	logger.Info("sleeping to demonstrate restart behavior")
 	time.Sleep(5 * time.Second)
@@ -63,6 +82,7 @@ func main() {
 	}
 
 	// Make sure certs are generated and valid if cert rotation is enabled.
+	setupFinished := make(chan struct{})
 	if err := rotator.AddRotator(mgr, &rotator.CertRotator{
 		SecretKey: types.NamespacedName{
 			Namespace: *nameSpace,
@@ -72,10 +92,10 @@ func main() {
 		CAName:         *caName,
 		CAOrganization: *caOrganization,
 		DNSName:        *dnsName,
+		IsReady:        setupFinished,
 		Webhooks:       webhooks,
 	}); err != nil {
 		logger.Error("unable to set up cert rotation", zap.Error(err))
-
 		os.Exit(1)
 	}
 

pkg/rotator/rotator.go

@@ -12,6 +12,7 @@ import (
 	"encoding/pem"
 	"flag"
 	"fmt"
+	"go.uber.org/zap"
 	"math/big"
 	"os"
 	"time"
@@ -29,7 +30,6 @@ import (
 	"sigs.k8s.io/controller-runtime/pkg/client"
 	"sigs.k8s.io/controller-runtime/pkg/controller"
 	"sigs.k8s.io/controller-runtime/pkg/handler"
-	logf "sigs.k8s.io/controller-runtime/pkg/log"
 	"sigs.k8s.io/controller-runtime/pkg/manager"
 	"sigs.k8s.io/controller-runtime/pkg/reconcile"
 	"sigs.k8s.io/controller-runtime/pkg/source"
@@ -44,7 +44,7 @@ const (
 	lookaheadInterval      = 90 * 24 * time.Hour
 )
 
-var crLog = logf.Log.WithName("cert-rotation")
+var crLog, _  = zap.NewDevelopment()
 
 //WebhookType it the type of webhook, either validating/mutating webhook or a CRD conversion webhook
 type WebhookType int
@@ -182,7 +182,7 @@ func (cr *CertRotator) Start(stop <-chan struct{}) error {
 	crLog.Info("starting cert rotator controller")
 	defer crLog.Info("stopping cert rotator controller")
 	if err := cr.refreshCertIfNeeded(); err != nil {
-		crLog.Error(err, "could not refresh cert on startup")
+		crLog.Error("could not refresh cert on startup", zap.Error(err))
 		return err
 	}
 
@@ -197,7 +197,7 @@ tickerLoop:
 		select {
 		case <-ticker.C:
 			if err := cr.refreshCertIfNeeded(); err != nil {
-				crLog.Error(err, "error rotating certs")
+				crLog.Error("error rotating certs", zap.Error(err))
 			}
 		case <-stop:
 			break tickerLoop
@@ -222,7 +222,7 @@ func (cr *CertRotator) refreshCertIfNeeded() error {
 		if secret.Data == nil || !cr.validCACert(secret.Data[caCertName], secret.Data[caKeyName]) {
 			crLog.Info("refreshing CA and server certs")
 			if err := cr.refreshCerts(true, secret); err != nil {
-				crLog.Error(err, "could not refresh CA and server certs")
+				crLog.Error("could not refresh CA and server certs", zap.Error(err))
 				return false, nil
 			}
 			crLog.Info("server certs refreshed")
@@ -236,7 +236,7 @@ func (cr *CertRotator) refreshCertIfNeeded() error {
 		if !cr.validServerCert(secret.Data[caCertName], secret.Data[certName], secret.Data[keyName]) {
 			crLog.Info("refreshing server certs")
 			if err := cr.refreshCerts(false, secret); err != nil {
-				crLog.Error(err, "could not refresh server certs")
+				crLog.Error("could not refresh server certs", zap.Error(err))
 				return false, nil
 			}
 			crLog.Info("server certs refreshed")
@@ -685,38 +685,34 @@ func (r *ReconcileWH) ensureCerts(certPem []byte) error {
 
 	for _, webhook := range r.webhooks {
 		gvk := webhook.gvk()
-		log := crLog.WithValues("name", webhook.Name, "gvk", gvk)
 		updatedResource := &unstructured.Unstructured{}
 		updatedResource.SetGroupVersionKind(gvk)
 		if err := r.cache.Get(r.ctx, types.NamespacedName{Name: webhook.Name}, updatedResource); err != nil {
 			if k8sErrors.IsNotFound(err) {
-				fmt.Println("Webhook not found. Unable to update certificate.", err)
-				log.Error(err, "Webhook not found. Unable to update certificate.")
+				crLog.Error("Webhook not found. Unable to update certificate.", zap.Error(err))
 				continue
 			}
 			anyError = err
-			log.Error(err, "Error getting webhook for certificate update.")
-			fmt.Println("Error getting webhook for certificate update.", err)
+			crLog.Error("Error getting webhook for certificate update.", zap.Error(err))
 
 			continue
 		}
 		if !updatedResource.GetDeletionTimestamp().IsZero() {
-			fmt.Println("Webhook is being deleted. Unable to update certificate")
-			log.Info("Webhook is being deleted. Unable to update certificate")
+			crLog.Info("Webhook is being deleted. Unable to update certificate")
 			continue
 		}
 
-		log.Info("Ensuring CA cert", "name", webhook.Name, "gvk", gvk)
+		crLog.Info("Ensuring CA cert")
 		if err := injectCert(updatedResource, certPem, webhook.Type); err != nil {
 			fmt.Println("Unable to inject cert to webhook.:", err)
-			log.Error(err, "Unable to inject cert to webhook.")
+			crLog.Error("Unable to inject cert to webhook.", zap.Error(err))
 			anyError = err
 			continue
 		}
 		if err := r.writer.Update(r.ctx, updatedResource); err != nil {
 			fmt.Println("Error updating webhook with certificate:", err)
 
-			log.Error(err, "Error updating webhook with certificate")
+			crLog.Error("Error updating webhook with certificate", zap.Error(err))
 			anyError = err
 			continue
 		}
@@ -740,7 +736,7 @@ func (cr *CertRotator) ensureCertsMounted() {
 		Jitter:   1,
 		Steps:    10,
 	}, checkFn); err != nil {
-		crLog.Error(err, "max retries for checking certs existence")
+		crLog.Error("max retries for checking certs existence", zap.Error(err))
 		close(cr.certsNotMounted)
 		return
 	}
@@ -760,7 +756,7 @@ func (cr *CertRotator) ensureReady() {
 		Jitter:   1,
 		Steps:    10,
 	}, checkFn); err != nil {
-		crLog.Error(err, "max retries for checking CA injection")
+		crLog.Error("max retries for checking CA injection", zap.Error(err))
 		close(cr.caNotInjected)
 		return
 	}

test.yaml

@@ -18,29 +18,40 @@ spec:
         foo: bar4
     spec:
       containers:
-      - name: busybox
-        image: busybox
-        command: ["sh", "-c", "watch ls /certs"]
-        volumeMounts:
-        - name: certs
-          mountPath: "/certs"
-          readOnly: true
-      - name: cert-controller
-        args:
-          - -cert-dir=/certs
-          - -ca-name=foocaname
-          - -secret-name=vpa-admission-controller-secret
-          - -service-name=fooservice
-          - -ca-organization=fooorg
-          - -namespace=default
-          - -dns-name=foo.bar.svc
-          - -webhook-name=vpa-webhook-config
-        imagePullPolicy: Never
-        image: cert-controller
+        - name: busybox
+          image: busybox
+          command: ["sh", "-c", "watch ls /certs"]
+          volumeMounts:
+            - name: certs
+              mountPath: "/certs"
+              readOnly: true
+        - name: cert-controller
+          args:
+            - -cert-dir=/certs
+            - -ca-name=foocaname
+            - -secret-name=vpa-admission-controller-secret
+            - -service-name=fooservice
+            - -ca-organization=fooorg
+            - -namespace=default
+            - -dns-name=foo.bar.svc
+            - -webhook-name=vpa-webhook-config
+          imagePullPolicy: Never
+          image: cert-controller
+          resources:
+            limits:
+              cpu: 200m
+              memory: 500Mi
+            requests:
+              cpu: 50m
+              memory: 200Mi
+          volumeMounts:
+            - name: certs
+              mountPath: "/certs"
+              readOnly: true
       volumes:
-      - name: certs
-        secret:
-          secretName: vpa-admission-controller-secret
+        - name: certs
+          secret:
+            secretName: vpa-admission-controller-secret
 ---
 apiVersion: admissionregistration.k8s.io/v1
 kind: MutatingWebhookConfiguration
@@ -54,21 +65,21 @@ metadata:
   annotations:
     samson/server_side_apply: 'true'
 webhooks:
-- name: vpa.k8s.io
-  failurePolicy: Ignore
-  admissionReviewVersions: ["v1beta1"]
-  rules:
-  - apiGroups:   [""]
-    apiVersions: ["v1"]
-    operations:  ["CREATE"]
-    resources:   ["pods"]
-  clientConfig:
-    caBundle: Cg==
-    service:
-      namespace: default
-      name: vpa-webhook
-  sideEffects: None
-  timeoutSeconds: 30
+  - name: vpa.k8s.io
+    failurePolicy: Ignore
+    admissionReviewVersions: ["v1beta1"]
+    rules:
+      - apiGroups:   [""]
+        apiVersions: ["v1"]
+        operations:  ["CREATE"]
+        resources:   ["pods"]
+    clientConfig:
+      caBundle: Cg==
+      service:
+        namespace: default
+        name: vpa-webhook
+    sideEffects: None
+    timeoutSeconds: 30
 
 # We need to create a bogus secret for the updater to fill
 ---