diff --git a/plugin/kubernetes/logger.go b/plugin/kubernetes/logger.go index 1c239881b..a1940a9cf 100644 --- a/plugin/kubernetes/logger.go +++ b/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) { - l.P.Info(msg) +func (l *loggerAdapter) Info(_ int, msg string, keysAndValues ...any) { + l.P.Info(l.sprint(msg, nil, keysAndValues)) } -func (l *loggerAdapter) Error(err error, msg string, _ ...any) { - l.Errorf("%s: %s", msg, err) +func (l *loggerAdapter) Error(err error, msg string, keysAndValues ...any) { + l.P.Error(l.sprint(msg, err, keysAndValues)) } -func (l *loggerAdapter) WithValues(_ ...any) logr.LogSink { - return l +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 +} diff --git a/plugin/kubernetes/logger_test.go b/plugin/kubernetes/logger_test.go new file mode 100644 index 000000000..9ea6d543e --- /dev/null +++ b/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, "") { + 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) + } + } +} diff --git a/plugin/kubernetes/setup.go b/plugin/kubernetes/setup.go index 765a80964..1efaac946 100644 --- a/plugin/kubernetes/setup.go +++ b/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 {