diff --git a/cmd/pinniped-server/main.go b/cmd/pinniped-server/main.go index fdce4f9d..b70aed8f 100644 --- a/cmd/pinniped-server/main.go +++ b/cmd/pinniped-server/main.go @@ -8,22 +8,23 @@ package main import ( + "fmt" "os" "path/filepath" "k8s.io/apimachinery/pkg/util/sets" - "k8s.io/klog/v2" - concierge "go.pinniped.dev/internal/concierge/server" // this side effect import ensures that we use fipsonly crypto in fips_strict mode. + concierge "go.pinniped.dev/internal/concierge/server" _ "go.pinniped.dev/internal/crypto/ptls" lua "go.pinniped.dev/internal/localuserauthenticator" + "go.pinniped.dev/internal/plog" supervisor "go.pinniped.dev/internal/supervisor/server" ) -//nolint: gochecknoglobals // these are swapped during unit tests. +// nolint: gochecknoglobals // these are swapped during unit tests. var ( - fail = klog.Fatalf + fail = plog.Fatal subcommands = map[string]func(){ "pinniped-concierge": concierge.Main, "pinniped-supervisor": supervisor.Main, @@ -33,11 +34,11 @@ var ( func main() { if len(os.Args) == 0 { - fail("missing os.Args") + fail(fmt.Errorf("missing os.Args")) } binary := filepath.Base(os.Args[0]) if subcommands[binary] == nil { - fail("must be invoked as one of %v, not %q", sets.StringKeySet(subcommands).List(), binary) + fail(fmt.Errorf("must be invoked as one of %v, not %q", sets.StringKeySet(subcommands).List(), binary)) } subcommands[binary]() } diff --git a/cmd/pinniped-server/main_test.go b/cmd/pinniped-server/main_test.go index 6a1e1e68..e262afe3 100644 --- a/cmd/pinniped-server/main_test.go +++ b/cmd/pinniped-server/main_test.go @@ -43,8 +43,11 @@ func TestEntrypoint(t *testing.T) { var logBuf bytes.Buffer testLog := log.New(&logBuf, "", 0) exited := "exiting via fatal" - fail = func(format string, v ...interface{}) { - testLog.Printf(format, v...) + fail = func(err error, keysAndValues ...interface{}) { + testLog.Print(err) + if len(keysAndValues) > 0 { + testLog.Print(keysAndValues...) + } panic(exited) } diff --git a/cmd/pinniped/cmd/kubeconfig.go b/cmd/pinniped/cmd/kubeconfig.go index e46eebde..1e59f481 100644 --- a/cmd/pinniped/cmd/kubeconfig.go +++ b/cmd/pinniped/cmd/kubeconfig.go @@ -11,7 +11,6 @@ import ( "fmt" "io" "io/ioutil" - "log" "net/http" "os" "strconv" @@ -19,8 +18,6 @@ import ( "time" "github.com/coreos/go-oidc/v3/oidc" - "github.com/go-logr/logr" - "github.com/go-logr/stdr" "github.com/spf13/cobra" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" clientauthenticationv1beta1 "k8s.io/client-go/pkg/apis/clientauthentication/v1beta1" @@ -34,23 +31,24 @@ import ( conciergeclientset "go.pinniped.dev/generated/latest/client/concierge/clientset/versioned" "go.pinniped.dev/internal/groupsuffix" "go.pinniped.dev/internal/net/phttp" + "go.pinniped.dev/internal/plog" ) type kubeconfigDeps struct { getPathToSelf func() (string, error) getClientset getConciergeClientsetFunc - log logr.Logger + log plog.MinLogger } func kubeconfigRealDeps() kubeconfigDeps { return kubeconfigDeps{ getPathToSelf: os.Executable, getClientset: getRealConciergeClientset, - log: stdr.New(log.New(os.Stderr, "", 0)), + log: plog.New(), } } -//nolint: gochecknoinits +// nolint: gochecknoinits func init() { getCmd.AddCommand(kubeconfigCommand(kubeconfigRealDeps())) } @@ -175,6 +173,11 @@ func runGetKubeconfig(ctx context.Context, out io.Writer, deps kubeconfigDeps, f ctx, cancel := context.WithTimeout(ctx, flags.timeout) defer cancel() + // the log statements in this file assume that Info logs are unconditionally printed so we set the global level to info + if err := plog.ValidateAndSetLogLevelAndFormatGlobally(ctx, plog.LogSpec{Level: plog.LevelInfo, Format: plog.FormatCLI}); err != nil { + return err + } + // Validate api group suffix and immediately return an error if it is invalid. if err := groupsuffix.Validate(flags.concierge.apiGroupSuffix); err != nil { return fmt.Errorf("invalid API group suffix: %w", err) @@ -398,7 +401,7 @@ func waitForCredentialIssuer(ctx context.Context, clientset conciergeclientset.I return credentialIssuer, nil } -func discoverConciergeParams(credentialIssuer *configv1alpha1.CredentialIssuer, flags *getKubeconfigParams, v1Cluster *clientcmdapi.Cluster, log logr.Logger) error { +func discoverConciergeParams(credentialIssuer *configv1alpha1.CredentialIssuer, flags *getKubeconfigParams, v1Cluster *clientcmdapi.Cluster, log plog.MinLogger) error { // Autodiscover the --concierge-mode. frontend, err := getConciergeFrontend(credentialIssuer, flags.concierge.mode) if err != nil { @@ -446,7 +449,7 @@ func discoverConciergeParams(credentialIssuer *configv1alpha1.CredentialIssuer, return nil } -func logStrategies(credentialIssuer *configv1alpha1.CredentialIssuer, log logr.Logger) { +func logStrategies(credentialIssuer *configv1alpha1.CredentialIssuer, log plog.MinLogger) { for _, strategy := range credentialIssuer.Status.Strategies { log.Info("found CredentialIssuer strategy", "type", strategy.Type, @@ -457,7 +460,7 @@ func logStrategies(credentialIssuer *configv1alpha1.CredentialIssuer, log logr.L } } -func discoverAuthenticatorParams(authenticator metav1.Object, flags *getKubeconfigParams, log logr.Logger) error { +func discoverAuthenticatorParams(authenticator metav1.Object, flags *getKubeconfigParams, log plog.MinLogger) error { switch auth := authenticator.(type) { case *conciergev1alpha1.WebhookAuthenticator: // If the --concierge-authenticator-type/--concierge-authenticator-name flags were not set explicitly, set @@ -556,7 +559,7 @@ func newExecKubeconfig(cluster *clientcmdapi.Cluster, execConfig *clientcmdapi.E } } -func lookupCredentialIssuer(clientset conciergeclientset.Interface, name string, log logr.Logger) (*configv1alpha1.CredentialIssuer, error) { +func lookupCredentialIssuer(clientset conciergeclientset.Interface, name string, log plog.MinLogger) (*configv1alpha1.CredentialIssuer, error) { ctx, cancelFunc := context.WithTimeout(context.Background(), time.Second*20) defer cancelFunc() @@ -582,7 +585,7 @@ func lookupCredentialIssuer(clientset conciergeclientset.Interface, name string, return result, nil } -func lookupAuthenticator(clientset conciergeclientset.Interface, authType, authName string, log logr.Logger) (metav1.Object, error) { +func lookupAuthenticator(clientset conciergeclientset.Interface, authType, authName string, log plog.MinLogger) (metav1.Object, error) { ctx, cancelFunc := context.WithTimeout(context.Background(), time.Second*20) defer cancelFunc() @@ -643,7 +646,7 @@ func writeConfigAsYAML(out io.Writer, config clientcmdapi.Config) error { return nil } -func validateKubeconfig(ctx context.Context, flags getKubeconfigParams, kubeconfig clientcmdapi.Config, log logr.Logger) error { +func validateKubeconfig(ctx context.Context, flags getKubeconfigParams, kubeconfig clientcmdapi.Config, log plog.MinLogger) error { if flags.skipValidate { return nil } @@ -706,7 +709,7 @@ func validateKubeconfig(ctx context.Context, flags getKubeconfigParams, kubeconf log.Info("validated connection to the cluster", "attempts", attempts) return nil } - log.Error(err, "could not connect to cluster, retrying...", "attempts", attempts, "remaining", time.Until(deadline).Round(time.Second).String()) + log.Info("could not connect to cluster, retrying...", "error", err, "attempts", attempts, "remaining", time.Until(deadline).Round(time.Second).String()) } } } @@ -726,7 +729,7 @@ func hasPendingStrategy(credentialIssuer *configv1alpha1.CredentialIssuer) bool return false } -func discoverSupervisorUpstreamIDP(ctx context.Context, flags *getKubeconfigParams, log logr.Logger) error { +func discoverSupervisorUpstreamIDP(ctx context.Context, flags *getKubeconfigParams, log plog.MinLogger) error { httpClient, err := newDiscoveryHTTPClient(flags.oidc.caBundle) if err != nil { return err @@ -898,7 +901,7 @@ func selectUpstreamIDPNameAndType(pinnipedIDPs []idpdiscoveryv1alpha1.PinnipedID } } -func selectUpstreamIDPFlow(discoveredIDPFlows []idpdiscoveryv1alpha1.IDPFlow, selectedIDPName string, selectedIDPType idpdiscoveryv1alpha1.IDPType, specifiedFlow string, log logr.Logger) (idpdiscoveryv1alpha1.IDPFlow, error) { +func selectUpstreamIDPFlow(discoveredIDPFlows []idpdiscoveryv1alpha1.IDPFlow, selectedIDPName string, selectedIDPType idpdiscoveryv1alpha1.IDPType, specifiedFlow string, log plog.MinLogger) (idpdiscoveryv1alpha1.IDPFlow, error) { switch { case len(discoveredIDPFlows) == 0: // No flows listed by discovery means that we are talking to an old Supervisor from before this feature existed. diff --git a/cmd/pinniped/cmd/kubeconfig_test.go b/cmd/pinniped/cmd/kubeconfig_test.go index 76a216f0..9c3ee5e0 100644 --- a/cmd/pinniped/cmd/kubeconfig_test.go +++ b/cmd/pinniped/cmd/kubeconfig_test.go @@ -2889,7 +2889,7 @@ func TestGetKubeconfig(t *testing.T) { }) issuerEndpointPtr = &issuerEndpoint - testLog := testlogger.NewLegacy(t) //nolint: staticcheck // old test with lots of log statements + testLog := testlogger.NewLegacy(t) // nolint: staticcheck // old test with lots of log statements cmd := kubeconfigCommand(kubeconfigDeps{ getPathToSelf: func() (string, error) { if tt.getPathToSelfErr != nil { diff --git a/cmd/pinniped/cmd/login_oidc.go b/cmd/pinniped/cmd/login_oidc.go index bf35a6ba..8f9378f5 100644 --- a/cmd/pinniped/cmd/login_oidc.go +++ b/cmd/pinniped/cmd/login_oidc.go @@ -20,7 +20,6 @@ import ( "github.com/spf13/cobra" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" clientauthv1beta1 "k8s.io/client-go/pkg/apis/clientauthentication/v1beta1" - "k8s.io/klog/v2/klogr" idpdiscoveryv1alpha1 "go.pinniped.dev/generated/latest/apis/supervisor/idpdiscovery/v1alpha1" "go.pinniped.dev/internal/execcredcache" @@ -33,7 +32,7 @@ import ( "go.pinniped.dev/pkg/oidcclient/oidctypes" ) -//nolint: gochecknoinits +// nolint: gochecknoinits func init() { loginCmd.AddCommand(oidcLoginCommand(oidcLoginCommandRealDeps())) } @@ -125,7 +124,7 @@ func oidcLoginCommand(deps oidcLoginCommandDeps) *cobra.Command { } func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLoginFlags) error { //nolint:funlen - pLogger, err := SetLogLevel(deps.lookupEnv) + pLogger, err := SetLogLevel(cmd.Context(), deps.lookupEnv) if err != nil { plog.WarningErr("Received error while setting log level", err) } @@ -133,11 +132,11 @@ func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLogin // Initialize the session cache. var sessionOptions []filesession.Option - // If the hidden --debug-session-cache option is passed, log all the errors from the session cache with klog. + // If the hidden --debug-session-cache option is passed, log all the errors from the session cache. if flags.debugSessionCache { - logger := klogr.New().WithName("session") + logger := plog.WithName("session") sessionOptions = append(sessionOptions, filesession.WithErrorReporter(func(err error) { - logger.Error(err, "error during session cache operation") + logger.Error("error during session cache operation", err) })) } sessionCache := filesession.New(flags.sessionCachePath, sessionOptions...) @@ -145,7 +144,7 @@ func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLogin // Initialize the login handler. opts := []oidcclient.Option{ oidcclient.WithContext(cmd.Context()), - oidcclient.WithLogger(klogr.New()), + oidcclient.WithLogger(plog.Logr()), // nolint: staticcheck // old code with lots of log statements oidcclient.WithScopes(flags.scopes), oidcclient.WithSessionCache(sessionCache), } @@ -326,15 +325,15 @@ func tokenCredential(token *oidctypes.Token) *clientauthv1beta1.ExecCredential { return &cred } -func SetLogLevel(lookupEnv func(string) (string, bool)) (plog.Logger, error) { +func SetLogLevel(ctx context.Context, lookupEnv func(string) (string, bool)) (plog.Logger, error) { debug, _ := lookupEnv("PINNIPED_DEBUG") if debug == "true" { - err := plog.ValidateAndSetLogLevelGlobally(plog.LevelDebug) + err := plog.ValidateAndSetLogLevelAndFormatGlobally(ctx, plog.LogSpec{Level: plog.LevelDebug, Format: plog.FormatCLI}) if err != nil { return nil, err } } - logger := plog.New("Pinniped login: ") + logger := plog.New().WithName("pinniped-login") return logger, nil } diff --git a/cmd/pinniped/cmd/login_oidc_test.go b/cmd/pinniped/cmd/login_oidc_test.go index da0cfcb7..492891e2 100644 --- a/cmd/pinniped/cmd/login_oidc_test.go +++ b/cmd/pinniped/cmd/login_oidc_test.go @@ -10,18 +10,20 @@ import ( "fmt" "io/ioutil" "path/filepath" + "strings" "testing" "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" - "k8s.io/klog/v2" + clocktesting "k8s.io/utils/clock/testing" "go.pinniped.dev/internal/certauthority" "go.pinniped.dev/internal/here" + "go.pinniped.dev/internal/plog" "go.pinniped.dev/internal/testutil" - "go.pinniped.dev/internal/testutil/testlogger" "go.pinniped.dev/pkg/conciergeclient" "go.pinniped.dev/pkg/oidcclient" "go.pinniped.dev/pkg/oidcclient/oidctypes" @@ -38,6 +40,10 @@ func TestLoginOIDCCommand(t *testing.T) { time1 := time.Date(3020, 10, 12, 13, 14, 15, 16, time.UTC) + now, err := time.Parse(time.RFC3339Nano, "2028-10-11T23:37:26.953313745Z") + require.NoError(t, err) + nowStr := now.Local().Format(time.RFC1123) + tests := []struct { name string args []string @@ -342,8 +348,8 @@ func TestLoginOIDCCommand(t *testing.T) { wantOptionsCount: 4, wantStdout: `{"kind":"ExecCredential","apiVersion":"client.authentication.k8s.io/v1beta1","spec":{"interactive":false},"status":{"expirationTimestamp":"3020-10-12T13:14:15Z","token":"test-id-token"}}` + "\n", wantLogs: []string{ - "\"level\"=0 \"msg\"=\"Pinniped login: Performing OIDC login\" \"client id\"=\"test-client-id\" \"issuer\"=\"test-issuer\"", - "\"level\"=0 \"msg\"=\"Pinniped login: No concierge configured, skipping token credential exchange\"", + nowStr + ` pinniped-login cmd/login_oidc.go:222 Performing OIDC login {"issuer": "test-issuer", "client id": "test-client-id"}`, + nowStr + ` pinniped-login cmd/login_oidc.go:242 No concierge configured, skipping token credential exchange`, }, }, { @@ -372,18 +378,20 @@ func TestLoginOIDCCommand(t *testing.T) { wantOptionsCount: 11, wantStdout: `{"kind":"ExecCredential","apiVersion":"client.authentication.k8s.io/v1beta1","spec":{"interactive":false},"status":{"token":"exchanged-token"}}` + "\n", wantLogs: []string{ - "\"level\"=0 \"msg\"=\"Pinniped login: Performing OIDC login\" \"client id\"=\"test-client-id\" \"issuer\"=\"test-issuer\"", - "\"level\"=0 \"msg\"=\"Pinniped login: Exchanging token for cluster credential\" \"authenticator name\"=\"test-authenticator\" \"authenticator type\"=\"webhook\" \"endpoint\"=\"https://127.0.0.1:1234/\"", - "\"level\"=0 \"msg\"=\"Pinniped login: Successfully exchanged token for cluster credential.\"", - "\"level\"=0 \"msg\"=\"Pinniped login: caching cluster credential for future use.\"", + nowStr + ` pinniped-login cmd/login_oidc.go:222 Performing OIDC login {"issuer": "test-issuer", "client id": "test-client-id"}`, + nowStr + ` pinniped-login cmd/login_oidc.go:232 Exchanging token for cluster credential {"endpoint": "https://127.0.0.1:1234/", "authenticator type": "webhook", "authenticator name": "test-authenticator"}`, + nowStr + ` pinniped-login cmd/login_oidc.go:240 Successfully exchanged token for cluster credential.`, + nowStr + ` pinniped-login cmd/login_oidc.go:247 caching cluster credential for future use.`, }, }, } for _, tt := range tests { tt := tt t.Run(tt.name, func(t *testing.T) { - testLogger := testlogger.NewLegacy(t) //nolint: staticcheck // old test with lots of log statements - klog.SetLogger(testLogger.Logger) + var buf bytes.Buffer + fakeClock := clocktesting.NewFakeClock(now) + ctx := plog.TestZapOverrides(context.Background(), t, &buf, nil, zap.WithClock(plog.ZapClock(fakeClock))) + var ( gotOptions []oidcclient.Option ) @@ -428,7 +436,7 @@ func TestLoginOIDCCommand(t *testing.T) { cmd.SetOut(&stdout) cmd.SetErr(&stderr) cmd.SetArgs(tt.args) - err := cmd.Execute() + err = cmd.ExecuteContext(ctx) if tt.wantError { require.Error(t, err) } else { @@ -438,7 +446,15 @@ func TestLoginOIDCCommand(t *testing.T) { require.Equal(t, tt.wantStderr, stderr.String(), "unexpected stderr") require.Len(t, gotOptions, tt.wantOptionsCount) - require.Equal(t, tt.wantLogs, testLogger.Lines()) + require.Equal(t, tt.wantLogs, logLines(buf.String())) }) } } + +func logLines(logs string) []string { + if len(logs) == 0 { + return nil + } + + return strings.Split(strings.TrimSpace(logs), "\n") +} diff --git a/cmd/pinniped/cmd/login_static.go b/cmd/pinniped/cmd/login_static.go index 3642ffe1..2af80907 100644 --- a/cmd/pinniped/cmd/login_static.go +++ b/cmd/pinniped/cmd/login_static.go @@ -7,7 +7,6 @@ import ( "context" "encoding/json" "fmt" - "io" "os" "path/filepath" "time" @@ -22,7 +21,7 @@ import ( "go.pinniped.dev/pkg/oidcclient/oidctypes" ) -//nolint: gochecknoinits +// nolint: gochecknoinits func init() { loginCmd.AddCommand(staticLoginCommand(staticLoginRealDeps())) } @@ -75,7 +74,7 @@ func staticLoginCommand(deps staticLoginDeps) *cobra.Command { cmd.Flags().StringVar(&flags.conciergeAPIGroupSuffix, "concierge-api-group-suffix", groupsuffix.PinnipedDefaultSuffix, "Concierge API group suffix") cmd.Flags().StringVar(&flags.credentialCachePath, "credential-cache", filepath.Join(mustGetConfigDir(), "credentials.yaml"), "Path to cluster-specific credentials cache (\"\" disables the cache)") - cmd.RunE = func(cmd *cobra.Command, args []string) error { return runStaticLogin(cmd.OutOrStdout(), deps, flags) } + cmd.RunE = func(cmd *cobra.Command, args []string) error { return runStaticLogin(cmd, deps, flags) } mustMarkDeprecated(cmd, "concierge-namespace", "not needed anymore") mustMarkHidden(cmd, "concierge-namespace") @@ -83,8 +82,9 @@ func staticLoginCommand(deps staticLoginDeps) *cobra.Command { return cmd } -func runStaticLogin(out io.Writer, deps staticLoginDeps, flags staticLoginParams) error { - pLogger, err := SetLogLevel(deps.lookupEnv) +func runStaticLogin(cmd *cobra.Command, deps staticLoginDeps, flags staticLoginParams) error { + out := cmd.OutOrStdout() + pLogger, err := SetLogLevel(cmd.Context(), deps.lookupEnv) if err != nil { plog.WarningErr("Received error while setting log level", err) } diff --git a/cmd/pinniped/cmd/login_static_test.go b/cmd/pinniped/cmd/login_static_test.go index 5fd04e0d..7af4ac85 100644 --- a/cmd/pinniped/cmd/login_static_test.go +++ b/cmd/pinniped/cmd/login_static_test.go @@ -12,16 +12,15 @@ import ( "testing" "time" - "k8s.io/klog/v2" - - "go.pinniped.dev/internal/testutil/testlogger" - "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" "go.pinniped.dev/internal/certauthority" "go.pinniped.dev/internal/here" + "go.pinniped.dev/internal/plog" "go.pinniped.dev/internal/testutil" "go.pinniped.dev/pkg/conciergeclient" ) @@ -35,6 +34,10 @@ func TestLoginStaticCommand(t *testing.T) { testCABundlePath := filepath.Join(tmpdir, "testca.pem") require.NoError(t, ioutil.WriteFile(testCABundlePath, testCA.Bundle(), 0600)) + now, err := time.Parse(time.RFC3339Nano, "2038-12-07T23:37:26.953313745Z") + require.NoError(t, err) + nowStr := now.Local().Format(time.RFC1123) + tests := []struct { name string args []string @@ -136,7 +139,9 @@ func TestLoginStaticCommand(t *testing.T) { wantStderr: here.Doc(` Error: could not complete Concierge credential exchange: some concierge error `), - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped login: exchanging static token for cluster credential\" \"authenticator name\"=\"test-authenticator\" \"authenticator type\"=\"webhook\" \"endpoint\"=\"https://127.0.0.1/\""}, + wantLogs: []string{ + nowStr + ` pinniped-login cmd/login_static.go:147 exchanging static token for cluster credential {"endpoint": "https://127.0.0.1/", "authenticator type": "webhook", "authenticator name": "test-authenticator"}`, + }, }, { name: "invalid API group suffix", @@ -165,8 +170,10 @@ func TestLoginStaticCommand(t *testing.T) { for _, tt := range tests { tt := tt t.Run(tt.name, func(t *testing.T) { - testLogger := testlogger.NewLegacy(t) //nolint: staticcheck // old test with lots of log statements - klog.SetLogger(testLogger.Logger) + var buf bytes.Buffer + fakeClock := clocktesting.NewFakeClock(now) + ctx := plog.TestZapOverrides(context.Background(), t, &buf, nil, zap.WithClock(plog.ZapClock(fakeClock))) + cmd := staticLoginCommand(staticLoginDeps{ lookupEnv: func(s string) (string, bool) { v, ok := tt.env[s] @@ -194,7 +201,7 @@ func TestLoginStaticCommand(t *testing.T) { cmd.SetOut(&stdout) cmd.SetErr(&stderr) cmd.SetArgs(tt.args) - err := cmd.Execute() + err := cmd.ExecuteContext(ctx) if tt.wantError { require.Error(t, err) } else { @@ -203,7 +210,7 @@ func TestLoginStaticCommand(t *testing.T) { require.Equal(t, tt.wantStdout, stdout.String(), "unexpected stdout") require.Equal(t, tt.wantStderr, stderr.String(), "unexpected stderr") - require.Equal(t, tt.wantLogs, testLogger.Lines()) + require.Equal(t, tt.wantLogs, logLines(buf.String())) }) } } diff --git a/cmd/pinniped/cmd/root.go b/cmd/pinniped/cmd/root.go index 509e5a0b..4345b6c8 100644 --- a/cmd/pinniped/cmd/root.go +++ b/cmd/pinniped/cmd/root.go @@ -4,12 +4,14 @@ package cmd import ( - "os" + "context" "github.com/spf13/cobra" + + "go.pinniped.dev/internal/plog" ) -//nolint: gochecknoglobals +// nolint: gochecknoglobals var rootCmd = &cobra.Command{ Use: "pinniped", Short: "pinniped", @@ -19,8 +21,11 @@ var rootCmd = &cobra.Command{ // Execute adds all child commands to the root command and sets flags appropriately. // This is called by main.main(). It only needs to happen once to the rootCmd. -func Execute() { - if err := rootCmd.Execute(); err != nil { - os.Exit(1) +func Execute() error { + defer plog.Setup()() + // the context does not matter here because it is unused when CLI formatting is provided + if err := plog.ValidateAndSetLogLevelAndFormatGlobally(context.Background(), plog.LogSpec{Format: plog.FormatCLI}); err != nil { + return err } + return rootCmd.Execute() } diff --git a/cmd/pinniped/main.go b/cmd/pinniped/main.go index d4776f24..93433b66 100644 --- a/cmd/pinniped/main.go +++ b/cmd/pinniped/main.go @@ -13,7 +13,7 @@ import ( _ "go.pinniped.dev/internal/crypto/ptls" ) -//nolint: gochecknoinits +// nolint: gochecknoinits func init() { // browsers like chrome like to write to our std out which breaks our JSON ExecCredential output // thus we redirect the browser's std out to our std err @@ -21,5 +21,7 @@ func init() { } func main() { - cmd.Execute() + if err := cmd.Execute(); err != nil { + os.Exit(1) + } } diff --git a/deploy/concierge/deployment.yaml b/deploy/concierge/deployment.yaml index 1cad1b6d..06bb8a1b 100644 --- a/deploy/concierge/deployment.yaml +++ b/deploy/concierge/deployment.yaml @@ -86,8 +86,14 @@ data: imagePullSecrets: - image-pull-secret (@ end @) - (@ if data.values.log_level: @) - logLevel: (@= getAndValidateLogLevel() @) + (@ if data.values.log_level or data.values.deprecated_log_format: @) + log: + (@ if data.values.log_level: @) + level: (@= getAndValidateLogLevel() @) + (@ end @) + (@ if data.values.deprecated_log_format: @) + format: (@= data.values.deprecated_log_format @) + (@ end @) (@ end @) --- #@ if data.values.image_pull_dockerconfigjson and data.values.image_pull_dockerconfigjson != "": diff --git a/deploy/concierge/values.yaml b/deploy/concierge/values.yaml index d902f89f..9267b0fc 100644 --- a/deploy/concierge/values.yaml +++ b/deploy/concierge/values.yaml @@ -54,6 +54,10 @@ api_serving_certificate_renew_before_seconds: 2160000 #! Specify the verbosity of logging: info ("nice to know" information), debug (developer #! information), trace (timing information), all (kitchen sink). log_level: #! By default, when this value is left unset, only warnings and errors are printed. There is no way to suppress warning and error logs. +#! Specify the format of logging: json (for machine parsable logs) and text (for legacy klog formatted logs). +#! By default, when this value is left unset, logs are formatted in json. +#! This configuration is deprecated and will be removed in a future release at which point logs will always be formatted as json. +deprecated_log_format: run_as_user: 65532 #! run_as_user specifies the user ID that will own the process, see the Dockerfile for the reasoning behind this choice run_as_group: 65532 #! run_as_group specifies the group ID that will own the process, see the Dockerfile for the reasoning behind this choice diff --git a/deploy/supervisor/helpers.lib.yaml b/deploy/supervisor/helpers.lib.yaml index acd6d5a4..d759e874 100644 --- a/deploy/supervisor/helpers.lib.yaml +++ b/deploy/supervisor/helpers.lib.yaml @@ -54,8 +54,14 @@ _: #@ template.replace(data.values.custom_labels) #@ "labels": labels(), #@ "insecureAcceptExternalUnencryptedHttpRequests": data.values.deprecated_insecure_accept_external_unencrypted_http_requests #@ } +#@ if data.values.log_level or data.values.deprecated_log_format: +#@ config["log"] = {} +#@ end #@ if data.values.log_level: -#@ config["logLevel"] = getAndValidateLogLevel() +#@ config["log"]["level"] = getAndValidateLogLevel() +#@ end +#@ if data.values.deprecated_log_format: +#@ config["log"]["format"] = data.values.deprecated_log_format #@ end #@ if data.values.endpoints: #@ config["endpoints"] = data.values.endpoints diff --git a/deploy/supervisor/values.yaml b/deploy/supervisor/values.yaml index e0fd50f3..888d5038 100644 --- a/deploy/supervisor/values.yaml +++ b/deploy/supervisor/values.yaml @@ -57,6 +57,10 @@ service_loadbalancer_ip: #! e.g. 1.2.3.4 #! Specify the verbosity of logging: info ("nice to know" information), debug (developer information), trace (timing information), #! or all (kitchen sink). Do not use trace or all on production systems, as credentials may get logged. log_level: #! By default, when this value is left unset, only warnings and errors are printed. There is no way to suppress warning and error logs. +#! Specify the format of logging: json (for machine parsable logs) and text (for legacy klog formatted logs). +#! By default, when this value is left unset, logs are formatted in json. +#! This configuration is deprecated and will be removed in a future release at which point logs will always be formatted as json. +deprecated_log_format: run_as_user: 65532 #! run_as_user specifies the user ID that will own the process, see the Dockerfile for the reasoning behind this choice run_as_group: 65532 #! run_as_group specifies the group ID that will own the process, see the Dockerfile for the reasoning behind this choice diff --git a/go.mod b/go.mod index 251b43e2..5ee1267e 100644 --- a/go.mod +++ b/go.mod @@ -45,6 +45,7 @@ require ( github.com/go-ldap/ldap/v3 v3.4.3 github.com/go-logr/logr v1.2.3 github.com/go-logr/stdr v1.2.2 + github.com/go-logr/zapr v1.2.3 github.com/gofrs/flock v0.8.1 github.com/golang/mock v1.6.0 github.com/google/go-cmp v0.5.8 @@ -64,6 +65,7 @@ require ( github.com/stretchr/testify v1.7.1 github.com/tdewolff/minify/v2 v2.11.2 go.uber.org/atomic v1.9.0 + go.uber.org/zap v1.21.0 golang.org/x/crypto v0.0.0-20220427172511-eb4f295cb31f golang.org/x/net v0.0.0-20220425223048-2871e0cb64e4 golang.org/x/oauth2 v0.0.0-20220411215720-9780585627b5 @@ -168,7 +170,6 @@ require ( go.opentelemetry.io/otel/trace v1.6.3 // indirect go.opentelemetry.io/proto/otlp v0.15.0 // indirect go.uber.org/multierr v1.8.0 // indirect - go.uber.org/zap v1.21.0 // indirect golang.org/x/mod v0.6.0-dev.0.20220106191415-9b9b3d81d5e3 // indirect golang.org/x/sys v0.0.0-20220422013727-9388b58f7150 // indirect golang.org/x/time v0.0.0-20220411224347-583f2d630306 // indirect diff --git a/go.sum b/go.sum index b04534a9..86bc0ea4 100644 --- a/go.sum +++ b/go.sum @@ -299,6 +299,8 @@ github.com/go-logr/logr v1.2.3/go.mod h1:jdQByPbusPIv2/zmleS9BjJVeZ6kBagPoEUsqbV github.com/go-logr/stdr v1.2.2 h1:hSWxHoqTgW2S2qGc0LTAI563KZ5YKYRhT3MFKZMbjag= github.com/go-logr/stdr v1.2.2/go.mod h1:mMo/vtBO5dYbehREoey6XUKy/eSumjCCveDpRre4VKE= github.com/go-logr/zapr v1.2.0/go.mod h1:Qa4Bsj2Vb+FAVeAKsLD8RLQ+YRJB8YDmOAKxaBQf7Ro= +github.com/go-logr/zapr v1.2.3 h1:a9vnzlIBPQBBkeaR9IuMUfmVOrQlkoC4YfPoFkX3T7A= +github.com/go-logr/zapr v1.2.3/go.mod h1:eIauM6P8qSvTw5o2ez6UEAfGjQKrxQTl5EoK+Qa2oG4= github.com/go-openapi/analysis v0.0.0-20180825180245-b006789cd277/go.mod h1:k70tL6pCuVxPJOHXQ+wIac1FUrvNkHolPie/cLEU6hI= github.com/go-openapi/analysis v0.17.0/go.mod h1:IowGgpVeD0vNm45So8nr+IcQ3pxVtpRoBWb8PVZO0ik= github.com/go-openapi/analysis v0.18.0/go.mod h1:IowGgpVeD0vNm45So8nr+IcQ3pxVtpRoBWb8PVZO0ik= diff --git a/internal/concierge/server/server.go b/internal/concierge/server/server.go index 1b724700..ebba1c4b 100644 --- a/internal/concierge/server/server.go +++ b/internal/concierge/server/server.go @@ -15,12 +15,11 @@ import ( "k8s.io/apimachinery/pkg/runtime" "k8s.io/apimachinery/pkg/runtime/schema" "k8s.io/apimachinery/pkg/runtime/serializer" + apimachineryversion "k8s.io/apimachinery/pkg/version" genericapiserver "k8s.io/apiserver/pkg/server" genericoptions "k8s.io/apiserver/pkg/server/options" "k8s.io/client-go/pkg/version" "k8s.io/client-go/rest" - "k8s.io/component-base/logs" - "k8s.io/klog/v2" "go.pinniped.dev/internal/certauthority/dynamiccertauthority" "go.pinniped.dev/internal/concierge/apiserver" @@ -35,6 +34,7 @@ import ( "go.pinniped.dev/internal/here" "go.pinniped.dev/internal/issuer" "go.pinniped.dev/internal/kubeclient" + "go.pinniped.dev/internal/plog" "go.pinniped.dev/internal/registry/credentialrequest" ) @@ -100,7 +100,7 @@ func addCommandlineFlagsToCommand(cmd *cobra.Command, app *App) { // Boot the aggregated API server, which will in turn boot the controllers. func (a *App) runServer(ctx context.Context) error { // Read the server config file. - cfg, err := concierge.FromPath(a.configPath) + cfg, err := concierge.FromPath(ctx, a.configPath) if err != nil { return fmt.Errorf("could not load config: %w", err) } @@ -250,16 +250,20 @@ func getAggregatedAPIServerConfig( return apiServerConfig, nil } -func main() error { // return an error instead of klog.Fatal to allow defer statements to run - logs.InitLogs() - defer logs.FlushLogs() +func main() error { // return an error instead of plog.Fatal to allow defer statements to run + defer plog.Setup()() // Dump out the time since compile (mostly useful for benchmarking our local development cycle latency). var timeSinceCompile time.Duration if buildDate, err := time.Parse(time.RFC3339, version.Get().BuildDate); err == nil { timeSinceCompile = time.Since(buildDate).Round(time.Second) } - klog.Infof("Running %s at %#v (%s since build)", rest.DefaultKubernetesUserAgent(), version.Get(), timeSinceCompile) + + plog.Always("Running concierge", + "user-agent", rest.DefaultKubernetesUserAgent(), + "version", versionInfo(version.Get()), + "time-since-build", timeSinceCompile, + ) ctx := genericapiserver.SetupSignalContext() @@ -268,6 +272,8 @@ func main() error { // return an error instead of klog.Fatal to allow defer stat func Main() { if err := main(); err != nil { - klog.Fatal(err) + plog.Fatal(err) } } + +type versionInfo apimachineryversion.Info // hide .String() method from plog diff --git a/internal/config/concierge/config.go b/internal/config/concierge/config.go index 4749c7ca..605f72d4 100644 --- a/internal/config/concierge/config.go +++ b/internal/config/concierge/config.go @@ -6,6 +6,7 @@ package concierge import ( + "context" "fmt" "io/ioutil" "strings" @@ -41,7 +42,7 @@ const ( // Note! The Config file should contain base64-encoded WebhookCABundle data. // This function will decode that base64-encoded data to PEM bytes to be stored // in the Config. -func FromPath(path string) (*Config, error) { +func FromPath(ctx context.Context, path string) (*Config, error) { data, err := ioutil.ReadFile(path) if err != nil { return nil, fmt.Errorf("read file: %w", err) @@ -78,7 +79,8 @@ func FromPath(path string) (*Config, error) { return nil, fmt.Errorf("validate names: %w", err) } - if err := plog.ValidateAndSetLogLevelGlobally(config.LogLevel); err != nil { + plog.MaybeSetDeprecatedLogLevel(config.LogLevel, &config.Log) + if err := plog.ValidateAndSetLogLevelAndFormatGlobally(ctx, config.Log); err != nil { return nil, fmt.Errorf("validate log level: %w", err) } diff --git a/internal/config/concierge/config_test.go b/internal/config/concierge/config_test.go index 86139182..ce7c9929 100644 --- a/internal/config/concierge/config_test.go +++ b/internal/config/concierge/config_test.go @@ -4,6 +4,7 @@ package concierge import ( + "context" "io/ioutil" "os" "testing" @@ -90,9 +91,186 @@ func TestFromPath(t *testing.T) { Image: pointer.StringPtr("kube-cert-agent-image"), ImagePullSecrets: []string{"kube-cert-agent-image-pull-secret"}, }, - LogLevel: plog.LevelDebug, + LogLevel: func(level plog.LogLevel) *plog.LogLevel { return &level }(plog.LevelDebug), + Log: plog.LogSpec{ + Level: plog.LevelDebug, + }, }, }, + { + name: "Fully filled out new log struct", + yaml: here.Doc(` + --- + discovery: + url: https://some.discovery/url + api: + servingCertificate: + durationSeconds: 3600 + renewBeforeSeconds: 2400 + apiGroupSuffix: some.suffix.com + aggregatedAPIServerPort: 12345 + impersonationProxyServerPort: 4242 + names: + servingCertificateSecret: pinniped-concierge-api-tls-serving-certificate + credentialIssuer: pinniped-config + apiService: pinniped-api + kubeCertAgentPrefix: kube-cert-agent-prefix + impersonationLoadBalancerService: impersonationLoadBalancerService-value + impersonationClusterIPService: impersonationClusterIPService-value + impersonationTLSCertificateSecret: impersonationTLSCertificateSecret-value + impersonationCACertificateSecret: impersonationCACertificateSecret-value + impersonationSignerSecret: impersonationSignerSecret-value + impersonationSignerSecret: impersonationSignerSecret-value + agentServiceAccount: agentServiceAccount-value + extraName: extraName-value + labels: + myLabelKey1: myLabelValue1 + myLabelKey2: myLabelValue2 + kubeCertAgent: + namePrefix: kube-cert-agent-name-prefix- + image: kube-cert-agent-image + imagePullSecrets: [kube-cert-agent-image-pull-secret] + log: + level: all + format: json + `), + wantConfig: &Config{ + DiscoveryInfo: DiscoveryInfoSpec{ + URL: pointer.StringPtr("https://some.discovery/url"), + }, + APIConfig: APIConfigSpec{ + ServingCertificateConfig: ServingCertificateConfigSpec{ + DurationSeconds: pointer.Int64Ptr(3600), + RenewBeforeSeconds: pointer.Int64Ptr(2400), + }, + }, + APIGroupSuffix: pointer.StringPtr("some.suffix.com"), + AggregatedAPIServerPort: pointer.Int64Ptr(12345), + ImpersonationProxyServerPort: pointer.Int64Ptr(4242), + NamesConfig: NamesConfigSpec{ + ServingCertificateSecret: "pinniped-concierge-api-tls-serving-certificate", + CredentialIssuer: "pinniped-config", + APIService: "pinniped-api", + ImpersonationLoadBalancerService: "impersonationLoadBalancerService-value", + ImpersonationClusterIPService: "impersonationClusterIPService-value", + ImpersonationTLSCertificateSecret: "impersonationTLSCertificateSecret-value", + ImpersonationCACertificateSecret: "impersonationCACertificateSecret-value", + ImpersonationSignerSecret: "impersonationSignerSecret-value", + AgentServiceAccount: "agentServiceAccount-value", + }, + Labels: map[string]string{ + "myLabelKey1": "myLabelValue1", + "myLabelKey2": "myLabelValue2", + }, + KubeCertAgentConfig: KubeCertAgentSpec{ + NamePrefix: pointer.StringPtr("kube-cert-agent-name-prefix-"), + Image: pointer.StringPtr("kube-cert-agent-image"), + ImagePullSecrets: []string{"kube-cert-agent-image-pull-secret"}, + }, + Log: plog.LogSpec{ + Level: plog.LevelAll, + Format: plog.FormatJSON, + }, + }, + }, + { + name: "Fully filled out old log and new log struct", + yaml: here.Doc(` + --- + discovery: + url: https://some.discovery/url + api: + servingCertificate: + durationSeconds: 3600 + renewBeforeSeconds: 2400 + apiGroupSuffix: some.suffix.com + aggregatedAPIServerPort: 12345 + impersonationProxyServerPort: 4242 + names: + servingCertificateSecret: pinniped-concierge-api-tls-serving-certificate + credentialIssuer: pinniped-config + apiService: pinniped-api + kubeCertAgentPrefix: kube-cert-agent-prefix + impersonationLoadBalancerService: impersonationLoadBalancerService-value + impersonationClusterIPService: impersonationClusterIPService-value + impersonationTLSCertificateSecret: impersonationTLSCertificateSecret-value + impersonationCACertificateSecret: impersonationCACertificateSecret-value + impersonationSignerSecret: impersonationSignerSecret-value + impersonationSignerSecret: impersonationSignerSecret-value + agentServiceAccount: agentServiceAccount-value + extraName: extraName-value + labels: + myLabelKey1: myLabelValue1 + myLabelKey2: myLabelValue2 + kubeCertAgent: + namePrefix: kube-cert-agent-name-prefix- + image: kube-cert-agent-image + imagePullSecrets: [kube-cert-agent-image-pull-secret] + logLevel: debug + log: + level: all + format: json + `), + wantConfig: &Config{ + DiscoveryInfo: DiscoveryInfoSpec{ + URL: pointer.StringPtr("https://some.discovery/url"), + }, + APIConfig: APIConfigSpec{ + ServingCertificateConfig: ServingCertificateConfigSpec{ + DurationSeconds: pointer.Int64Ptr(3600), + RenewBeforeSeconds: pointer.Int64Ptr(2400), + }, + }, + APIGroupSuffix: pointer.StringPtr("some.suffix.com"), + AggregatedAPIServerPort: pointer.Int64Ptr(12345), + ImpersonationProxyServerPort: pointer.Int64Ptr(4242), + NamesConfig: NamesConfigSpec{ + ServingCertificateSecret: "pinniped-concierge-api-tls-serving-certificate", + CredentialIssuer: "pinniped-config", + APIService: "pinniped-api", + ImpersonationLoadBalancerService: "impersonationLoadBalancerService-value", + ImpersonationClusterIPService: "impersonationClusterIPService-value", + ImpersonationTLSCertificateSecret: "impersonationTLSCertificateSecret-value", + ImpersonationCACertificateSecret: "impersonationCACertificateSecret-value", + ImpersonationSignerSecret: "impersonationSignerSecret-value", + AgentServiceAccount: "agentServiceAccount-value", + }, + Labels: map[string]string{ + "myLabelKey1": "myLabelValue1", + "myLabelKey2": "myLabelValue2", + }, + KubeCertAgentConfig: KubeCertAgentSpec{ + NamePrefix: pointer.StringPtr("kube-cert-agent-name-prefix-"), + Image: pointer.StringPtr("kube-cert-agent-image"), + ImagePullSecrets: []string{"kube-cert-agent-image-pull-secret"}, + }, + LogLevel: func(level plog.LogLevel) *plog.LogLevel { return &level }(plog.LevelDebug), + Log: plog.LogSpec{ + Level: plog.LevelDebug, + Format: plog.FormatJSON, + }, + }, + }, + { + name: "invalid log format", + yaml: here.Doc(` + --- + names: + servingCertificateSecret: pinniped-concierge-api-tls-serving-certificate + credentialIssuer: pinniped-config + apiService: pinniped-api + impersonationLoadBalancerService: impersonationLoadBalancerService-value + impersonationClusterIPService: impersonationClusterIPService-value + impersonationTLSCertificateSecret: impersonationTLSCertificateSecret-value + impersonationCACertificateSecret: impersonationCACertificateSecret-value + impersonationSignerSecret: impersonationSignerSecret-value + agentServiceAccount: agentServiceAccount-value + log: + level: all + format: snorlax + `), + wantError: "decode yaml: error unmarshaling JSON: while decoding JSON: invalid log format, valid choices are the empty string, json and text", + }, { name: "When only the required fields are present, causes other fields to be defaulted", yaml: here.Doc(` @@ -404,6 +582,8 @@ func TestFromPath(t *testing.T) { for _, test := range tests { test := test t.Run(test.name, func(t *testing.T) { + // this is a serial test because it sets the global logger + // Write yaml to temp file f, err := ioutil.TempFile("", "pinniped-test-config-yaml-*") require.NoError(t, err) @@ -417,7 +597,9 @@ func TestFromPath(t *testing.T) { require.NoError(t, err) // Test FromPath() - config, err := FromPath(f.Name()) + ctx, cancel := context.WithCancel(context.Background()) + t.Cleanup(cancel) + config, err := FromPath(ctx, f.Name()) if test.wantError != "" { require.EqualError(t, err, test.wantError) diff --git a/internal/config/concierge/types.go b/internal/config/concierge/types.go index 1717aa3c..f444dc82 100644 --- a/internal/config/concierge/types.go +++ b/internal/config/concierge/types.go @@ -15,7 +15,9 @@ type Config struct { NamesConfig NamesConfigSpec `json:"names"` KubeCertAgentConfig KubeCertAgentSpec `json:"kubeCertAgent"` Labels map[string]string `json:"labels"` - LogLevel plog.LogLevel `json:"logLevel"` + // Deprecated: use log.level instead + LogLevel *plog.LogLevel `json:"logLevel"` + Log plog.LogSpec `json:"log"` } // DiscoveryInfoSpec contains configuration knobs specific to diff --git a/internal/config/supervisor/config.go b/internal/config/supervisor/config.go index b7baadf8..192d9790 100644 --- a/internal/config/supervisor/config.go +++ b/internal/config/supervisor/config.go @@ -6,6 +6,7 @@ package supervisor import ( + "context" "fmt" "io/ioutil" "net" @@ -28,7 +29,7 @@ const ( // FromPath loads an Config from a provided local file path, inserts any // defaults (from the Config documentation), and verifies that the config is // valid (Config documentation). -func FromPath(path string) (*Config, error) { +func FromPath(ctx context.Context, path string) (*Config, error) { data, err := ioutil.ReadFile(path) if err != nil { return nil, fmt.Errorf("read file: %w", err) @@ -53,7 +54,8 @@ func FromPath(path string) (*Config, error) { return nil, fmt.Errorf("validate names: %w", err) } - if err := plog.ValidateAndSetLogLevelGlobally(config.LogLevel); err != nil { + plog.MaybeSetDeprecatedLogLevel(config.LogLevel, &config.Log) + if err := plog.ValidateAndSetLogLevelAndFormatGlobally(ctx, config.Log); err != nil { return nil, fmt.Errorf("validate log level: %w", err) } diff --git a/internal/config/supervisor/config_test.go b/internal/config/supervisor/config_test.go index 5d4d7a85..ac4651a7 100644 --- a/internal/config/supervisor/config_test.go +++ b/internal/config/supervisor/config_test.go @@ -4,6 +4,7 @@ package supervisor import ( + "context" "fmt" "io/ioutil" "os" @@ -13,6 +14,7 @@ import ( "k8s.io/utils/pointer" "go.pinniped.dev/internal/here" + "go.pinniped.dev/internal/plog" ) func TestFromPath(t *testing.T) { @@ -40,6 +42,7 @@ func TestFromPath(t *testing.T) { network: tcp address: 127.0.0.1:1234 insecureAcceptExternalUnencryptedHttpRequests: false + logLevel: trace `), wantConfig: &Config{ APIGroupSuffix: pointer.StringPtr("some.suffix.com"), @@ -61,8 +64,122 @@ func TestFromPath(t *testing.T) { }, }, AllowExternalHTTP: false, + LogLevel: func(level plog.LogLevel) *plog.LogLevel { return &level }(plog.LevelTrace), + Log: plog.LogSpec{ + Level: plog.LevelTrace, + }, }, }, + { + name: "Happy with new log field", + yaml: here.Doc(` + --- + apiGroupSuffix: some.suffix.com + labels: + myLabelKey1: myLabelValue1 + myLabelKey2: myLabelValue2 + names: + defaultTLSCertificateSecret: my-secret-name + endpoints: + https: + network: unix + address: :1234 + http: + network: tcp + address: 127.0.0.1:1234 + insecureAcceptExternalUnencryptedHttpRequests: false + log: + level: info + format: text + `), + wantConfig: &Config{ + APIGroupSuffix: pointer.StringPtr("some.suffix.com"), + Labels: map[string]string{ + "myLabelKey1": "myLabelValue1", + "myLabelKey2": "myLabelValue2", + }, + NamesConfig: NamesConfigSpec{ + DefaultTLSCertificateSecret: "my-secret-name", + }, + Endpoints: &Endpoints{ + HTTPS: &Endpoint{ + Network: "unix", + Address: ":1234", + }, + HTTP: &Endpoint{ + Network: "tcp", + Address: "127.0.0.1:1234", + }, + }, + AllowExternalHTTP: false, + Log: plog.LogSpec{ + Level: plog.LevelInfo, + Format: plog.FormatText, + }, + }, + }, + { + name: "Happy with old and new log field", + yaml: here.Doc(` + --- + apiGroupSuffix: some.suffix.com + labels: + myLabelKey1: myLabelValue1 + myLabelKey2: myLabelValue2 + names: + defaultTLSCertificateSecret: my-secret-name + endpoints: + https: + network: unix + address: :1234 + http: + network: tcp + address: 127.0.0.1:1234 + insecureAcceptExternalUnencryptedHttpRequests: false + logLevel: trace + log: + level: info + format: text + `), + wantConfig: &Config{ + APIGroupSuffix: pointer.StringPtr("some.suffix.com"), + Labels: map[string]string{ + "myLabelKey1": "myLabelValue1", + "myLabelKey2": "myLabelValue2", + }, + NamesConfig: NamesConfigSpec{ + DefaultTLSCertificateSecret: "my-secret-name", + }, + Endpoints: &Endpoints{ + HTTPS: &Endpoint{ + Network: "unix", + Address: ":1234", + }, + HTTP: &Endpoint{ + Network: "tcp", + Address: "127.0.0.1:1234", + }, + }, + AllowExternalHTTP: false, + LogLevel: func(level plog.LogLevel) *plog.LogLevel { return &level }(plog.LevelTrace), + Log: plog.LogSpec{ + Level: plog.LevelTrace, + Format: plog.FormatText, + }, + }, + }, + { + name: "bad log format", + yaml: here.Doc(` + --- + names: + defaultTLSCertificateSecret: my-secret-name + log: + level: info + format: cli + `), + wantError: "decode yaml: error unmarshaling JSON: while decoding JSON: invalid log format, valid choices are the empty string, json and text", + }, { name: "When only the required fields are present, causes other fields to be defaulted", yaml: here.Doc(` @@ -307,7 +424,7 @@ func TestFromPath(t *testing.T) { for _, test := range tests { test := test t.Run(test.name, func(t *testing.T) { - t.Parallel() + // this is a serial test because it sets the global logger // Write yaml to temp file f, err := ioutil.TempFile("", "pinniped-test-config-yaml-*") @@ -322,7 +439,9 @@ func TestFromPath(t *testing.T) { require.NoError(t, err) // Test FromPath() - config, err := FromPath(f.Name()) + ctx, cancel := context.WithCancel(context.Background()) + t.Cleanup(cancel) + config, err := FromPath(ctx, f.Name()) if test.wantError != "" { require.EqualError(t, err, test.wantError) diff --git a/internal/config/supervisor/types.go b/internal/config/supervisor/types.go index e61d4068..147845fb 100644 --- a/internal/config/supervisor/types.go +++ b/internal/config/supervisor/types.go @@ -11,10 +11,12 @@ import ( // Config contains knobs to setup an instance of the Pinniped Supervisor. type Config struct { - APIGroupSuffix *string `json:"apiGroupSuffix,omitempty"` - Labels map[string]string `json:"labels"` - NamesConfig NamesConfigSpec `json:"names"` - LogLevel plog.LogLevel `json:"logLevel"` + APIGroupSuffix *string `json:"apiGroupSuffix,omitempty"` + Labels map[string]string `json:"labels"` + NamesConfig NamesConfigSpec `json:"names"` + // Deprecated: use log.level instead + LogLevel *plog.LogLevel `json:"logLevel"` + Log plog.LogSpec `json:"log"` Endpoints *Endpoints `json:"endpoints"` AllowExternalHTTP stringOrBoolAsBool `json:"insecureAcceptExternalUnencryptedHttpRequests"` } diff --git a/internal/controller/apicerts/certs_expirer.go b/internal/controller/apicerts/certs_expirer.go index dbd48628..bb4a28f8 100644 --- a/internal/controller/apicerts/certs_expirer.go +++ b/internal/controller/apicerts/certs_expirer.go @@ -32,6 +32,8 @@ type certsExpirerController struct { renewBefore time.Duration secretKey string + + logger plog.Logger } // NewCertsExpirerController returns a controllerlib.Controller that will delete a @@ -45,10 +47,12 @@ func NewCertsExpirerController( withInformer pinnipedcontroller.WithInformerOptionFunc, renewBefore time.Duration, secretKey string, + logger plog.Logger, ) controllerlib.Controller { + const name = "certs-expirer-controller" return controllerlib.New( controllerlib.Config{ - Name: "certs-expirer-controller", + Name: name, Syncer: &certsExpirerController{ namespace: namespace, certsSecretResourceName: certsSecretResourceName, @@ -56,6 +60,7 @@ func NewCertsExpirerController( secretInformer: secretInformer, renewBefore: renewBefore, secretKey: secretKey, + logger: logger.WithName(name), }, }, withInformer( @@ -74,7 +79,7 @@ func (c *certsExpirerController) Sync(ctx controllerlib.Context) error { return fmt.Errorf("failed to get %s/%s secret: %w", c.namespace, c.certsSecretResourceName, err) } if notFound { - plog.Info("secret does not exist yet or was deleted", + c.logger.Info("secret does not exist yet or was deleted", "controller", ctx.Name, "namespace", c.namespace, "name", c.certsSecretResourceName, @@ -91,7 +96,7 @@ func (c *certsExpirerController) Sync(ctx controllerlib.Context) error { certAge := time.Since(notBefore) renewDelta := certAge - c.renewBefore - plog.Debug("found renew delta", + c.logger.Debug("found renew delta", "controller", ctx.Name, "namespace", c.namespace, "name", c.certsSecretResourceName, diff --git a/internal/controller/apicerts/certs_expirer_test.go b/internal/controller/apicerts/certs_expirer_test.go index 9741de5d..3e33ee6a 100644 --- a/internal/controller/apicerts/certs_expirer_test.go +++ b/internal/controller/apicerts/certs_expirer_test.go @@ -4,12 +4,15 @@ package apicerts import ( + "bytes" "context" "crypto/ecdsa" "crypto/elliptic" "crypto/rand" "crypto/x509" "errors" + "io" + "strings" "testing" "time" @@ -24,6 +27,7 @@ import ( kubetesting "k8s.io/client-go/testing" "go.pinniped.dev/internal/controllerlib" + "go.pinniped.dev/internal/plog" "go.pinniped.dev/internal/testutil" ) @@ -101,6 +105,7 @@ func TestExpirerControllerFilters(t *testing.T) { withInformer.WithInformer, 0, // renewBefore, not needed "", // not needed + plog.TestLogger(t, io.Discard), ) unrelated := corev1.Secret{} @@ -125,10 +130,12 @@ func TestExpirerControllerSync(t *testing.T) { fillSecretData func(*testing.T, map[string][]byte) configKubeAPIClient func(*kubernetesfake.Clientset) wantDelete bool + wantLog string wantError string }{ { name: "secret does not exist", + wantLog: `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"certs-expirer-controller","caller":"apicerts/certs_expirer.go:$apicerts.(*certsExpirerController).Sync","message":"secret does not exist yet or was deleted","controller":"","namespace":"some-namespace","name":"some-resource-name","key":"some-awesome-key","renewBefore":"0s"}`, wantDelete: false, }, { @@ -251,6 +258,8 @@ func TestExpirerControllerSync(t *testing.T) { 0, ) + var log bytes.Buffer + c := NewCertsExpirerController( namespace, certsSecretResourceName, @@ -259,6 +268,7 @@ func TestExpirerControllerSync(t *testing.T) { controllerlib.WithInformer, test.renewBefore, fakeTestKey, + plog.TestLogger(t, &log), ) // Must start informers before calling TestRunSynchronously(). @@ -268,6 +278,9 @@ func TestExpirerControllerSync(t *testing.T) { err := controllerlib.TestSync(t, c, controllerlib.Context{ Context: ctx, }) + if len(test.wantLog) > 0 { + require.Equal(t, test.wantLog, strings.TrimSpace(log.String())) + } if test.wantError != "" { require.EqualError(t, err, test.wantError) return diff --git a/internal/controller/apicerts/certs_manager.go b/internal/controller/apicerts/certs_manager.go index c3d8bf36..d8551452 100644 --- a/internal/controller/apicerts/certs_manager.go +++ b/internal/controller/apicerts/certs_manager.go @@ -12,11 +12,11 @@ import ( metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" corev1informers "k8s.io/client-go/informers/core/v1" "k8s.io/client-go/kubernetes" - "k8s.io/klog/v2" "go.pinniped.dev/internal/certauthority" pinnipedcontroller "go.pinniped.dev/internal/controller" "go.pinniped.dev/internal/controllerlib" + "go.pinniped.dev/internal/plog" ) const ( @@ -139,6 +139,6 @@ func (c *certsManagerController) Sync(ctx controllerlib.Context) error { return fmt.Errorf("could not create secret: %w", err) } - klog.Info("certsManagerController Sync successfully created secret") + plog.Info("certsManagerController Sync successfully created secret") return nil } diff --git a/internal/controller/apicerts/certs_observer.go b/internal/controller/apicerts/certs_observer.go index f01312d5..704020f7 100644 --- a/internal/controller/apicerts/certs_observer.go +++ b/internal/controller/apicerts/certs_observer.go @@ -8,11 +8,11 @@ import ( k8serrors "k8s.io/apimachinery/pkg/api/errors" corev1informers "k8s.io/client-go/informers/core/v1" - "k8s.io/klog/v2" pinnipedcontroller "go.pinniped.dev/internal/controller" "go.pinniped.dev/internal/controllerlib" "go.pinniped.dev/internal/dynamiccert" + "go.pinniped.dev/internal/plog" ) type certsObserverController struct { @@ -55,7 +55,7 @@ func (c *certsObserverController) Sync(_ controllerlib.Context) error { return fmt.Errorf("failed to get %s/%s secret: %w", c.namespace, c.certsSecretResourceName, err) } if notFound { - klog.Info("certsObserverController Sync found that the secret does not exist yet or was deleted") + plog.Info("certsObserverController Sync found that the secret does not exist yet or was deleted") // The secret does not exist yet or was deleted. c.dynamicCertProvider.UnsetCertKeyContent() return nil @@ -66,6 +66,6 @@ func (c *certsObserverController) Sync(_ controllerlib.Context) error { return fmt.Errorf("failed to set serving cert/key content from secret %s/%s: %w", c.namespace, c.certsSecretResourceName, err) } - klog.Info("certsObserverController Sync updated certs in the dynamic cert provider") + plog.Info("certsObserverController Sync updated certs in the dynamic cert provider") return nil } diff --git a/internal/controller/conditionsutil/conditions_util.go.go b/internal/controller/conditionsutil/conditions_util.go.go index 67f13b03..dec4695a 100644 --- a/internal/controller/conditionsutil/conditions_util.go.go +++ b/internal/controller/conditionsutil/conditions_util.go.go @@ -6,15 +6,15 @@ package conditionsutil import ( "sort" - "github.com/go-logr/logr" "k8s.io/apimachinery/pkg/api/equality" v1 "k8s.io/apimachinery/pkg/apis/meta/v1" "go.pinniped.dev/generated/latest/apis/supervisor/idp/v1alpha1" + "go.pinniped.dev/internal/plog" ) // Merge merges conditions into conditionsToUpdate. If returns true if it merged any error conditions. -func Merge(conditions []*v1alpha1.Condition, observedGeneration int64, conditionsToUpdate *[]v1alpha1.Condition, log logr.Logger) bool { +func Merge(conditions []*v1alpha1.Condition, observedGeneration int64, conditionsToUpdate *[]v1alpha1.Condition, log plog.MinLogger) bool { hadErrorCondition := false for i := range conditions { cond := conditions[i].DeepCopy() diff --git a/internal/controller/impersonatorconfig/impersonator_config.go b/internal/controller/impersonatorconfig/impersonator_config.go index 4cd7b0b0..aa261e42 100644 --- a/internal/controller/impersonatorconfig/impersonator_config.go +++ b/internal/controller/impersonatorconfig/impersonator_config.go @@ -45,6 +45,7 @@ import ( "go.pinniped.dev/internal/controllerlib" "go.pinniped.dev/internal/dynamiccert" "go.pinniped.dev/internal/endpointaddr" + "go.pinniped.dev/internal/plog" ) const ( @@ -132,8 +133,8 @@ func NewImpersonatorConfigController( impersonationSigningCertProvider: impersonationSigningCertProvider, impersonatorFunc: impersonatorFunc, tlsServingCertDynamicCertProvider: dynamiccert.NewServingCert("impersonation-proxy-serving-cert"), - infoLog: log.V(2), - debugLog: log.V(4), + infoLog: log.V(plog.KlogLevelInfo), + debugLog: log.V(plog.KlogLevelDebug), }, }, withInformer(credentialIssuerInformer, diff --git a/internal/controller/impersonatorconfig/impersonator_config_test.go b/internal/controller/impersonatorconfig/impersonator_config_test.go index c080b575..6b760d3d 100644 --- a/internal/controller/impersonatorconfig/impersonator_config_test.go +++ b/internal/controller/impersonatorconfig/impersonator_config_test.go @@ -43,8 +43,8 @@ import ( "go.pinniped.dev/internal/controllerlib" "go.pinniped.dev/internal/dynamiccert" "go.pinniped.dev/internal/kubeclient" + "go.pinniped.dev/internal/plog" "go.pinniped.dev/internal/testutil" - "go.pinniped.dev/internal/testutil/testlogger" ) func TestImpersonatorConfigControllerOptions(t *testing.T) { @@ -63,7 +63,6 @@ func TestImpersonatorConfigControllerOptions(t *testing.T) { var credIssuerInformerFilter controllerlib.Filter var servicesInformerFilter controllerlib.Filter var secretsInformerFilter controllerlib.Filter - var testLog *testlogger.Logger it.Before(func() { r = require.New(t) @@ -73,7 +72,6 @@ func TestImpersonatorConfigControllerOptions(t *testing.T) { credIssuerInformer := pinnipedInformerFactory.Config().V1alpha1().CredentialIssuers() servicesInformer := sharedInformerFactory.Core().V1().Services() secretsInformer := sharedInformerFactory.Core().V1().Secrets() - testLog = testlogger.New(t) _ = NewImpersonatorConfigController( installedInNamespace, @@ -94,7 +92,7 @@ func TestImpersonatorConfigControllerOptions(t *testing.T) { nil, caSignerName, nil, - testLog.Logger, + plog.Logr(), // nolint: staticcheck // old test with no log assertions ) credIssuerInformerFilter = observableWithInformerOption.GetFilterForInformer(credIssuerInformer) servicesInformerFilter = observableWithInformerOption.GetFilterForInformer(servicesInformer) @@ -292,7 +290,6 @@ func TestImpersonatorConfigControllerSync(t *testing.T) { var testHTTPServerInterruptCh chan struct{} var queue *testQueue var validClientCert *tls.Certificate - var testLog *testlogger.Logger var impersonatorFunc = func( port int, @@ -563,7 +560,7 @@ func TestImpersonatorConfigControllerSync(t *testing.T) { impersonatorFunc, caSignerName, signingCertProvider, - testLog.Logger, + plog.Logr(), // nolint: staticcheck // old test with no log assertions ) controllerlib.TestWrap(t, subject, func(syncer controllerlib.Syncer) controllerlib.Syncer { tlsServingCertDynamicCertProvider = syncer.(*impersonatorConfigController).tlsServingCertDynamicCertProvider @@ -1120,7 +1117,6 @@ func TestImpersonatorConfigControllerSync(t *testing.T) { signingCASecret = newSigningKeySecret(caSignerName, signingCACertPEM, signingCAKeyPEM) validClientCert, err = ca.IssueClientCert("username", nil, time.Hour) r.NoError(err) - testLog = testlogger.New(t) }) it.After(func() { diff --git a/internal/controller/kubecertagent/kubecertagent.go b/internal/controller/kubecertagent/kubecertagent.go index 230cf0ba..c19b34b1 100644 --- a/internal/controller/kubecertagent/kubecertagent.go +++ b/internal/controller/kubecertagent/kubecertagent.go @@ -28,7 +28,6 @@ import ( corev1informers "k8s.io/client-go/informers/core/v1" "k8s.io/client-go/tools/clientcmd" "k8s.io/klog/v2" - "k8s.io/klog/v2/klogr" "k8s.io/utils/clock" "k8s.io/utils/pointer" @@ -39,6 +38,7 @@ import ( "go.pinniped.dev/internal/controllerlib" "go.pinniped.dev/internal/dynamiccert" "go.pinniped.dev/internal/kubeclient" + "go.pinniped.dev/internal/plog" ) const ( @@ -179,7 +179,7 @@ func NewAgentController( dynamicCertProvider, &clock.RealClock{}, cache.NewExpiring(), - klogr.New(), + plog.Logr(), // nolint: staticcheck // old controller with lots of log statements ) } diff --git a/internal/controller/kubecertagent/kubecertagent_test.go b/internal/controller/kubecertagent/kubecertagent_test.go index 38736213..3e8016b8 100644 --- a/internal/controller/kubecertagent/kubecertagent_test.go +++ b/internal/controller/kubecertagent/kubecertagent_test.go @@ -4,8 +4,10 @@ package kubecertagent import ( + "bytes" "context" "fmt" + "strings" "testing" "time" @@ -35,8 +37,8 @@ import ( "go.pinniped.dev/internal/controllerlib" "go.pinniped.dev/internal/here" "go.pinniped.dev/internal/kubeclient" + "go.pinniped.dev/internal/plog" "go.pinniped.dev/internal/testutil" - "go.pinniped.dev/internal/testutil/testlogger" "go.pinniped.dev/test/testlib" ) @@ -339,7 +341,7 @@ func TestAgentController(t *testing.T) { "could not ensure agent deployment: some creation error", }, wantDistinctLogs: []string{ - `kube-cert-agent-controller "level"=0 "msg"="creating new deployment" "deployment"={"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"} "templatePod"={"name":"kube-controller-manager-1","namespace":"kube-system"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:$kubecertagent.(*agentController).createOrUpdateDeployment","message":"creating new deployment","deployment":{"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"},"templatePod":{"name":"kube-controller-manager-1","namespace":"kube-system"}}`, }, wantStrategy: &configv1alpha1.CredentialIssuerStrategy{ Type: configv1alpha1.KubeClusterSigningCertificateStrategyType, @@ -386,7 +388,7 @@ func TestAgentController(t *testing.T) { `could not ensure agent deployment: deployments.apps "pinniped-concierge-kube-cert-agent" already exists`, }, wantDistinctLogs: []string{ - `kube-cert-agent-controller "level"=0 "msg"="creating new deployment" "deployment"={"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"} "templatePod"={"name":"kube-controller-manager-1","namespace":"kube-system"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:$kubecertagent.(*agentController).createOrUpdateDeployment","message":"creating new deployment","deployment":{"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"},"templatePod":{"name":"kube-controller-manager-1","namespace":"kube-system"}}`, }, wantAgentDeployment: healthyAgentDeployment, wantDeploymentActionVerbs: []string{"list", "watch", "create"}, @@ -435,7 +437,7 @@ func TestAgentController(t *testing.T) { `could not ensure agent deployment: deployments.apps "pinniped-concierge-kube-cert-agent" already exists`, }, wantDistinctLogs: []string{ - `kube-cert-agent-controller "level"=0 "msg"="creating new deployment" "deployment"={"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"} "templatePod"={"name":"kube-controller-manager-1","namespace":"kube-system"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:$kubecertagent.(*agentController).createOrUpdateDeployment","message":"creating new deployment","deployment":{"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"},"templatePod":{"name":"kube-controller-manager-1","namespace":"kube-system"}}`, }, wantAgentDeployment: healthyAgentDeploymentWithDefaultedPaths, wantDeploymentActionVerbs: []string{"list", "watch", "create"}, @@ -461,8 +463,8 @@ func TestAgentController(t *testing.T) { "could not find a healthy agent pod (1 candidate)", }, wantDistinctLogs: []string{ - `kube-cert-agent-controller "level"=0 "msg"="deleting deployment to update immutable Selector field" "deployment"={"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"} "templatePod"={"name":"kube-controller-manager-1","namespace":"kube-system"}`, - `kube-cert-agent-controller "level"=0 "msg"="creating new deployment to update immutable Selector field" "deployment"={"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"} "templatePod"={"name":"kube-controller-manager-1","namespace":"kube-system"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:$kubecertagent.(*agentController).createOrUpdateDeployment","message":"deleting deployment to update immutable Selector field","deployment":{"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"},"templatePod":{"name":"kube-controller-manager-1","namespace":"kube-system"}}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:$kubecertagent.(*agentController).createOrUpdateDeployment","message":"creating new deployment to update immutable Selector field","deployment":{"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"},"templatePod":{"name":"kube-controller-manager-1","namespace":"kube-system"}}`, }, wantAgentDeployment: healthyAgentDeployment, wantDeploymentActionVerbs: []string{"list", "watch", "delete", "create"}, // must recreate deployment when Selector field changes @@ -496,7 +498,7 @@ func TestAgentController(t *testing.T) { "could not ensure agent deployment: some delete error", }, wantDistinctLogs: []string{ - `kube-cert-agent-controller "level"=0 "msg"="deleting deployment to update immutable Selector field" "deployment"={"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"} "templatePod"={"name":"kube-controller-manager-1","namespace":"kube-system"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:$kubecertagent.(*agentController).createOrUpdateDeployment","message":"deleting deployment to update immutable Selector field","deployment":{"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"},"templatePod":{"name":"kube-controller-manager-1","namespace":"kube-system"}}`, }, wantAgentDeployment: healthyAgentDeploymentWithOldStyleSelector, // couldn't be deleted, so it didn't change // delete to try to recreate deployment when Selector field changes, but delete always fails, so keeps trying to delete @@ -532,9 +534,9 @@ func TestAgentController(t *testing.T) { "could not ensure agent deployment: some create error", }, wantDistinctLogs: []string{ - `kube-cert-agent-controller "level"=0 "msg"="deleting deployment to update immutable Selector field" "deployment"={"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"} "templatePod"={"name":"kube-controller-manager-1","namespace":"kube-system"}`, - `kube-cert-agent-controller "level"=0 "msg"="creating new deployment to update immutable Selector field" "deployment"={"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"} "templatePod"={"name":"kube-controller-manager-1","namespace":"kube-system"}`, - `kube-cert-agent-controller "level"=0 "msg"="creating new deployment" "deployment"={"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"} "templatePod"={"name":"kube-controller-manager-1","namespace":"kube-system"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:$kubecertagent.(*agentController).createOrUpdateDeployment","message":"deleting deployment to update immutable Selector field","deployment":{"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"},"templatePod":{"name":"kube-controller-manager-1","namespace":"kube-system"}}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:$kubecertagent.(*agentController).createOrUpdateDeployment","message":"creating new deployment to update immutable Selector field","deployment":{"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"},"templatePod":{"name":"kube-controller-manager-1","namespace":"kube-system"}}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:$kubecertagent.(*agentController).createOrUpdateDeployment","message":"creating new deployment","deployment":{"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"},"templatePod":{"name":"kube-controller-manager-1","namespace":"kube-system"}}`, }, wantAgentDeployment: nil, // was deleted, but couldn't be recreated // delete to try to recreate deployment when Selector field changes, but create always fails, so keeps trying to recreate @@ -584,7 +586,7 @@ func TestAgentController(t *testing.T) { "could not find a healthy agent pod (1 candidate)", }, wantDistinctLogs: []string{ - `kube-cert-agent-controller "level"=0 "msg"="updating existing deployment" "deployment"={"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"} "templatePod"={"name":"kube-controller-manager-1","namespace":"kube-system"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:$kubecertagent.(*agentController).createOrUpdateDeployment","message":"updating existing deployment","deployment":{"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"},"templatePod":{"name":"kube-controller-manager-1","namespace":"kube-system"}}`, }, wantAgentDeployment: healthyAgentDeploymentWithExtraLabels, wantDeploymentActionVerbs: []string{"list", "watch", "update"}, @@ -619,7 +621,7 @@ func TestAgentController(t *testing.T) { LastUpdateTime: metav1.NewTime(now), }, wantDistinctLogs: []string{ - `kube-cert-agent-controller "level"=0 "msg"="updating existing deployment" "deployment"={"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"} "templatePod"={"name":"kube-controller-manager-1","namespace":"kube-system"}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:$kubecertagent.(*agentController).createOrUpdateDeployment","message":"updating existing deployment","deployment":{"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"},"templatePod":{"name":"kube-controller-manager-1","namespace":"kube-system"}}`, }, }, { @@ -931,8 +933,8 @@ func TestAgentController(t *testing.T) { // delete to try to recreate deployment when Selector field changes, but delete always fails, so keeps trying to delete wantDeploymentActionVerbs: []string{"list", "watch", "delete", "delete"}, wantDistinctLogs: []string{ - `kube-cert-agent-controller "level"=0 "msg"="deleting deployment to update immutable Selector field" "deployment"={"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"} "templatePod"={"name":"kube-controller-manager-1","namespace":"kube-system"}`, - `kube-cert-agent-controller "level"=0 "msg"="successfully loaded signing key from agent pod into cache"`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:$kubecertagent.(*agentController).createOrUpdateDeployment","message":"deleting deployment to update immutable Selector field","deployment":{"name":"pinniped-concierge-kube-cert-agent","namespace":"concierge"},"templatePod":{"name":"kube-controller-manager-1","namespace":"kube-system"}}`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:$kubecertagent.(*agentController).loadSigningKey","message":"successfully loaded signing key from agent pod into cache"}`, }, wantDeploymentDeleteActionOpts: []metav1.DeleteOptions{ testutil.NewPreconditions(healthyAgentDeploymentWithOldStyleSelector.UID, healthyAgentDeploymentWithOldStyleSelector.ResourceVersion), @@ -962,7 +964,7 @@ func TestAgentController(t *testing.T) { wantAgentDeployment: healthyAgentDeployment, wantDeploymentActionVerbs: []string{"list", "watch"}, wantDistinctLogs: []string{ - `kube-cert-agent-controller "level"=0 "msg"="successfully loaded signing key from agent pod into cache"`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:$kubecertagent.(*agentController).loadSigningKey","message":"successfully loaded signing key from agent pod into cache"}`, }, wantStrategy: &configv1alpha1.CredentialIssuerStrategy{ Type: configv1alpha1.KubeClusterSigningCertificateStrategyType, @@ -996,7 +998,7 @@ func TestAgentController(t *testing.T) { wantAgentDeployment: healthyAgentDeployment, wantDeploymentActionVerbs: []string{"list", "watch"}, wantDistinctLogs: []string{ - `kube-cert-agent-controller "level"=0 "msg"="successfully loaded signing key from agent pod into cache"`, + `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"kube-cert-agent-controller","caller":"kubecertagent/kubecertagent.go:$kubecertagent.(*agentController).loadSigningKey","message":"successfully loaded signing key from agent pod into cache"}`, }, wantStrategy: &configv1alpha1.CredentialIssuerStrategy{ Type: configv1alpha1.KubeClusterSigningCertificateStrategyType, @@ -1028,7 +1030,9 @@ func TestAgentController(t *testing.T) { } kubeInformers := informers.NewSharedInformerFactory(kubeClientset, 0) - log := testlogger.NewLegacy(t) // nolint: staticcheck // old test with lots of log statements + + var buf bytes.Buffer + log := plog.TestZapr(t, &buf) ctrl := gomock.NewController(t) defer ctrl.Finish() @@ -1066,7 +1070,7 @@ func TestAgentController(t *testing.T) { mockDynamicCert, fakeClock, execCache, - log.Logger, + log, ) ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second) @@ -1081,7 +1085,7 @@ func TestAgentController(t *testing.T) { allAllowedErrors = append(allAllowedErrors, tt.alsoAllowUndesiredDistinctErrors...) assert.Subsetf(t, allAllowedErrors, actualErrors, "actual errors contained additional error(s) which is not expected by the test") - assert.Equal(t, tt.wantDistinctLogs, deduplicate(log.Lines()), "unexpected logs") + assert.Equal(t, tt.wantDistinctLogs, deduplicate(logLines(buf.String())), "unexpected logs") // Assert on all actions that happened to deployments. var actualDeploymentActionVerbs []string @@ -1124,6 +1128,14 @@ func TestAgentController(t *testing.T) { } } +func logLines(logs string) []string { + if len(logs) == 0 { + return nil + } + + return strings.Split(strings.TrimSpace(logs), "\n") +} + func TestMergeLabelsAndAnnotations(t *testing.T) { t.Parallel() diff --git a/internal/controller/supervisorconfig/activedirectoryupstreamwatcher/active_directory_upstream_watcher.go b/internal/controller/supervisorconfig/activedirectoryupstreamwatcher/active_directory_upstream_watcher.go index 4fb699b7..4aaa41b9 100644 --- a/internal/controller/supervisorconfig/activedirectoryupstreamwatcher/active_directory_upstream_watcher.go +++ b/internal/controller/supervisorconfig/activedirectoryupstreamwatcher/active_directory_upstream_watcher.go @@ -13,12 +13,10 @@ import ( "github.com/go-ldap/ldap/v3" "github.com/google/uuid" - "k8s.io/apimachinery/pkg/api/equality" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/apimachinery/pkg/labels" corev1informers "k8s.io/client-go/informers/core/v1" - "k8s.io/klog/v2/klogr" "go.pinniped.dev/generated/latest/apis/supervisor/idp/v1alpha1" pinnipedclientset "go.pinniped.dev/generated/latest/client/supervisor/clientset/versioned" @@ -28,6 +26,7 @@ import ( "go.pinniped.dev/internal/controller/supervisorconfig/upstreamwatchers" "go.pinniped.dev/internal/controllerlib" "go.pinniped.dev/internal/oidc/provider" + "go.pinniped.dev/internal/plog" "go.pinniped.dev/internal/upstreamldap" ) @@ -360,7 +359,7 @@ func (c *activeDirectoryWatcherController) validateUpstream(ctx context.Context, } func (c *activeDirectoryWatcherController) updateStatus(ctx context.Context, upstream *v1alpha1.ActiveDirectoryIdentityProvider, conditions []*v1alpha1.Condition) { - log := klogr.New().WithValues("namespace", upstream.Namespace, "name", upstream.Name) + log := plog.WithValues("namespace", upstream.Namespace, "name", upstream.Name) updated := upstream.DeepCopy() hadErrorCondition := conditionsutil.Merge(conditions, upstream.Generation, &updated.Status.Conditions, log) @@ -379,7 +378,7 @@ func (c *activeDirectoryWatcherController) updateStatus(ctx context.Context, ups ActiveDirectoryIdentityProviders(upstream.Namespace). UpdateStatus(ctx, updated, metav1.UpdateOptions{}) if err != nil { - log.Error(err, "failed to update status") + log.Error("failed to update status", err) } } diff --git a/internal/controller/supervisorconfig/ldapupstreamwatcher/ldap_upstream_watcher.go b/internal/controller/supervisorconfig/ldapupstreamwatcher/ldap_upstream_watcher.go index fd57cc28..a942bbf9 100644 --- a/internal/controller/supervisorconfig/ldapupstreamwatcher/ldap_upstream_watcher.go +++ b/internal/controller/supervisorconfig/ldapupstreamwatcher/ldap_upstream_watcher.go @@ -12,7 +12,6 @@ import ( metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/apimachinery/pkg/labels" corev1informers "k8s.io/client-go/informers/core/v1" - "k8s.io/klog/v2/klogr" "go.pinniped.dev/generated/latest/apis/supervisor/idp/v1alpha1" pinnipedclientset "go.pinniped.dev/generated/latest/client/supervisor/clientset/versioned" @@ -22,6 +21,7 @@ import ( "go.pinniped.dev/internal/controller/supervisorconfig/upstreamwatchers" "go.pinniped.dev/internal/controllerlib" "go.pinniped.dev/internal/oidc/provider" + "go.pinniped.dev/internal/plog" "go.pinniped.dev/internal/upstreamldap" ) @@ -252,7 +252,7 @@ func (c *ldapWatcherController) validateUpstream(ctx context.Context, upstream * } func (c *ldapWatcherController) updateStatus(ctx context.Context, upstream *v1alpha1.LDAPIdentityProvider, conditions []*v1alpha1.Condition) { - log := klogr.New().WithValues("namespace", upstream.Namespace, "name", upstream.Name) + log := plog.WithValues("namespace", upstream.Namespace, "name", upstream.Name) updated := upstream.DeepCopy() hadErrorCondition := conditionsutil.Merge(conditions, upstream.Generation, &updated.Status.Conditions, log) @@ -271,6 +271,6 @@ func (c *ldapWatcherController) updateStatus(ctx context.Context, upstream *v1al LDAPIdentityProviders(upstream.Namespace). UpdateStatus(ctx, updated, metav1.UpdateOptions{}) if err != nil { - log.Error(err, "failed to update status") + log.Error("failed to update status", err) } } diff --git a/internal/controller/supervisorconfig/oidcupstreamwatcher/oidc_upstream_watcher.go b/internal/controller/supervisorconfig/oidcupstreamwatcher/oidc_upstream_watcher.go index 56f34776..2faff38c 100644 --- a/internal/controller/supervisorconfig/oidcupstreamwatcher/oidc_upstream_watcher.go +++ b/internal/controller/supervisorconfig/oidcupstreamwatcher/oidc_upstream_watcher.go @@ -14,8 +14,6 @@ import ( "strings" "time" - "k8s.io/apimachinery/pkg/util/sets" - "github.com/coreos/go-oidc/v3/oidc" "github.com/go-logr/logr" "golang.org/x/oauth2" @@ -24,6 +22,7 @@ import ( metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/apimachinery/pkg/labels" "k8s.io/apimachinery/pkg/util/cache" + "k8s.io/apimachinery/pkg/util/sets" corev1informers "k8s.io/client-go/informers/core/v1" "go.pinniped.dev/generated/latest/apis/supervisor/idp/v1alpha1" @@ -36,6 +35,7 @@ import ( "go.pinniped.dev/internal/controllerlib" "go.pinniped.dev/internal/net/phttp" "go.pinniped.dev/internal/oidc/provider" + "go.pinniped.dev/internal/plog" "go.pinniped.dev/internal/upstreamoidc" ) @@ -67,7 +67,7 @@ const ( ) var ( - disallowedAdditionalAuthorizeParameters = map[string]bool{ //nolint: gochecknoglobals + disallowedAdditionalAuthorizeParameters = map[string]bool{ // nolint: gochecknoglobals // Reject these AdditionalAuthorizeParameters to avoid allowing the user's config to overwrite the parameters // that are always used by Pinniped in authcode authorization requests. The OIDC library used would otherwise // happily treat the user's config as an override. Users can already set the "client_id" and "scope" params @@ -331,8 +331,7 @@ func (c *oidcWatcherController) validateIssuer(ctx context.Context, upstream *v1 discoveredProvider, err = oidc.NewProvider(oidc.ClientContext(ctx, httpClient), upstream.Spec.Issuer) if err != nil { - const klogLevelTrace = 6 - c.log.V(klogLevelTrace).WithValues( + c.log.V(plog.KlogLevelTrace).WithValues( "namespace", upstream.Namespace, "name", upstream.Name, "issuer", upstream.Spec.Issuer, diff --git a/internal/controller/supervisorconfig/oidcupstreamwatcher/oidc_upstream_watcher_test.go b/internal/controller/supervisorconfig/oidcupstreamwatcher/oidc_upstream_watcher_test.go index 62e308e2..bbaeb2d4 100644 --- a/internal/controller/supervisorconfig/oidcupstreamwatcher/oidc_upstream_watcher_test.go +++ b/internal/controller/supervisorconfig/oidcupstreamwatcher/oidc_upstream_watcher_test.go @@ -29,6 +29,7 @@ import ( "go.pinniped.dev/internal/certauthority" "go.pinniped.dev/internal/controllerlib" "go.pinniped.dev/internal/oidc/provider" + "go.pinniped.dev/internal/plog" "go.pinniped.dev/internal/testutil" "go.pinniped.dev/internal/testutil/oidctestutil" "go.pinniped.dev/internal/testutil/testlogger" @@ -78,7 +79,6 @@ func TestOIDCUpstreamWatcherControllerFilterSecret(t *testing.T) { pinnipedInformers := pinnipedinformers.NewSharedInformerFactory(fakePinnipedClient, 0) fakeKubeClient := fake.NewSimpleClientset() kubeInformers := informers.NewSharedInformerFactory(fakeKubeClient, 0) - testLog := testlogger.New(t) cache := provider.NewDynamicUpstreamIDPProvider() cache.SetOIDCIdentityProviders([]provider.UpstreamOIDCIdentityProviderI{ &upstreamoidc.ProviderConfig{Name: "initial-entry"}, @@ -91,7 +91,7 @@ func TestOIDCUpstreamWatcherControllerFilterSecret(t *testing.T) { nil, pinnipedInformers.IDP().V1alpha1().OIDCIdentityProviders(), secretInformer, - testLog.Logger, + plog.Logr(), // nolint: staticcheck // old test with no log assertions withInformer.WithInformer, ) @@ -1400,7 +1400,7 @@ oidc: issuer did not match the issuer returned by provider, expected "` + testIs pinnipedInformers := pinnipedinformers.NewSharedInformerFactory(fakePinnipedClient, 0) fakeKubeClient := fake.NewSimpleClientset(tt.inputSecrets...) kubeInformers := informers.NewSharedInformerFactory(fakeKubeClient, 0) - testLog := testlogger.NewLegacy(t) //nolint: staticcheck // old test with lots of log statements + testLog := testlogger.NewLegacy(t) // nolint: staticcheck // old test with lots of log statements cache := provider.NewDynamicUpstreamIDPProvider() cache.SetOIDCIdentityProviders([]provider.UpstreamOIDCIdentityProviderI{ &upstreamoidc.ProviderConfig{Name: "initial-entry"}, diff --git a/internal/controllerlib/controller.go b/internal/controllerlib/controller.go index 4d3940a7..9314cd47 100644 --- a/internal/controllerlib/controller.go +++ b/internal/controllerlib/controller.go @@ -15,7 +15,6 @@ import ( "k8s.io/client-go/tools/cache" "k8s.io/client-go/tools/events" "k8s.io/client-go/util/workqueue" - "k8s.io/klog/v2" "go.pinniped.dev/internal/plog" ) @@ -215,7 +214,7 @@ func (c *controller) handleKey(key Key, err error) { if errors.Is(err, ErrSyntheticRequeue) { // logging this helps detecting wedged controllers with missing pre-requirements - klog.V(4).InfoS("requested synthetic requeue", "controller", c.Name(), "key", key) + plog.Debug("requested synthetic requeue", "controller", c.Name(), "key", key) } else { utilruntime.HandleError(fmt.Errorf("%s: %v failed with: %w", c.Name(), key, err)) } diff --git a/internal/controllerlib/option.go b/internal/controllerlib/option.go index 38e89f58..9b3b4510 100644 --- a/internal/controllerlib/option.go +++ b/internal/controllerlib/option.go @@ -13,7 +13,8 @@ import ( "k8s.io/client-go/tools/cache" "k8s.io/client-go/tools/events" "k8s.io/client-go/util/workqueue" - "k8s.io/klog/v2" + + "go.pinniped.dev/internal/plog" ) type Option func(*controller) @@ -62,7 +63,7 @@ func WithInformer(getter InformerGetter, filter Filter, opt InformerOption) Opti AddFunc: func(obj interface{}) { object := metaOrDie(obj) if filter.Add(object) { - klog.V(4).InfoS("handling add", + plog.Debug("handling add", "controller", c.Name(), "namespace", object.GetNamespace(), "name", object.GetName(), @@ -76,7 +77,7 @@ func WithInformer(getter InformerGetter, filter Filter, opt InformerOption) Opti oldObject := metaOrDie(oldObj) newObject := metaOrDie(newObj) if filter.Update(oldObject, newObject) { - klog.V(4).InfoS("handling update", + plog.Debug("handling update", "controller", c.Name(), "namespace", newObject.GetNamespace(), "name", newObject.GetName(), @@ -101,7 +102,7 @@ func WithInformer(getter InformerGetter, filter Filter, opt InformerOption) Opti } } if filter.Delete(accessor) { - klog.V(4).InfoS("handling delete", + plog.Debug("handling delete", "controller", c.Name(), "namespace", accessor.GetNamespace(), "name", accessor.GetName(), diff --git a/internal/controllerlib/recorder.go b/internal/controllerlib/recorder.go index d25d00e3..b329c5b6 100644 --- a/internal/controllerlib/recorder.go +++ b/internal/controllerlib/recorder.go @@ -8,7 +8,8 @@ import ( "k8s.io/apimachinery/pkg/runtime" "k8s.io/client-go/tools/events" - "k8s.io/klog/v2" + + "go.pinniped.dev/internal/plog" ) var _ events.EventRecorder = klogRecorder{} @@ -16,7 +17,7 @@ var _ events.EventRecorder = klogRecorder{} type klogRecorder struct{} func (n klogRecorder) Eventf(regarding runtime.Object, related runtime.Object, eventtype, reason, action, note string, args ...interface{}) { - klog.V(4).InfoS("recording event", + plog.Debug("recording event", "regarding", regarding, "related", related, "eventtype", eventtype, diff --git a/internal/controllerlib/test/integration/examplecontroller/controller/creating.go b/internal/controllerlib/test/integration/examplecontroller/controller/creating.go index 17fd15e2..d24f4044 100644 --- a/internal/controllerlib/test/integration/examplecontroller/controller/creating.go +++ b/internal/controllerlib/test/integration/examplecontroller/controller/creating.go @@ -14,10 +14,10 @@ import ( corev1informers "k8s.io/client-go/informers/core/v1" corev1client "k8s.io/client-go/kubernetes/typed/core/v1" "k8s.io/client-go/tools/events" - "k8s.io/klog/v2" "go.pinniped.dev/internal/controllerlib" "go.pinniped.dev/internal/controllerlib/test/integration/examplecontroller/api" + "go.pinniped.dev/internal/plog" ) //nolint:funlen @@ -59,7 +59,7 @@ func NewExampleCreatingController( } generateSecret := func(service *corev1.Service) error { - klog.V(4).InfoS("generating new secret for service", "namespace", service.Namespace, "name", service.Name) + plog.Debug("generating new secret for service", "namespace", service.Namespace, "name", service.Name) secret := &corev1.Secret{ ObjectMeta: metav1.ObjectMeta{ @@ -97,7 +97,7 @@ func NewExampleCreatingController( return nil // drop from queue because we cannot safely update this secret } - klog.V(4).InfoS("updating data in existing secret", "namespace", secret.Namespace, "name", secret.Name) + plog.Debug("updating data in existing secret", "namespace", secret.Namespace, "name", secret.Name) // Actually update the secret in the regeneration case (the secret already exists but we want to update to new secretData). _, updateErr := secretClient.Secrets(secret.Namespace).Update(context.TODO(), secret, metav1.UpdateOptions{}) return updateErr @@ -169,7 +169,7 @@ func NewExampleCreatingController( utilruntime.HandleError(fmt.Errorf("unable to get service %s/%s: %w", secret.Namespace, serviceName, err)) return false } - klog.V(4).InfoS("recreating secret", "namespace", service.Namespace, "name", service.Name) + plog.Debug("recreating secret", "namespace", service.Namespace, "name", service.Name) return true }, }, controllerlib.InformerOption{}), diff --git a/internal/controllermanager/prepare_controllers.go b/internal/controllermanager/prepare_controllers.go index 21326ceb..eccbe2e6 100644 --- a/internal/controllermanager/prepare_controllers.go +++ b/internal/controllermanager/prepare_controllers.go @@ -11,7 +11,6 @@ import ( k8sinformers "k8s.io/client-go/informers" "k8s.io/client-go/kubernetes" - "k8s.io/klog/v2/klogr" "k8s.io/utils/clock" pinnipedclientset "go.pinniped.dev/generated/latest/client/concierge/clientset/versioned" @@ -34,6 +33,7 @@ import ( "go.pinniped.dev/internal/groupsuffix" "go.pinniped.dev/internal/kubeclient" "go.pinniped.dev/internal/leaderelection" + "go.pinniped.dev/internal/plog" ) const ( @@ -197,6 +197,7 @@ func PrepareControllers(c *Config) (controllerinit.RunnerBuilder, error) { controllerlib.WithInformer, c.ServingCertRenewBefore, apicerts.TLSCertificateChainSecretKey, + plog.New(), ), singletonWorker, ). @@ -222,7 +223,7 @@ func PrepareControllers(c *Config) (controllerinit.RunnerBuilder, error) { agentConfig, client, informers.installationNamespaceK8s.Core().V1().Pods(), - klogr.New(), + plog.Logr(), // nolint: staticcheck // old controller with lots of log statements ), singletonWorker, ). @@ -232,7 +233,7 @@ func PrepareControllers(c *Config) (controllerinit.RunnerBuilder, error) { webhookcachefiller.New( c.AuthenticatorCache, informers.pinniped.Authentication().V1alpha1().WebhookAuthenticators(), - klogr.New(), + plog.Logr(), // nolint: staticcheck // old controller with lots of log statements ), singletonWorker, ). @@ -240,7 +241,7 @@ func PrepareControllers(c *Config) (controllerinit.RunnerBuilder, error) { jwtcachefiller.New( c.AuthenticatorCache, informers.pinniped.Authentication().V1alpha1().JWTAuthenticators(), - klogr.New(), + plog.Logr(), // nolint: staticcheck // old controller with lots of log statements ), singletonWorker, ). @@ -249,7 +250,7 @@ func PrepareControllers(c *Config) (controllerinit.RunnerBuilder, error) { c.AuthenticatorCache, informers.pinniped.Authentication().V1alpha1().WebhookAuthenticators(), informers.pinniped.Authentication().V1alpha1().JWTAuthenticators(), - klogr.New(), + plog.Logr(), // nolint: staticcheck // old controller with lots of log statements ), singletonWorker, ). @@ -275,7 +276,7 @@ func PrepareControllers(c *Config) (controllerinit.RunnerBuilder, error) { impersonator.New, c.NamesConfig.ImpersonationSignerSecret, c.ImpersonationSigningCertProvider, - klogr.New(), + plog.Logr(), // nolint: staticcheck // old controller with lots of log statements ), singletonWorker, ). @@ -303,6 +304,7 @@ func PrepareControllers(c *Config) (controllerinit.RunnerBuilder, error) { controllerlib.WithInformer, 365*24*time.Hour-time.Hour, // 1 year minus 1 hour hard coded value (i.e. wait until the last moment to break the signer) apicerts.CACertificateSecretKey, + plog.New(), ), singletonWorker, ) diff --git a/internal/crypto/ptls/fips_strict.go b/internal/crypto/ptls/fips_strict.go index fa79f2c7..c132401e 100644 --- a/internal/crypto/ptls/fips_strict.go +++ b/internal/crypto/ptls/fips_strict.go @@ -20,7 +20,8 @@ import ( _ "crypto/tls/fipsonly" // restricts all TLS configuration to FIPS-approved settings. "k8s.io/apiserver/pkg/server/options" - "k8s.io/klog/v2" + + "go.pinniped.dev/internal/plog" ) // Always use TLS 1.2 for FIPs @@ -36,9 +37,7 @@ func init() { // this init runs before we have parsed our config to determine our log level // thus we must use a log statement that will always print instead of conditionally print - // for plog, that is only error and warning logs, neither of which seem appropriate here - // therefore, just use klog directly with no V level requirement - klog.InfoS("using boring crypto in fips only mode", "go version", runtime.Version()) + plog.Always("using boring crypto in fips only mode", "go version", runtime.Version()) } func Default(rootCAs *x509.CertPool) *tls.Config { diff --git a/internal/groupsuffix/groupsuffix.go b/internal/groupsuffix/groupsuffix.go index c05c3d7a..1dc3397c 100644 --- a/internal/groupsuffix/groupsuffix.go +++ b/internal/groupsuffix/groupsuffix.go @@ -16,7 +16,6 @@ import ( loginv1alpha1 "go.pinniped.dev/generated/latest/apis/concierge/login/v1alpha1" "go.pinniped.dev/internal/constable" "go.pinniped.dev/internal/kubeclient" - "go.pinniped.dev/internal/plog" ) const ( @@ -86,8 +85,8 @@ func New(apiGroupSuffix string) kubeclient.Middleware { // want our middleware to be opinionated so that it can be really good at a specific task // and give us specific feedback when it can't do that specific task return fmt.Errorf( - "cannot replace token credential request %q without authenticator API group", - plog.KObj(obj), + "cannot replace token credential request %s/%s without authenticator API group", + obj.GetNamespace(), obj.GetName(), ) } @@ -95,8 +94,8 @@ func New(apiGroupSuffix string) kubeclient.Middleware { if !ok { // see comment above about specificity of middleware return fmt.Errorf( - "cannot replace token credential request %q authenticator API group %q with group suffix %q", - plog.KObj(obj), + "cannot replace token credential request %s/%s authenticator API group %q with group suffix %q", + obj.GetNamespace(), obj.GetName(), *tokenCredentialRequest.Spec.Authenticator.APIGroup, apiGroupSuffix, ) @@ -176,7 +175,7 @@ func Unreplace(baseAPIGroup, apiGroupSuffix string) (string, bool) { // makes sure that the provided apiGroupSuffix is a valid DNS-1123 subdomain with at least one dot, // to match Kubernetes behavior. func Validate(apiGroupSuffix string) error { - var errs []error //nolint: prealloc + var errs []error // nolint: prealloc if len(strings.Split(apiGroupSuffix, ".")) < 2 { errs = append(errs, constable.Error("must contain '.'")) diff --git a/internal/groupsuffix/groupsuffix_test.go b/internal/groupsuffix/groupsuffix_test.go index d51119d4..21ff239f 100644 --- a/internal/groupsuffix/groupsuffix_test.go +++ b/internal/groupsuffix/groupsuffix_test.go @@ -435,7 +435,7 @@ func TestMiddlware(t *testing.T) { responseObj: tokenCredentialRequestWithNewGroup, // a token credential response does not contain a spec wantMutateRequests: 3, wantMutateResponses: 1, - wantMutateRequestErrors: []string{`cannot replace token credential request "/" authenticator API group "authentication.concierge.some.suffix.com" with group suffix "some.suffix.com"`}, + wantMutateRequestErrors: []string{`cannot replace token credential request / authenticator API group "authentication.concierge.some.suffix.com" with group suffix "some.suffix.com"`}, wantResponseObj: tokenCredentialRequestWithNewGroup, // the middleware will reset object GVK for us }, { @@ -475,7 +475,7 @@ func TestMiddlware(t *testing.T) { responseObj: tokenCredentialRequestWithNewGroup, // a token credential response does not contain a spec wantMutateRequests: 3, wantMutateResponses: 1, - wantMutateRequestErrors: []string{`cannot replace token credential request "/" without authenticator API group`}, + wantMutateRequestErrors: []string{`cannot replace token credential request / without authenticator API group`}, wantResponseObj: tokenCredentialRequestWithNewGroup, // the middleware will reset object GVK for us }, { diff --git a/internal/kubeclient/copied.go b/internal/kubeclient/copied.go index cd682937..ef40e939 100644 --- a/internal/kubeclient/copied.go +++ b/internal/kubeclient/copied.go @@ -39,9 +39,9 @@ func glogBody(prefix string, body []byte) { if bytes.IndexFunc(body, func(r rune) bool { return r < 0x0a }) != -1 { - plog.Debug(prefix, "body", hex.Dump(body)) + plog.All(prefix, "body", hex.Dump(body)) } else { - plog.Debug(prefix, "body", string(body)) + plog.All(prefix, "body", string(body)) } } } diff --git a/internal/localuserauthenticator/localuserauthenticator.go b/internal/localuserauthenticator/localuserauthenticator.go index 3cc2f8d2..6ef851df 100644 --- a/internal/localuserauthenticator/localuserauthenticator.go +++ b/internal/localuserauthenticator/localuserauthenticator.go @@ -22,6 +22,7 @@ import ( "os" "os/signal" "strings" + "syscall" "time" "golang.org/x/crypto/bcrypt" @@ -31,7 +32,6 @@ import ( kubeinformers "k8s.io/client-go/informers" corev1informers "k8s.io/client-go/informers/core/v1" "k8s.io/client-go/kubernetes" - "k8s.io/klog/v2" "go.pinniped.dev/internal/constable" "go.pinniped.dev/internal/controller/apicerts" @@ -339,10 +339,7 @@ func waitForSignal() os.Signal { return <-signalCh } -func run() error { - ctx, cancel := context.WithCancel(context.Background()) - defer cancel() - +func run(ctx context.Context) error { client, err := kubeclient.New() if err != nil { return fmt.Errorf("cannot create k8s client: %w", err) @@ -359,7 +356,7 @@ func run() error { startControllers(ctx, dynamicCertProvider, client.Kubernetes, kubeInformers) plog.Debug("controllers are ready") - //nolint: gosec // Intentionally binding to all network interfaces. + // nolint: gosec // Intentionally binding to all network interfaces. l, err := net.Listen("tcp", ":8443") if err != nil { return fmt.Errorf("cannot create listener: %w", err) @@ -378,13 +375,35 @@ func run() error { return nil } -func Main() { +func main() error { // return an error instead of plog.Fatal to allow defer statements to run + ctx := signalCtx() + // Hardcode the logging level to debug, since this is a test app and it is very helpful to have // verbose logs to debug test failures. - if err := plog.ValidateAndSetLogLevelGlobally(plog.LevelDebug); err != nil { - klog.Fatal(err) + if err := plog.ValidateAndSetLogLevelAndFormatGlobally(ctx, plog.LogSpec{Level: plog.LevelDebug}); err != nil { + plog.Fatal(err) } - if err := run(); err != nil { - klog.Fatal(err) + + return run(ctx) +} + +func Main() { + if err := main(); err != nil { + plog.Fatal(err) } } + +func signalCtx() context.Context { + signalCh := make(chan os.Signal, 1) + signal.Notify(signalCh, os.Interrupt, syscall.SIGTERM) + + ctx, cancel := context.WithCancel(context.Background()) + go func() { + defer cancel() + + s := <-signalCh + plog.Debug("saw signal", "signal", s) + }() + + return ctx +} diff --git a/internal/plog/config.go b/internal/plog/config.go new file mode 100644 index 00000000..dd5d1f61 --- /dev/null +++ b/internal/plog/config.go @@ -0,0 +1,107 @@ +// Copyright 2020-2022 the Pinniped contributors. All Rights Reserved. +// SPDX-License-Identifier: Apache-2.0 + +package plog + +import ( + "context" + "encoding/json" + "strconv" + "time" + + "go.uber.org/zap/zapcore" + "k8s.io/apimachinery/pkg/util/wait" + "k8s.io/component-base/logs" + + "go.pinniped.dev/internal/constable" +) + +type LogFormat string + +func (l *LogFormat) UnmarshalJSON(b []byte) error { + switch string(b) { + case `""`, `"json"`: + *l = FormatJSON + case `"text"`: + *l = FormatText + // there is no "cli" case because it is not a supported option via our config + default: + return errInvalidLogFormat + } + return nil +} + +const ( + FormatJSON LogFormat = "json" + FormatText LogFormat = "text" + FormatCLI LogFormat = "cli" // only used by the pinniped CLI and not the server components + + errInvalidLogLevel = constable.Error("invalid log level, valid choices are the empty string, info, debug, trace and all") + errInvalidLogFormat = constable.Error("invalid log format, valid choices are the empty string, json and text") +) + +var _ json.Unmarshaler = func() *LogFormat { + var f LogFormat + return &f +}() + +type LogSpec struct { + Level LogLevel `json:"level,omitempty"` + Format LogFormat `json:"format,omitempty"` +} + +func MaybeSetDeprecatedLogLevel(level *LogLevel, log *LogSpec) { + if level != nil { + Warning("logLevel is deprecated, set log.level instead") + log.Level = *level + } +} + +func ValidateAndSetLogLevelAndFormatGlobally(ctx context.Context, spec LogSpec) error { + klogLevel := klogLevelForPlogLevel(spec.Level) + if klogLevel < 0 { + return errInvalidLogLevel + } + + // set the global log levels used by our code and the kube code underneath us + if _, err := logs.GlogSetter(strconv.Itoa(int(klogLevel))); err != nil { + panic(err) // programmer error + } + globalLevel.SetLevel(zapcore.Level(-klogLevel)) // klog levels are inverted when zap handles them + + var encoding string + switch spec.Format { + case "", FormatJSON: + encoding = "json" + case FormatCLI: + encoding = "console" + case FormatText: + encoding = "text" + default: + return errInvalidLogFormat + } + + log, flush, err := newLogr(ctx, encoding, klogLevel) + if err != nil { + return err + } + + setGlobalLoggers(log, flush) + + // nolint: exhaustive // the switch above is exhaustive for format already + switch spec.Format { + case FormatCLI: + return nil // do not spawn go routines on the CLI to allow the CLI to call this more than once + case FormatText: + Warning("setting log.format to 'text' is deprecated - this option will be removed in a future release") + } + + // do spawn go routines on the server + go wait.UntilWithContext(ctx, func(_ context.Context) { flush() }, time.Minute) + go func() { + <-ctx.Done() + flush() // best effort flush before shutdown as this is not coordinated with a wait group + }() + + return nil +} diff --git a/internal/plog/config_test.go b/internal/plog/config_test.go new file mode 100644 index 00000000..2cdd9f57 --- /dev/null +++ b/internal/plog/config_test.go @@ -0,0 +1,359 @@ +// Copyright 2020-2021 the Pinniped contributors. All Rights Reserved. +// SPDX-License-Identifier: Apache-2.0 + +package plog + +import ( + "bufio" + "bytes" + "context" + "fmt" + "os" + "runtime" + "strconv" + "testing" + "time" + + "github.com/stretchr/testify/require" + "go.uber.org/zap" + "k8s.io/component-base/logs" + "k8s.io/klog/v2" + "k8s.io/klog/v2/textlogger" + clocktesting "k8s.io/utils/clock/testing" +) + +func TestFormat(t *testing.T) { + ctx, cancel := context.WithCancel(context.Background()) + t.Cleanup(cancel) + + var buf bytes.Buffer + + scanner := bufio.NewScanner(&buf) + + now, 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) + + ctx = TestZapOverrides(ctx, t, &buf, nil, zap.WithClock(ZapClock(fakeClock))) + + err = ValidateAndSetLogLevelAndFormatGlobally(ctx, LogSpec{Level: LevelDebug}) + require.NoError(t, err) + + wd, err := os.Getwd() + require.NoError(t, err) + + const startLogLine = 46 // make this match the current line number + + Info("hello", "happy", "day", "duration", time.Hour+time.Minute) + require.True(t, scanner.Scan()) + require.NoError(t, scanner.Err()) + require.JSONEq(t, fmt.Sprintf(` +{ + "level": "info", + "timestamp": "2022-11-21T23:37:26.953313Z", + "caller": "%s/config_test.go:%d$plog.TestFormat", + "message": "hello", + "happy": "day", + "duration": "1h1m0s" +}`, wd, startLogLine+2), scanner.Text()) + + Logr().WithName("burrito").Error(errInvalidLogLevel, "wee", "a", "b") + require.True(t, scanner.Scan()) + require.NoError(t, scanner.Err()) + require.JSONEq(t, fmt.Sprintf(` +{ + "level": "error", + "timestamp": "2022-11-21T23:37:26.953313Z", + "caller": "%s/config_test.go:%d$plog.TestFormat", + "message": "wee", + "a": "b", + "error": "invalid log level, valid choices are the empty string, info, debug, trace and all", + "logger": "burrito" +}`, wd, startLogLine+2+13), scanner.Text()) + + Logr().V(klogLevelWarning).Info("hey") // note that this fails to set the custom warning key because it is not via plog + require.True(t, scanner.Scan()) + require.NoError(t, scanner.Err()) + require.JSONEq(t, fmt.Sprintf(` +{ + "level": "info", + "timestamp": "2022-11-21T23:37:26.953313Z", + "caller": "%s/config_test.go:%d$plog.TestFormat", + "message": "hey" +}`, wd, startLogLine+2+13+14), scanner.Text()) + + Warning("bad stuff") // note that this sets the custom warning key because it is via plog + require.True(t, scanner.Scan()) + require.NoError(t, scanner.Err()) + require.JSONEq(t, fmt.Sprintf(` +{ + "level": "info", + "timestamp": "2022-11-21T23:37:26.953313Z", + "caller": "%s/config_test.go:%d$plog.TestFormat", + "message": "bad stuff", + "warning": true +}`, wd, startLogLine+2+13+14+11), scanner.Text()) + + func() { DebugErr("something happened", errInvalidLogFormat, "an", "item") }() + require.True(t, scanner.Scan()) + require.NoError(t, scanner.Err()) + require.JSONEq(t, fmt.Sprintf(` +{ + "level": "debug", + "timestamp": "2022-11-21T23:37:26.953313Z", + "caller": "%s/config_test.go:%d$plog.TestFormat.func1", + "message": "something happened", + "error": "invalid log format, valid choices are the empty string, json and text", + "an": "item" +}`, wd, startLogLine+2+13+14+11+12), scanner.Text()) + + Trace("should not be logged", "for", "sure") + require.Empty(t, buf.String()) + + 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)) + + err = ValidateAndSetLogLevelAndFormatGlobally(ctx, LogSpec{Level: LevelDebug}) + require.NoError(t, err) + + WithName("stacky").WithName("does").Info("has a stack trace!") + require.True(t, scanner.Scan()) + require.NoError(t, scanner.Err()) + require.JSONEq(t, fmt.Sprintf(` +{ + "level": "info", + "timestamp": "2022-11-21T23:37:26.953313Z", + "caller": "%s/config_test.go:%d$plog.TestFormat", + "message": "has a stack trace!", + "logger": "stacky.does", + "stacktrace": %s +}`, wd, startLogLine+2+13+14+11+12+24, + strconv.Quote( + fmt.Sprintf( + `go.pinniped.dev/internal/plog.TestFormat + %s/config_test.go:%d +testing.tRunner + %s/src/testing/testing.go:1439`, + wd, startLogLine+2+13+14+11+12+24, runtime.GOROOT(), + ), + ), + ), scanner.Text()) + + ctx = TestZapOverrides(ctx, t, &buf, nil, zap.WithClock(ZapClock(fakeClock))) + + err = ValidateAndSetLogLevelAndFormatGlobally(ctx, LogSpec{Level: LevelDebug, Format: FormatCLI}) + require.NoError(t, err) + + DebugErr("something happened", errInvalidLogFormat, "an", "item") + require.True(t, scanner.Scan()) + require.NoError(t, scanner.Err()) + require.Equal(t, fmt.Sprintf(nowStr+` plog/config_test.go:%d something happened {"error": "invalid log format, valid choices are the empty string, json and text", "an": "item"}`, + startLogLine+2+13+14+11+12+24+28), scanner.Text()) + + Logr().WithName("burrito").Error(errInvalidLogLevel, "wee", "a", "b", "slightly less than a year", 363*24*time.Hour, "slightly more than 2 years", 2*367*24*time.Hour) + require.True(t, scanner.Scan()) + require.NoError(t, scanner.Err()) + 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"}`, + startLogLine+2+13+14+11+12+24+28+6), 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}) + require.NoError(t, err) + pid := os.Getpid() + + // check for the deprecation warning + require.True(t, scanner.Scan()) + require.NoError(t, scanner.Err()) + require.Equal(t, fmt.Sprintf(`I1121 23:37:26.953313%8d config.go:96] "setting log.format to 'text' is deprecated - this option will be removed in a future release" warning=true`, + pid), scanner.Text()) + + Debug("what is happening", "does klog", "work?") + 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] "what is happening" does klog="work?"`, + pid, startLogLine+2+13+14+11+12+24+28+6+26), scanner.Text()) + + 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."`, + pid, startLogLine+2+13+14+11+12+24+28+6+26+6), 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`, + pid, startLogLine+2+13+14+11+12+24+28+6+26+6+6), scanner.Text()) + + l := WithValues("x", 33, "z", 22) + l.Debug("what to do") + l.Debug("and why") + 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] "what to do" x=33 z=22`, + pid, startLogLine+2+13+14+11+12+24+28+6+26+6+6+7), 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] "and why" x=33 z=22`, + pid, startLogLine+2+13+14+11+12+24+28+6+26+6+6+7+1), scanner.Text()) + + 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"`, + pid, startLogLine+2+13+14+11+12+24+28+6+26+6+6+7+1+10), scanner.Text()) + + // make sure child loggers do not share state + old1 := old.WithValues("i am", "old1") + old2 := old.WithName("old2") + old1.Warning("warn") + 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`, + pid, startLogLine+2+13+14+11+12+24+28+6+26+6+6+7+1+10+9), 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"`, + pid, startLogLine+2+13+14+11+12+24+28+6+26+6+6+7+1+10+9+1), scanner.Text()) + + Trace("should not be logged", "for", "sure") + require.Empty(t, buf.String()) + + Logr().V(klogLevelAll).Info("also should not be logged", "open", "close") + require.Empty(t, buf.String()) + + require.False(t, scanner.Scan()) + require.NoError(t, scanner.Err()) + require.Empty(t, scanner.Text()) + require.Empty(t, buf.String()) +} + +func TestValidateAndSetLogLevelGlobally(t *testing.T) { + originalLogLevel := getKlogLevel() + require.GreaterOrEqual(t, int(originalLogLevel), int(klog.Level(0)), "cannot get klog level") + + tests := []struct { + name string + level LogLevel + wantLevel klog.Level + wantEnabled []LogLevel + wantErr string + }{ + { + name: "unset", + wantLevel: 0, + wantEnabled: []LogLevel{LevelWarning}, + }, + { + name: "warning", + level: LevelWarning, + wantLevel: 0, + wantEnabled: []LogLevel{LevelWarning}, + }, + { + name: "info", + level: LevelInfo, + wantLevel: 2, + wantEnabled: []LogLevel{LevelWarning, LevelInfo}, + }, + { + name: "debug", + level: LevelDebug, + wantLevel: 4, + wantEnabled: []LogLevel{LevelWarning, LevelInfo, LevelDebug}, + }, + { + name: "trace", + level: LevelTrace, + wantLevel: 6, + wantEnabled: []LogLevel{LevelWarning, LevelInfo, LevelDebug, LevelTrace}, + }, + { + name: "all", + level: LevelAll, + wantLevel: 108, + wantEnabled: []LogLevel{LevelWarning, LevelInfo, LevelDebug, LevelTrace, LevelAll}, + }, + { + name: "invalid level", + level: "panda", + wantLevel: originalLogLevel, + wantErr: errInvalidLogLevel.Error(), + }, + } + for _, tt := range tests { + tt := tt // capture range variable + t.Run(tt.name, func(t *testing.T) { + defer func() { + undoGlobalLogLevelChanges(t, originalLogLevel) + }() + + ctx, cancel := context.WithCancel(context.Background()) + t.Cleanup(cancel) + err := ValidateAndSetLogLevelAndFormatGlobally(ctx, LogSpec{Level: tt.level}) + require.Equal(t, tt.wantErr, errString(err)) + require.Equal(t, tt.wantLevel, getKlogLevel()) + + if tt.wantEnabled != nil { + allLevels := []LogLevel{LevelWarning, LevelInfo, LevelDebug, LevelTrace, LevelAll} + for _, level := range allLevels { + if contains(tt.wantEnabled, level) { + require.Truef(t, Enabled(level), "wanted %q to be enabled", level) + } else { + require.False(t, Enabled(level), "did not want %q to be enabled", level) + } + } + } + }) + } + + require.Equal(t, originalLogLevel, getKlogLevel()) +} + +func contains(haystack []LogLevel, needle LogLevel) bool { + for _, hay := range haystack { + if hay == needle { + return true + } + } + return false +} + +func errString(err error) string { + if err == nil { + return "" + } + + return err.Error() +} + +func undoGlobalLogLevelChanges(t *testing.T, originalLogLevel klog.Level) { + t.Helper() + _, err := logs.GlogSetter(strconv.Itoa(int(originalLogLevel))) + require.NoError(t, err) +} + +func getKlogLevel() klog.Level { + // hack around klog not exposing a Get method + for i := klog.Level(0); i < 256; i++ { + if klog.V(i).Enabled() { + continue + } + return i - 1 + } + + return -1 +} diff --git a/internal/plog/global.go b/internal/plog/global.go new file mode 100644 index 00000000..dc4dfbcd --- /dev/null +++ b/internal/plog/global.go @@ -0,0 +1,77 @@ +// Copyright 2020-2022 the Pinniped contributors. All Rights Reserved. +// SPDX-License-Identifier: Apache-2.0 + +package plog + +import ( + "context" + "fmt" + "net/url" + "sync" + + "github.com/go-logr/logr" + "go.uber.org/zap" + "k8s.io/component-base/logs" + "k8s.io/klog/v2" +) + +// nolint: gochecknoglobals +var ( + // note that these globals have no locks on purpose - they are expected to be set at init and then again after config parsing. + globalLevel zap.AtomicLevel + globalLogger logr.Logger + globalFlush func() + + // used as a temporary storage for a buffer per call of newLogr. see the init function below for more details. + sinkMap sync.Map +) + +// nolint: gochecknoinits +func init() { + // make sure we always have a functional global logger + globalLevel = zap.NewAtomicLevelAt(0) // log at the 0 verbosity level to start with, i.e. the "always" logs + // use json encoding to start with + // the context here is just used for test injection and thus can be ignored + log, flush, err := newLogr(context.Background(), "json", 0) + if err != nil { + panic(err) // default logging config must always work + } + setGlobalLoggers(log, flush) + + // this is a little crazy but zap's builder code does not allow us to directly specify what + // writer we want to use as our log sink. to get around this limitation in tests, we use a + // global map to temporarily hold the writer (the key is a random string that is generated + // per invocation of newLogr). we register a fake "pinniped" scheme so that we can lookup + // the writer via pinniped:///. + if err := zap.RegisterSink("pinniped", func(u *url.URL) (zap.Sink, error) { + value, ok := sinkMap.Load(u.Path) + if !ok { + return nil, fmt.Errorf("key %q not in global sink", u.Path) + } + return value.(zap.Sink), nil + }); err != nil { + panic(err) // custom sink must always work + } +} + +// Deprecated: Use New instead. This is meant for old code only. +// New provides a more ergonomic API and correctly responds to global log config change. +func Logr() logr.Logger { + return globalLogger +} + +func Setup() func() { + logs.InitLogs() + return func() { + logs.FlushLogs() + globalFlush() + } +} + +// setGlobalLoggers sets the plog and klog global loggers. it is *not* go routine safe. +func setGlobalLoggers(log logr.Logger, flush func()) { + // a contextual logger does its own level based enablement checks, which is true for all of our loggers + klog.SetLoggerWithOptions(log, klog.ContextualLogger(true), klog.FlushLogger(flush)) + globalLogger = log + globalFlush = flush +} diff --git a/internal/plog/klog.go b/internal/plog/klog.go deleted file mode 100644 index cd62b6c6..00000000 --- a/internal/plog/klog.go +++ /dev/null @@ -1,32 +0,0 @@ -// Copyright 2020-2022 the Pinniped contributors. All Rights Reserved. -// SPDX-License-Identifier: Apache-2.0 - -package plog - -import ( - "fmt" - - "k8s.io/klog/v2" -) - -// KObj is (mostly) copied from klog - it is a standard way to represent a metav1.Object in logs. -func KObj(obj klog.KMetadata) string { - return fmt.Sprintf("%s/%s", obj.GetNamespace(), obj.GetName()) -} - -func klogLevelForPlogLevel(plogLevel LogLevel) klog.Level { - switch plogLevel { - case LevelWarning: - return klogLevelWarning // unset means minimal logs (Error and Warning) - case LevelInfo: - return klogLevelInfo - case LevelDebug: - return klogLevelDebug - case LevelTrace: - return klogLevelTrace - case LevelAll: - return klogLevelAll + 100 // make all really mean all - default: - return -1 - } -} diff --git a/internal/plog/level.go b/internal/plog/level.go index 0f8401d6..4daa7b93 100644 --- a/internal/plog/level.go +++ b/internal/plog/level.go @@ -4,18 +4,18 @@ package plog import ( - "strconv" - - "k8s.io/component-base/logs" + "go.uber.org/zap/zapcore" "k8s.io/klog/v2" - - "go.pinniped.dev/internal/constable" ) // LogLevel is an enum that controls verbosity of logs. // Valid values in order of increasing verbosity are leaving it unset, info, debug, trace and all. type LogLevel string +func (l LogLevel) Enabled(_ zapcore.Level) bool { + return Enabled(l) // this basically says "log if the global plog level is l or greater" +} + const ( // LevelWarning (i.e. leaving the log level unset) maps to klog log level 0. LevelWarning LogLevel = "" @@ -27,33 +27,40 @@ const ( LevelTrace LogLevel = "trace" // LevelAll maps to klog log level 100 (conceptually it is log level 8). LevelAll LogLevel = "all" - - errInvalidLogLevel = constable.Error("invalid log level, valid choices are the empty string, info, debug, trace and all") ) +var _ zapcore.LevelEnabler = LevelWarning + const ( klogLevelWarning = iota * 2 - klogLevelInfo - klogLevelDebug - klogLevelTrace + KlogLevelInfo + KlogLevelDebug + KlogLevelTrace klogLevelAll ) -func ValidateAndSetLogLevelGlobally(level LogLevel) error { - klogLevel := klogLevelForPlogLevel(level) - if klogLevel < 0 { - return errInvalidLogLevel - } - - if _, err := logs.GlogSetter(strconv.Itoa(int(klogLevel))); err != nil { - panic(err) // programmer error - } - - return nil -} - // Enabled returns whether the provided plog level is enabled, i.e., whether print statements at the // provided level will show up. func Enabled(level LogLevel) bool { - return klog.V(klogLevelForPlogLevel(level)).Enabled() + l := klogLevelForPlogLevel(level) + // check that both our global level and the klog global level agree that the plog level is enabled + // klog levels are inverted when zap handles them + return globalLevel.Enabled(zapcore.Level(-l)) && klog.V(l).Enabled() +} + +func klogLevelForPlogLevel(plogLevel LogLevel) klog.Level { + switch plogLevel { + case LevelWarning: + return klogLevelWarning // unset means minimal logs (Error and Warning) + case LevelInfo: + return KlogLevelInfo + case LevelDebug: + return KlogLevelDebug + case LevelTrace: + return KlogLevelTrace + case LevelAll: + return klogLevelAll + 100 // make all really mean all + default: + return -1 + } } diff --git a/internal/plog/level_test.go b/internal/plog/level_test.go deleted file mode 100644 index 9da066f4..00000000 --- a/internal/plog/level_test.go +++ /dev/null @@ -1,128 +0,0 @@ -// Copyright 2020-2021 the Pinniped contributors. All Rights Reserved. -// SPDX-License-Identifier: Apache-2.0 - -package plog - -import ( - "strconv" - "testing" - - "github.com/stretchr/testify/require" - "k8s.io/component-base/logs" - "k8s.io/klog/v2" -) - -func TestValidateAndSetLogLevelGlobally(t *testing.T) { - originalLogLevel := getKlogLevel() - require.GreaterOrEqual(t, int(originalLogLevel), int(klog.Level(0)), "cannot get klog level") - - tests := []struct { - name string - level LogLevel - wantLevel klog.Level - wantEnabled []LogLevel - wantErr string - }{ - { - name: "unset", - wantLevel: 0, - wantEnabled: []LogLevel{LevelWarning}, - }, - { - name: "warning", - level: LevelWarning, - wantLevel: 0, - wantEnabled: []LogLevel{LevelWarning}, - }, - { - name: "info", - level: LevelInfo, - wantLevel: 2, - wantEnabled: []LogLevel{LevelWarning, LevelInfo}, - }, - { - name: "debug", - level: LevelDebug, - wantLevel: 4, - wantEnabled: []LogLevel{LevelWarning, LevelInfo, LevelDebug}, - }, - { - name: "trace", - level: LevelTrace, - wantLevel: 6, - wantEnabled: []LogLevel{LevelWarning, LevelInfo, LevelDebug, LevelTrace}, - }, - { - name: "all", - level: LevelAll, - wantLevel: 108, - wantEnabled: []LogLevel{LevelWarning, LevelInfo, LevelDebug, LevelTrace, LevelAll}, - }, - { - name: "invalid level", - level: "panda", - wantLevel: originalLogLevel, - wantErr: errInvalidLogLevel.Error(), - }, - } - for _, tt := range tests { - tt := tt // capture range variable - t.Run(tt.name, func(t *testing.T) { - defer func() { - undoGlobalLogLevelChanges(t, originalLogLevel) - }() - - err := ValidateAndSetLogLevelGlobally(tt.level) - require.Equal(t, tt.wantErr, errString(err)) - require.Equal(t, tt.wantLevel, getKlogLevel()) - - if tt.wantEnabled != nil { - allLevels := []LogLevel{LevelWarning, LevelInfo, LevelDebug, LevelTrace, LevelAll} - for _, level := range allLevels { - if contains(tt.wantEnabled, level) { - require.Truef(t, Enabled(level), "wanted %q to be enabled", level) - } else { - require.False(t, Enabled(level), "did not want %q to be enabled", level) - } - } - } - }) - } - - require.Equal(t, originalLogLevel, getKlogLevel()) -} - -func contains(haystack []LogLevel, needle LogLevel) bool { - for _, hay := range haystack { - if hay == needle { - return true - } - } - return false -} - -func errString(err error) string { - if err == nil { - return "" - } - - return err.Error() -} - -func undoGlobalLogLevelChanges(t *testing.T, originalLogLevel klog.Level) { - t.Helper() - _, err := logs.GlogSetter(strconv.Itoa(int(originalLogLevel))) - require.NoError(t, err) -} - -func getKlogLevel() klog.Level { - // hack around klog not exposing a Get method - for i := klog.Level(0); i < 256; i++ { - if klog.V(i).Enabled() { - continue - } - return i - 1 - } - - return -1 -} diff --git a/internal/plog/plog.go b/internal/plog/plog.go index 5fbfb512..060e7036 100644 --- a/internal/plog/plog.go +++ b/internal/plog/plog.go @@ -1,7 +1,7 @@ // Copyright 2020-2021 the Pinniped contributors. All Rights Reserved. // SPDX-License-Identifier: Apache-2.0 -// Package plog implements a thin layer over klog to help enforce pinniped's logging convention. +// Package plog implements a thin layer over logr to help enforce pinniped's logging convention. // Logs are always structured as a constant message with key and value pairs of related metadata. // // The logging levels in order of increasing verbosity are: @@ -26,10 +26,18 @@ // act of desperation to determine why the system is broken. package plog -import "k8s.io/klog/v2" +import ( + "os" -const errorKey = "error" + "github.com/go-logr/logr" +) +const errorKey = "error" // this matches zapr's default for .Error calls (which is asserted via tests) + +// Logger implements the plog logging convention described above. The global functions in this package +// such as Info should be used when one does not intend to write tests assertions for specific log messages. +// If test assertions are desired, Logger should be passed in as an input. New should be used as the +// production implementation and TestLogger should be used to write test assertions. type Logger interface { Error(msg string, err error, keysAndValues ...interface{}) Warning(msg string, keysAndValues ...interface{}) @@ -41,100 +49,155 @@ type Logger interface { Trace(msg string, keysAndValues ...interface{}) TraceErr(msg string, err error, keysAndValues ...interface{}) All(msg string, keysAndValues ...interface{}) + Always(msg string, keysAndValues ...interface{}) + WithValues(keysAndValues ...interface{}) Logger + WithName(name string) Logger + + // does not include Fatal on purpose because that is not a method you should be using + + // for internal and test use only + withDepth(d int) Logger + withLogrMod(mod func(logr.Logger) logr.Logger) Logger } +// MinLogger is the overlap between Logger and logr.Logger. +type MinLogger interface { + Info(msg string, keysAndValues ...interface{}) +} + +var _ Logger = pLogger{} +var _, _, _ MinLogger = pLogger{}, logr.Logger{}, Logger(nil) + type pLogger struct { - prefix string - depth int + mods []func(logr.Logger) logr.Logger + depth int } -func New(prefix string) Logger { - return &pLogger{ - depth: 0, - prefix: prefix, +func New() Logger { + return pLogger{} +} + +func (p pLogger) Error(msg string, err error, keysAndValues ...interface{}) { + p.logr().WithCallDepth(p.depth+1).Error(err, msg, keysAndValues...) +} + +func (p pLogger) warningDepth(msg string, depth int, keysAndValues ...interface{}) { + if p.logr().V(klogLevelWarning).Enabled() { + // klog's structured logging has no concept of a warning (i.e. no WarningS function) + // Thus we use info at log level zero as a proxy + // klog's info logs have an I prefix and its warning logs have a W prefix + // Since we lose the W prefix by using InfoS, just add a key to make these easier to find + keysAndValues = append([]interface{}{"warning", true}, keysAndValues...) + p.logr().V(klogLevelWarning).WithCallDepth(depth+1).Info(msg, keysAndValues...) } } -func (p *pLogger) Error(msg string, err error, keysAndValues ...interface{}) { - klog.ErrorSDepth(p.depth+1, err, p.prefix+msg, keysAndValues...) -} - -func (p *pLogger) warningDepth(msg string, depth int, keysAndValues ...interface{}) { - // klog's structured logging has no concept of a warning (i.e. no WarningS function) - // Thus we use info at log level zero as a proxy - // klog's info logs have an I prefix and its warning logs have a W prefix - // Since we lose the W prefix by using InfoS, just add a key to make these easier to find - keysAndValues = append([]interface{}{"warning", "true"}, keysAndValues...) - if klog.V(klogLevelWarning).Enabled() { - klog.InfoSDepth(depth+1, p.prefix+msg, keysAndValues...) - } -} - -func (p *pLogger) Warning(msg string, keysAndValues ...interface{}) { +func (p pLogger) Warning(msg string, keysAndValues ...interface{}) { p.warningDepth(msg, p.depth+1, keysAndValues...) } -// Use WarningErr to issue a Warning message with an error object as part of the message. -func (p *pLogger) WarningErr(msg string, err error, keysAndValues ...interface{}) { +func (p pLogger) WarningErr(msg string, err error, keysAndValues ...interface{}) { p.warningDepth(msg, p.depth+1, append([]interface{}{errorKey, err}, keysAndValues...)...) } -func (p *pLogger) infoDepth(msg string, depth int, keysAndValues ...interface{}) { - if klog.V(klogLevelInfo).Enabled() { - klog.InfoSDepth(depth+1, p.prefix+msg, keysAndValues...) +func (p pLogger) infoDepth(msg string, depth int, keysAndValues ...interface{}) { + if p.logr().V(KlogLevelInfo).Enabled() { + p.logr().V(KlogLevelInfo).WithCallDepth(depth+1).Info(msg, keysAndValues...) } } -func (p *pLogger) Info(msg string, keysAndValues ...interface{}) { +func (p pLogger) Info(msg string, keysAndValues ...interface{}) { p.infoDepth(msg, p.depth+1, keysAndValues...) } -// Use InfoErr to log an expected error, e.g. validation failure of an http parameter. -func (p *pLogger) InfoErr(msg string, err error, keysAndValues ...interface{}) { +func (p pLogger) InfoErr(msg string, err error, keysAndValues ...interface{}) { p.infoDepth(msg, p.depth+1, append([]interface{}{errorKey, err}, keysAndValues...)...) } -func (p *pLogger) debugDepth(msg string, depth int, keysAndValues ...interface{}) { - if klog.V(klogLevelDebug).Enabled() { - klog.InfoSDepth(depth+1, p.prefix+msg, keysAndValues...) +func (p pLogger) debugDepth(msg string, depth int, keysAndValues ...interface{}) { + if p.logr().V(KlogLevelDebug).Enabled() { + p.logr().V(KlogLevelDebug).WithCallDepth(depth+1).Info(msg, keysAndValues...) } } -func (p *pLogger) Debug(msg string, keysAndValues ...interface{}) { +func (p pLogger) Debug(msg string, keysAndValues ...interface{}) { p.debugDepth(msg, p.depth+1, keysAndValues...) } -// Use DebugErr to issue a Debug message with an error object as part of the message. -func (p *pLogger) DebugErr(msg string, err error, keysAndValues ...interface{}) { +func (p pLogger) DebugErr(msg string, err error, keysAndValues ...interface{}) { p.debugDepth(msg, p.depth+1, append([]interface{}{errorKey, err}, keysAndValues...)...) } -func (p *pLogger) traceDepth(msg string, depth int, keysAndValues ...interface{}) { - if klog.V(klogLevelTrace).Enabled() { - klog.InfoSDepth(depth+1, p.prefix+msg, keysAndValues...) +func (p pLogger) traceDepth(msg string, depth int, keysAndValues ...interface{}) { + if p.logr().V(KlogLevelTrace).Enabled() { + p.logr().V(KlogLevelTrace).WithCallDepth(depth+1).Info(msg, keysAndValues...) } } -func (p *pLogger) Trace(msg string, keysAndValues ...interface{}) { +func (p pLogger) Trace(msg string, keysAndValues ...interface{}) { p.traceDepth(msg, p.depth+1, keysAndValues...) } -// Use TraceErr to issue a Trace message with an error object as part of the message. -func (p *pLogger) TraceErr(msg string, err error, keysAndValues ...interface{}) { +func (p pLogger) TraceErr(msg string, err error, keysAndValues ...interface{}) { p.traceDepth(msg, p.depth+1, append([]interface{}{errorKey, err}, keysAndValues...)...) } -func (p *pLogger) All(msg string, keysAndValues ...interface{}) { - if klog.V(klogLevelAll).Enabled() { - klog.InfoSDepth(p.depth+1, p.prefix+msg, keysAndValues...) +func (p pLogger) All(msg string, keysAndValues ...interface{}) { + if p.logr().V(klogLevelAll).Enabled() { + p.logr().V(klogLevelAll).WithCallDepth(p.depth+1).Info(msg, keysAndValues...) } } -var logger Logger = &pLogger{ //nolint:gochecknoglobals - depth: 1, +func (p pLogger) Always(msg string, keysAndValues ...interface{}) { + p.logr().WithCallDepth(p.depth+1).Info(msg, keysAndValues...) } -// Use Error to log an unexpected system error. +func (p pLogger) WithValues(keysAndValues ...interface{}) Logger { + if len(keysAndValues) == 0 { + return p + } + + return p.withLogrMod(func(l logr.Logger) logr.Logger { + return l.WithValues(keysAndValues...) + }) +} + +func (p pLogger) WithName(name string) Logger { + if len(name) == 0 { + return p + } + + return p.withLogrMod(func(l logr.Logger) logr.Logger { + return l.WithName(name) + }) +} + +func (p pLogger) withDepth(d int) Logger { + out := p + out.depth += d // out is a copy so this does not mutate p + return out +} + +func (p pLogger) withLogrMod(mod func(logr.Logger) logr.Logger) Logger { + out := p // make a copy and carefully avoid mutating the mods slice + mods := make([]func(logr.Logger) logr.Logger, 0, len(out.mods)+1) + mods = append(mods, out.mods...) + mods = append(mods, mod) + out.mods = mods + return out +} + +func (p pLogger) logr() logr.Logger { + l := Logr() // grab the current global logger and its current config + for _, mod := range p.mods { + mod := mod + l = mod(l) // and then update it with all modifications + } + return l // this logger is guaranteed to have the latest config and all modifications +} + +var logger = New().withDepth(1) //nolint:gochecknoglobals + func Error(msg string, err error, keysAndValues ...interface{}) { logger.Error(msg, err, keysAndValues...) } @@ -143,7 +206,6 @@ func Warning(msg string, keysAndValues ...interface{}) { logger.Warning(msg, keysAndValues...) } -// Use WarningErr to issue a Warning message with an error object as part of the message. func WarningErr(msg string, err error, keysAndValues ...interface{}) { logger.WarningErr(msg, err, keysAndValues...) } @@ -152,7 +214,6 @@ func Info(msg string, keysAndValues ...interface{}) { logger.Info(msg, keysAndValues...) } -// Use InfoErr to log an expected error, e.g. validation failure of an http parameter. func InfoErr(msg string, err error, keysAndValues ...interface{}) { logger.InfoErr(msg, err, keysAndValues...) } @@ -161,7 +222,6 @@ func Debug(msg string, keysAndValues ...interface{}) { logger.Debug(msg, keysAndValues...) } -// Use DebugErr to issue a Debug message with an error object as part of the message. func DebugErr(msg string, err error, keysAndValues ...interface{}) { logger.DebugErr(msg, err, keysAndValues...) } @@ -170,7 +230,6 @@ func Trace(msg string, keysAndValues ...interface{}) { logger.Trace(msg, keysAndValues...) } -// Use TraceErr to issue a Trace message with an error object as part of the message. func TraceErr(msg string, err error, keysAndValues ...interface{}) { logger.TraceErr(msg, err, keysAndValues...) } @@ -178,3 +237,23 @@ func TraceErr(msg string, err error, keysAndValues ...interface{}) { func All(msg string, keysAndValues ...interface{}) { logger.All(msg, keysAndValues...) } + +func Always(msg string, keysAndValues ...interface{}) { + logger.Always(msg, keysAndValues...) +} + +func WithValues(keysAndValues ...interface{}) Logger { + // this looks weird but it is the same as New().WithValues(keysAndValues...) because it returns a new logger rooted at the call site + return logger.withDepth(-1).WithValues(keysAndValues...) +} + +func WithName(name string) Logger { + // this looks weird but it is the same as New().WithName(name) because it returns a new logger rooted at the call site + return logger.withDepth(-1).WithName(name) +} + +func Fatal(err error, keysAndValues ...interface{}) { + logger.Error("unrecoverable error encountered", err, keysAndValues...) + globalFlush() + os.Exit(1) +} diff --git a/internal/plog/plog_test.go b/internal/plog/plog_test.go new file mode 100644 index 00000000..d66b8871 --- /dev/null +++ b/internal/plog/plog_test.go @@ -0,0 +1,366 @@ +// Copyright 2022 the Pinniped contributors. All Rights Reserved. +// SPDX-License-Identifier: Apache-2.0 + +package plog + +import ( + "bytes" + "fmt" + "strings" + "testing" + "time" + + "github.com/stretchr/testify/require" +) + +func TestPlog(t *testing.T) { + tests := []struct { + name string + run func(Logger) + want string + }{ + { + name: "basic", + run: testAllPlogMethods, + want: ` +{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"e","panda":2,"error":"some err"} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"w","warning":true,"panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"we","warning":true,"error":"some err","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"i","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"ie","error":"some err","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"d","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"de","error":"some err","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"t","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"te","error":"some err","panda":2} +{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"all","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"always","panda":2} +`, + }, + { + name: "with values", + run: func(l Logger) { + testAllPlogMethods(l.WithValues("hi", 42)) + }, + want: ` +{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"e","hi":42,"panda":2,"error":"some err"} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"w","hi":42,"warning":true,"panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"we","hi":42,"warning":true,"error":"some err","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"i","hi":42,"panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"ie","hi":42,"error":"some err","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"d","hi":42,"panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"de","hi":42,"error":"some err","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"t","hi":42,"panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"te","hi":42,"error":"some err","panda":2} +{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"all","hi":42,"panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"always","hi":42,"panda":2} +`, + }, + { + name: "with values conflict", // duplicate key is included twice ... + run: func(l Logger) { + testAllPlogMethods(l.WithValues("panda", false)) + }, + want: ` +{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"e","panda":false,"panda":2,"error":"some err"} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"w","panda":false,"warning":true,"panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"we","panda":false,"warning":true,"error":"some err","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"i","panda":false,"panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"ie","panda":false,"error":"some err","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"d","panda":false,"panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"de","panda":false,"error":"some err","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"t","panda":false,"panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"te","panda":false,"error":"some err","panda":2} +{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"all","panda":false,"panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"always","panda":false,"panda":2} +`, + }, + { + name: "with values nested", + run: func(l Logger) { + testAllPlogMethods(l.WithValues("hi", 42).WithValues("not", time.Hour)) + }, + want: ` +{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"e","hi":42,"not":"1h0m0s","panda":2,"error":"some err"} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"w","hi":42,"not":"1h0m0s","warning":true,"panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"we","hi":42,"not":"1h0m0s","warning":true,"error":"some err","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"i","hi":42,"not":"1h0m0s","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"ie","hi":42,"not":"1h0m0s","error":"some err","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"d","hi":42,"not":"1h0m0s","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"de","hi":42,"not":"1h0m0s","error":"some err","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"t","hi":42,"not":"1h0m0s","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"te","hi":42,"not":"1h0m0s","error":"some err","panda":2} +{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"all","hi":42,"not":"1h0m0s","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"always","hi":42,"not":"1h0m0s","panda":2} +`, + }, + { + name: "with name", + run: func(l Logger) { + testAllPlogMethods(l.WithName("yoyo")) + }, + want: ` +{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"e","panda":2,"error":"some err"} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"w","warning":true,"panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"we","warning":true,"error":"some err","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"i","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"ie","error":"some err","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"d","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"de","error":"some err","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"t","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"te","error":"some err","panda":2} +{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"all","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"always","panda":2} +`, + }, + { + name: "with name nested", + run: func(l Logger) { + testAllPlogMethods(l.WithName("yoyo").WithName("gold")) + }, + want: ` +{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"e","panda":2,"error":"some err"} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"w","warning":true,"panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"we","warning":true,"error":"some err","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"i","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"ie","error":"some err","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"d","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"de","error":"some err","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"t","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"te","error":"some err","panda":2} +{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"all","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"always","panda":2} +`, + }, + { + name: "depth 3", + run: func(l Logger) { + testAllPlogMethods(l.withDepth(3)) + }, + want: ` +{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"e","panda":2,"error":"some err"} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"w","warning":true,"panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"we","warning":true,"error":"some err","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"i","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"ie","error":"some err","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"d","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"de","error":"some err","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"t","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"te","error":"some err","panda":2} +{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"all","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"always","panda":2} +`, + }, + { + name: "depth 2", + run: func(l Logger) { + testAllPlogMethods(l.withDepth(2)) + }, + want: ` +{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func15","message":"e","panda":2,"error":"some err"} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func15","message":"w","warning":true,"panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func15","message":"we","warning":true,"error":"some err","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func15","message":"i","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func15","message":"ie","error":"some err","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func15","message":"d","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func15","message":"de","error":"some err","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func15","message":"t","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func15","message":"te","error":"some err","panda":2} +{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func15","message":"all","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func15","message":"always","panda":2} +`, + }, + { + name: "depth 1", + run: func(l Logger) { + testAllPlogMethods(l.withDepth(1)) + }, + want: ` +{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"e","panda":2,"error":"some err"} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"w","warning":true,"panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"we","warning":true,"error":"some err","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"i","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"ie","error":"some err","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"d","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"de","error":"some err","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"t","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"te","error":"some err","panda":2} +{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"all","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"always","panda":2} +`, + }, + { + name: "depth 0", + run: func(l Logger) { + testAllPlogMethods(l.withDepth(0)) + }, + want: ` +{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"e","panda":2,"error":"some err"} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"w","warning":true,"panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"we","warning":true,"error":"some err","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"i","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"ie","error":"some err","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"d","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"de","error":"some err","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"t","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"te","error":"some err","panda":2} +{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"all","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"always","panda":2} +`, + }, + { + name: "depth -1", + run: func(l Logger) { + testAllPlogMethods(l.withDepth(-1)) + }, + want: ` +{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Error","message":"e","panda":2,"error":"some err"} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Warning","message":"w","warning":true,"panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.WarningErr","message":"we","warning":true,"error":"some err","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Info","message":"i","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.InfoErr","message":"ie","error":"some err","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Debug","message":"d","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.DebugErr","message":"de","error":"some err","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Trace","message":"t","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.TraceErr","message":"te","error":"some err","panda":2} +{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.All","message":"all","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Always","message":"always","panda":2} +`, + }, + { + name: "depth -2", + run: func(l Logger) { + testAllPlogMethods(l.withDepth(-2)) + }, + want: ` +{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.2.3/logr.go:$logr.Logger.Error","message":"e","panda":2,"error":"some err"} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.warningDepth","message":"w","warning":true,"panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.warningDepth","message":"we","warning":true,"error":"some err","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.infoDepth","message":"i","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.infoDepth","message":"ie","error":"some err","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.debugDepth","message":"d","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.debugDepth","message":"de","error":"some err","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.traceDepth","message":"t","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.traceDepth","message":"te","error":"some err","panda":2} +{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.2.3/logr.go:$logr.Logger.Info","message":"all","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.2.3/logr.go:$logr.Logger.Info","message":"always","panda":2} +`, + }, + { + name: "depth -3", + run: func(l Logger) { + testAllPlogMethods(l.withDepth(-3)) + }, + want: ` +{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"zapr@v1.2.3/zapr.go:$zapr.(*zapLogger).Error","message":"e","panda":2,"error":"some err"} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.2.3/logr.go:$logr.Logger.Info","message":"w","warning":true,"panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.2.3/logr.go:$logr.Logger.Info","message":"we","warning":true,"error":"some err","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.2.3/logr.go:$logr.Logger.Info","message":"i","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.2.3/logr.go:$logr.Logger.Info","message":"ie","error":"some err","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.2.3/logr.go:$logr.Logger.Info","message":"d","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.2.3/logr.go:$logr.Logger.Info","message":"de","error":"some err","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.2.3/logr.go:$logr.Logger.Info","message":"t","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.2.3/logr.go:$logr.Logger.Info","message":"te","error":"some err","panda":2} +{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"zapr@v1.2.3/zapr.go:$zapr.(*zapLogger).Info","message":"all","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"zapr@v1.2.3/zapr.go:$zapr.(*zapLogger).Info","message":"always","panda":2} +`, + }, + { + name: "closure", + run: func(l Logger) { + func() { + func() { + testErr := fmt.Errorf("some err") + + l.Error("e", testErr, "panda", 2) + l.Warning("w", "panda", 2) + l.WarningErr("we", testErr, "panda", 2) + l.Info("i", "panda", 2) + l.InfoErr("ie", testErr, "panda", 2) + l.Debug("d", "panda", 2) + l.DebugErr("de", testErr, "panda", 2) + l.Trace("t", "panda", 2) + l.TraceErr("te", testErr, "panda", 2) + l.All("all", "panda", 2) + l.Always("always", "panda", 2) + }() + }() + }, + want: ` +{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func13.1.1","message":"e","panda":2,"error":"some err"} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func13.1.1","message":"w","warning":true,"panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func13.1.1","message":"we","warning":true,"error":"some err","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func13.1.1","message":"i","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func13.1.1","message":"ie","error":"some err","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func13.1.1","message":"d","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func13.1.1","message":"de","error":"some err","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func13.1.1","message":"t","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func13.1.1","message":"te","error":"some err","panda":2} +{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func13.1.1","message":"all","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func13.1.1","message":"always","panda":2} +`, + }, + { + name: "closure depth -1", + run: func(l Logger) { + func() { + func() { + testErr := fmt.Errorf("some err") + + l = l.withDepth(-1) + l.Error("e", testErr, "panda", 2) + l.Warning("w", "panda", 2) + l.WarningErr("we", testErr, "panda", 2) + l.Info("i", "panda", 2) + l.InfoErr("ie", testErr, "panda", 2) + l.Debug("d", "panda", 2) + l.DebugErr("de", testErr, "panda", 2) + l.Trace("t", "panda", 2) + l.TraceErr("te", testErr, "panda", 2) + l.All("all", "panda", 2) + l.Always("always", "panda", 2) + }() + }() + }, + want: ` +{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Error","message":"e","panda":2,"error":"some err"} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Warning","message":"w","warning":true,"panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.WarningErr","message":"we","warning":true,"error":"some err","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Info","message":"i","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.InfoErr","message":"ie","error":"some err","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Debug","message":"d","panda":2} +{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.DebugErr","message":"de","error":"some err","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Trace","message":"t","panda":2} +{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.TraceErr","message":"te","error":"some err","panda":2} +{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.All","message":"all","panda":2} +{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Always","message":"always","panda":2} +`, + }, + } + for _, tt := range tests { + tt := tt + t.Run(tt.name, func(t *testing.T) { + t.Parallel() + + var log bytes.Buffer + tt.run(TestLogger(t, &log)) + + require.Equal(t, strings.TrimSpace(tt.want), strings.TrimSpace(log.String())) + }) + } +} + +func testAllPlogMethods(l Logger) { + testErr := fmt.Errorf("some err") + + l.Error("e", testErr, "panda", 2) + l.Warning("w", "panda", 2) + l.WarningErr("we", testErr, "panda", 2) + l.Info("i", "panda", 2) + l.InfoErr("ie", testErr, "panda", 2) + l.Debug("d", "panda", 2) + l.DebugErr("de", testErr, "panda", 2) + l.Trace("t", "panda", 2) + l.TraceErr("te", testErr, "panda", 2) + l.All("all", "panda", 2) + l.Always("always", "panda", 2) +} diff --git a/internal/plog/testing.go b/internal/plog/testing.go new file mode 100644 index 00000000..f5c1fea4 --- /dev/null +++ b/internal/plog/testing.go @@ -0,0 +1,120 @@ +// Copyright 2020-2022 the Pinniped contributors. All Rights Reserved. +// SPDX-License-Identifier: Apache-2.0 + +package plog + +import ( + "context" + "io" + "math" + "strings" + "testing" + "time" + + "github.com/go-logr/logr" + "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + "k8s.io/utils/clock" + clocktesting "k8s.io/utils/clock/testing" +) + +// contextKey type is unexported to prevent collisions. +type contextKey int + +const zapOverridesKey contextKey = iota + +func TestZapOverrides(ctx context.Context, t *testing.T, w io.Writer, f func(*zap.Config), opts ...zap.Option) context.Context { + t.Helper() // discourage use outside of tests + + overrides := &testOverrides{ + t: t, + w: w, + f: f, + opts: opts, + } + return context.WithValue(ctx, zapOverridesKey, overrides) +} + +func TestLogger(t *testing.T, w io.Writer) Logger { + t.Helper() + + return New().withLogrMod(func(l logr.Logger) logr.Logger { + return l.WithSink(TestZapr(t, w).GetSink()) + }) +} + +func TestZapr(t *testing.T, w io.Writer) logr.Logger { + t.Helper() + + now, err := time.Parse(time.RFC3339Nano, "2099-08-08T13:57:36.123456789Z") + require.NoError(t, err) + + ctx, cancel := context.WithCancel(context.Background()) + t.Cleanup(cancel) + + ctx = TestZapOverrides(ctx, t, w, + func(config *zap.Config) { + config.Level = zap.NewAtomicLevelAt(math.MinInt8) // log everything during tests + + // make test assertions less painful to write while keeping them as close to the real thing as possible + config.EncoderConfig.EncodeCaller = func(caller zapcore.EntryCaller, enc zapcore.PrimitiveArrayEncoder) { + trimmed := caller.TrimmedPath() + if idx := strings.LastIndexByte(trimmed, ':'); idx != -1 { + trimmed = trimmed[:idx+1] + "" + } + 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 + ) + + // there is no buffering so we can ignore flush + zl, _, err := newLogr(ctx, "json", 0) + require.NoError(t, err) + + return zl +} + +var _ zapcore.Clock = &clockAdapter{} + +type clockAdapter struct { + clock clock.Clock +} + +func (c *clockAdapter) Now() time.Time { + return c.clock.Now() +} + +func (c *clockAdapter) NewTicker(duration time.Duration) *time.Ticker { + return &time.Ticker{C: c.clock.Tick(duration)} +} + +func ZapClock(c clock.Clock) zapcore.Clock { + return &clockAdapter{clock: c} +} + +var _ zap.Sink = nopCloserSink{} + +type nopCloserSink struct{ zapcore.WriteSyncer } + +func (nopCloserSink) Close() error { return nil } + +// newSink returns a wrapper around the input writer that is safe for concurrent use. +func newSink(w io.Writer) zap.Sink { + return nopCloserSink{WriteSyncer: zapcore.Lock(zapcore.AddSync(w))} +} + +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 new file mode 100644 index 00000000..2b9976ef --- /dev/null +++ b/internal/plog/zap.go @@ -0,0 +1,187 @@ +// Copyright 2020-2022 the Pinniped contributors. All Rights Reserved. +// SPDX-License-Identifier: Apache-2.0 + +package plog + +import ( + "context" + "encoding/base64" + "fmt" + "io" + "os" + "strings" + "time" + + "github.com/go-logr/logr" + "github.com/go-logr/zapr" + "github.com/stretchr/testify/require" + "go.uber.org/zap" + "go.uber.org/zap/zapcore" + metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" + "k8s.io/apimachinery/pkg/util/duration" + "k8s.io/apimachinery/pkg/util/rand" + "k8s.io/klog/v2" + "k8s.io/klog/v2/textlogger" +) + +func newLogr(ctx context.Context, encoding string, klogLevel klog.Level) (logr.Logger, func(), error) { + 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 { + if overrides.w != nil { + w = newSink(overrides.w) // make sure the value is safe for concurrent use + flush = func() {} + } + } + + return textlogger.NewLogger(textlogger.NewConfig(textlogger.Verbosity(int(klogLevel)), textlogger.Output(w))), flush, nil + } + + path := "stderr" // this is how zap refers to os.Stderr + f := func(config *zap.Config) { + if encoding == "console" { + config.EncoderConfig.LevelKey = zapcore.OmitKey + config.EncoderConfig.EncodeCaller = zapcore.ShortCallerEncoder + config.EncoderConfig.EncodeTime = humanTimeEncoder + config.EncoderConfig.EncodeDuration = humanDurationEncoder + } + } + var opts []zap.Option + + // allow tests to override zap config + if overrides, ok := ctx.Value(zapOverridesKey).(*testOverrides); ok { + 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))) + + // tell zap to use our custom sink registry to find the writer + path = "pinniped://" + testKey + + // the registry may be called multiple times so make sure the value is safe for concurrent use + sink := newSink(overrides.w) + + // store the test's buffer where we can find it globally + actual, loaded := sinkMap.LoadOrStore(testKey, sink) + require.False(overrides.t, loaded) + require.Equal(overrides.t, sink, actual) + + defer func() { + // delete buffer from the global map to prevent a memory leak + value, loaded := sinkMap.LoadAndDelete(testKey) + require.True(overrides.t, loaded) + require.Equal(overrides.t, sink, value) + }() + } + if overrides.f != nil { + f = overrides.f + } + if overrides.opts != nil { + opts = overrides.opts + } + } + + // when using the trace or all log levels, an error log will contain the full stack. + // this is too noisy for regular use because things like leader election conflicts + // result in transient errors and we do not want all of that noise in the logs. + // this check is performed dynamically on the global log level. + return newZapr(globalLevel, LevelTrace, encoding, path, f, opts...) +} + +func newZapr(level zap.AtomicLevel, addStack zapcore.LevelEnabler, encoding, path string, f func(config *zap.Config), opts ...zap.Option) (logr.Logger, func(), error) { + opts = append([]zap.Option{zap.AddStacktrace(addStack)}, opts...) + + config := zap.Config{ + Level: level, + Development: false, + DisableCaller: false, + DisableStacktrace: true, // handled via the AddStacktrace call above + Sampling: nil, // keep all logs for now + Encoding: encoding, + EncoderConfig: zapcore.EncoderConfig{ + MessageKey: "message", + LevelKey: "level", + TimeKey: "timestamp", + NameKey: "logger", + CallerKey: "caller", + FunctionKey: zapcore.OmitKey, // included in caller + StacktraceKey: "stacktrace", + SkipLineEnding: false, + LineEnding: zapcore.DefaultLineEnding, + EncodeLevel: levelEncoder, + // human-readable and machine parsable with microsecond precision (same as klog, kube audit event, etc) + EncodeTime: zapcore.TimeEncoderOfLayout(metav1.RFC3339Micro), + EncodeDuration: zapcore.StringDurationEncoder, + EncodeCaller: callerEncoder, + EncodeName: nil, + NewReflectedEncoder: nil, + ConsoleSeparator: " ", + }, + OutputPaths: []string{path}, + ErrorOutputPaths: []string{path}, + InitialFields: nil, + } + + f(&config) + + log, err := config.Build(opts...) + if err != nil { + return logr.Logger{}, nil, fmt.Errorf("failed to build zap logger: %w", err) + } + + return zapr.NewLogger(log), func() { _ = log.Sync() }, nil +} + +func levelEncoder(l zapcore.Level, enc zapcore.PrimitiveArrayEncoder) { + plogLevel := zapLevelToPlogLevel(l) + + if len(plogLevel) == 0 { + return // this tells zap that it should handle encoding the level itself because we do not know the mapping + } + + enc.AppendString(string(plogLevel)) +} + +func zapLevelToPlogLevel(l zapcore.Level) LogLevel { + if l > 0 { + // best effort mapping, the zap levels do not really translate to klog + // but this is correct for "error" level which is all we need for logr + return LogLevel(l.String()) + } + + // klog levels are inverted when zap handles them + switch { + case -l >= klogLevelAll: + return LevelAll + case -l >= KlogLevelTrace: + return LevelTrace + case -l >= KlogLevelDebug: + return LevelDebug + case -l >= KlogLevelInfo: + return LevelInfo + default: + return "" // warning is handled via a custom key since klog level 0 is ambiguous + } +} + +func callerEncoder(caller zapcore.EntryCaller, enc zapcore.PrimitiveArrayEncoder) { + enc.AppendString(caller.String() + funcEncoder(caller)) +} + +func funcEncoder(caller zapcore.EntryCaller) string { + funcName := caller.Function + if idx := strings.LastIndexByte(funcName, '/'); idx != -1 { + funcName = funcName[idx+1:] // keep everything after the last / + } + return "$" + funcName +} + +func humanDurationEncoder(d time.Duration, enc zapcore.PrimitiveArrayEncoder) { + enc.AppendString(duration.HumanDuration(d)) +} + +func humanTimeEncoder(t time.Time, enc zapcore.PrimitiveArrayEncoder) { + enc.AppendString(t.Local().Format(time.RFC1123)) +} diff --git a/internal/registry/credentialrequest/rest_test.go b/internal/registry/credentialrequest/rest_test.go index f5b6f8cd..e7752e50 100644 --- a/internal/registry/credentialrequest/rest_test.go +++ b/internal/registry/credentialrequest/rest_test.go @@ -71,8 +71,8 @@ func TestCreate(t *testing.T) { it.Before(func() { r = require.New(t) ctrl = gomock.NewController(t) - logger = testutil.NewTranscriptLogger(t) - klog.SetLogger(logr.New(logger)) // this is unfortunately a global logger, so can't run these tests in parallel :( + logger = testutil.NewTranscriptLogger(t) // nolint: staticcheck // old test with lots of log statements + klog.SetLogger(logr.New(logger)) // this is unfortunately a global logger, so can't run these tests in parallel :( }) it.After(func() { diff --git a/internal/supervisor/server/server.go b/internal/supervisor/server/server.go index 501cbd3f..772f0f5a 100644 --- a/internal/supervisor/server/server.go +++ b/internal/supervisor/server/server.go @@ -22,14 +22,12 @@ import ( "github.com/joshlf/go-acl" appsv1 "k8s.io/api/apps/v1" corev1 "k8s.io/api/core/v1" + apimachineryversion "k8s.io/apimachinery/pkg/version" genericapifilters "k8s.io/apiserver/pkg/endpoints/filters" kubeinformers "k8s.io/client-go/informers" "k8s.io/client-go/kubernetes" "k8s.io/client-go/pkg/version" "k8s.io/client-go/rest" - "k8s.io/component-base/logs" - "k8s.io/klog/v2" - "k8s.io/klog/v2/klogr" "k8s.io/utils/clock" configv1alpha1 "go.pinniped.dev/generated/latest/apis/supervisor/config/v1alpha1" @@ -272,7 +270,7 @@ func prepareControllers( pinnipedClient, pinnipedInformers.IDP().V1alpha1().OIDCIdentityProviders(), secretInformer, - klogr.New(), + plog.Logr(), // nolint: staticcheck // old controller with lots of log statements controllerlib.WithInformer, ), singletonWorker). @@ -315,7 +313,7 @@ func startControllers(ctx context.Context, shutdown *sync.WaitGroup, buildContro } //nolint:funlen -func runSupervisor(podInfo *downward.PodInfo, cfg *supervisor.Config) error { +func runSupervisor(ctx context.Context, podInfo *downward.PodInfo, cfg *supervisor.Config) error { serverInstallationNamespace := podInfo.Namespace dref, supervisorDeployment, supervisorPod, err := deploymentref.New(podInfo) @@ -389,7 +387,6 @@ func runSupervisor(podInfo *downward.PodInfo, cfg *supervisor.Config) error { leaderElector, ) - ctx := signalCtx() shutdown := &sync.WaitGroup{} if err := startControllers(ctx, shutdown, buildControllersFunc); err != nil { @@ -504,12 +501,14 @@ func maybeSetupUnixPerms(endpoint *supervisor.Endpoint, pod *corev1.Pod) func() } } -func main() error { // return an error instead of klog.Fatal to allow defer statements to run - logs.InitLogs() - defer logs.FlushLogs() +func main() error { // return an error instead of plog.Fatal to allow defer statements to run + defer plog.Setup()() - klog.Infof("Running %s at %#v", rest.DefaultKubernetesUserAgent(), version.Get()) - klog.Infof("Command-line arguments were: %s %s %s", os.Args[0], os.Args[1], os.Args[2]) + plog.Always("Running supervisor", + "user-agent", rest.DefaultKubernetesUserAgent(), + "version", versionInfo(version.Get()), + "arguments", os.Args, + ) // Discover in which namespace we are installed. podInfo, err := downward.Load(os.Args[1]) @@ -517,17 +516,21 @@ func main() error { // return an error instead of klog.Fatal to allow defer stat return fmt.Errorf("could not read pod metadata: %w", err) } + ctx := signalCtx() + // Read the server config file. - cfg, err := supervisor.FromPath(os.Args[2]) + cfg, err := supervisor.FromPath(ctx, os.Args[2]) if err != nil { return fmt.Errorf("could not load config: %w", err) } - return runSupervisor(podInfo, cfg) + return runSupervisor(ctx, podInfo, cfg) } func Main() { if err := main(); err != nil { - klog.Fatal(err) + plog.Fatal(err) } } + +type versionInfo apimachineryversion.Info // hide .String() method from plog diff --git a/internal/testutil/testlogger/testlogger.go b/internal/testutil/testlogger/testlogger.go index 907d3722..17d31df5 100644 --- a/internal/testutil/testlogger/testlogger.go +++ b/internal/testutil/testlogger/testlogger.go @@ -24,14 +24,14 @@ type Logger struct { buffer syncBuffer } -// New returns a new test Logger. Use this for all new tests. +// Deprecated: Use plog.TestLogger or plog.TestZapr instead. This is meant for old tests only. func New(t *testing.T) *Logger { res := Logger{t: t} res.Logger = stdr.New(log.New(&res.buffer, "", 0)) return &res } -// Deprecated: NewLegacy returns a new test Logger. Use this for old tests if necessary. +// Deprecated: Use plog.TestLogger or plog.TestZapr instead. This is meant for old tests only. func NewLegacy(t *testing.T) *Logger { res := New(t) res.Logger = newStdLogger(log.New(&res.buffer, "", 0)) diff --git a/internal/testutil/transcript_logger.go b/internal/testutil/transcript_logger.go index add67486..f11da06a 100644 --- a/internal/testutil/transcript_logger.go +++ b/internal/testutil/transcript_logger.go @@ -24,6 +24,7 @@ type TranscriptLogMessage struct { Message string } +// Deprecated: Use plog.TestLogger or plog.TestZapr instead. This is meant for old tests only. func NewTranscriptLogger(t *testing.T) *TranscriptLogger { return &TranscriptLogger{t: t} } diff --git a/internal/upstreamoidc/upstreamoidc.go b/internal/upstreamoidc/upstreamoidc.go index 6c71b83a..cb480f8b 100644 --- a/internal/upstreamoidc/upstreamoidc.go +++ b/internal/upstreamoidc/upstreamoidc.go @@ -411,13 +411,13 @@ func (p *ProviderConfig) maybeFetchUserInfo(ctx context.Context, tok *oauth2.Tok func maybeLogClaims(msg, name string, claims map[string]interface{}) { if plog.Enabled(plog.LevelAll) { // log keys and values at all level data, _ := json.Marshal(claims) // nothing we can do if it fails, but it really never should - plog.Info(msg, "providerName", name, "claims", string(data)) + plog.All(msg, "providerName", name, "claims", string(data)) return } if plog.Enabled(plog.LevelDebug) { // log keys at debug level keys := sets.StringKeySet(claims).List() // note: this is only safe because the compiler asserts that claims is a map[string] - plog.Info(msg, "providerName", name, "keys", keys) + plog.Debug(msg, "providerName", name, "keys", keys) return } } diff --git a/pkg/oidcclient/login.go b/pkg/oidcclient/login.go index 39f375d3..3ff1b9a4 100644 --- a/pkg/oidcclient/login.go +++ b/pkg/oidcclient/login.go @@ -33,6 +33,7 @@ import ( "go.pinniped.dev/internal/httputil/securityheader" "go.pinniped.dev/internal/net/phttp" "go.pinniped.dev/internal/oidc/provider" + "go.pinniped.dev/internal/plog" "go.pinniped.dev/internal/upstreamoidc" "go.pinniped.dev/pkg/oidcclient/nonce" "go.pinniped.dev/pkg/oidcclient/oidctypes" @@ -63,8 +64,6 @@ const ( defaultPasswordEnvVarName = "PINNIPED_PASSWORD" //nolint:gosec // this is not a credential httpLocationHeaderName = "Location" - - debugLogLevel = 4 ) // stdin returns the file descriptor for stdin as an int. @@ -356,7 +355,7 @@ func (h *handlerState) baseLogin() (*oidctypes.Token, error) { // If the ID token is still valid for a bit, return it immediately and skip the rest of the flow. cached := h.cache.GetToken(cacheKey) if cached != nil && cached.IDToken != nil && time.Until(cached.IDToken.Expiry.Time) > minIDTokenValidity { - h.logger.V(debugLogLevel).Info("Pinniped: Found unexpired cached token.") + h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Found unexpired cached token.") return cached, nil } @@ -520,7 +519,7 @@ func (h *handlerState) getUsernameAndPassword() (string, string, error) { return "", "", fmt.Errorf("error prompting for username: %w", err) } } else { - h.logger.V(debugLogLevel).Info("Pinniped: Read username from environment variable", "name", defaultUsernameEnvVarName) + h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Read username from environment variable", "name", defaultUsernameEnvVarName) } password := h.getEnv(defaultPasswordEnvVarName) @@ -530,7 +529,7 @@ func (h *handlerState) getUsernameAndPassword() (string, string, error) { return "", "", fmt.Errorf("error prompting for password: %w", err) } } else { - h.logger.V(debugLogLevel).Info("Pinniped: Read password from environment variable", "name", defaultPasswordEnvVarName) + h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Read password from environment variable", "name", defaultPasswordEnvVarName) } return username, password, nil @@ -542,7 +541,7 @@ func (h *handlerState) webBrowserBasedAuth(authorizeOptions *[]oauth2.AuthCodeOp // Attempt to open a local TCP listener, logging but otherwise ignoring any error. listener, err := h.listen("tcp", h.listenAddr) if err != nil { - h.logger.V(debugLogLevel).Error(err, "could not open callback listener") + h.logger.V(plog.KlogLevelDebug).Error(err, "could not open callback listener") } // If the listener failed to start and stdin is not a TTY, then we have no hope of succeeding, @@ -578,7 +577,7 @@ func (h *handlerState) webBrowserBasedAuth(authorizeOptions *[]oauth2.AuthCodeOp // Open the authorize URL in the users browser, logging but otherwise ignoring any error. if err := h.openURL(authorizeURL); err != nil { - h.logger.V(debugLogLevel).Error(err, "could not open browser") + h.logger.V(plog.KlogLevelDebug).Error(err, "could not open browser") } // Prompt the user to visit the authorize URL, and to paste a manually-copied auth code (if possible). @@ -709,7 +708,7 @@ func (h *handlerState) initOIDCDiscovery() error { return err } - h.logger.V(debugLogLevel).Info("Pinniped: Performing OIDC discovery", "issuer", h.issuer) + h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Performing OIDC discovery", "issuer", h.issuer) var err error h.provider, err = oidc.NewProvider(h.ctx, h.issuer) if err != nil { @@ -767,7 +766,7 @@ func stringSliceContains(slice []string, s string) bool { } func (h *handlerState) tokenExchangeRFC8693(baseToken *oidctypes.Token) (*oidctypes.Token, error) { - h.logger.V(debugLogLevel).Info("Pinniped: Performing RFC8693 token exchange", "requestedAudience", h.requestedAudience) + h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Performing RFC8693 token exchange", "requestedAudience", h.requestedAudience) // Perform OIDC discovery. This may have already been performed if there was not a cached base token. if err := h.initOIDCDiscovery(); err != nil { return nil, err @@ -838,13 +837,13 @@ func (h *handlerState) tokenExchangeRFC8693(baseToken *oidctypes.Token) (*oidcty } func (h *handlerState) handleRefresh(ctx context.Context, refreshToken *oidctypes.RefreshToken) (*oidctypes.Token, error) { - h.logger.V(debugLogLevel).Info("Pinniped: Refreshing cached token.") + h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Refreshing cached token.") upstreamOIDCIdentityProvider := h.getProvider(h.oauth2Config, h.provider, h.httpClient) refreshed, err := upstreamOIDCIdentityProvider.PerformRefresh(ctx, refreshToken.Token) if err != nil { // Ignore errors during refresh, but return nil which will trigger the full login flow. - h.logger.V(debugLogLevel).Info("Pinniped: Refresh failed.", "error", err.Error()) + h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Refresh failed.", "error", err.Error()) return nil, nil } @@ -865,7 +864,7 @@ func (h *handlerState) handleAuthCodeCallback(w http.ResponseWriter, r *http.Req if h.useFormPost { // nolint:nestif // Return HTTP 405 for anything that's not a POST or an OPTIONS request. if r.Method != http.MethodPost && r.Method != http.MethodOptions { - h.logger.V(debugLogLevel).Info("Pinniped: Got unexpected request on callback listener", "method", r.Method) + h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Got unexpected request on callback listener", "method", r.Method) w.WriteHeader(http.StatusMethodNotAllowed) return nil // keep listening for more requests } @@ -883,11 +882,11 @@ func (h *handlerState) handleAuthCodeCallback(w http.ResponseWriter, r *http.Req origin := r.Header.Get("Origin") if origin == "" { // The CORS preflight request should have an origin. - h.logger.V(debugLogLevel).Info("Pinniped: Got OPTIONS request without origin header") + h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Got OPTIONS request without origin header") w.WriteHeader(http.StatusBadRequest) return nil // keep listening for more requests } - h.logger.V(debugLogLevel).Info("Pinniped: Got CORS preflight request from browser", "origin", origin) + h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Got CORS preflight request from browser", "origin", origin) // To tell the browser that it is okay to make the real POST request, return the following response. w.Header().Set("Access-Control-Allow-Origin", allowOrigin) w.Header().Set("Vary", "*") // supposed to use Vary when Access-Control-Allow-Origin is a specific host @@ -921,7 +920,7 @@ func (h *handlerState) handleAuthCodeCallback(w http.ResponseWriter, r *http.Req } else { // Return HTTP 405 for anything that's not a GET. if r.Method != http.MethodGet { - h.logger.V(debugLogLevel).Info("Pinniped: Got unexpected request on callback listener", "method", r.Method) + h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Got unexpected request on callback listener", "method", r.Method) w.WriteHeader(http.StatusMethodNotAllowed) return nil // keep listening for more requests } diff --git a/pkg/oidcclient/login_test.go b/pkg/oidcclient/login_test.go index 5a3c176a..2d8b266e 100644 --- a/pkg/oidcclient/login_test.go +++ b/pkg/oidcclient/login_test.go @@ -20,10 +20,6 @@ import ( "testing" "time" - "go.pinniped.dev/internal/net/phttp" - - "go.pinniped.dev/internal/testutil/tlsserver" - "github.com/coreos/go-oidc/v3/oidc" "github.com/golang/mock/gomock" "github.com/stretchr/testify/assert" @@ -35,9 +31,12 @@ import ( "go.pinniped.dev/internal/httputil/httperr" "go.pinniped.dev/internal/httputil/roundtripper" "go.pinniped.dev/internal/mocks/mockupstreamoidcidentityprovider" + "go.pinniped.dev/internal/net/phttp" "go.pinniped.dev/internal/oidc/provider" + "go.pinniped.dev/internal/plog" "go.pinniped.dev/internal/testutil" "go.pinniped.dev/internal/testutil/testlogger" + "go.pinniped.dev/internal/testutil/tlsserver" "go.pinniped.dev/internal/upstreamoidc" "go.pinniped.dev/pkg/oidcclient/nonce" "go.pinniped.dev/pkg/oidcclient/oidctypes" @@ -1891,7 +1890,7 @@ func TestLogin(t *testing.T) { // nolint:gocyclo for _, tt := range tests { tt := tt t.Run(tt.name, func(t *testing.T) { - testLogger := testlogger.NewLegacy(t) //nolint: staticcheck // old test with lots of log statements + testLogger := testlogger.NewLegacy(t) // nolint: staticcheck // old test with lots of log statements klog.SetLogger(testLogger.Logger) tok, err := Login(tt.issuer, tt.clientID, @@ -2334,7 +2333,7 @@ func TestHandleAuthCodeCallback(t *testing.T) { state: state.State("test-state"), pkce: pkce.Code("test-pkce"), nonce: nonce.Nonce("test-nonce"), - logger: testlogger.New(t).Logger, + logger: plog.Logr(), // nolint: staticcheck // old test with no log assertions issuer: "https://valid-issuer.com/with/some/path", } if tt.opt != nil {