mirrors/pinniped
1
0
Fork 0
mirror of https://github.com/vmware-tanzu/pinniped.git synced 2026-01-07 14:05:50 +00:00
Code Issues Actions Packages Projects Releases Wiki Activity

Use plog.Logger instead of logr.Logger wherever possible

Browse Source
This commit is contained in:
Joshua Casey
2024-05-12 19:11:16 -05:00
parent 247ac10215
commit c6463831ac
19 changed files with 586 additions and 448 deletions
Download Patch File Download Diff File Expand all files Collapse all files

82
pkg/oidcclient/login.go
View File

@@ -80,13 +80,15 @@ func stdin() int { return int(os.Stdin.Fd()) }
type handlerState struct {
// Basic parameters.
ctx context.Context
logger logr.Logger
logger Logger
issuer string
clientID string
scopes []string
cache SessionCache
out io.Writer // this is stderr except in unit tests
loggerOptionsCount int
// Tracking the usage of some other functional options.
upstreamIdentityProviderName string
upstreamIdentityProviderType idpdiscoveryv1alpha1.IDPType
@@ -143,11 +145,57 @@ func WithContext(ctx context.Context) Option {
}
}
type Logger interface {
Error(msg string, err error, keysAndValues ...any)
Info(msg string, keysAndValues ...any)
}
type logrLoggerWrapper struct {
logger logr.Logger
}
var _ Logger = (*logrLoggerWrapper)(nil)
func (l *logrLoggerWrapper) Error(msg string, err error, keysAndValues ...any) {
l.logger.V(plog.KlogLevelDebug).Error(err, msg, keysAndValues...)
}
func (l *logrLoggerWrapper) Info(msg string, keysAndValues ...any) {
l.logger.V(plog.KlogLevelDebug).Info(msg, keysAndValues...)
}
type emptyLogger struct{}
var _ Logger = (*emptyLogger)(nil)
func (e emptyLogger) Error(_ string, _ error, _ ...any) {
// NOOP
}
func (e emptyLogger) Info(_ string, _ ...any) {
// NOOP
}
// WithLogger specifies a PLogger to use with the login.
// If not specified this will default to a new logger.
// If not specified this will default to a no-op logger.
//
// Deprecated: Use WithLoginLogger instead.
// This option will be removed in a future version of Pinniped.
// If this option is used along with WithLoginLogger, it will cause an error.
func WithLogger(logger logr.Logger) Option {
return func(h *handlerState) error {
h.logger = &logrLoggerWrapper{logger: logger}
h.loggerOptionsCount++
return nil
}
}
// WithLoginLogger specifies a Logger to use.
// If not specified this will default to a no-op logger.
func WithLoginLogger(logger Logger) Option {
return func(h *handlerState) error {
h.logger = logger
h.loggerOptionsCount++
return nil
}
}
@@ -319,7 +367,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
logger: &emptyLogger{},
callbacks: make(chan callbackResult, 2),
httpClient: phttp.Default(nil),
@@ -352,6 +400,10 @@ func Login(issuer string, clientID string, opts ...Option) (*oidctypes.Token, er
h.loginFlow = idpdiscoveryv1alpha1.IDPFlowCLIPassword
}
if h.loggerOptionsCount > 1 {
return nil, fmt.Errorf("please use only one mechanism to specify the logger")
}
// Copy the configured HTTP client to set a request timeout (the Go default client has no timeout configured).
httpClientWithTimeout := *h.httpClient
httpClientWithTimeout.Timeout = httpRequestTimeout
@@ -444,7 +496,7 @@ func (h *handlerState) baseLogin() (*oidctypes.Token, error) {
// return the cached tokens immediately and skip the rest of the flow.
cached := h.cache.GetToken(cacheKey)
if valid, whichTokenWasValid := h.tokenValidForNearFuture(cached); valid {
h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Found unexpired cached token.", "type", whichTokenWasValid)
h.logger.Info("Pinniped: Found unexpired cached token.", "type", whichTokenWasValid)
return cached, nil
}
@@ -713,7 +765,7 @@ func (h *handlerState) getUsernameAndPassword() (string, string, error) {
return "", "", fmt.Errorf("error prompting for username: %w", err)
}
} else {
h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Read username from environment variable", "name", defaultUsernameEnvVarName)
h.logger.Info("Pinniped: Read username from environment variable", "name", defaultUsernameEnvVarName)
}
password := h.getEnv(defaultPasswordEnvVarName)
@@ -723,7 +775,7 @@ func (h *handlerState) getUsernameAndPassword() (string, string, error) {
return "", "", fmt.Errorf("error prompting for password: %w", err)
}
} else {
h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Read password from environment variable", "name", defaultPasswordEnvVarName)
h.logger.Info("Pinniped: Read password from environment variable", "name", defaultPasswordEnvVarName)
}
return username, password, nil
@@ -735,7 +787,7 @@ func (h *handlerState) webBrowserBasedAuth(authorizeOptions *[]oauth2.AuthCodeOp
// Attempt to open a local TCP listener, logging but otherwise ignoring any error.
listener, err := h.listen("tcp", h.listenAddr)
if err != nil {
h.logger.V(plog.KlogLevelDebug).Error(err, "could not open callback listener")
h.logger.Error("could not open callback listener", err)
}
// If the listener failed to start and stdin is not a TTY, then we have no hope of succeeding,
@@ -774,7 +826,7 @@ func (h *handlerState) webBrowserBasedAuth(authorizeOptions *[]oauth2.AuthCodeOp
openedBrowser := false
if !h.skipBrowser {
if err := h.openURL(authorizeURL); err != nil {
h.logger.V(plog.KlogLevelDebug).Error(err, "could not open browser")
h.logger.Error("could not open browser", err)
} else {
openedBrowser = true
}
@@ -924,7 +976,7 @@ func (h *handlerState) initOIDCDiscovery() error {
return err
}
h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Performing OIDC discovery", "issuer", h.issuer)
h.logger.Info("Pinniped: Performing OIDC discovery", "issuer", h.issuer)
var err error
h.provider, err = coreosoidc.NewProvider(h.ctx, h.issuer)
if err != nil {
@@ -1027,7 +1079,7 @@ func validateURLUsesHTTPS(uri string, uriName string) error {
}
func (h *handlerState) tokenExchangeRFC8693(baseToken *oidctypes.Token) (*oidctypes.Token, error) {
h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Performing RFC8693 token exchange", "requestedAudience", h.requestedAudience)
h.logger.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
@@ -1098,13 +1150,13 @@ func (h *handlerState) tokenExchangeRFC8693(baseToken *oidctypes.Token) (*oidcty
}
func (h *handlerState) handleRefresh(ctx context.Context, refreshToken *oidctypes.RefreshToken) (*oidctypes.Token, error) {
h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Refreshing cached tokens.")
h.logger.Info("Pinniped: Refreshing cached tokens.")
upstreamOIDCIdentityProvider := h.getProvider(h.oauth2Config, h.provider, h.httpClient)
refreshed, err := upstreamOIDCIdentityProvider.PerformRefresh(ctx, refreshToken.Token)
if err != nil {
// Ignore errors during refresh, but return nil which will trigger the full login flow.
h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Refresh failed.", "error", err.Error())
h.logger.Info("Pinniped: Refresh failed.", "error", err.Error())
return nil, nil
}
@@ -1153,11 +1205,11 @@ func (h *handlerState) handleAuthCodeCallback(w http.ResponseWriter, r *http.Req
origin := r.Header.Get("Origin")
if origin == "" {
// The CORS preflight request should have an origin.
h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Got OPTIONS request without origin header")
h.logger.Info("Pinniped: Got OPTIONS request without origin header")
w.WriteHeader(http.StatusBadRequest)
return nil // keep listening for more requests
}
h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Got CORS preflight request from browser", "origin", origin)
h.logger.Info("Pinniped: Got CORS preflight request from browser", "origin", origin)
// To tell the browser that it is okay to make the real POST or GET request, return the following response.
w.Header().Set("Access-Control-Allow-Origin", allowOrigin)
w.Header().Set("Vary", "*") // supposed to use Vary when Access-Control-Allow-Origin is a specific host
@@ -1188,7 +1240,7 @@ func (h *handlerState) handleAuthCodeCallback(w http.ResponseWriter, r *http.Req
default:
// Return HTTP 405 for anything that's not a POST, GET, or an OPTIONS request.
h.logger.V(plog.KlogLevelDebug).Info("Pinniped: Got unexpected request on callback listener", "method", r.Method)
h.logger.Info("Pinniped: Got unexpected request on callback listener", "method", r.Method)
w.WriteHeader(http.StatusMethodNotAllowed)
return nil // keep listening for more requests
}

49
pkg/oidcclient/login_test.go
View File

@@ -22,6 +22,7 @@ import (
"time"
coreosoidc "github.com/coreos/go-oidc/v3/oidc"
"github.com/go-logr/logr"
"github.com/stretchr/testify/assert"
"github.com/stretchr/testify/require"
"go.uber.org/mock/gomock"
@@ -3370,7 +3371,7 @@ func TestHandleAuthCodeCallback(t *testing.T) {
state: state.State("test-state"),
pkce: pkce.Code("test-pkce"),
nonce: nonce.Nonce("test-nonce"),
logger: plog.Logr(), //nolint:staticcheck // old test with no log assertions
logger: plog.New(),
issuer: "https://valid-issuer.com/with/some/path",
}
if tt.opt != nil {
@@ -3864,3 +3865,49 @@ func TestMaybePerformPinnipedSupervisorValidations(t *testing.T) {
})
}
}
func TestLoggers(t *testing.T) {
t.Run("with deprecated logger and new logger, returns an error", func(t *testing.T) {
token, err := Login("https://127.0.0.1", "clientID",
WithLogger(logr.Discard()),
WithLoginLogger(plog.New()),
)
require.EqualError(t, err, "please use only one mechanism to specify the logger")
require.Nil(t, token)
})
issuer, _ := tlsserver.TestServerIPv4(t, http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
http.Error(w, "some discovery error", http.StatusInternalServerError)
}), nil)
t.Run("with new logger, outputs logs", func(t *testing.T) {
var log bytes.Buffer
token, err := Login(issuer.URL, "clientID",
WithLoginLogger(plog.TestLogger(t, &log)),
)
// This error is expected, we're testing logs not discovery
require.EqualError(t, err, `could not perform OIDC discovery for "`+issuer.URL+`": Get "`+issuer.URL+`/.well-known/openid-configuration": tls: failed to verify certificate: x509: certificate signed by unknown authority`)
require.Nil(t, token)
wantLog := `{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"oidcclient/login.go:<line>$oidcclient.(*handlerState).initOIDCDiscovery","message":"Pinniped: Performing OIDC discovery","issuer":"` + issuer.URL + `"}`
require.Equal(t, wantLog+"\n", log.String())
})
t.Run("with deprecated logger, outputs logs", func(t *testing.T) {
testLog := testlogger.NewLegacy(t) //nolint:staticcheck // This is specifically meant to test deprecated code
token, err := Login(issuer.URL, "clientID",
WithLogger(testLog.Logger),
)
// This error is expected, we're testing logs not discovery
require.EqualError(t, err, `could not perform OIDC discovery for "`+issuer.URL+`": Get "`+issuer.URL+`/.well-known/openid-configuration": tls: failed to verify certificate: x509: certificate signed by unknown authority`)
require.Nil(t, token)
wantLogs := []string{
`"level"=4 "msg"="Pinniped: Performing OIDC discovery" "issuer"="` + issuer.URL + `"`,
}
require.Equal(t, wantLogs, testLog.Lines())
})
// NOTE: We can't really test logs with the default (e.g. no logger option specified)
}