From 211d4fd0b6f5e312e62bc3e360c659c457b06408 Mon Sep 17 00:00:00 2001 From: Margo Crawford Date: Wed, 7 Apr 2021 15:30:29 -0700 Subject: [PATCH] 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 9eaa433f..88a5d36a 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 53b6efd4..4d753944 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 3bf37437..6f58ed61 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.