diff --git a/cmd/pinniped/cmd/login_oidc_test.go b/cmd/pinniped/cmd/login_oidc_test.go index c73565a59..ff7409e54 100644 --- a/cmd/pinniped/cmd/login_oidc_test.go +++ b/cmd/pinniped/cmd/login_oidc_test.go @@ -15,7 +15,6 @@ import ( "time" "github.com/stretchr/testify/require" - "go.uber.org/zap" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" clientauthv1beta1 "k8s.io/client-go/pkg/apis/clientauthentication/v1beta1" clocktesting "k8s.io/utils/clock/testing" @@ -531,12 +530,9 @@ func TestLoginOIDCCommand(t *testing.T) { tt := tt t.Run(tt.name, func(t *testing.T) { var buf bytes.Buffer - fakeClock := clocktesting.NewFakeClock(now) - ctx := plog.TestZapOverrides(context.Background(), t, &buf, nil, zap.WithClock(plog.ZapClock(fakeClock))) + ctx := plog.AddZapOverridesToContext(context.Background(), t, &buf, nil, clocktesting.NewFakeClock(now)) - var ( - gotOptions []oidcclient.Option - ) + var gotOptions []oidcclient.Option cmd := oidcLoginCommand(oidcLoginCommandDeps{ lookupEnv: func(s string) (string, bool) { v, ok := tt.env[s] diff --git a/cmd/pinniped/cmd/login_static_test.go b/cmd/pinniped/cmd/login_static_test.go index f11a76bad..e2f520bdc 100644 --- a/cmd/pinniped/cmd/login_static_test.go +++ b/cmd/pinniped/cmd/login_static_test.go @@ -13,7 +13,6 @@ import ( "time" "github.com/stretchr/testify/require" - "go.uber.org/zap" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" clientauthv1beta1 "k8s.io/client-go/pkg/apis/clientauthentication/v1beta1" clocktesting "k8s.io/utils/clock/testing" @@ -178,8 +177,7 @@ func TestLoginStaticCommand(t *testing.T) { tt := tt t.Run(tt.name, func(t *testing.T) { var buf bytes.Buffer - fakeClock := clocktesting.NewFakeClock(now) - ctx := plog.TestZapOverrides(context.Background(), t, &buf, nil, zap.WithClock(plog.ZapClock(fakeClock))) + ctx := plog.AddZapOverridesToContext(context.Background(), t, &buf, nil, clocktesting.NewFakeClock(now)) cmd := staticLoginCommand(staticLoginDeps{ lookupEnv: func(s string) (string, bool) { diff --git a/internal/plog/config_test.go b/internal/plog/config_test.go index 4645cb62e..1c7888631 100644 --- a/internal/plog/config_test.go +++ b/internal/plog/config_test.go @@ -18,7 +18,6 @@ import ( "go.uber.org/zap" "k8s.io/component-base/logs" "k8s.io/klog/v2" - "k8s.io/klog/v2/textlogger" clocktesting "k8s.io/utils/clock/testing" ) @@ -30,12 +29,12 @@ func TestFormat(t *testing.T) { scanner := bufio.NewScanner(&buf) - now, err := time.Parse(time.RFC3339Nano, "2022-11-21T23:37:26.953313745Z") + fakeNow, err := time.Parse(time.RFC3339Nano, "2022-11-21T23:37:26.953313745Z") require.NoError(t, err) - fakeClock := clocktesting.NewFakeClock(now) - nowStr := now.Local().Format(time.RFC1123) + fakeClock := clocktesting.NewFakeClock(fakeNow) + nowStr := fakeNow.Local().Format(time.RFC1123) - ctx = TestZapOverrides(ctx, t, &buf, nil, zap.WithClock(ZapClock(fakeClock))) + ctx = AddZapOverridesToContext(ctx, t, &buf, nil, fakeClock) err = ValidateAndSetLogLevelAndFormatGlobally(ctx, LogSpec{Level: LevelDebug}) require.NoError(t, err) @@ -112,7 +111,7 @@ func TestFormat(t *testing.T) { Logr().V(klogLevelAll).Info("also should not be logged", "open", "close") require.Empty(t, buf.String()) - ctx = TestZapOverrides(ctx, t, &buf, nil, zap.WithClock(ZapClock(fakeClock)), zap.AddStacktrace(LevelInfo)) + ctx = AddZapOverridesToContext(ctx, t, &buf, nil, fakeClock, zap.AddStacktrace(LevelInfo)) err = ValidateAndSetLogLevelAndFormatGlobally(ctx, LogSpec{Level: LevelDebug}) require.NoError(t, err) @@ -141,7 +140,7 @@ testing.tRunner ), ), scanner.Text()) - ctx = TestZapOverrides(ctx, t, &buf, nil, zap.WithClock(ZapClock(fakeClock))) + ctx = AddZapOverridesToContext(ctx, t, &buf, nil, fakeClock) err = ValidateAndSetLogLevelAndFormatGlobally(ctx, LogSpec{Level: LevelDebug, Format: FormatCLI}) require.NoError(t, err) @@ -158,14 +157,6 @@ testing.tRunner require.Equal(t, fmt.Sprintf(nowStr+` burrito plog/config_test.go:%d wee {"a": "b", "slightly less than a year": "363d", "slightly more than 2 years": "2y4d", "error": "invalid log level, valid choices are the empty string, info, debug, trace and all"}`, getLineNumberOfCaller()-4), scanner.Text()) - origTimeNow := textlogger.TimeNow - t.Cleanup(func() { - textlogger.TimeNow = origTimeNow - }) - textlogger.TimeNow = func() time.Time { - return now - } - old := New().WithName("created before mode change").WithValues("is", "old") err = ValidateAndSetLogLevelAndFormatGlobally(ctx, LogSpec{Level: LevelDebug, Format: FormatText}) @@ -187,13 +178,13 @@ testing.tRunner Logr().WithName("panda").V(KlogLevelDebug).Info("are the best", "yes?", "yes.") require.True(t, scanner.Scan()) require.NoError(t, scanner.Err()) - require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "panda: are the best" yes?="yes."`, + require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "are the best" logger="panda" yes?="yes."`, pid, getLineNumberOfCaller()-4), scanner.Text()) New().WithName("hi").WithName("there").WithValues("a", 1, "b", 2).Always("do it") require.True(t, scanner.Scan()) require.NoError(t, scanner.Err()) - require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "hi/there: do it" a=1 b=2`, + require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "do it" logger="hi.there" a=1 b=2`, pid, getLineNumberOfCaller()-4), scanner.Text()) l := WithValues("x", 33, "z", 22) @@ -211,7 +202,7 @@ testing.tRunner old.Always("should be klog text format", "for", "sure") require.True(t, scanner.Scan()) require.NoError(t, scanner.Err()) - require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "created before mode change: should be klog text format" is="old" for="sure"`, + require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "should be klog text format" logger="created before mode change" is="old" for="sure"`, pid, getLineNumberOfCaller()-4), scanner.Text()) // make sure child loggers do not share state @@ -221,11 +212,11 @@ testing.tRunner old2.Info("info") require.True(t, scanner.Scan()) require.NoError(t, scanner.Err()) - require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "created before mode change: warn" is="old" i am="old1" warning=true`, + require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "warn" logger="created before mode change" is="old" i am="old1" warning=true`, pid, getLineNumberOfCaller()-5), scanner.Text()) require.True(t, scanner.Scan()) require.NoError(t, scanner.Err()) - require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "created before mode change/old2: info" is="old"`, + require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config_test.go:%d] "info" logger="created before mode change.old2" is="old"`, pid, getLineNumberOfCaller()-8), scanner.Text()) Trace("should not be logged", "for", "sure") diff --git a/internal/plog/testing.go b/internal/plog/testing.go index f5c1fea49..2d74a705c 100644 --- a/internal/plog/testing.go +++ b/internal/plog/testing.go @@ -1,4 +1,4 @@ -// Copyright 2020-2022 the Pinniped contributors. All Rights Reserved. +// Copyright 2020-2023 the Pinniped contributors. All Rights Reserved. // SPDX-License-Identifier: Apache-2.0 package plog @@ -22,18 +22,41 @@ import ( // contextKey type is unexported to prevent collisions. type contextKey int -const zapOverridesKey contextKey = iota +const testOverridesContextKey contextKey = iota -func TestZapOverrides(ctx context.Context, t *testing.T, w io.Writer, f func(*zap.Config), opts ...zap.Option) context.Context { +type testOverrides struct { + t *testing.T + w io.Writer + f func(*zap.Config) + fakeClock *clocktesting.FakeClock + opts []zap.Option +} + +// AddZapOverridesToContext adds Zap (and klog/textlogger) overrides to the context. +// This is done so that production code can read these values for test overrides. +// Do not pass zap.WithClock in opts since that will be constructed for you from fakeClock. +func AddZapOverridesToContext( + ctx context.Context, + t *testing.T, + w io.Writer, + f func(*zap.Config), + fakeClock *clocktesting.FakeClock, + opts ...zap.Option, +) context.Context { t.Helper() // discourage use outside of tests + require.NotNil(t, fakeClock, "fakeClock is required") + + opts = append(opts, zap.WithClock(ZapClock(fakeClock))) overrides := &testOverrides{ - t: t, - w: w, - f: f, - opts: opts, + t: t, + w: w, + f: f, + fakeClock: fakeClock, + opts: opts, } - return context.WithValue(ctx, zapOverridesKey, overrides) + + return context.WithValue(ctx, testOverridesContextKey, overrides) } func TestLogger(t *testing.T, w io.Writer) Logger { @@ -53,7 +76,7 @@ func TestZapr(t *testing.T, w io.Writer) logr.Logger { ctx, cancel := context.WithCancel(context.Background()) t.Cleanup(cancel) - ctx = TestZapOverrides(ctx, t, w, + ctx = AddZapOverridesToContext(ctx, t, w, func(config *zap.Config) { config.Level = zap.NewAtomicLevelAt(math.MinInt8) // log everything during tests @@ -66,8 +89,8 @@ func TestZapr(t *testing.T, w io.Writer) logr.Logger { enc.AppendString(trimmed + funcEncoder(caller)) } }, - zap.WithClock(ZapClock(clocktesting.NewFakeClock(now))), // have the clock be static during tests - zap.AddStacktrace(nopLevelEnabler{}), // do not log stacktraces + clocktesting.NewFakeClock(now), // have the clock be static during tests + zap.AddStacktrace(nopLevelEnabler{}), // do not log stacktraces ) // there is no buffering so we can ignore flush @@ -111,10 +134,3 @@ var _ zapcore.LevelEnabler = nopLevelEnabler{} type nopLevelEnabler struct{} func (nopLevelEnabler) Enabled(_ zapcore.Level) bool { return false } - -type testOverrides struct { - t *testing.T - w io.Writer - f func(*zap.Config) - opts []zap.Option -} diff --git a/internal/plog/zap.go b/internal/plog/zap.go index 2b9976ef8..57dd16a36 100644 --- a/internal/plog/zap.go +++ b/internal/plog/zap.go @@ -1,4 +1,4 @@ -// Copyright 2020-2022 the Pinniped contributors. All Rights Reserved. +// Copyright 2020-2023 the Pinniped contributors. All Rights Reserved. // SPDX-License-Identifier: Apache-2.0 package plog @@ -25,19 +25,27 @@ import ( ) func newLogr(ctx context.Context, encoding string, klogLevel klog.Level) (logr.Logger, func(), error) { + overrides, hasOverrides := ctx.Value(testOverridesContextKey).(*testOverrides) + if encoding == "text" { var w io.Writer = os.Stderr flush := func() { _ = os.Stderr.Sync() } - // allow tests to override klog config (but cheat and re-use the zap override key) - if overrides, ok := ctx.Value(zapOverridesKey).(*testOverrides); ok { + var textloggerOptions []textlogger.ConfigOption + + if hasOverrides { if overrides.w != nil { w = newSink(overrides.w) // make sure the value is safe for concurrent use flush = func() {} } + textloggerOptions = append(textloggerOptions, textlogger.FixedTime(overrides.fakeClock.Now())) } - return textlogger.NewLogger(textlogger.NewConfig(textlogger.Verbosity(int(klogLevel)), textlogger.Output(w))), flush, nil + textloggerOptions = append(textloggerOptions, + textlogger.Verbosity(int(klogLevel)), + textlogger.Output(w)) + + return textlogger.NewLogger(textlogger.NewConfig(textloggerOptions...)), flush, nil } path := "stderr" // this is how zap refers to os.Stderr @@ -51,8 +59,7 @@ func newLogr(ctx context.Context, encoding string, klogLevel klog.Level) (logr.L } var opts []zap.Option - // allow tests to override zap config - if overrides, ok := ctx.Value(zapOverridesKey).(*testOverrides); ok { + if hasOverrides { if overrides.w != nil { // use a per invocation random string as the key into the global map testKey := "/" + base64.RawURLEncoding.EncodeToString([]byte(rand.String(32))) @@ -78,9 +85,7 @@ func newLogr(ctx context.Context, encoding string, klogLevel klog.Level) (logr.L if overrides.f != nil { f = overrides.f } - if overrides.opts != nil { - opts = overrides.opts - } + opts = append(opts, overrides.opts...) } // when using the trace or all log levels, an error log will contain the full stack.