fix(kubernetes): include structured key/value context in client-go logs (#8490)

plugin/kubernetes/logger.go

@@ -1,16 +1,24 @@
 package kubernetes
 
 import (
+	"fmt"
+	"slices"
+	"strings"
+
 	clog "github.com/coredns/coredns/plugin/pkg/log"
 
 	"github.com/go-logr/logr"
 )
 
+// missingValue is what klog prints for a key without a value.
+const missingValue = "(MISSING)"
+
 // loggerAdapter is a simple wrapper around CoreDNS plugin logger made to implement logr.LogSink interface, which is used
 // as part of klog library for logging in Kubernetes client. By using this adapter CoreDNS is able to log messages/errors from
 // kubernetes client in a CoreDNS logging format
 type loggerAdapter struct {
 	clog.P
+	values []any // always even-length, see WithValues
 }
 
 func (l *loggerAdapter) Init(_ logr.RuntimeInfo) {
@@ -21,18 +29,71 @@ func (l *loggerAdapter) Enabled(_ int) bool {
 	return true
 }
 
-func (l *loggerAdapter) Info(_ int, msg string, _ ...any) {
+func (l *loggerAdapter) Info(_ int, msg string, keysAndValues ...any) {
-	l.P.Info(msg)
+	l.P.Info(l.sprint(msg, nil, keysAndValues))
 }
 
-func (l *loggerAdapter) Error(err error, msg string, _ ...any) {
+func (l *loggerAdapter) Error(err error, msg string, keysAndValues ...any) {
-	l.Errorf("%s: %s", msg, err)
+	l.P.Error(l.sprint(msg, err, keysAndValues))
 }
 
-func (l *loggerAdapter) WithValues(_ ...any) logr.LogSink {
+func (l *loggerAdapter) WithValues(keysAndValues ...any) logr.LogSink {
+	if len(keysAndValues) == 0 {
 		return l
+	}
+	clone := *l
+	clone.values = append(slices.Clip(l.values), keysAndValues...)
+	if len(clone.values)%2 != 0 {
+		// pad like klog does, so later pairs don't shift
+		clone.values = append(clone.values, missingValue)
+	}
+	return &clone
 }
 
 func (l *loggerAdapter) WithName(_ string) logr.LogSink {
 	return l
 }
+
+// sprint renders the message followed by the error (if any) and key/value pairs,
+// since client-go puts most context (resource type, reflector name) in the latter.
+// Duplicate keys are collapsed with the last value winning, as in klog.
+func (l *loggerAdapter) sprint(msg string, err error, keysAndValues []any) string {
+	var b strings.Builder
+	b.WriteString(msg)
+	if err != nil {
+		b.WriteString(": ")
+		b.WriteString(err.Error())
+	}
+	kvs := keysAndValues
+	if len(l.values) > 0 {
+		kvs = append(slices.Clip(l.values), keysAndValues...)
+	}
+	for i := 0; i < len(kvs); i += 2 {
+		k := fmt.Sprint(kvs[i])
+		if hasLaterKey(kvs, i+2, k) {
+			continue
+		}
+		var v any = missingValue
+		if i+1 < len(kvs) {
+			v = kvs[i+1]
+		}
+		switch v := v.(type) {
+		case string:
+			fmt.Fprintf(&b, " %s=%q", k, v)
+		case error:
+			fmt.Fprintf(&b, " %s=%q", k, v.Error())
+		default:
+			fmt.Fprintf(&b, " %s=%v", k, v)
+		}
+	}
+	return b.String()
+}
+
+func hasLaterKey(kvs []any, from int, key string) bool {
+	for j := from; j < len(kvs); j += 2 {
+		if fmt.Sprint(kvs[j]) == key {
+			return true
+		}
+	}
+	return false
+}

plugin/kubernetes/logger_test.go

@@ -0,0 +1,136 @@
+package kubernetes
+
+import (
+	"bytes"
+	"errors"
+	golog "log"
+	"strings"
+	"testing"
+
+	clog "github.com/coredns/coredns/plugin/pkg/log"
+)
+
+func newTestLoggerAdapter(buf *bytes.Buffer) *loggerAdapter {
+	golog.SetOutput(buf)
+	return &loggerAdapter{P: clog.NewWithPlugin("kubernetes")}
+}
+
+func TestLoggerAdapterErrorIncludesKeysAndValues(t *testing.T) {
+	var buf bytes.Buffer
+	l := newTestLoggerAdapter(&buf)
+	defer clog.Discard()
+
+	err := errors.New(`Get "https://10.96.0.1:443/api/v1/services": i/o timeout`)
+	l.Error(err, "Failed to watch", "reflector", "reflector-x", "type", "*v1.Service")
+
+	got := buf.String()
+	for _, want := range []string{
+		"Failed to watch",
+		`Get "https://10.96.0.1:443/api/v1/services": i/o timeout`,
+		`reflector="reflector-x"`,
+		`type="*v1.Service"`,
+	} {
+		if !strings.Contains(got, want) {
+			t.Errorf("log output missing %q, got: %q", want, got)
+		}
+	}
+}
+
+func TestLoggerAdapterErrorNilError(t *testing.T) {
+	var buf bytes.Buffer
+	l := newTestLoggerAdapter(&buf)
+	defer clog.Discard()
+
+	l.Error(nil, "Unexpected watch event object", "reflector", "reflector-x")
+
+	got := buf.String()
+	if strings.Contains(got, "<nil>") {
+		t.Errorf("log output contains formatting artifact for nil error: %q", got)
+	}
+	for _, want := range []string{"Unexpected watch event object", `reflector="reflector-x"`} {
+		if !strings.Contains(got, want) {
+			t.Errorf("log output missing %q, got: %q", want, got)
+		}
+	}
+}
+
+func TestLoggerAdapterInfoIncludesKeysAndValues(t *testing.T) {
+	var buf bytes.Buffer
+	l := newTestLoggerAdapter(&buf)
+	defer clog.Discard()
+
+	err := errors.New("very short watch")
+	l.Info(0, "Warning: watch ended with error", "reflector", "reflector-x", "err", err)
+
+	got := buf.String()
+	for _, want := range []string{
+		"Warning: watch ended with error",
+		`reflector="reflector-x"`,
+		`err="very short watch"`,
+	} {
+		if !strings.Contains(got, want) {
+			t.Errorf("log output missing %q, got: %q", want, got)
+		}
+	}
+}
+
+func TestLoggerAdapterWithValues(t *testing.T) {
+	var buf bytes.Buffer
+	l := newTestLoggerAdapter(&buf)
+	defer clog.Discard()
+
+	sink := l.WithValues("reflector", "reflector-x")
+	sink.Error(errors.New("boom"), "Failed to watch")
+
+	got := buf.String()
+	for _, want := range []string{"Failed to watch", "boom", `reflector="reflector-x"`} {
+		if !strings.Contains(got, want) {
+			t.Errorf("log output missing %q, got: %q", want, got)
+		}
+	}
+
+	// WithValues must not mutate the parent sink.
+	buf.Reset()
+	l.Error(errors.New("boom"), "Failed to watch")
+	if strings.Contains(buf.String(), "reflector-x") {
+		t.Errorf("parent sink polluted by WithValues: %q", buf.String())
+	}
+}
+
+func TestLoggerAdapterWithValuesOddLength(t *testing.T) {
+	var buf bytes.Buffer
+	l := newTestLoggerAdapter(&buf)
+	defer clog.Discard()
+
+	// An odd-length WithValues list must be padded so that later
+	// key/value pairs stay aligned, matching klog behaviour.
+	sink := l.WithValues("base-key")
+	sink.Info(0, "msg", "call-key", "call-value")
+
+	got := buf.String()
+	if want := `base-key="(MISSING)" call-key="call-value"`; !strings.Contains(got, want) {
+		t.Errorf("log output missing %q, got: %q", want, got)
+	}
+	if strings.Contains(got, `base-key="call-key"`) {
+		t.Errorf("key/value pairs misaligned: %q", got)
+	}
+}
+
+func TestLoggerAdapterDuplicateKeysLastWins(t *testing.T) {
+	var buf bytes.Buffer
+	l := newTestLoggerAdapter(&buf)
+	defer clog.Discard()
+
+	sink := l.WithValues("reflector", "old", "type", "*v1.Service")
+	sink.Error(nil, "msg", "reflector", "new")
+
+	got := buf.String()
+	if strings.Count(got, "reflector=") != 1 {
+		t.Errorf("expected a single reflector key, got: %q", got)
+	}
+	for _, want := range []string{`reflector="new"`, `type="*v1.Service"`} {
+		if !strings.Contains(got, want) {
+			t.Errorf("log output missing %q, got: %q", want, got)
+		}
+	}
+}

plugin/kubernetes/setup.go

@@ -32,7 +32,7 @@ func init() { plugin.Register(pluginName, setup) }
 
 func setup(c *caddy.Controller) error {
 	// Do not call klog.InitFlags(nil) here.  It will cause reload to panic.
-	klog.SetLogger(logr.New(&loggerAdapter{log}))
+	klog.SetLogger(logr.New(&loggerAdapter{P: log}))
 
 	k, err := kubernetesParse(c)
 	if err != nil {