Merge pull request #560 from vmware-tanzu/client-debug-logging

Client debug logging

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"
@@ -36,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)
 		},
@@ -110,6 +114,11 @@ func oidcLoginCommand(deps oidcLoginCommandDeps) *cobra.Command {
 }
 
 func runOIDCLogin(cmd *cobra.Command, deps oidcLoginCommandDeps, flags oidcLoginFlags) error {
+	pLogger, err := SetLogLevel(deps.lookupEnv)
+	if err != nil {
+		plog.WarningErr("Received error while setting log level", err)
+	}
+
 	// Initialize the session cache.
 	var sessionOptions []filesession.Option
 
@@ -125,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(klogr.New()),
 		oidcclient.WithScopes(flags.scopes),
 		oidcclient.WithSessionCache(sessionCache),
 	}
@@ -166,7 +176,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"`
@@ -179,10 +188,12 @@ 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)
 		}
 	}
 
+	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 {
@@ -192,6 +203,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 {
+		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()
 
@@ -199,10 +211,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("Successfully 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)
@@ -224,7 +240,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 +248,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 +270,18 @@ func tokenCredential(token *oidctypes.Token) *clientauthv1beta1.ExecCredential {
 	return &cred
 }
 
+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
+		}
+	}
+	logger := plog.New("Pinniped login: ")
+	return &logger, nil
+}
+
 // 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.

cmd/pinniped/cmd/login_oidc_test.go

@@ -16,10 +16,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 +43,12 @@ func TestLoginOIDCCommand(t *testing.T) {
 		args             []string
 		loginErr         error
 		conciergeErr     error
+		env              map[string]string
 		wantError        bool
 		wantStdout       string
 		wantStderr       string
 		wantOptionsCount int
+		wantLogs         []string
 	}{
 		{
 			name: "help flag passed",
@@ -141,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
@@ -158,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
@@ -170,8 +174,14 @@ func TestLoginOIDCCommand(t *testing.T) {
 				"--client-id", "test-client-id",
 				"--issuer", "test-issuer",
 			},
-			wantOptionsCount: 3,
+			env:              map[string]string{"PINNIPED_DEBUG": "true"},
+			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\"",
+				"\"level\"=0 \"msg\"=\"Pinniped login: No concierge configured, skipping token credential exchange\"",
+				"\"level\"=0 \"msg\"=\"Pinniped login: caching cluster credential for future use.\"",
+			},
 		},
 		{
 			name: "success with all options",
@@ -192,17 +202,30 @@ func TestLoginOIDCCommand(t *testing.T) {
 				"--concierge-api-group-suffix", "some.suffix.com",
 				"--credential-cache", testutil.TempDir(t) + "/credentials.yaml",
 			},
-			wantOptionsCount: 7,
+			env:              map[string]string{"PINNIPED_DEBUG": "true"},
+			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\"",
+				"\"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.\"",
+			},
 		},
 	}
 	for _, tt := range tests {
 		tt := tt
 		t.Run(tt.name, func(t *testing.T) {
+			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)
@@ -248,6 +271,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())
 		})
 	}
 }

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,11 @@ func staticLoginCommand(deps staticLoginDeps) *cobra.Command {
 }
 
 func runStaticLogin(out io.Writer, deps staticLoginDeps, flags staticLoginParams) error {
+	pLogger, err := SetLogLevel(deps.lookupEnv)
+	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")
 	}
@@ -131,12 +137,14 @@ 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)
 		}
 	}
 
 	// If the concierge was configured, exchange the credential for a separate short-lived, cluster-specific credential.
 	if concierge != nil {
+		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()
 
@@ -145,6 +153,7 @@ func runStaticLogin(out io.Writer, deps staticLoginDeps, flags staticLoginParams
 		if err != nil {
 			return fmt.Errorf("could not complete Concierge credential exchange: %w", err)
 		}
+		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

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",
@@ -151,12 +158,15 @@ 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",
 		},
 	}
 	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 +202,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())
 		})
 	}
 }

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.
+type _ interface {
-func Error(msg string, err error, keysAndValues ...interface{}) {
+	Error(msg string, err error, keysAndValues ...interface{})
-	klog.ErrorS(err, msg, keysAndValues...)
+	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...)
 }

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.
@@ -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"
@@ -44,11 +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   logr.Logger
 	issuer   string
 	clientID string
 	scopes   []string
@@ -97,6 +101,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 logr.Logger) 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:
@@ -183,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,
 
@@ -260,6 +274,7 @@ func (h *handlerState) baseLogin() (*oidctypes.Token, error) {
 	// If the ID token is still valid for a bit, return it immediately and skip the rest of the flow.
 	cached := h.cache.GetToken(cacheKey)
 	if cached != nil && cached.IDToken != nil && time.Until(cached.IDToken.Expiry.Time) > minIDTokenValidity {
+		h.logger.V(debugLogLevel).Info("Pinniped: Found unexpired cached token.")
 		return cached, nil
 	}
 
@@ -327,6 +342,7 @@ func (h *handlerState) initOIDCDiscovery() error {
 		return nil
 	}
 
+	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 {
@@ -343,6 +359,7 @@ func (h *handlerState) initOIDCDiscovery() error {
 }
 
 func (h *handlerState) tokenExchangeRFC8693(baseToken *oidctypes.Token) (*oidctypes.Token, error) {
+	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
@@ -413,6 +430,7 @@ func (h *handlerState) tokenExchangeRFC8693(baseToken *oidctypes.Token) (*oidcty
 }
 
 func (h *handlerState) handleRefresh(ctx context.Context, refreshToken *oidctypes.RefreshToken) (*oidctypes.Token, error) {
+	h.logger.V(debugLogLevel).Info("Pinniped: Refreshing cached token.")
 	refreshSource := h.oauth2Config.TokenSource(ctx, &oauth2.Token{RefreshToken: refreshToken.Token})
 
 	refreshed, err := refreshSource.Token()

pkg/oidcclient/login_test.go

@@ -13,17 +13,21 @@ 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"
 	"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/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 +209,7 @@ func TestLogin(t *testing.T) {
 		clientID  string
 		wantErr   string
 		wantToken *oidctypes.Token
+		wantLogs  []string
 	}{
 		{
 			name: "option error",
@@ -269,7 +274,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\"=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 ""`,
 		},
 		{
 			name:     "session cache hit with valid token",
@@ -290,6 +296,7 @@ func TestLogin(t *testing.T) {
 					return WithSessionCache(cache)(h)
 				}
 			},
+			wantLogs:  []string{"\"level\"=4 \"msg\"=\"Pinniped: Found unexpired cached token.\""},
 			wantToken: &testToken,
 		},
 		{
@@ -297,8 +304,9 @@ func TestLogin(t *testing.T) {
 			opt: func(t *testing.T) Option {
 				return func(h *handlerState) error { return nil }
 			},
-			issuer:  errorServer.URL,
+			issuer:   errorServer.URL,
-			wantErr: fmt.Sprintf("could not perform OIDC discovery for %q: 500 Internal Server Error: some discovery error\n", 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),
 		},
 		{
 			name:     "session cache hit with refreshable token",
@@ -337,6 +345,8 @@ func TestLogin(t *testing.T) {
 					return nil
 				}
 			},
+			wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\"  \"issuer\"=\"" + successServer.URL + "\"",
+				"\"level\"=4 \"msg\"=\"Pinniped: Refreshing cached token.\""},
 			wantToken: &testToken,
 		},
 		{
@@ -369,6 +379,8 @@ func TestLogin(t *testing.T) {
 					return nil
 				}
 			},
+			wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\"  \"issuer\"=\"" + successServer.URL + "\"",
+				"\"level\"=4 \"msg\"=\"Pinniped: Refreshing cached token.\""},
 			wantErr: "some validation error",
 		},
 		{
@@ -395,6 +407,8 @@ func TestLogin(t *testing.T) {
 					return nil
 				}
 			},
+			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",
 		},
@@ -406,8 +420,9 @@ func TestLogin(t *testing.T) {
 					return nil
 				}
 			},
-			issuer:  successServer.URL,
+			issuer:   successServer.URL,
-			wantErr: "could not open callback listener: listen tcp: address invalid-listen-address: missing port in address",
+			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",
 		},
 		{
 			name: "browser open failure",
@@ -416,8 +431,9 @@ func TestLogin(t *testing.T) {
 					return fmt.Errorf("some browser open error")
 				})
 			},
-			issuer:  successServer.URL,
+			issuer:   successServer.URL,
-			wantErr: "could not open browser: some browser open error",
+			wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\"  \"issuer\"=\"" + successServer.URL + "\""},
+			wantErr:  "could not open browser: some browser open error",
 		},
 		{
 			name: "timeout waiting for callback",
@@ -433,8 +449,9 @@ func TestLogin(t *testing.T) {
 					return nil
 				}
 			},
-			issuer:  successServer.URL,
+			issuer:   successServer.URL,
-			wantErr: "timed out waiting for token callback: context canceled",
+			wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\"  \"issuer\"=\"" + successServer.URL + "\""},
+			wantErr:  "timed out waiting for token callback: context canceled",
 		},
 		{
 			name: "callback returns error",
@@ -449,8 +466,9 @@ func TestLogin(t *testing.T) {
 					return nil
 				}
 			},
-			issuer:  successServer.URL,
+			issuer:   successServer.URL,
-			wantErr: "error handling callback: some callback error",
+			wantLogs: []string{"\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\"  \"issuer\"=\"" + successServer.URL + "\""},
+			wantErr:  "error handling callback: some callback error",
 		},
 		{
 			name:     "callback returns success",
@@ -510,6 +528,7 @@ func TestLogin(t *testing.T) {
 				}
 			},
 			issuer:    successServer.URL,
+			wantLogs:  []string{"\"level\"=4 \"msg\"=\"Pinniped: Performing OIDC discovery\"  \"issuer\"=\"" + successServer.URL + "\""},
 			wantToken: &testToken,
 		},
 		{
@@ -533,6 +552,9 @@ func TestLogin(t *testing.T) {
 					return nil
 				}
 			},
+			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),
 		},
 		{
@@ -556,6 +578,9 @@ func TestLogin(t *testing.T) {
 					return nil
 				}
 			},
+			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 "%"`,
 		},
 		{
@@ -579,6 +604,9 @@ func TestLogin(t *testing.T) {
 					return nil
 				}
 			},
+			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),
 		},
 		{
@@ -602,6 +630,9 @@ func TestLogin(t *testing.T) {
 					return nil
 				}
 			},
+			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`,
 		},
 		{
@@ -625,6 +656,9 @@ func TestLogin(t *testing.T) {
 					return nil
 				}
 			},
+			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`,
 		},
 		{
@@ -648,6 +682,9 @@ func TestLogin(t *testing.T) {
 					return nil
 				}
 			},
+			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"`,
 		},
 		{
@@ -671,6 +708,9 @@ func TestLogin(t *testing.T) {
 					return nil
 				}
 			},
+			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`,
 		},
 		{
@@ -694,6 +734,9 @@ func TestLogin(t *testing.T) {
 					return nil
 				}
 			},
+			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"`,
 		},
 		{
@@ -717,6 +760,9 @@ func TestLogin(t *testing.T) {
 					return nil
 				}
 			},
+			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"`,
 		},
 		{
@@ -740,6 +786,9 @@ func TestLogin(t *testing.T) {
 					return nil
 				}
 			},
+			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`,
 		},
 		{
@@ -769,6 +818,9 @@ func TestLogin(t *testing.T) {
 					return nil
 				}
 			},
+			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,
 		},
 		{
@@ -816,18 +868,29 @@ func TestLogin(t *testing.T) {
 					return nil
 				}
 			},
+			wantLogs: []string{
+				"\"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,
 		},
 	}
 	for _, tt := range tests {
 		tt := tt
 		t.Run(tt.name, func(t *testing.T) {
+			testLogger := testlogger.New(t)
+			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(testLogger),
 			)
+			require.Equal(t, tt.wantLogs, testLogger.Lines())
 			if tt.wantErr != "" {
 				require.EqualError(t, err, tt.wantErr)
 				require.Nil(t, tok)

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,6 +239,26 @@ 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()
+	cmd4StringOutput := string(cmd4CombinedOutput)
+	require.NoError(t, err, cmd4StringOutput)
+
+	// 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)
 }
 
 func runPinnipedLoginOIDC(
@@ -271,6 +293,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 +305,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.