Add more logging, integration test checks that debug flag works.

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.

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

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 {
+		scanner := bufio.NewScanner(reader)
-			return fmt.Errorf("could not read login URL line from stderr: %w", err)
-		}
 		const prompt = "Please log in: "
-		if !strings.HasPrefix(line, prompt) {
+		for scanner.Scan() {
-			return fmt.Errorf("expected %q to have prefix %q", line, prompt)
+			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.