From b5889f37ff68b10bc4fe3dca8a3c1d01913dcc16 Mon Sep 17 00:00:00 2001 From: Margo Crawford Date: Fri, 16 Apr 2021 10:46:59 -0700 Subject: [PATCH] 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 c7ad0594..091827cc 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 8472f6af..541c6a6d 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 dcdc8c4d..fb1df4d5 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 b38e7179..cf6bc80b 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 8005bcaf..f1f5f6cf 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)