From 1006dd93796d60e5fdbb7104090cd0a152669779 Mon Sep 17 00:00:00 2001 From: Ryan Richard Date: Mon, 4 Nov 2024 11:10:37 -0800 Subject: [PATCH] resolve some todos --- .../supervisorstorage/garbage_collector.go | 7 ++-- .../endpoints/auth/auth_handler_test.go | 3 ++ .../callback/callback_handler_test.go | 7 ++-- .../endpoints/login/login_handler_test.go | 3 ++ .../endpointsmanager/manager.go | 32 ++++++------------- .../requestlogger/request_logger.go | 18 +++++++---- .../requestlogger/request_logger_test.go | 4 +-- internal/plog/plog.go | 1 - internal/testutil/log_lines.go | 11 ++++--- site/content/docs/reference/audit-logging.md | 2 +- 10 files changed, 46 insertions(+), 42 deletions(-) diff --git a/internal/controller/supervisorstorage/garbage_collector.go b/internal/controller/supervisorstorage/garbage_collector.go index 0ed723197..4e92f1da8 100644 --- a/internal/controller/supervisorstorage/garbage_collector.go +++ b/internal/controller/supervisorstorage/garbage_collector.go @@ -283,7 +283,7 @@ func (c *garbageCollectorController) tryRevokeUpstreamOIDCToken( if err != nil { return err } - c.auditLogger.Audit(plog.AuditEventUpstreamOIDCTokenRevoked, nil, request, + c.auditLogger.Audit(plog.AuditEventUpstreamOIDCTokenRevoked, plog.NoHTTPRequestAvailable(), request, "type", upstreamprovider.RefreshTokenType) plog.Trace("garbage collector successfully revoked upstream OIDC refresh token (or provider has no revocation endpoint)", logKV(secret)...) } @@ -293,7 +293,7 @@ func (c *garbageCollectorController) tryRevokeUpstreamOIDCToken( if err != nil { return err } - c.auditLogger.Audit(plog.AuditEventUpstreamOIDCTokenRevoked, nil, request, + c.auditLogger.Audit(plog.AuditEventUpstreamOIDCTokenRevoked, plog.NoHTTPRequestAvailable(), request, "type", upstreamprovider.AccessTokenType) plog.Trace("garbage collector successfully revoked upstream OIDC access token (or provider has no revocation endpoint)", logKV(secret)...) } @@ -304,7 +304,8 @@ func (c *garbageCollectorController) tryRevokeUpstreamOIDCToken( func (c *garbageCollectorController) maybeAuditLogGC(storageType string, secret *corev1.Secret) { r, err := c.requestFromSecret(storageType, secret) if err == nil && r != nil { - c.auditLogger.Audit(plog.AuditEventSessionGarbageCollected, nil, r, "storageType", storageType) + c.auditLogger.Audit(plog.AuditEventSessionGarbageCollected, plog.NoHTTPRequestAvailable(), r, + "storageType", storageType) } } diff --git a/internal/federationdomain/endpoints/auth/auth_handler_test.go b/internal/federationdomain/endpoints/auth/auth_handler_test.go index 5a1dd4e35..c71cefb62 100644 --- a/internal/federationdomain/endpoints/auth/auth_handler_test.go +++ b/internal/federationdomain/endpoints/auth/auth_handler_test.go @@ -35,6 +35,7 @@ import ( "go.pinniped.dev/internal/federationdomain/endpoints/jwks" "go.pinniped.dev/internal/federationdomain/oidc" "go.pinniped.dev/internal/federationdomain/oidcclientvalidator" + "go.pinniped.dev/internal/federationdomain/requestlogger" "go.pinniped.dev/internal/federationdomain/stateparam" "go.pinniped.dev/internal/federationdomain/storage" "go.pinniped.dev/internal/here" @@ -3803,6 +3804,7 @@ func TestAuthorizationEndpoint(t *testing.T) { //nolint:gocyclo if test.customPasswordHeader != nil { req.Header.Set("Pinniped-Password", *test.customPasswordHeader) } + req, _ = requestlogger.NewRequestWithAuditID(req, func() string { return "fake-audit-id" }) rsp := httptest.NewRecorder() subject.ServeHTTP(rsp, req) @@ -3874,6 +3876,7 @@ func TestAuthorizationEndpoint(t *testing.T) { //nolint:gocyclo if test.wantAuditLogs != nil { wantAuditLogs := test.wantAuditLogs(stateparam.Encoded(actualQueryStateParam), sessionID) + testutil.WantAuditIDOnEveryAuditLog(wantAuditLogs, "fake-audit-id") testutil.CompareAuditLogs(t, wantAuditLogs, auditLog.String()) } diff --git a/internal/federationdomain/endpoints/callback/callback_handler_test.go b/internal/federationdomain/endpoints/callback/callback_handler_test.go index 19ae26a39..01bcb8fd3 100644 --- a/internal/federationdomain/endpoints/callback/callback_handler_test.go +++ b/internal/federationdomain/endpoints/callback/callback_handler_test.go @@ -25,6 +25,7 @@ import ( "go.pinniped.dev/internal/federationdomain/endpoints/jwks" "go.pinniped.dev/internal/federationdomain/oidc" "go.pinniped.dev/internal/federationdomain/oidcclientvalidator" + "go.pinniped.dev/internal/federationdomain/requestlogger" "go.pinniped.dev/internal/federationdomain/stateparam" "go.pinniped.dev/internal/federationdomain/storage" "go.pinniped.dev/internal/federationdomain/upstreamprovider" @@ -1868,6 +1869,7 @@ func TestCallbackEndpoint(t *testing.T) { if test.csrfCookie != "" { req.Header.Set("Cookie", test.csrfCookie) } + req, _ = requestlogger.NewRequestWithAuditID(req, func() string { return "fake-audit-id" }) rsp := httptest.NewRecorder() subject.ServeHTTP(rsp, req) t.Logf("response: %#v", rsp) @@ -1877,13 +1879,13 @@ func TestCallbackEndpoint(t *testing.T) { switch { case test.wantOIDCAuthcodeExchangeCall != nil: - test.wantOIDCAuthcodeExchangeCall.args.Ctx = reqContext + test.wantOIDCAuthcodeExchangeCall.args.Ctx = req.Context() test.idps.RequireExactlyOneOIDCAuthcodeExchange(t, test.wantOIDCAuthcodeExchangeCall.performedByUpstreamName, test.wantOIDCAuthcodeExchangeCall.args, ) case test.wantGitHubAuthcodeExchangeCall != nil: - test.wantGitHubAuthcodeExchangeCall.args.Ctx = reqContext + test.wantGitHubAuthcodeExchangeCall.args.Ctx = req.Context() test.idps.RequireExactlyOneGitHubAuthcodeExchange(t, test.wantGitHubAuthcodeExchangeCall.performedByUpstreamName, test.wantGitHubAuthcodeExchangeCall.args, @@ -1956,6 +1958,7 @@ func TestCallbackEndpoint(t *testing.T) { if test.wantAuditLogs != nil { wantAuditLogs := test.wantAuditLogs(testutil.GetStateParam(t, test.path), sessionID) + testutil.WantAuditIDOnEveryAuditLog(wantAuditLogs, "fake-audit-id") testutil.CompareAuditLogs(t, wantAuditLogs, log.String()) } }) diff --git a/internal/federationdomain/endpoints/login/login_handler_test.go b/internal/federationdomain/endpoints/login/login_handler_test.go index 776b93ca5..fa753b05f 100644 --- a/internal/federationdomain/endpoints/login/login_handler_test.go +++ b/internal/federationdomain/endpoints/login/login_handler_test.go @@ -14,6 +14,7 @@ import ( "github.com/stretchr/testify/require" "go.pinniped.dev/internal/federationdomain/oidc" + "go.pinniped.dev/internal/federationdomain/requestlogger" "go.pinniped.dev/internal/federationdomain/stateparam" "go.pinniped.dev/internal/httputil/httperr" "go.pinniped.dev/internal/plog" @@ -411,6 +412,7 @@ func TestLoginEndpoint(t *testing.T) { if test.csrfCookie != "" { req.Header.Set("Cookie", test.csrfCookie) } + req, _ = requestlogger.NewRequestWithAuditID(req, func() string { return "fake-audit-id" }) rsp := httptest.NewRecorder() testGetHandler := func( @@ -465,6 +467,7 @@ func TestLoginEndpoint(t *testing.T) { if test.wantAuditLogs != nil { wantAuditLogs := test.wantAuditLogs(testutil.GetStateParam(t, test.path)) + testutil.WantAuditIDOnEveryAuditLog(wantAuditLogs, "fake-audit-id") testutil.CompareAuditLogs(t, wantAuditLogs, log.String()) } }) diff --git a/internal/federationdomain/endpointsmanager/manager.go b/internal/federationdomain/endpointsmanager/manager.go index 566d5c9a7..b3a0a60ee 100644 --- a/internal/federationdomain/endpointsmanager/manager.go +++ b/internal/federationdomain/endpointsmanager/manager.go @@ -8,7 +8,6 @@ import ( "strings" "sync" - "github.com/google/uuid" corev1client "k8s.io/client-go/kubernetes/typed/core/v1" "go.pinniped.dev/generated/latest/client/supervisor/clientset/versioned/typed/config/v1alpha1" @@ -29,7 +28,6 @@ import ( "go.pinniped.dev/internal/federationdomain/oidcclientvalidator" "go.pinniped.dev/internal/federationdomain/requestlogger" "go.pinniped.dev/internal/federationdomain/storage" - "go.pinniped.dev/internal/httputil/requestutil" "go.pinniped.dev/internal/plog" "go.pinniped.dev/internal/secret" "go.pinniped.dev/pkg/oidcclient/nonce" @@ -194,36 +192,24 @@ func (m *Manager) SetFederationDomains(federationDomains ...*federationdomainpro } func (m *Manager) buildHandlerChain(nextHandler http.Handler, auditCfg supervisor.AuditSpec) { - // build the basic handler for FederationDomain endpoints + // Build the basic handler for FederationDomain endpoints. handler := m.buildManagerHandler(nextHandler) - // log all requests, including audit ID + // Log all requests, including audit ID. handler = requestlogger.WithHTTPRequestAuditLogging(handler, m.auditLogger, auditCfg) - // add random audit ID to request context and response headers - handler = requestlogger.WithAuditID(handler, func() string { - return uuid.New().String() - }) + // Add random audit ID to request context and response headers. + handler = requestlogger.WithAuditID(handler) m.handlerChain = handler } func (m *Manager) buildManagerHandler(nextHandler http.Handler) http.Handler { return http.HandlerFunc(func(resp http.ResponseWriter, req *http.Request) { requestHandler := m.findHandler(req) - - // TODO: Should this old log message change in light of the new audit logs? Or do we not want to force people to enable audit logs to debug this SNI stuff? - // Using Info level so the user can safely configure a production Supervisor to show this message if they choose. - plog.Info("received incoming request", - "proto", req.Proto, - "method", req.Method, - "host", req.Host, - "requestSNIServerName", requestutil.SNIServerName(req), - "path", req.URL.Path, - "remoteAddr", req.RemoteAddr, - "userAgent", req.UserAgent(), - "foundFederationDomainRequestHandler", requestHandler != nil, - ) - if requestHandler == nil { - requestHandler = nextHandler // couldn't find an issuer to handle the request + // Couldn't find any FederationDomain to handle this request based on the request's host and path. + // It could be a bad request to a path that does not exist. Or it could be because something in + // front of the Supervisor is not passing the SNI of the original request through to the Supervisor. + // All 404's will be logged by request_logger.go, so we don't need to log it here. + requestHandler = nextHandler } requestHandler.ServeHTTP(resp, req) }) diff --git a/internal/federationdomain/requestlogger/request_logger.go b/internal/federationdomain/requestlogger/request_logger.go index 9b026c33a..d82a78494 100644 --- a/internal/federationdomain/requestlogger/request_logger.go +++ b/internal/federationdomain/requestlogger/request_logger.go @@ -11,6 +11,7 @@ import ( "slices" "time" + "github.com/google/uuid" "k8s.io/apimachinery/pkg/types" "k8s.io/apimachinery/pkg/util/sets" apisaudit "k8s.io/apiserver/pkg/apis/audit" @@ -23,6 +24,7 @@ import ( "go.pinniped.dev/internal/plog" ) +// NewRequestWithAuditID is public for use in unit tests. Production code should use WithAuditID(). func NewRequestWithAuditID(r *http.Request, newAuditIDFunc func() string) (*http.Request, string) { ctx := audit.WithAuditContext(r.Context()) r = r.WithContext(ctx) @@ -33,9 +35,12 @@ func NewRequestWithAuditID(r *http.Request, newAuditIDFunc func() string) (*http return r, auditID } -func WithAuditID(handler http.Handler, newAuditIDFunc func() string) http.Handler { +func WithAuditID(handler http.Handler) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - r, auditID := NewRequestWithAuditID(r, newAuditIDFunc) + // Add a randomly generated request ID to the context for this request. + r, auditID := NewRequestWithAuditID(r, func() string { + return uuid.New().String() + }) // Send the Audit-ID response header. w.Header().Set(apisaudit.HeaderAuditID, auditID) @@ -48,8 +53,8 @@ func WithHTTPRequestAuditLogging(handler http.Handler, auditLogger plog.AuditLog return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { rl := newRequestLogger(req, w, auditLogger, time.Now(), auditCfg) - rl.LogRequestReceived() - defer rl.LogRequestComplete() + rl.logRequestReceived() + defer rl.logRequestComplete() statusCodeCapturingResponseWriter := responsewriter.WrapForHTTP1Or2(rl) handler.ServeHTTP(statusCodeCapturingResponseWriter, req) @@ -90,13 +95,14 @@ func internalPaths() []string { } } -func (rl *requestLogger) LogRequestReceived() { +func (rl *requestLogger) logRequestReceived() { r := rl.req if rl.auditCfg.InternalPaths != supervisor.AuditInternalPathsEnabled && slices.Contains(internalPaths(), r.URL.Path) { return } + // Always log all other requests, including 404's caused by bad paths, for debugging purposes. rl.auditLogger.Audit(plog.AuditEventHTTPRequestReceived, r.Context(), plog.NoSessionPersisted(), @@ -110,7 +116,7 @@ func (rl *requestLogger) LogRequestReceived() { ) } -func (rl *requestLogger) LogRequestComplete() { +func (rl *requestLogger) logRequestComplete() { r := rl.req if rl.auditCfg.InternalPaths != supervisor.AuditInternalPathsEnabled && slices.Contains(internalPaths(), r.URL.Path) { diff --git a/internal/federationdomain/requestlogger/request_logger_test.go b/internal/federationdomain/requestlogger/request_logger_test.go index 2e2aae20d..82a12c3c5 100644 --- a/internal/federationdomain/requestlogger/request_logger_test.go +++ b/internal/federationdomain/requestlogger/request_logger_test.go @@ -98,7 +98,7 @@ func TestLogRequestReceived(t *testing.T) { auditCfg: test.auditCfg, } - subject.LogRequestReceived() + subject.logRequestReceived() testutil.CompareAuditLogs(t, test.wantAuditLogs, log.String()) }) @@ -217,7 +217,7 @@ func TestLogRequestComplete(t *testing.T) { auditCfg: test.auditCfg, } - subject.LogRequestComplete() + subject.logRequestComplete() testutil.CompareAuditLogs(t, test.wantAuditLogs, log.String()) }) diff --git a/internal/plog/plog.go b/internal/plog/plog.go index 6253e8027..81e9893da 100644 --- a/internal/plog/plog.go +++ b/internal/plog/plog.go @@ -126,7 +126,6 @@ func (p pLogger) Error(msg string, err error, keysAndValues ...any) { // by their own separate configuration. This is because Audit logs should always be printed when they are desired // by the admin, regardless of global log level, yet the admin should also have a way to entirely disable them // when they want to avoid potential PII (e.g. usernames) in their pod logs. -// TODO: Add a way to disable output of audit logs, separate from the log level config. func (p pLogger) Audit(msg AuditEventMessage, reqCtx context.Context, session SessionIDGetter, keysAndValues ...any) { // Always add a key/value auditEvent=true. keysAndValues = slices.Concat([]any{"auditEvent", true}, keysAndValues) diff --git a/internal/testutil/log_lines.go b/internal/testutil/log_lines.go index d60ae0bbf..048e7c916 100644 --- a/internal/testutil/log_lines.go +++ b/internal/testutil/log_lines.go @@ -30,17 +30,20 @@ type WantedAuditLog struct { Params map[string]any } -func WantAuditLog(message string, params map[string]any, auditID ...string) WantedAuditLog { +func WantAuditLog(message string, params map[string]any) WantedAuditLog { result := WantedAuditLog{ Message: message, Params: params, } - if len(auditID) > 0 { - result.Params["auditID"] = auditID[0] - } return result } +func WantAuditIDOnEveryAuditLog(wantedAuditLogs []WantedAuditLog, wantAuditID string) { + for _, wantedAuditLog := range wantedAuditLogs { + wantedAuditLog.Params["auditID"] = wantAuditID + } +} + func GetStateParam(t *testing.T, fullURL string) stateparam.Encoded { var encodedStateParam stateparam.Encoded if fullURL != "" { diff --git a/site/content/docs/reference/audit-logging.md b/site/content/docs/reference/audit-logging.md index 978fc28ab..23f43cc34 100644 --- a/site/content/docs/reference/audit-logging.md +++ b/site/content/docs/reference/audit-logging.md @@ -64,7 +64,7 @@ Every log line in a Supervisor or Concierge pod log is a JSON object. Only those key/value pair `"auditEvent": true` are audit events. Other lines are for errors, warnings, and debugging information. -Every audit log contains the following keys, and audit event lines also contain these common keys/values: +Every line in the pod logs contains the following common keys/values, including audit event log lines: - `timestamp`, whose value is in UTC time, e.g. `2024-07-10T20:03:26.164470Z` - `level`, which for an audit event will always have the value `info`