Unit test fixes

Co-authored-by: Joshua Casey <joshuatcasey@gmail.com>
Co-authored-by: Ryan Richard <richardry@vmware.com>

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]

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) {

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")

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
-}

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.