From 8ffd9fdc4e083b8abc6c168e185e1cabaa884e9a Mon Sep 17 00:00:00 2001 From: Margo Crawford Date: Tue, 6 Apr 2021 15:13:27 -0700 Subject: [PATCH 01/12] Started debug logging. --- cmd/pinniped/cmd/login_oidc.go | 21 ++++++++++++++++++--- cmd/pinniped/cmd/login_static.go | 5 +++++ 2 files changed, 23 insertions(+), 3 deletions(-) diff --git a/cmd/pinniped/cmd/login_oidc.go b/cmd/pinniped/cmd/login_oidc.go index 34ead8f80..9eaa433f3 100644 --- a/cmd/pinniped/cmd/login_oidc.go +++ b/cmd/pinniped/cmd/login_oidc.go @@ -20,10 +20,12 @@ import ( "github.com/spf13/cobra" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" clientauthv1beta1 "k8s.io/client-go/pkg/apis/clientauthentication/v1beta1" + "k8s.io/client-go/transport" "k8s.io/klog/v2/klogr" "go.pinniped.dev/internal/execcredcache" "go.pinniped.dev/internal/groupsuffix" + "go.pinniped.dev/internal/plog" "go.pinniped.dev/pkg/conciergeclient" "go.pinniped.dev/pkg/oidcclient" "go.pinniped.dev/pkg/oidcclient/filesession" @@ -110,6 +112,8 @@ func oidcLoginCommand(deps oidcLoginCommandDeps) *cobra.Command { } func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLoginFlags) error { + SetLogLevel() + // Initialize the session cache. var sessionOptions []filesession.Option @@ -153,6 +157,7 @@ func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLogin // --skip-browser replaces the default "browser open" function with one that prints to stderr. if flags.skipBrowser { + plog.Debug("skipping browser.") opts = append(opts, oidcclient.WithBrowserOpen(func(url string) error { cmd.PrintErr("Please log in: ", url, "\n") return nil @@ -166,7 +171,6 @@ func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLogin } opts = append(opts, oidcclient.WithClient(client)) } - // Look up cached credentials based on a hash of all the CLI arguments and the cluster info. cacheKey := struct { Args []string `json:"args"` @@ -183,6 +187,7 @@ func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLogin } } + plog.Debug("performing OIDC login", "issuer", flags.issuer, "client id", flags.clientID) // Do the basic login to get an OIDC token. token, err := deps.login(flags.issuer, flags.clientID, opts...) if err != nil { @@ -192,6 +197,7 @@ func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLogin // If the concierge was configured, exchange the credential for a separate short-lived, cluster-specific credential. if concierge != nil { + plog.Debug("exchanging token for cluster credential", "endpoint", flags.conciergeEndpoint, "authenticator type", flags.conciergeAuthenticatorType, "authenticator name", flags.conciergeAuthenticatorName) ctx, cancel := context.WithTimeout(context.Background(), 30*time.Second) defer cancel() @@ -224,7 +230,7 @@ func makeClient(caBundlePaths []string, caBundleData []string) (*http.Client, er } pool.AppendCertsFromPEM(pem) } - return &http.Client{ + client := &http.Client{ Transport: &http.Transport{ Proxy: http.ProxyFromEnvironment, TLSClientConfig: &tls.Config{ @@ -232,7 +238,10 @@ func makeClient(caBundlePaths []string, caBundleData []string) (*http.Client, er MinVersion: tls.VersionTLS12, }, }, - }, nil + } + + client.Transport = transport.DebugWrappers(client.Transport) + return client, nil } func tokenCredential(token *oidctypes.Token) *clientauthv1beta1.ExecCredential { @@ -251,6 +260,12 @@ func tokenCredential(token *oidctypes.Token) *clientauthv1beta1.ExecCredential { return &cred } +func SetLogLevel() { + if os.Getenv("PINNIPED_DEBUG") == "true" { + _ = plog.ValidateAndSetLogLevelGlobally(plog.LevelDebug) + } +} + // mustGetConfigDir returns a directory that follows the XDG base directory convention: // $XDG_CONFIG_HOME defines the base directory relative to which user specific configuration files should // be stored. If $XDG_CONFIG_HOME is either not set or empty, a default equal to $HOME/.config should be used. diff --git a/cmd/pinniped/cmd/login_static.go b/cmd/pinniped/cmd/login_static.go index 4b9ac2fd9..4a6b0513e 100644 --- a/cmd/pinniped/cmd/login_static.go +++ b/cmd/pinniped/cmd/login_static.go @@ -17,6 +17,7 @@ import ( "go.pinniped.dev/internal/execcredcache" "go.pinniped.dev/internal/groupsuffix" + "go.pinniped.dev/internal/plog" "go.pinniped.dev/pkg/conciergeclient" "go.pinniped.dev/pkg/oidcclient/oidctypes" ) @@ -83,6 +84,8 @@ func staticLoginCommand(deps staticLoginDeps) *cobra.Command { } func runStaticLogin(out io.Writer, deps staticLoginDeps, flags staticLoginParams) error { + SetLogLevel() + if flags.staticToken == "" && flags.staticTokenEnvName == "" { return fmt.Errorf("one of --token or --token-env must be set") } @@ -137,6 +140,7 @@ func runStaticLogin(out io.Writer, deps staticLoginDeps, flags staticLoginParams // If the concierge was configured, exchange the credential for a separate short-lived, cluster-specific credential. if concierge != nil { + plog.Debug("exchanging static token for cluster credential", "endpoint", flags.conciergeEndpoint, "authenticator type", flags.conciergeAuthenticatorType, "authenticator name", flags.conciergeAuthenticatorName) ctx, cancel := context.WithTimeout(context.Background(), 30*time.Second) defer cancel() @@ -145,6 +149,7 @@ func runStaticLogin(out io.Writer, deps staticLoginDeps, flags staticLoginParams if err != nil { return fmt.Errorf("could not complete Concierge credential exchange: %w", err) } + plog.Debug("exchanged static token for cluster credential") } // If there was a credential cache, save the resulting credential for future use. We only save to the cache if From 211d4fd0b6f5e312e62bc3e360c659c457b06408 Mon Sep 17 00:00:00 2001 From: Margo Crawford Date: Wed, 7 Apr 2021 15:30:29 -0700 Subject: [PATCH 02/12] Add more logging, integration test checks that debug flag works. --- cmd/pinniped/cmd/login_oidc.go | 7 ++++--- pkg/oidcclient/login.go | 7 ++++++- test/integration/cli_test.go | 31 +++++++++++++++++++++++-------- 3 files changed, 33 insertions(+), 12 deletions(-) diff --git a/cmd/pinniped/cmd/login_oidc.go b/cmd/pinniped/cmd/login_oidc.go index 9eaa433f3..88a5d36a5 100644 --- a/cmd/pinniped/cmd/login_oidc.go +++ b/cmd/pinniped/cmd/login_oidc.go @@ -157,7 +157,6 @@ func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLogin // --skip-browser replaces the default "browser open" function with one that prints to stderr. if flags.skipBrowser { - plog.Debug("skipping browser.") opts = append(opts, oidcclient.WithBrowserOpen(func(url string) error { cmd.PrintErr("Please log in: ", url, "\n") return nil @@ -187,7 +186,7 @@ func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLogin } } - plog.Debug("performing OIDC login", "issuer", flags.issuer, "client id", flags.clientID) + plog.Debug("Pinniped: Performing OIDC login", "issuer", flags.issuer, "client id", flags.clientID) // Do the basic login to get an OIDC token. token, err := deps.login(flags.issuer, flags.clientID, opts...) if err != nil { @@ -197,7 +196,7 @@ func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLogin // If the concierge was configured, exchange the credential for a separate short-lived, cluster-specific credential. if concierge != nil { - plog.Debug("exchanging token for cluster credential", "endpoint", flags.conciergeEndpoint, "authenticator type", flags.conciergeAuthenticatorType, "authenticator name", flags.conciergeAuthenticatorName) + plog.Debug("Pinniped: Exchanging token for cluster credential", "endpoint", flags.conciergeEndpoint, "authenticator type", flags.conciergeAuthenticatorType, "authenticator name", flags.conciergeAuthenticatorName) ctx, cancel := context.WithTimeout(context.Background(), 30*time.Second) defer cancel() @@ -205,6 +204,8 @@ func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLogin if err != nil { return fmt.Errorf("could not complete Concierge credential exchange: %w", err) } + } else { + plog.Debug("Pinniped: No concierge configured, skipping token credential exchange") } // If there was a credential cache, save the resulting credential for future use. diff --git a/pkg/oidcclient/login.go b/pkg/oidcclient/login.go index 53b6efd47..4d7539449 100644 --- a/pkg/oidcclient/login.go +++ b/pkg/oidcclient/login.go @@ -1,4 +1,4 @@ -// Copyright 2020 the Pinniped contributors. All Rights Reserved. +// Copyright 2020-2021 the Pinniped contributors. All Rights Reserved. // SPDX-License-Identifier: Apache-2.0 // Package oidcclient implements a CLI OIDC login flow. @@ -24,6 +24,7 @@ import ( "go.pinniped.dev/internal/httputil/httperr" "go.pinniped.dev/internal/httputil/securityheader" "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" @@ -260,6 +261,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 { + plog.Debug("Pinniped: Found unexpired cached token") return cached, nil } @@ -327,6 +329,7 @@ func (h *handlerState) initOIDCDiscovery() error { return nil } + plog.Debug("Pinniped: Performing OIDC discovery", "issuer", h.issuer) var err error h.provider, err = oidc.NewProvider(h.ctx, h.issuer) if err != nil { @@ -343,6 +346,7 @@ func (h *handlerState) initOIDCDiscovery() error { } func (h *handlerState) tokenExchangeRFC8693(baseToken *oidctypes.Token) (*oidctypes.Token, error) { + plog.Debug("Pinniped: Performing RFC8693 token exchange", "requested audience", 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 @@ -413,6 +417,7 @@ func (h *handlerState) tokenExchangeRFC8693(baseToken *oidctypes.Token) (*oidcty } func (h *handlerState) handleRefresh(ctx context.Context, refreshToken *oidctypes.RefreshToken) (*oidctypes.Token, error) { + plog.Debug("refreshing cached token") refreshSource := h.oauth2Config.TokenSource(ctx, &oauth2.Token{RefreshToken: refreshToken.Token}) refreshed, err := refreshSource.Token() diff --git a/test/integration/cli_test.go b/test/integration/cli_test.go index 3bf374370..6f58ed61f 100644 --- a/test/integration/cli_test.go +++ b/test/integration/cli_test.go @@ -237,6 +237,18 @@ func TestCLILoginOIDC(t *testing.T) { require.NoErrorf(t, json.Unmarshal(cmd3Output, &credOutput3), "command returned something other than an ExecCredential:\n%s", string(cmd2Output)) require.NotEqual(t, credOutput2.Status.Token, credOutput3.Status.Token) + + t.Logf("starting fourth CLI subprocess to test debug logging") + err = os.Setenv("PINNIPED_DEBUG", "true") + require.NoError(t, err) + command := oidcLoginCommand(ctx, t, pinnipedExe, sessionCachePath) + cmd4CombinedOutput, err := command.CombinedOutput() + require.NoError(t, err, string(cmd4CombinedOutput)) + + require.Contains(t, string(cmd4CombinedOutput), "Performing OIDC login") + require.Contains(t, string(cmd4CombinedOutput), "Found unexpired cached token") + require.Contains(t, string(cmd4CombinedOutput), "No concierge configured, skipping token credential exchange") + require.Contains(t, string(cmd4CombinedOutput), credOutput3.Status.Token) } func runPinnipedLoginOIDC( @@ -271,6 +283,7 @@ func runPinnipedLoginOIDC( // Start a background goroutine to read stderr from the CLI and parse out the login URL. loginURLChan := make(chan string) spawnTestGoroutine(t, func() (err error) { + t.Helper() defer func() { closeErr := stderr.Close() if closeErr == nil || errors.Is(closeErr, os.ErrClosed) { @@ -282,16 +295,18 @@ func runPinnipedLoginOIDC( }() reader := bufio.NewReader(library.NewLoggerReader(t, "stderr", stderr)) - line, err := reader.ReadString('\n') - if err != nil { - return fmt.Errorf("could not read login URL line from stderr: %w", err) - } + + scanner := bufio.NewScanner(reader) const prompt = "Please log in: " - if !strings.HasPrefix(line, prompt) { - return fmt.Errorf("expected %q to have prefix %q", line, prompt) + for scanner.Scan() { + line := scanner.Text() + if strings.HasPrefix(line, prompt) { + loginURLChan <- strings.TrimPrefix(line, prompt) + return nil + } } - loginURLChan <- strings.TrimPrefix(line, prompt) - return readAndExpectEmpty(reader) + + return fmt.Errorf("expected stderr to contain %s", prompt) }) // Start a background goroutine to read stdout from the CLI and parse out an ExecCredential. From 6a21499ed31a5bf82cd488afb8d66f0dea3a9f1b Mon Sep 17 00:00:00 2001 From: Margo Crawford Date: Wed, 7 Apr 2021 15:54:48 -0700 Subject: [PATCH 03/12] Add check for number of log lines. --- test/integration/cli_test.go | 17 ++++++++++++----- 1 file changed, 12 insertions(+), 5 deletions(-) diff --git a/test/integration/cli_test.go b/test/integration/cli_test.go index 6f58ed61f..2181290ac 100644 --- a/test/integration/cli_test.go +++ b/test/integration/cli_test.go @@ -208,6 +208,8 @@ func TestCLILoginOIDC(t *testing.T) { require.NoErrorf(t, json.Unmarshal(cmd2Output, &credOutput2), "command returned something other than an ExecCredential:\n%s", string(cmd2Output)) require.Equal(t, credOutput, credOutput2) + // the logs contain only the ExecCredential. There are 2 elements because the last one is "". + require.Len(t, strings.Split(string(cmd2Output), "\n"), 2) // Overwrite the cache entry to remove the access and ID tokens. t.Logf("overwriting cache to remove valid ID token") @@ -237,18 +239,23 @@ func TestCLILoginOIDC(t *testing.T) { require.NoErrorf(t, json.Unmarshal(cmd3Output, &credOutput3), "command returned something other than an ExecCredential:\n%s", string(cmd2Output)) require.NotEqual(t, credOutput2.Status.Token, credOutput3.Status.Token) + // the logs contain only the ExecCredential. There are 2 elements because the last one is "". + require.Len(t, strings.Split(string(cmd3Output), "\n"), 2) t.Logf("starting fourth CLI subprocess to test debug logging") err = os.Setenv("PINNIPED_DEBUG", "true") require.NoError(t, err) command := oidcLoginCommand(ctx, t, pinnipedExe, sessionCachePath) cmd4CombinedOutput, err := command.CombinedOutput() - require.NoError(t, err, string(cmd4CombinedOutput)) + cmd4StringOutput := string(cmd4CombinedOutput) + require.NoError(t, err, cmd4StringOutput) - require.Contains(t, string(cmd4CombinedOutput), "Performing OIDC login") - require.Contains(t, string(cmd4CombinedOutput), "Found unexpired cached token") - require.Contains(t, string(cmd4CombinedOutput), "No concierge configured, skipping token credential exchange") - require.Contains(t, string(cmd4CombinedOutput), credOutput3.Status.Token) + // the logs contain only the 3 debug lines plus the ExecCredential. There are 5 elements because the last one is "". + require.Len(t, strings.Split(cmd4StringOutput, "\n"), 5) + require.Contains(t, cmd4StringOutput, "Performing OIDC login") + require.Contains(t, cmd4StringOutput, "Found unexpired cached token") + require.Contains(t, cmd4StringOutput, "No concierge configured, skipping token credential exchange") + require.Contains(t, cmd4StringOutput, credOutput3.Status.Token) } func runPinnipedLoginOIDC( From 45e4695444157f9c6b96db349e046197159b706f Mon Sep 17 00:00:00 2001 From: Margo Crawford Date: Thu, 8 Apr 2021 10:14:29 -0700 Subject: [PATCH 04/12] Unset pinniped debug environment variable at end of integration test Also log when setting the debug log level fails --- cmd/pinniped/cmd/login_oidc.go | 13 ++++++++++--- cmd/pinniped/cmd/login_static.go | 5 ++++- test/integration/cli_test.go | 2 ++ 3 files changed, 16 insertions(+), 4 deletions(-) diff --git a/cmd/pinniped/cmd/login_oidc.go b/cmd/pinniped/cmd/login_oidc.go index 88a5d36a5..c7ad05941 100644 --- a/cmd/pinniped/cmd/login_oidc.go +++ b/cmd/pinniped/cmd/login_oidc.go @@ -112,7 +112,10 @@ func oidcLoginCommand(deps oidcLoginCommandDeps) *cobra.Command { } func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLoginFlags) error { - SetLogLevel() + err := SetLogLevel() + if err != nil { + plog.WarningErr("Received error while setting log level", err) + } // Initialize the session cache. var sessionOptions []filesession.Option @@ -261,10 +264,14 @@ func tokenCredential(token *oidctypes.Token) *clientauthv1beta1.ExecCredential { return &cred } -func SetLogLevel() { +func SetLogLevel() error { if os.Getenv("PINNIPED_DEBUG") == "true" { - _ = plog.ValidateAndSetLogLevelGlobally(plog.LevelDebug) + err := plog.ValidateAndSetLogLevelGlobally(plog.LevelDebug) + if err != nil { + return err + } } + return nil } // mustGetConfigDir returns a directory that follows the XDG base directory convention: diff --git a/cmd/pinniped/cmd/login_static.go b/cmd/pinniped/cmd/login_static.go index 4a6b0513e..dcdc8c4d6 100644 --- a/cmd/pinniped/cmd/login_static.go +++ b/cmd/pinniped/cmd/login_static.go @@ -84,7 +84,10 @@ func staticLoginCommand(deps staticLoginDeps) *cobra.Command { } func runStaticLogin(out io.Writer, deps staticLoginDeps, flags staticLoginParams) error { - SetLogLevel() + err := SetLogLevel() + if err != nil { + plog.WarningErr("Received error while setting log level", err) + } if flags.staticToken == "" && flags.staticTokenEnvName == "" { return fmt.Errorf("one of --token or --token-env must be set") diff --git a/test/integration/cli_test.go b/test/integration/cli_test.go index 2181290ac..622e9ba53 100644 --- a/test/integration/cli_test.go +++ b/test/integration/cli_test.go @@ -256,6 +256,8 @@ func TestCLILoginOIDC(t *testing.T) { require.Contains(t, cmd4StringOutput, "Found unexpired cached token") require.Contains(t, cmd4StringOutput, "No concierge configured, skipping token credential exchange") require.Contains(t, cmd4StringOutput, credOutput3.Status.Token) + err = os.Unsetenv("PINNIPED_DEBUG") + require.NoError(t, err) } func runPinnipedLoginOIDC( From b5889f37ff68b10bc4fe3dca8a3c1d01913dcc16 Mon Sep 17 00:00:00 2001 From: Margo Crawford Date: Fri, 16 Apr 2021 10:46:59 -0700 Subject: [PATCH 05/12] WIP on new plog --- cmd/pinniped/cmd/login_oidc.go | 15 ++-- cmd/pinniped/cmd/login_oidc_test.go | 28 ++++++ cmd/pinniped/cmd/login_static.go | 6 +- internal/plog/plog.go | 131 ++++++++++++++++++++++++---- pkg/oidcclient/login_test.go | 84 +++++++++++++++--- 5 files changed, 228 insertions(+), 36 deletions(-) diff --git a/cmd/pinniped/cmd/login_oidc.go b/cmd/pinniped/cmd/login_oidc.go index c7ad05941..091827cc8 100644 --- a/cmd/pinniped/cmd/login_oidc.go +++ b/cmd/pinniped/cmd/login_oidc.go @@ -112,7 +112,7 @@ func oidcLoginCommand(deps oidcLoginCommandDeps) *cobra.Command { } func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLoginFlags) error { - err := SetLogLevel() + pLogger, err := SetLogLevel() if err != nil { plog.WarningErr("Received error while setting log level", err) } @@ -189,7 +189,7 @@ func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLogin } } - plog.Debug("Pinniped: Performing OIDC login", "issuer", flags.issuer, "client id", flags.clientID) + pLogger.Debug("Performing OIDC login", "issuer", flags.issuer, "client id", flags.clientID) // Do the basic login to get an OIDC token. token, err := deps.login(flags.issuer, flags.clientID, opts...) if err != nil { @@ -199,7 +199,7 @@ func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLogin // If the concierge was configured, exchange the credential for a separate short-lived, cluster-specific credential. if concierge != nil { - plog.Debug("Pinniped: Exchanging token for cluster credential", "endpoint", flags.conciergeEndpoint, "authenticator type", flags.conciergeAuthenticatorType, "authenticator name", flags.conciergeAuthenticatorName) + pLogger.Debug("Exchanging token for cluster credential", "endpoint", flags.conciergeEndpoint, "authenticator type", flags.conciergeAuthenticatorType, "authenticator name", flags.conciergeAuthenticatorName) ctx, cancel := context.WithTimeout(context.Background(), 30*time.Second) defer cancel() @@ -208,7 +208,7 @@ func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLogin return fmt.Errorf("could not complete Concierge credential exchange: %w", err) } } else { - plog.Debug("Pinniped: No concierge configured, skipping token credential exchange") + pLogger.Debug("No concierge configured, skipping token credential exchange") } // If there was a credential cache, save the resulting credential for future use. @@ -264,14 +264,15 @@ func tokenCredential(token *oidctypes.Token) *clientauthv1beta1.ExecCredential { return &cred } -func SetLogLevel() error { +func SetLogLevel() (*plog.PLogger, error) { if os.Getenv("PINNIPED_DEBUG") == "true" { err := plog.ValidateAndSetLogLevelGlobally(plog.LevelDebug) if err != nil { - return err + return nil, err } } - return nil + logger := plog.New("Pinniped login: ") + return &logger, nil } // mustGetConfigDir returns a directory that follows the XDG base directory convention: diff --git a/cmd/pinniped/cmd/login_oidc_test.go b/cmd/pinniped/cmd/login_oidc_test.go index 8472f6af2..541c6a6da 100644 --- a/cmd/pinniped/cmd/login_oidc_test.go +++ b/cmd/pinniped/cmd/login_oidc_test.go @@ -9,6 +9,7 @@ import ( "encoding/base64" "fmt" "io/ioutil" + "os" "path/filepath" "testing" "time" @@ -16,10 +17,12 @@ import ( "github.com/stretchr/testify/require" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" clientauthv1beta1 "k8s.io/client-go/pkg/apis/clientauthentication/v1beta1" + "k8s.io/klog/v2" "go.pinniped.dev/internal/certauthority" "go.pinniped.dev/internal/here" "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" @@ -41,10 +44,12 @@ func TestLoginOIDCCommand(t *testing.T) { args []string loginErr error conciergeErr error + envVars map[string]string wantError bool wantStdout string wantStderr string wantOptionsCount int + wantLogs []string }{ { name: "help flag passed", @@ -170,8 +175,13 @@ func TestLoginOIDCCommand(t *testing.T) { "--client-id", "test-client-id", "--issuer", "test-issuer", }, + envVars: map[string]string{"PINNIPED_DEBUG": "true"}, wantOptionsCount: 3, wantStdout: `{"kind":"ExecCredential","apiVersion":"client.authentication.k8s.io/v1beta1","spec":{},"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\"", + }, }, { name: "success with all options", @@ -192,13 +202,29 @@ func TestLoginOIDCCommand(t *testing.T) { "--concierge-api-group-suffix", "some.suffix.com", "--credential-cache", testutil.TempDir(t) + "/credentials.yaml", }, + envVars: map[string]string{"PINNIPED_DEBUG": "true"}, wantOptionsCount: 7, wantStdout: `{"kind":"ExecCredential","apiVersion":"client.authentication.k8s.io/v1beta1","spec":{},"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/\"", + }, }, } for _, tt := range tests { tt := tt t.Run(tt.name, func(t *testing.T) { + for k, v := range tt.envVars { + kk := k + err := os.Setenv(kk, v) + require.NoError(t, err) + t.Cleanup(func() { + t.Log("cleaning up " + kk) + err = os.Unsetenv(kk) + }) + } + testLogger := testlogger.New(t) + klog.SetLogger(testLogger) var ( gotOptions []oidcclient.Option ) @@ -248,6 +274,8 @@ func TestLoginOIDCCommand(t *testing.T) { require.Equal(t, tt.wantStdout, stdout.String(), "unexpected stdout") require.Equal(t, tt.wantStderr, stderr.String(), "unexpected stderr") require.Len(t, gotOptions, tt.wantOptionsCount) + + require.Equal(t, tt.wantLogs, testLogger.Lines()) }) } } diff --git a/cmd/pinniped/cmd/login_static.go b/cmd/pinniped/cmd/login_static.go index dcdc8c4d6..fb1df4d5e 100644 --- a/cmd/pinniped/cmd/login_static.go +++ b/cmd/pinniped/cmd/login_static.go @@ -84,7 +84,7 @@ func staticLoginCommand(deps staticLoginDeps) *cobra.Command { } func runStaticLogin(out io.Writer, deps staticLoginDeps, flags staticLoginParams) error { - err := SetLogLevel() + pLogger, err := SetLogLevel() if err != nil { plog.WarningErr("Received error while setting log level", err) } @@ -143,7 +143,7 @@ func runStaticLogin(out io.Writer, deps staticLoginDeps, flags staticLoginParams // If the concierge was configured, exchange the credential for a separate short-lived, cluster-specific credential. if concierge != nil { - plog.Debug("exchanging static token for cluster credential", "endpoint", flags.conciergeEndpoint, "authenticator type", flags.conciergeAuthenticatorType, "authenticator name", flags.conciergeAuthenticatorName) + pLogger.Debug("exchanging static token for cluster credential", "endpoint", flags.conciergeEndpoint, "authenticator type", flags.conciergeAuthenticatorType, "authenticator name", flags.conciergeAuthenticatorName) ctx, cancel := context.WithTimeout(context.Background(), 30*time.Second) defer cancel() @@ -152,7 +152,7 @@ func runStaticLogin(out io.Writer, deps staticLoginDeps, flags staticLoginParams if err != nil { return fmt.Errorf("could not complete Concierge credential exchange: %w", err) } - plog.Debug("exchanged static token for cluster credential") + pLogger.Debug("exchanged static token for cluster credential") } // If there was a credential cache, save the resulting credential for future use. We only save to the cache if diff --git a/internal/plog/plog.go b/internal/plog/plog.go index b38e7179b..cf6bc80b1 100644 --- a/internal/plog/plog.go +++ b/internal/plog/plog.go @@ -1,4 +1,4 @@ -// Copyright 2020 the Pinniped contributors. All Rights Reserved. +// 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. @@ -26,56 +26,157 @@ // act of desperation to determine why the system is broken. package plog -import "k8s.io/klog/v2" +import ( + "k8s.io/klog/v2" +) const errorKey = "error" -// Use Error to log an unexpected system error. -func Error(msg string, err error, keysAndValues ...interface{}) { - klog.ErrorS(err, msg, keysAndValues...) +type _ interface { + Error(msg string, err error, keysAndValues ...interface{}) + Warning(msg string, keysAndValues ...interface{}) + WarningErr(msg string, err error, keysAndValues ...interface{}) + Info(msg string, keysAndValues ...interface{}) + InfoErr(msg string, err error, keysAndValues ...interface{}) + Debug(msg string, keysAndValues ...interface{}) + DebugErr(msg string, err error, keysAndValues ...interface{}) + Trace(msg string, keysAndValues ...interface{}) + TraceErr(msg string, err error, keysAndValues ...interface{}) + All(msg string, keysAndValues ...interface{}) } -func Warning(msg string, keysAndValues ...interface{}) { +type PLogger struct { + prefix string + depth int +} + +func New(prefix string) PLogger { + return PLogger{ + depth: 0, + prefix: prefix, + } +} + +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...) - klog.V(klogLevelWarning).InfoS(msg, keysAndValues...) + if klog.V(klogLevelWarning).Enabled() { + klog.InfoSDepth(depth+1, p.prefix+msg, keysAndValues...) + } +} + +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{}) { + 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) 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{}) { + 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) 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{}) { + 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) 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{}) { + 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...) + } +} + +var pLogger = PLogger{ //nolint:gochecknoglobals + depth: 1, +} + +// Use Error to log an unexpected system error. +func Error(msg string, err error, keysAndValues ...interface{}) { + pLogger.Error(msg, err, keysAndValues...) +} + +func Warning(msg string, keysAndValues ...interface{}) { + pLogger.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{}) { - Warning(msg, append([]interface{}{errorKey, err}, keysAndValues...)...) + pLogger.WarningErr(msg, err, keysAndValues...) } func Info(msg string, keysAndValues ...interface{}) { - klog.V(klogLevelInfo).InfoS(msg, keysAndValues...) + pLogger.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{}) { - Info(msg, append([]interface{}{errorKey, err}, keysAndValues...)...) + pLogger.InfoErr(msg, err, keysAndValues...) } func Debug(msg string, keysAndValues ...interface{}) { - klog.V(klogLevelDebug).InfoS(msg, keysAndValues...) + pLogger.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{}) { - Debug(msg, append([]interface{}{errorKey, err}, keysAndValues...)...) + pLogger.DebugErr(msg, err, keysAndValues...) } func Trace(msg string, keysAndValues ...interface{}) { - klog.V(klogLevelTrace).InfoS(msg, keysAndValues...) + pLogger.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{}) { - Trace(msg, append([]interface{}{errorKey, err}, keysAndValues...)...) + pLogger.TraceErr(msg, err, keysAndValues...) } func All(msg string, keysAndValues ...interface{}) { - klog.V(klogLevelAll).InfoS(msg, keysAndValues...) + pLogger.All(msg, keysAndValues...) } diff --git a/pkg/oidcclient/login_test.go b/pkg/oidcclient/login_test.go index 8005bcafa..f1f5f6cfc 100644 --- a/pkg/oidcclient/login_test.go +++ b/pkg/oidcclient/login_test.go @@ -19,11 +19,14 @@ import ( "github.com/stretchr/testify/require" "golang.org/x/oauth2" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" + "k8s.io/klog/v2" "go.pinniped.dev/internal/httputil/httperr" "go.pinniped.dev/internal/mocks/mockupstreamoidcidentityprovider" "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/pkg/oidcclient/nonce" "go.pinniped.dev/pkg/oidcclient/oidctypes" "go.pinniped.dev/pkg/oidcclient/pkce" @@ -205,6 +208,7 @@ func TestLogin(t *testing.T) { clientID string wantErr string wantToken *oidctypes.Token + wantLogs []string }{ { name: "option error", @@ -269,7 +273,8 @@ func TestLogin(t *testing.T) { return WithSessionCache(cache)(h) } }, - wantErr: `could not perform OIDC discovery for "test-issuer": Get "test-issuer/.well-known/openid-configuration": unsupported protocol scheme ""`, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"test-issuer\""}, + wantErr: `could not perform OIDC discovery for "test-issuer": Get "test-issuer/.well-known/openid-configuration": unsupported protocol scheme ""`, }, { name: "session cache hit with valid token", @@ -290,6 +295,7 @@ func TestLogin(t *testing.T) { return WithSessionCache(cache)(h) } }, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Found unexpired cached token\""}, wantToken: &testToken, }, { @@ -297,8 +303,9 @@ func TestLogin(t *testing.T) { opt: func(t *testing.T) Option { return func(h *handlerState) error { return nil } }, - issuer: errorServer.URL, - wantErr: fmt.Sprintf("could not perform OIDC discovery for %q: 500 Internal Server Error: some discovery error\n", errorServer.URL), + issuer: errorServer.URL, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + errorServer.URL + "\""}, + wantErr: fmt.Sprintf("could not perform OIDC discovery for %q: 500 Internal Server Error: some discovery error\n", errorServer.URL), }, { name: "session cache hit with refreshable token", @@ -337,6 +344,8 @@ func TestLogin(t *testing.T) { return nil } }, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\"", + "\"level\"=0 \"msg\"=\"refreshing cached token\""}, wantToken: &testToken, }, { @@ -369,6 +378,8 @@ func TestLogin(t *testing.T) { return nil } }, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\"", + "\"level\"=0 \"msg\"=\"refreshing cached token\""}, wantErr: "some validation error", }, { @@ -395,6 +406,8 @@ func TestLogin(t *testing.T) { return nil } }, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\"", + "\"level\"=0 \"msg\"=\"refreshing cached token\""}, // Expect this to fall through to the authorization code flow, so it fails here. wantErr: "could not open callback listener: listen tcp: address invalid-listen-address: missing port in address", }, @@ -406,8 +419,9 @@ func TestLogin(t *testing.T) { return nil } }, - issuer: successServer.URL, - wantErr: "could not open callback listener: listen tcp: address invalid-listen-address: missing port in address", + issuer: successServer.URL, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantErr: "could not open callback listener: listen tcp: address invalid-listen-address: missing port in address", }, { name: "browser open failure", @@ -416,8 +430,9 @@ func TestLogin(t *testing.T) { return fmt.Errorf("some browser open error") }) }, - issuer: successServer.URL, - wantErr: "could not open browser: some browser open error", + issuer: successServer.URL, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantErr: "could not open browser: some browser open error", }, { name: "timeout waiting for callback", @@ -433,8 +448,9 @@ func TestLogin(t *testing.T) { return nil } }, - issuer: successServer.URL, - wantErr: "timed out waiting for token callback: context canceled", + issuer: successServer.URL, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantErr: "timed out waiting for token callback: context canceled", }, { name: "callback returns error", @@ -449,8 +465,9 @@ func TestLogin(t *testing.T) { return nil } }, - issuer: successServer.URL, - wantErr: "error handling callback: some callback error", + issuer: successServer.URL, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantErr: "error handling callback: some callback error", }, { name: "callback returns success", @@ -510,6 +527,7 @@ func TestLogin(t *testing.T) { } }, issuer: successServer.URL, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantToken: &testToken, }, { @@ -533,6 +551,9 @@ func TestLogin(t *testing.T) { return nil } }, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Found unexpired cached token\"", + "\"level\"=0 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requested audience\"=\"cluster-1234\"", + "\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + errorServer.URL + "\""}, wantErr: fmt.Sprintf("failed to exchange token: could not perform OIDC discovery for %q: 500 Internal Server Error: some discovery error\n", errorServer.URL), }, { @@ -556,6 +577,9 @@ func TestLogin(t *testing.T) { return nil } }, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Found unexpired cached token\"", + "\"level\"=0 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requested audience\"=\"cluster-1234\"", + "\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + brokenTokenURLServer.URL + "\""}, wantErr: `failed to exchange token: could not build RFC8693 request: parse "%": invalid URL escape "%"`, }, { @@ -579,6 +603,9 @@ func TestLogin(t *testing.T) { return nil } }, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Found unexpired cached token\"", + "\"level\"=0 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requested audience\"=\"test-audience-produce-invalid-http-response\"", + "\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: fmt.Sprintf(`failed to exchange token: Post "%s/token": failed to parse Location header "%%": parse "%%": invalid URL escape "%%"`, successServer.URL), }, { @@ -602,6 +629,9 @@ func TestLogin(t *testing.T) { return nil } }, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Found unexpired cached token\"", + "\"level\"=0 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requested audience\"=\"test-audience-produce-http-400\"", + "\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: `failed to exchange token: unexpected HTTP response status 400`, }, { @@ -625,6 +655,9 @@ func TestLogin(t *testing.T) { return nil } }, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Found unexpired cached token\"", + "\"level\"=0 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requested audience\"=\"test-audience-produce-invalid-content-type\"", + "\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: `failed to exchange token: failed to decode content-type header: mime: invalid media parameter`, }, { @@ -648,6 +681,9 @@ func TestLogin(t *testing.T) { return nil } }, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Found unexpired cached token\"", + "\"level\"=0 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requested audience\"=\"test-audience-produce-wrong-content-type\"", + "\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: `failed to exchange token: unexpected HTTP response content type "invalid"`, }, { @@ -671,6 +707,9 @@ func TestLogin(t *testing.T) { return nil } }, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Found unexpired cached token\"", + "\"level\"=0 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requested audience\"=\"test-audience-produce-invalid-json\"", + "\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: `failed to exchange token: failed to decode response: unexpected EOF`, }, { @@ -694,6 +733,9 @@ func TestLogin(t *testing.T) { return nil } }, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Found unexpired cached token\"", + "\"level\"=0 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requested audience\"=\"test-audience-produce-invalid-tokentype\"", + "\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: `failed to exchange token: got unexpected token_type "invalid"`, }, { @@ -717,6 +759,9 @@ func TestLogin(t *testing.T) { return nil } }, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Found unexpired cached token\"", + "\"level\"=0 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requested audience\"=\"test-audience-produce-invalid-issuedtokentype\"", + "\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: `failed to exchange token: got unexpected issued_token_type "invalid"`, }, { @@ -740,6 +785,9 @@ func TestLogin(t *testing.T) { return nil } }, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Found unexpired cached token\"", + "\"level\"=0 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requested audience\"=\"test-audience-produce-invalid-jwt\"", + "\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: `failed to exchange token: received invalid JWT: oidc: malformed jwt: square/go-jose: compact JWS format must have three parts`, }, { @@ -769,6 +817,9 @@ func TestLogin(t *testing.T) { return nil } }, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Found unexpired cached token\"", + "\"level\"=0 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requested audience\"=\"test-audience\"", + "\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantToken: &testExchangedToken, }, { @@ -816,18 +867,29 @@ func TestLogin(t *testing.T) { return nil } }, + wantLogs: []string{ + "\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\"", + "\"level\"=0 \"msg\"=\"refreshing cached token\"", + "\"level\"=0 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requested audience\"=\"test-audience\"", + }, wantToken: &testExchangedToken, }, } for _, tt := range tests { tt := tt t.Run(tt.name, func(t *testing.T) { + err := plog.ValidateAndSetLogLevelGlobally(plog.LevelDebug) + require.NoError(t, err) + testLogger := testlogger.New(t) + klog.SetLogger(testLogger) + tok, err := Login(tt.issuer, tt.clientID, WithContext(context.Background()), WithListenPort(0), WithScopes([]string{"test-scope"}), tt.opt(t), ) + require.Equal(t, tt.wantLogs, testLogger.Lines()) if tt.wantErr != "" { require.EqualError(t, err, tt.wantErr) require.Nil(t, tok) From 264778113d75ef6fb0014fa4d53fcd4eb6bdf92f Mon Sep 17 00:00:00 2001 From: Margo Crawford Date: Fri, 16 Apr 2021 14:38:05 -0700 Subject: [PATCH 06/12] lookupEnv in oidclogin same as for static --- cmd/pinniped/cmd/login_oidc.go | 11 +++++++---- cmd/pinniped/cmd/login_oidc_test.go | 20 +++++++------------- cmd/pinniped/cmd/login_static.go | 2 +- cmd/pinniped/cmd/login_static_test.go | 11 +++++++++++ 4 files changed, 26 insertions(+), 18 deletions(-) diff --git a/cmd/pinniped/cmd/login_oidc.go b/cmd/pinniped/cmd/login_oidc.go index 091827cc8..37a19d589 100644 --- a/cmd/pinniped/cmd/login_oidc.go +++ b/cmd/pinniped/cmd/login_oidc.go @@ -38,13 +38,15 @@ func init() { } type oidcLoginCommandDeps struct { + lookupEnv func(string) (string, bool) login func(string, string, ...oidcclient.Option) (*oidctypes.Token, error) exchangeToken func(context.Context, *conciergeclient.Client, string) (*clientauthv1beta1.ExecCredential, error) } func oidcLoginCommandRealDeps() oidcLoginCommandDeps { return oidcLoginCommandDeps{ - login: oidcclient.Login, + lookupEnv: os.LookupEnv, + login: oidcclient.Login, exchangeToken: func(ctx context.Context, client *conciergeclient.Client, token string) (*clientauthv1beta1.ExecCredential, error) { return client.ExchangeToken(ctx, token) }, @@ -112,7 +114,7 @@ func oidcLoginCommand(deps oidcLoginCommandDeps) *cobra.Command { } func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLoginFlags) error { - pLogger, err := SetLogLevel() + pLogger, err := SetLogLevel(deps.lookupEnv) if err != nil { plog.WarningErr("Received error while setting log level", err) } @@ -264,8 +266,9 @@ func tokenCredential(token *oidctypes.Token) *clientauthv1beta1.ExecCredential { return &cred } -func SetLogLevel() (*plog.PLogger, error) { - if os.Getenv("PINNIPED_DEBUG") == "true" { +func SetLogLevel(lookupEnv func(string) (string, bool)) (*plog.PLogger, error) { + debug, _ := lookupEnv("PINNIPED_DEBUG") + if debug == "true" { err := plog.ValidateAndSetLogLevelGlobally(plog.LevelDebug) if err != nil { return nil, err diff --git a/cmd/pinniped/cmd/login_oidc_test.go b/cmd/pinniped/cmd/login_oidc_test.go index 541c6a6da..32179fdeb 100644 --- a/cmd/pinniped/cmd/login_oidc_test.go +++ b/cmd/pinniped/cmd/login_oidc_test.go @@ -9,7 +9,6 @@ import ( "encoding/base64" "fmt" "io/ioutil" - "os" "path/filepath" "testing" "time" @@ -44,7 +43,7 @@ func TestLoginOIDCCommand(t *testing.T) { args []string loginErr error conciergeErr error - envVars map[string]string + env map[string]string wantError bool wantStdout string wantStderr string @@ -175,7 +174,7 @@ func TestLoginOIDCCommand(t *testing.T) { "--client-id", "test-client-id", "--issuer", "test-issuer", }, - envVars: map[string]string{"PINNIPED_DEBUG": "true"}, + env: map[string]string{"PINNIPED_DEBUG": "true"}, wantOptionsCount: 3, wantStdout: `{"kind":"ExecCredential","apiVersion":"client.authentication.k8s.io/v1beta1","spec":{},"status":{"expirationTimestamp":"3020-10-12T13:14:15Z","token":"test-id-token"}}` + "\n", wantLogs: []string{ @@ -202,7 +201,7 @@ func TestLoginOIDCCommand(t *testing.T) { "--concierge-api-group-suffix", "some.suffix.com", "--credential-cache", testutil.TempDir(t) + "/credentials.yaml", }, - envVars: map[string]string{"PINNIPED_DEBUG": "true"}, + env: map[string]string{"PINNIPED_DEBUG": "true"}, wantOptionsCount: 7, wantStdout: `{"kind":"ExecCredential","apiVersion":"client.authentication.k8s.io/v1beta1","spec":{},"status":{"token":"exchanged-token"}}` + "\n", wantLogs: []string{ @@ -214,21 +213,16 @@ func TestLoginOIDCCommand(t *testing.T) { for _, tt := range tests { tt := tt t.Run(tt.name, func(t *testing.T) { - for k, v := range tt.envVars { - kk := k - err := os.Setenv(kk, v) - require.NoError(t, err) - t.Cleanup(func() { - t.Log("cleaning up " + kk) - err = os.Unsetenv(kk) - }) - } testLogger := testlogger.New(t) klog.SetLogger(testLogger) var ( gotOptions []oidcclient.Option ) cmd := oidcLoginCommand(oidcLoginCommandDeps{ + lookupEnv: func(s string) (string, bool) { + v, ok := tt.env[s] + return v, ok + }, login: func(issuer string, clientID string, opts ...oidcclient.Option) (*oidctypes.Token, error) { require.Equal(t, "test-issuer", issuer) require.Equal(t, "test-client-id", clientID) diff --git a/cmd/pinniped/cmd/login_static.go b/cmd/pinniped/cmd/login_static.go index fb1df4d5e..2b3fed1dd 100644 --- a/cmd/pinniped/cmd/login_static.go +++ b/cmd/pinniped/cmd/login_static.go @@ -84,7 +84,7 @@ func staticLoginCommand(deps staticLoginDeps) *cobra.Command { } func runStaticLogin(out io.Writer, deps staticLoginDeps, flags staticLoginParams) error { - pLogger, err := SetLogLevel() + pLogger, err := SetLogLevel(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 c2e6d3ea3..f391da483 100644 --- a/cmd/pinniped/cmd/login_static_test.go +++ b/cmd/pinniped/cmd/login_static_test.go @@ -12,6 +12,10 @@ import ( "testing" "time" + "k8s.io/klog/v2" + + "go.pinniped.dev/internal/testutil/testlogger" + "github.com/stretchr/testify/require" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" clientauthv1beta1 "k8s.io/client-go/pkg/apis/clientauthentication/v1beta1" @@ -41,6 +45,7 @@ func TestLoginStaticCommand(t *testing.T) { wantStdout string wantStderr string wantOptionsCount int + wantLogs []string }{ { name: "help flag passed", @@ -126,10 +131,12 @@ func TestLoginStaticCommand(t *testing.T) { "--concierge-authenticator-name", "test-authenticator", }, conciergeErr: fmt.Errorf("some concierge error"), + env: map[string]string{"PINNIPED_DEBUG": "true"}, wantError: true, 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/\""}, }, { name: "invalid API group suffix", @@ -157,6 +164,8 @@ func TestLoginStaticCommand(t *testing.T) { for _, tt := range tests { tt := tt t.Run(tt.name, func(t *testing.T) { + testLogger := testlogger.New(t) + klog.SetLogger(testLogger) cmd := staticLoginCommand(staticLoginDeps{ lookupEnv: func(s string) (string, bool) { v, ok := tt.env[s] @@ -192,6 +201,8 @@ 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()) }) } } From 09560fd8dc07c6d2ac01120b315db80cd7770243 Mon Sep 17 00:00:00 2001 From: Margo Crawford Date: Mon, 19 Apr 2021 10:46:22 -0700 Subject: [PATCH 07/12] Log lines about using cached credential --- cmd/pinniped/cmd/login_oidc.go | 3 +++ cmd/pinniped/cmd/login_static.go | 1 + cmd/pinniped/cmd/login_static_test.go | 1 + 3 files changed, 5 insertions(+) diff --git a/cmd/pinniped/cmd/login_oidc.go b/cmd/pinniped/cmd/login_oidc.go index 37a19d589..07f871f3f 100644 --- a/cmd/pinniped/cmd/login_oidc.go +++ b/cmd/pinniped/cmd/login_oidc.go @@ -187,6 +187,7 @@ func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLogin if flags.credentialCachePath != "" { credCache = execcredcache.New(flags.credentialCachePath) if cred := credCache.Get(cacheKey); cred != nil { + pLogger.Debug("using cached cluster credential.") return json.NewEncoder(cmd.OutOrStdout()).Encode(cred) } } @@ -209,12 +210,14 @@ func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLogin if err != nil { return fmt.Errorf("could not complete Concierge credential exchange: %w", err) } + pLogger.Debug("Exchanged token for cluster credential") } else { pLogger.Debug("No concierge configured, skipping token credential exchange") } // If there was a credential cache, save the resulting credential for future use. if credCache != nil { + pLogger.Debug("caching cluster credential for future use.") credCache.Put(cacheKey, cred) } return json.NewEncoder(cmd.OutOrStdout()).Encode(cred) diff --git a/cmd/pinniped/cmd/login_static.go b/cmd/pinniped/cmd/login_static.go index 2b3fed1dd..3642ffe14 100644 --- a/cmd/pinniped/cmd/login_static.go +++ b/cmd/pinniped/cmd/login_static.go @@ -137,6 +137,7 @@ func runStaticLogin(out io.Writer, deps staticLoginDeps, flags staticLoginParams if flags.credentialCachePath != "" { credCache = execcredcache.New(flags.credentialCachePath) if cred := credCache.Get(cacheKey); cred != nil { + pLogger.Debug("using cached cluster credential.") return json.NewEncoder(out).Encode(cred) } } diff --git a/cmd/pinniped/cmd/login_static_test.go b/cmd/pinniped/cmd/login_static_test.go index f391da483..7db88e325 100644 --- a/cmd/pinniped/cmd/login_static_test.go +++ b/cmd/pinniped/cmd/login_static_test.go @@ -158,6 +158,7 @@ func TestLoginStaticCommand(t *testing.T) { args: []string{ "--token", "test-token", }, + env: map[string]string{"PINNIPED_DEBUG": "true"}, wantStdout: `{"kind":"ExecCredential","apiVersion":"client.authentication.k8s.io/v1beta1","spec":{},"status":{"token":"test-token"}}` + "\n", }, } From c45d48d02758dd321413f08526a6034668ead86b Mon Sep 17 00:00:00 2001 From: Margo Crawford Date: Wed, 21 Apr 2021 10:58:48 -0700 Subject: [PATCH 08/12] Change test log expectations --- cmd/pinniped/cmd/login_oidc.go | 2 +- cmd/pinniped/cmd/login_oidc_test.go | 3 +++ 2 files changed, 4 insertions(+), 1 deletion(-) diff --git a/cmd/pinniped/cmd/login_oidc.go b/cmd/pinniped/cmd/login_oidc.go index 07f871f3f..27c6b22b3 100644 --- a/cmd/pinniped/cmd/login_oidc.go +++ b/cmd/pinniped/cmd/login_oidc.go @@ -210,7 +210,7 @@ func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLogin if err != nil { return fmt.Errorf("could not complete Concierge credential exchange: %w", err) } - pLogger.Debug("Exchanged token for cluster credential") + pLogger.Debug("Successfully exchanged token for cluster credential.") } else { pLogger.Debug("No concierge configured, skipping token credential exchange") } diff --git a/cmd/pinniped/cmd/login_oidc_test.go b/cmd/pinniped/cmd/login_oidc_test.go index 32179fdeb..559d2c36d 100644 --- a/cmd/pinniped/cmd/login_oidc_test.go +++ b/cmd/pinniped/cmd/login_oidc_test.go @@ -180,6 +180,7 @@ func TestLoginOIDCCommand(t *testing.T) { 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\"", + "\"level\"=0 \"msg\"=\"Pinniped login: caching cluster credential for future use.\"", }, }, { @@ -207,6 +208,8 @@ func TestLoginOIDCCommand(t *testing.T) { 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.\"", }, }, } From 5f3eab25388a53d0dba19238e08f3ad6abcbd387 Mon Sep 17 00:00:00 2001 From: Margo Crawford Date: Wed, 21 Apr 2021 13:05:32 -0700 Subject: [PATCH 09/12] Fix expected number of log lines in TestCLILoginOIDC --- test/integration/cli_test.go | 5 +++-- 1 file changed, 3 insertions(+), 2 deletions(-) diff --git a/test/integration/cli_test.go b/test/integration/cli_test.go index 622e9ba53..e840b34da 100644 --- a/test/integration/cli_test.go +++ b/test/integration/cli_test.go @@ -250,11 +250,12 @@ func TestCLILoginOIDC(t *testing.T) { cmd4StringOutput := string(cmd4CombinedOutput) require.NoError(t, err, cmd4StringOutput) - // the logs contain only the 3 debug lines plus the ExecCredential. There are 5 elements because the last one is "". - require.Len(t, strings.Split(cmd4StringOutput, "\n"), 5) + // the logs contain only the 4 debug lines plus the ExecCredential. There are 6 elements because the last one is "". + require.Len(t, strings.Split(cmd4StringOutput, "\n"), 6) require.Contains(t, cmd4StringOutput, "Performing OIDC login") require.Contains(t, cmd4StringOutput, "Found unexpired cached token") require.Contains(t, cmd4StringOutput, "No concierge configured, skipping token credential exchange") + require.Contains(t, cmd4StringOutput, "caching cluster credential for future use.") require.Contains(t, cmd4StringOutput, credOutput3.Status.Token) err = os.Unsetenv("PINNIPED_DEBUG") require.NoError(t, err) From 90b2854032f0dcd103867acd5e4ddf43ea81044f Mon Sep 17 00:00:00 2001 From: Margo Crawford Date: Wed, 28 Apr 2021 09:34:42 -0700 Subject: [PATCH 10/12] Avoid using global logger in login.go --- cmd/pinniped/cmd/login_oidc.go | 1 + cmd/pinniped/cmd/login_oidc_test.go | 8 +-- pkg/oidcclient/login.go | 18 +++-- pkg/oidcclient/login_test.go | 102 ++++++++++++++-------------- 4 files changed, 71 insertions(+), 58 deletions(-) diff --git a/cmd/pinniped/cmd/login_oidc.go b/cmd/pinniped/cmd/login_oidc.go index 27c6b22b3..d52b71d8b 100644 --- a/cmd/pinniped/cmd/login_oidc.go +++ b/cmd/pinniped/cmd/login_oidc.go @@ -134,6 +134,7 @@ func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLogin // Initialize the login handler. opts := []oidcclient.Option{ oidcclient.WithContext(cmd.Context()), + oidcclient.WithLogger(*pLogger), oidcclient.WithScopes(flags.scopes), oidcclient.WithSessionCache(sessionCache), } diff --git a/cmd/pinniped/cmd/login_oidc_test.go b/cmd/pinniped/cmd/login_oidc_test.go index 559d2c36d..68dc18d7e 100644 --- a/cmd/pinniped/cmd/login_oidc_test.go +++ b/cmd/pinniped/cmd/login_oidc_test.go @@ -145,7 +145,7 @@ func TestLoginOIDCCommand(t *testing.T) { "--issuer", "test-issuer", }, loginErr: fmt.Errorf("some login error"), - wantOptionsCount: 3, + wantOptionsCount: 4, wantError: true, wantStderr: here.Doc(` Error: could not complete Pinniped login: some login error @@ -162,7 +162,7 @@ func TestLoginOIDCCommand(t *testing.T) { "--concierge-endpoint", "https://127.0.0.1:1234/", }, conciergeErr: fmt.Errorf("some concierge error"), - wantOptionsCount: 3, + wantOptionsCount: 4, wantError: true, wantStderr: here.Doc(` Error: could not complete Concierge credential exchange: some concierge error @@ -175,7 +175,7 @@ func TestLoginOIDCCommand(t *testing.T) { "--issuer", "test-issuer", }, env: map[string]string{"PINNIPED_DEBUG": "true"}, - wantOptionsCount: 3, + wantOptionsCount: 4, wantStdout: `{"kind":"ExecCredential","apiVersion":"client.authentication.k8s.io/v1beta1","spec":{},"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\"", @@ -203,7 +203,7 @@ func TestLoginOIDCCommand(t *testing.T) { "--credential-cache", testutil.TempDir(t) + "/credentials.yaml", }, env: map[string]string{"PINNIPED_DEBUG": "true"}, - wantOptionsCount: 7, + wantOptionsCount: 8, wantStdout: `{"kind":"ExecCredential","apiVersion":"client.authentication.k8s.io/v1beta1","spec":{},"status":{"token":"exchanged-token"}}` + "\n", wantLogs: []string{ "\"level\"=0 \"msg\"=\"Pinniped login: Performing OIDC login\" \"client id\"=\"test-client-id\" \"issuer\"=\"test-issuer\"", diff --git a/pkg/oidcclient/login.go b/pkg/oidcclient/login.go index 4d7539449..d606dec7d 100644 --- a/pkg/oidcclient/login.go +++ b/pkg/oidcclient/login.go @@ -50,6 +50,7 @@ const ( type handlerState struct { // Basic parameters. ctx context.Context + logger plog.PLogger issuer string clientID string scopes []string @@ -98,6 +99,15 @@ func WithContext(ctx context.Context) Option { } } +// WithLogger specifies a PLogger to use with the login. +// If not specified this will default to a new logger. +func WithLogger(logger plog.PLogger) Option { + return func(h *handlerState) error { + h.logger = logger + return nil + } +} + // WithListenPort specifies a TCP listen port on localhost, which will be used for the redirect_uri and to handle the // authorization code callback. By default, a random high port will be chosen which requires the authorization server // to support wildcard port numbers as described by https://tools.ietf.org/html/rfc8252: @@ -261,7 +271,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 { - plog.Debug("Pinniped: Found unexpired cached token") + h.logger.Debug("Found unexpired cached token.") return cached, nil } @@ -329,7 +339,7 @@ func (h *handlerState) initOIDCDiscovery() error { return nil } - plog.Debug("Pinniped: Performing OIDC discovery", "issuer", h.issuer) + h.logger.Debug("Performing OIDC discovery", "issuer", h.issuer) var err error h.provider, err = oidc.NewProvider(h.ctx, h.issuer) if err != nil { @@ -346,7 +356,7 @@ func (h *handlerState) initOIDCDiscovery() error { } func (h *handlerState) tokenExchangeRFC8693(baseToken *oidctypes.Token) (*oidctypes.Token, error) { - plog.Debug("Pinniped: Performing RFC8693 token exchange", "requested audience", h.requestedAudience) + h.logger.Debug("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 @@ -417,7 +427,7 @@ func (h *handlerState) tokenExchangeRFC8693(baseToken *oidctypes.Token) (*oidcty } func (h *handlerState) handleRefresh(ctx context.Context, refreshToken *oidctypes.RefreshToken) (*oidctypes.Token, error) { - plog.Debug("refreshing cached token") + h.logger.Debug("Refreshing cached token.") refreshSource := h.oauth2Config.TokenSource(ctx, &oauth2.Token{RefreshToken: refreshToken.Token}) refreshed, err := refreshSource.Token() diff --git a/pkg/oidcclient/login_test.go b/pkg/oidcclient/login_test.go index f1f5f6cfc..89d25e842 100644 --- a/pkg/oidcclient/login_test.go +++ b/pkg/oidcclient/login_test.go @@ -273,7 +273,7 @@ func TestLogin(t *testing.T) { return WithSessionCache(cache)(h) } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"test-issuer\""}, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"test-issuer\""}, wantErr: `could not perform OIDC discovery for "test-issuer": Get "test-issuer/.well-known/openid-configuration": unsupported protocol scheme ""`, }, { @@ -295,7 +295,7 @@ func TestLogin(t *testing.T) { return WithSessionCache(cache)(h) } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Found unexpired cached token\""}, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Found unexpired cached token.\""}, wantToken: &testToken, }, { @@ -304,7 +304,7 @@ func TestLogin(t *testing.T) { return func(h *handlerState) error { return nil } }, issuer: errorServer.URL, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + errorServer.URL + "\""}, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + errorServer.URL + "\""}, wantErr: fmt.Sprintf("could not perform OIDC discovery for %q: 500 Internal Server Error: some discovery error\n", errorServer.URL), }, { @@ -344,8 +344,8 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\"", - "\"level\"=0 \"msg\"=\"refreshing cached token\""}, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Refreshing cached token.\""}, wantToken: &testToken, }, { @@ -378,8 +378,8 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\"", - "\"level\"=0 \"msg\"=\"refreshing cached token\""}, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Refreshing cached token.\""}, wantErr: "some validation error", }, { @@ -406,8 +406,8 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\"", - "\"level\"=0 \"msg\"=\"refreshing cached token\""}, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Refreshing cached token.\""}, // Expect this to fall through to the authorization code flow, so it fails here. wantErr: "could not open callback listener: listen tcp: address invalid-listen-address: missing port in address", }, @@ -420,7 +420,7 @@ func TestLogin(t *testing.T) { } }, issuer: successServer.URL, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: "could not open callback listener: listen tcp: address invalid-listen-address: missing port in address", }, { @@ -431,7 +431,7 @@ func TestLogin(t *testing.T) { }) }, issuer: successServer.URL, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: "could not open browser: some browser open error", }, { @@ -449,7 +449,7 @@ func TestLogin(t *testing.T) { } }, issuer: successServer.URL, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: "timed out waiting for token callback: context canceled", }, { @@ -466,7 +466,7 @@ func TestLogin(t *testing.T) { } }, issuer: successServer.URL, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: "error handling callback: some callback error", }, { @@ -527,7 +527,7 @@ func TestLogin(t *testing.T) { } }, issuer: successServer.URL, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantToken: &testToken, }, { @@ -551,9 +551,9 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Found unexpired cached token\"", - "\"level\"=0 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requested audience\"=\"cluster-1234\"", - "\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + errorServer.URL + "\""}, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Found unexpired cached token.\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing RFC8693 token exchange\" \"requestedAudience\"=\"cluster-1234\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + errorServer.URL + "\""}, wantErr: fmt.Sprintf("failed to exchange token: could not perform OIDC discovery for %q: 500 Internal Server Error: some discovery error\n", errorServer.URL), }, { @@ -577,9 +577,9 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Found unexpired cached token\"", - "\"level\"=0 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requested audience\"=\"cluster-1234\"", - "\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + brokenTokenURLServer.URL + "\""}, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Found unexpired cached token.\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing RFC8693 token exchange\" \"requestedAudience\"=\"cluster-1234\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + brokenTokenURLServer.URL + "\""}, wantErr: `failed to exchange token: could not build RFC8693 request: parse "%": invalid URL escape "%"`, }, { @@ -603,9 +603,9 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Found unexpired cached token\"", - "\"level\"=0 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requested audience\"=\"test-audience-produce-invalid-http-response\"", - "\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Found unexpired cached token.\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience-produce-invalid-http-response\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: fmt.Sprintf(`failed to exchange token: Post "%s/token": failed to parse Location header "%%": parse "%%": invalid URL escape "%%"`, successServer.URL), }, { @@ -629,9 +629,9 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Found unexpired cached token\"", - "\"level\"=0 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requested audience\"=\"test-audience-produce-http-400\"", - "\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Found unexpired cached token.\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience-produce-http-400\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: `failed to exchange token: unexpected HTTP response status 400`, }, { @@ -655,9 +655,9 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Found unexpired cached token\"", - "\"level\"=0 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requested audience\"=\"test-audience-produce-invalid-content-type\"", - "\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Found unexpired cached token.\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience-produce-invalid-content-type\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: `failed to exchange token: failed to decode content-type header: mime: invalid media parameter`, }, { @@ -681,9 +681,9 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Found unexpired cached token\"", - "\"level\"=0 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requested audience\"=\"test-audience-produce-wrong-content-type\"", - "\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Found unexpired cached token.\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience-produce-wrong-content-type\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: `failed to exchange token: unexpected HTTP response content type "invalid"`, }, { @@ -707,9 +707,9 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Found unexpired cached token\"", - "\"level\"=0 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requested audience\"=\"test-audience-produce-invalid-json\"", - "\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Found unexpired cached token.\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience-produce-invalid-json\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: `failed to exchange token: failed to decode response: unexpected EOF`, }, { @@ -733,9 +733,9 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Found unexpired cached token\"", - "\"level\"=0 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requested audience\"=\"test-audience-produce-invalid-tokentype\"", - "\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Found unexpired cached token.\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience-produce-invalid-tokentype\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: `failed to exchange token: got unexpected token_type "invalid"`, }, { @@ -759,9 +759,9 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Found unexpired cached token\"", - "\"level\"=0 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requested audience\"=\"test-audience-produce-invalid-issuedtokentype\"", - "\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Found unexpired cached token.\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience-produce-invalid-issuedtokentype\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: `failed to exchange token: got unexpected issued_token_type "invalid"`, }, { @@ -785,9 +785,9 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Found unexpired cached token\"", - "\"level\"=0 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requested audience\"=\"test-audience-produce-invalid-jwt\"", - "\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Found unexpired cached token.\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience-produce-invalid-jwt\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: `failed to exchange token: received invalid JWT: oidc: malformed jwt: square/go-jose: compact JWS format must have three parts`, }, { @@ -817,9 +817,9 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped: Found unexpired cached token\"", - "\"level\"=0 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requested audience\"=\"test-audience\"", - "\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Found unexpired cached token.\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantToken: &testExchangedToken, }, { @@ -868,9 +868,9 @@ func TestLogin(t *testing.T) { } }, wantLogs: []string{ - "\"level\"=0 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\"", - "\"level\"=0 \"msg\"=\"refreshing cached token\"", - "\"level\"=0 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requested audience\"=\"test-audience\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Refreshing cached token.\"", + "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience\"", }, wantToken: &testExchangedToken, }, @@ -881,6 +881,7 @@ func TestLogin(t *testing.T) { err := plog.ValidateAndSetLogLevelGlobally(plog.LevelDebug) require.NoError(t, err) testLogger := testlogger.New(t) + pLogger := plog.New("Pinniped Test Prefix: ") klog.SetLogger(testLogger) tok, err := Login(tt.issuer, tt.clientID, @@ -888,6 +889,7 @@ func TestLogin(t *testing.T) { WithListenPort(0), WithScopes([]string{"test-scope"}), tt.opt(t), + WithLogger(pLogger), ) require.Equal(t, tt.wantLogs, testLogger.Lines()) if tt.wantErr != "" { From ab94b97f4a43f80e3509368aaab57a631a48cb79 Mon Sep 17 00:00:00 2001 From: Margo Crawford Date: Fri, 30 Apr 2021 12:10:04 -0700 Subject: [PATCH 11/12] Change login.go to use logr.logger --- cmd/pinniped/cmd/login_oidc.go | 2 +- pkg/oidcclient/login.go | 16 ++--- pkg/oidcclient/login_test.go | 109 ++++++++++++++++----------------- 3 files changed, 64 insertions(+), 63 deletions(-) diff --git a/cmd/pinniped/cmd/login_oidc.go b/cmd/pinniped/cmd/login_oidc.go index d52b71d8b..4c1620bee 100644 --- a/cmd/pinniped/cmd/login_oidc.go +++ b/cmd/pinniped/cmd/login_oidc.go @@ -134,7 +134,7 @@ func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLogin // Initialize the login handler. opts := []oidcclient.Option{ oidcclient.WithContext(cmd.Context()), - oidcclient.WithLogger(*pLogger), + oidcclient.WithLogger(klogr.New()), oidcclient.WithScopes(flags.scopes), oidcclient.WithSessionCache(sessionCache), } diff --git a/pkg/oidcclient/login.go b/pkg/oidcclient/login.go index d606dec7d..142b67792 100644 --- a/pkg/oidcclient/login.go +++ b/pkg/oidcclient/login.go @@ -17,6 +17,7 @@ import ( "time" "github.com/coreos/go-oidc/v3/oidc" + "github.com/go-logr/logr" "github.com/pkg/browser" "golang.org/x/oauth2" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" @@ -24,7 +25,6 @@ import ( "go.pinniped.dev/internal/httputil/httperr" "go.pinniped.dev/internal/httputil/securityheader" "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" @@ -45,12 +45,14 @@ const ( // overallTimeout is the overall time that a login is allowed to take. This includes several user interactions, so // we set this to be relatively long. overallTimeout = 90 * time.Minute + + debugLogLevel = 4 ) type handlerState struct { // Basic parameters. ctx context.Context - logger plog.PLogger + logger logr.Logger issuer string clientID string scopes []string @@ -101,7 +103,7 @@ func WithContext(ctx context.Context) Option { // WithLogger specifies a PLogger to use with the login. // If not specified this will default to a new logger. -func WithLogger(logger plog.PLogger) Option { +func WithLogger(logger logr.Logger) Option { return func(h *handlerState) error { h.logger = logger return nil @@ -271,7 +273,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.Debug("Found unexpired cached token.") + h.logger.V(debugLogLevel).Info("Pinniped: Found unexpired cached token.") return cached, nil } @@ -339,7 +341,7 @@ func (h *handlerState) initOIDCDiscovery() error { return nil } - h.logger.Debug("Performing OIDC discovery", "issuer", h.issuer) + h.logger.V(debugLogLevel).Info("Pinniped: Performing OIDC discovery", "issuer", h.issuer) var err error h.provider, err = oidc.NewProvider(h.ctx, h.issuer) if err != nil { @@ -356,7 +358,7 @@ func (h *handlerState) initOIDCDiscovery() error { } func (h *handlerState) tokenExchangeRFC8693(baseToken *oidctypes.Token) (*oidctypes.Token, error) { - h.logger.Debug("Performing RFC8693 token exchange", "requestedAudience", h.requestedAudience) + h.logger.V(debugLogLevel).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 @@ -427,7 +429,7 @@ func (h *handlerState) tokenExchangeRFC8693(baseToken *oidctypes.Token) (*oidcty } func (h *handlerState) handleRefresh(ctx context.Context, refreshToken *oidctypes.RefreshToken) (*oidctypes.Token, error) { - h.logger.Debug("Refreshing cached token.") + h.logger.V(debugLogLevel).Info("Pinniped: Refreshing cached token.") refreshSource := h.oauth2Config.TokenSource(ctx, &oauth2.Token{RefreshToken: refreshToken.Token}) refreshed, err := refreshSource.Token() diff --git a/pkg/oidcclient/login_test.go b/pkg/oidcclient/login_test.go index 89d25e842..c3ac66090 100644 --- a/pkg/oidcclient/login_test.go +++ b/pkg/oidcclient/login_test.go @@ -13,6 +13,8 @@ import ( "testing" "time" + "github.com/go-logr/stdr" + "github.com/coreos/go-oidc/v3/oidc" "github.com/golang/mock/gomock" "github.com/stretchr/testify/assert" @@ -24,7 +26,6 @@ import ( "go.pinniped.dev/internal/httputil/httperr" "go.pinniped.dev/internal/mocks/mockupstreamoidcidentityprovider" "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/pkg/oidcclient/nonce" @@ -273,7 +274,7 @@ func TestLogin(t *testing.T) { return WithSessionCache(cache)(h) } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"test-issuer\""}, + wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"test-issuer\""}, wantErr: `could not perform OIDC discovery for "test-issuer": Get "test-issuer/.well-known/openid-configuration": unsupported protocol scheme ""`, }, { @@ -295,7 +296,7 @@ func TestLogin(t *testing.T) { return WithSessionCache(cache)(h) } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Found unexpired cached token.\""}, + wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Found unexpired cached token.\""}, wantToken: &testToken, }, { @@ -304,7 +305,7 @@ func TestLogin(t *testing.T) { return func(h *handlerState) error { return nil } }, issuer: errorServer.URL, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + errorServer.URL + "\""}, + wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + errorServer.URL + "\""}, wantErr: fmt.Sprintf("could not perform OIDC discovery for %q: 500 Internal Server Error: some discovery error\n", errorServer.URL), }, { @@ -344,8 +345,8 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Refreshing cached token.\""}, + wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\"", + "\"level\"=4 \"msg\"=\"Pinniped: Refreshing cached token.\""}, wantToken: &testToken, }, { @@ -378,8 +379,8 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Refreshing cached token.\""}, + wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\"", + "\"level\"=4 \"msg\"=\"Pinniped: Refreshing cached token.\""}, wantErr: "some validation error", }, { @@ -406,8 +407,8 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Refreshing cached token.\""}, + wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\"", + "\"level\"=4 \"msg\"=\"Pinniped: Refreshing cached token.\""}, // Expect this to fall through to the authorization code flow, so it fails here. wantErr: "could not open callback listener: listen tcp: address invalid-listen-address: missing port in address", }, @@ -420,7 +421,7 @@ func TestLogin(t *testing.T) { } }, issuer: successServer.URL, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: "could not open callback listener: listen tcp: address invalid-listen-address: missing port in address", }, { @@ -431,7 +432,7 @@ func TestLogin(t *testing.T) { }) }, issuer: successServer.URL, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: "could not open browser: some browser open error", }, { @@ -449,7 +450,7 @@ func TestLogin(t *testing.T) { } }, issuer: successServer.URL, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: "timed out waiting for token callback: context canceled", }, { @@ -466,7 +467,7 @@ func TestLogin(t *testing.T) { } }, issuer: successServer.URL, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: "error handling callback: some callback error", }, { @@ -527,7 +528,7 @@ func TestLogin(t *testing.T) { } }, issuer: successServer.URL, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantToken: &testToken, }, { @@ -551,9 +552,9 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Found unexpired cached token.\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing RFC8693 token exchange\" \"requestedAudience\"=\"cluster-1234\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + errorServer.URL + "\""}, + wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Found unexpired cached token.\"", + "\"level\"=4 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requestedAudience\"=\"cluster-1234\"", + "\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + errorServer.URL + "\""}, wantErr: fmt.Sprintf("failed to exchange token: could not perform OIDC discovery for %q: 500 Internal Server Error: some discovery error\n", errorServer.URL), }, { @@ -577,9 +578,9 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Found unexpired cached token.\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing RFC8693 token exchange\" \"requestedAudience\"=\"cluster-1234\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + brokenTokenURLServer.URL + "\""}, + wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Found unexpired cached token.\"", + "\"level\"=4 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requestedAudience\"=\"cluster-1234\"", + "\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + brokenTokenURLServer.URL + "\""}, wantErr: `failed to exchange token: could not build RFC8693 request: parse "%": invalid URL escape "%"`, }, { @@ -603,9 +604,9 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Found unexpired cached token.\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience-produce-invalid-http-response\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Found unexpired cached token.\"", + "\"level\"=4 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience-produce-invalid-http-response\"", + "\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: fmt.Sprintf(`failed to exchange token: Post "%s/token": failed to parse Location header "%%": parse "%%": invalid URL escape "%%"`, successServer.URL), }, { @@ -629,9 +630,9 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Found unexpired cached token.\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience-produce-http-400\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Found unexpired cached token.\"", + "\"level\"=4 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience-produce-http-400\"", + "\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: `failed to exchange token: unexpected HTTP response status 400`, }, { @@ -655,9 +656,9 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Found unexpired cached token.\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience-produce-invalid-content-type\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Found unexpired cached token.\"", + "\"level\"=4 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience-produce-invalid-content-type\"", + "\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: `failed to exchange token: failed to decode content-type header: mime: invalid media parameter`, }, { @@ -681,9 +682,9 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Found unexpired cached token.\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience-produce-wrong-content-type\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Found unexpired cached token.\"", + "\"level\"=4 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience-produce-wrong-content-type\"", + "\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: `failed to exchange token: unexpected HTTP response content type "invalid"`, }, { @@ -707,9 +708,9 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Found unexpired cached token.\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience-produce-invalid-json\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Found unexpired cached token.\"", + "\"level\"=4 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience-produce-invalid-json\"", + "\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: `failed to exchange token: failed to decode response: unexpected EOF`, }, { @@ -733,9 +734,9 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Found unexpired cached token.\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience-produce-invalid-tokentype\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Found unexpired cached token.\"", + "\"level\"=4 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience-produce-invalid-tokentype\"", + "\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: `failed to exchange token: got unexpected token_type "invalid"`, }, { @@ -759,9 +760,9 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Found unexpired cached token.\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience-produce-invalid-issuedtokentype\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Found unexpired cached token.\"", + "\"level\"=4 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience-produce-invalid-issuedtokentype\"", + "\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: `failed to exchange token: got unexpected issued_token_type "invalid"`, }, { @@ -785,9 +786,9 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Found unexpired cached token.\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience-produce-invalid-jwt\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Found unexpired cached token.\"", + "\"level\"=4 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience-produce-invalid-jwt\"", + "\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantErr: `failed to exchange token: received invalid JWT: oidc: malformed jwt: square/go-jose: compact JWS format must have three parts`, }, { @@ -817,9 +818,9 @@ func TestLogin(t *testing.T) { return nil } }, - wantLogs: []string{"\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Found unexpired cached token.\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, + wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Found unexpired cached token.\"", + "\"level\"=4 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience\"", + "\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\""}, wantToken: &testExchangedToken, }, { @@ -868,9 +869,9 @@ func TestLogin(t *testing.T) { } }, wantLogs: []string{ - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Refreshing cached token.\"", - "\"level\"=0 \"msg\"=\"Pinniped Test Prefix: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience\"", + "\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\" \"issuer\"=\"" + successServer.URL + "\"", + "\"level\"=4 \"msg\"=\"Pinniped: Refreshing cached token.\"", + "\"level\"=4 \"msg\"=\"Pinniped: Performing RFC8693 token exchange\" \"requestedAudience\"=\"test-audience\"", }, wantToken: &testExchangedToken, }, @@ -878,18 +879,16 @@ func TestLogin(t *testing.T) { for _, tt := range tests { tt := tt t.Run(tt.name, func(t *testing.T) { - err := plog.ValidateAndSetLogLevelGlobally(plog.LevelDebug) - require.NoError(t, err) testLogger := testlogger.New(t) - pLogger := plog.New("Pinniped Test Prefix: ") klog.SetLogger(testLogger) + stdr.SetVerbosity(debugLogLevel) // set stdr's global log level to debug so the test logger will send output. tok, err := Login(tt.issuer, tt.clientID, WithContext(context.Background()), WithListenPort(0), WithScopes([]string{"test-scope"}), tt.opt(t), - WithLogger(pLogger), + WithLogger(testLogger), ) require.Equal(t, tt.wantLogs, testLogger.Lines()) if tt.wantErr != "" { From 71e38d232e70bce84a63ff2cf26fce6566edb6db Mon Sep 17 00:00:00 2001 From: Ryan Richard Date: Mon, 3 May 2021 09:13:18 -0700 Subject: [PATCH 12/12] login.go discards logs by default Signed-off-by: Margo Crawford --- pkg/oidcclient/login.go | 1 + 1 file changed, 1 insertion(+) diff --git a/pkg/oidcclient/login.go b/pkg/oidcclient/login.go index 142b67792..14ca72d31 100644 --- a/pkg/oidcclient/login.go +++ b/pkg/oidcclient/login.go @@ -196,6 +196,7 @@ func Login(issuer string, clientID string, opts ...Option) (*oidctypes.Token, er cache: &nopCache{}, callbackPath: "/callback", ctx: context.Background(), + logger: logr.Discard(), // discard logs unless a logger is specified callbacks: make(chan callbackResult), httpClient: http.DefaultClient,