From c5f4cce3aec35a23690ace6b6a1c811b18463689 Mon Sep 17 00:00:00 2001 From: Ryan Richard Date: Mon, 11 Nov 2024 18:05:00 -0800 Subject: [PATCH] make Audit() take struct as param for all optional params and redact PII --- .../supervisorstorage/garbage_collector.go | 18 +- .../downstreamsession/downstream_session.go | 41 +- .../endpoints/auth/auth_handler.go | 38 +- .../endpoints/callback/callback_handler.go | 8 +- .../endpoints/login/login_handler.go | 6 +- .../endpoints/token/token_handler.go | 30 +- .../tokenendpointauditor/parameter_auditor.go | 7 +- .../requestlogger/request_logger.go | 40 +- internal/plog/plog.go | 103 +++- internal/plog/plog_test.go | 536 +++++++++++------- internal/plog/testing.go | 6 +- internal/registry/credentialrequest/rest.go | 14 +- 12 files changed, 562 insertions(+), 285 deletions(-) diff --git a/internal/controller/supervisorstorage/garbage_collector.go b/internal/controller/supervisorstorage/garbage_collector.go index 7f64cf527..394ddf371 100644 --- a/internal/controller/supervisorstorage/garbage_collector.go +++ b/internal/controller/supervisorstorage/garbage_collector.go @@ -291,8 +291,10 @@ func (c *garbageCollectorController) tryRevokeUpstreamOIDCToken( if err != nil { return err } - c.auditLogger.Audit(auditevent.UpstreamOIDCTokenRevoked, plog.NoHTTPRequestAvailable(), request, - "type", upstreamprovider.RefreshTokenType) + c.auditLogger.Audit(auditevent.UpstreamOIDCTokenRevoked, &plog.AuditParams{ + Session: request, + KeysAndValues: []any{"type", upstreamprovider.RefreshTokenType}, + }) plog.Trace("garbage collector successfully revoked upstream OIDC refresh token (or provider has no revocation endpoint)", logKV(secret)...) } @@ -301,8 +303,10 @@ func (c *garbageCollectorController) tryRevokeUpstreamOIDCToken( if err != nil { return err } - c.auditLogger.Audit(auditevent.UpstreamOIDCTokenRevoked, plog.NoHTTPRequestAvailable(), request, - "type", upstreamprovider.AccessTokenType) + c.auditLogger.Audit(auditevent.UpstreamOIDCTokenRevoked, &plog.AuditParams{ + Session: request, + KeysAndValues: []any{"type", upstreamprovider.AccessTokenType}, + }) plog.Trace("garbage collector successfully revoked upstream OIDC access token (or provider has no revocation endpoint)", logKV(secret)...) } @@ -312,8 +316,10 @@ 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(auditevent.SessionGarbageCollected, plog.NoHTTPRequestAvailable(), r, - "storageType", storageType) + c.auditLogger.Audit(auditevent.SessionGarbageCollected, &plog.AuditParams{ + Session: r, + KeysAndValues: []any{"storageType", storageType}, + }) } } diff --git a/internal/federationdomain/downstreamsession/downstream_session.go b/internal/federationdomain/downstreamsession/downstream_session.go index 8a4bcb4d8..609d8ece8 100644 --- a/internal/federationdomain/downstreamsession/downstream_session.go +++ b/internal/federationdomain/downstreamsession/downstream_session.go @@ -50,19 +50,25 @@ func NewPinnipedSession( ) (*psession.PinnipedSession, error) { now := time.Now().UTC() - auditLogger.Audit(auditevent.IdentityFromUpstreamIDP, ctx, plog.NoSessionPersisted(), - "upstreamIDPDisplayName", c.IdentityProvider.GetDisplayName(), - "upstreamIDPType", c.IdentityProvider.GetSessionProviderType(), - "upstreamIDPResourceName", c.IdentityProvider.GetProvider().GetResourceName(), - "upstreamIDPResourceUID", c.IdentityProvider.GetProvider().GetResourceUID(), - "upstreamUsername", c.UpstreamIdentity.UpstreamUsername, - "upstreamGroups", c.UpstreamIdentity.UpstreamGroups) + auditLogger.Audit(auditevent.IdentityFromUpstreamIDP, &plog.AuditParams{ + ReqCtx: ctx, + KeysAndValues: []any{ + "upstreamIDPDisplayName", c.IdentityProvider.GetDisplayName(), + "upstreamIDPType", c.IdentityProvider.GetSessionProviderType(), + "upstreamIDPResourceName", c.IdentityProvider.GetProvider().GetResourceName(), + "upstreamIDPResourceUID", c.IdentityProvider.GetProvider().GetResourceUID(), + "upstreamUsername", c.UpstreamIdentity.UpstreamUsername, + "upstreamGroups", c.UpstreamIdentity.UpstreamGroups, + }, + }) downstreamUsername, downstreamGroups, err := applyIdentityTransformations(ctx, c.IdentityProvider.GetTransforms(), c.UpstreamIdentity.UpstreamUsername, c.UpstreamIdentity.UpstreamGroups) if err != nil { - auditLogger.Audit(auditevent.AuthenticationRejectedByTransforms, ctx, plog.NoSessionPersisted(), - "reason", err) + auditLogger.Audit(auditevent.AuthenticationRejectedByTransforms, &plog.AuditParams{ + ReqCtx: ctx, + KeysAndValues: []any{"reason", err}, + }) return nil, err } @@ -109,12 +115,17 @@ func NewPinnipedSession( pinnipedSession.IDTokenClaims().Extra = extras - auditLogger.Audit(auditevent.SessionStarted, ctx, c.SessionIDGetter, - "username", downstreamUsername, - "groups", downstreamGroups, - "subject", c.UpstreamIdentity.DownstreamSubject, - "additionalClaims", c.UpstreamLoginExtras.DownstreamAdditionalClaims, - "warnings", c.UpstreamLoginExtras.Warnings) + auditLogger.Audit(auditevent.SessionStarted, &plog.AuditParams{ + ReqCtx: ctx, + Session: c.SessionIDGetter, + KeysAndValues: []any{ + "username", downstreamUsername, + "groups", downstreamGroups, + "subject", c.UpstreamIdentity.DownstreamSubject, + "additionalClaims", c.UpstreamLoginExtras.DownstreamAdditionalClaims, + "warnings", c.UpstreamLoginExtras.Warnings, + }, + }) return pinnipedSession, nil } diff --git a/internal/federationdomain/endpoints/auth/auth_handler.go b/internal/federationdomain/endpoints/auth/auth_handler.go index a046ccc75..93bffc61f 100644 --- a/internal/federationdomain/endpoints/auth/auth_handler.go +++ b/internal/federationdomain/endpoints/auth/auth_handler.go @@ -112,12 +112,18 @@ func (h *authorizeHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { // Log if these headers were present, but don't log the actual values. The password is obviously sensitive, // and sometimes users use their password as their username by mistake. - h.auditLogger.Audit(auditevent.HTTPRequestCustomHeadersUsed, r.Context(), plog.NoSessionPersisted(), - oidcapi.AuthorizeUsernameHeaderName, hadUsernameHeader, - oidcapi.AuthorizePasswordHeaderName, hadPasswordHeader) + h.auditLogger.Audit(auditevent.HTTPRequestCustomHeadersUsed, &plog.AuditParams{ + ReqCtx: r.Context(), + KeysAndValues: []any{ + oidcapi.AuthorizeUsernameHeaderName, hadUsernameHeader, + oidcapi.AuthorizePasswordHeaderName, hadPasswordHeader, + }, + }) - h.auditLogger.Audit(auditevent.HTTPRequestParameters, r.Context(), plog.NoSessionPersisted(), - auditevent.SanitizeParams(r.Form, paramsSafeToLog())...) + h.auditLogger.Audit(auditevent.HTTPRequestParameters, &plog.AuditParams{ + ReqCtx: r.Context(), + KeysAndValues: auditevent.SanitizeParams(r.Form, paramsSafeToLog()), + }) if r.Method != http.MethodPost && r.Method != http.MethodGet { // https://openid.net/specs/openid-connect-core-1_0.html#AuthRequest @@ -156,17 +162,21 @@ func (h *authorizeHandler) ServeHTTP(w http.ResponseWriter, r *http.Request) { return } - h.auditLogger.Audit(auditevent.UsingUpstreamIDP, r.Context(), plog.NoSessionPersisted(), - "displayName", idp.GetDisplayName(), - "resourceName", idp.GetProvider().GetResourceName(), - "resourceUID", idp.GetProvider().GetResourceUID(), - "type", idp.GetSessionProviderType()) + h.auditLogger.Audit(auditevent.UsingUpstreamIDP, &plog.AuditParams{ + ReqCtx: r.Context(), + KeysAndValues: []any{ + "displayName", idp.GetDisplayName(), + "resourceName", idp.GetProvider().GetResourceName(), + "resourceUID", idp.GetProvider().GetResourceUID(), + "type", idp.GetSessionProviderType(), + }, + }) h.authorize(w, r, requestedBrowserlessFlow, idp) } // parseForm parses the query params and/or POST body form params. It returns an error, or in the case of success it -// has the side-effect of leaving the parsed form params on the http.Request in the Form field. Request body +// has the side effect of leaving the parsed form params on the http.Request in the Form field. Request body // parameters take precedence over URL query string values. func parseForm(r *http.Request) error { // The style of form parsing and the text of the error is inspired by fosite's implementation of NewAuthorizeRequest(). @@ -221,8 +231,10 @@ func (h *authorizeHandler) authorize( authorizeID, err = h.authorizeWithBrowser(r, w, oauthHelper, authorizeRequester, idp) if err == nil { - h.auditLogger.Audit(auditevent.UpstreamAuthorizeRedirect, r.Context(), plog.NoSessionPersisted(), - "authorizeID", authorizeID) + h.auditLogger.Audit(auditevent.UpstreamAuthorizeRedirect, &plog.AuditParams{ + ReqCtx: r.Context(), + KeysAndValues: []any{"authorizeID", authorizeID}, + }) } } if err != nil { diff --git a/internal/federationdomain/endpoints/callback/callback_handler.go b/internal/federationdomain/endpoints/callback/callback_handler.go index 8078e530b..79e149e50 100644 --- a/internal/federationdomain/endpoints/callback/callback_handler.go +++ b/internal/federationdomain/endpoints/callback/callback_handler.go @@ -34,8 +34,10 @@ func NewHandler( return err } - auditLogger.Audit(auditevent.AuthorizeIDFromParameters, r.Context(), plog.NoSessionPersisted(), - "authorizeID", encodedState.AuthorizeID()) + auditLogger.Audit(auditevent.AuthorizeIDFromParameters, &plog.AuditParams{ + ReqCtx: r.Context(), + KeysAndValues: []any{"authorizeID", encodedState.AuthorizeID()}, + }) idp, err := upstreamIDPs.FindUpstreamIDPByDisplayName(decodedState.UpstreamName) if err != nil || idp == nil { @@ -49,7 +51,7 @@ func NewHandler( return httperr.New(http.StatusBadRequest, "error reading state downstream auth params") } - // Recreate enough of the original authorize request so we can pass it to NewAuthorizeRequest(). + // Recreate enough of the original authorize request, so we can pass it to NewAuthorizeRequest(). reconstitutedAuthRequest := &http.Request{Form: downstreamAuthParams} authorizeRequester, err := oauthHelper.NewAuthorizeRequest(r.Context(), reconstitutedAuthRequest) if err != nil { diff --git a/internal/federationdomain/endpoints/login/login_handler.go b/internal/federationdomain/endpoints/login/login_handler.go index d1a4c4126..288694db1 100644 --- a/internal/federationdomain/endpoints/login/login_handler.go +++ b/internal/federationdomain/endpoints/login/login_handler.go @@ -59,8 +59,10 @@ func NewHandler( return err } - auditLogger.Audit(auditevent.AuthorizeIDFromParameters, r.Context(), plog.NoSessionPersisted(), - "authorizeID", encodedState.AuthorizeID()) + auditLogger.Audit(auditevent.AuthorizeIDFromParameters, &plog.AuditParams{ + ReqCtx: r.Context(), + KeysAndValues: []any{"authorizeID", encodedState.AuthorizeID()}, + }) switch decodedState.UpstreamType { case string(idpdiscoveryv1alpha1.IDPTypeLDAP), string(idpdiscoveryv1alpha1.IDPTypeActiveDirectory): diff --git a/internal/federationdomain/endpoints/token/token_handler.go b/internal/federationdomain/endpoints/token/token_handler.go index e701be106..46f3b7c05 100644 --- a/internal/federationdomain/endpoints/token/token_handler.go +++ b/internal/federationdomain/endpoints/token/token_handler.go @@ -192,9 +192,14 @@ func upstreamRefresh( return err } - auditLogger.Audit(auditevent.IdentityRefreshedFromUpstreamIDP, ctx, accessRequest, - "upstreamUsername", refreshedIdentity.UpstreamUsername, - "upstreamGroups", refreshedIdentity.UpstreamGroups) + auditLogger.Audit(auditevent.IdentityRefreshedFromUpstreamIDP, &plog.AuditParams{ + ReqCtx: ctx, + Session: accessRequest, + KeysAndValues: []any{ + "upstreamUsername", refreshedIdentity.UpstreamUsername, + "upstreamGroups", refreshedIdentity.UpstreamGroups, + }, + }) // If the idp wants to update the session with new information from the refresh, then update it. if refreshedIdentity.IDPSpecificSessionData != nil { @@ -221,8 +226,11 @@ func upstreamRefresh( if fositeErr != nil { // The HintField is always populated by applyIdentityTransformationsDuringRefresh, // and more descriptive than fositeErr.Error() which is just "error". - auditLogger.Audit(auditevent.AuthenticationRejectedByTransforms, ctx, accessRequest, - "reason", fositeErr.HintField) + auditLogger.Audit(auditevent.AuthenticationRejectedByTransforms, &plog.AuditParams{ + ReqCtx: ctx, + Session: accessRequest, + KeysAndValues: []any{"reason", fositeErr.HintField}, + }) return fositeErr } @@ -239,10 +247,14 @@ func upstreamRefresh( session.Fosite.Claims.Extra[oidcapi.IDTokenClaimGroups] = refreshedTransformedGroups } - auditLogger.Audit(auditevent.SessionRefreshed, ctx, accessRequest, - "username", oldTransformedUsername, // not allowed to change above so must be the same as old - "groups", refreshedTransformedGroups, - "subject", previousIdentity.DownstreamSubject) + auditLogger.Audit(auditevent.SessionRefreshed, &plog.AuditParams{ + ReqCtx: ctx, + Session: accessRequest, + KeysAndValues: []any{ + "username", oldTransformedUsername, // not allowed to change above so must be the same as old + "groups", refreshedTransformedGroups, + "subject", previousIdentity.DownstreamSubject}, + }) return nil } diff --git a/internal/federationdomain/endpoints/tokenendpointauditor/parameter_auditor.go b/internal/federationdomain/endpoints/tokenendpointauditor/parameter_auditor.go index 011949f91..e4765a17d 100644 --- a/internal/federationdomain/endpoints/tokenendpointauditor/parameter_auditor.go +++ b/internal/federationdomain/endpoints/tokenendpointauditor/parameter_auditor.go @@ -53,8 +53,9 @@ func paramsSafeToLogTokenEndpoint() sets.Set[string] { } func (p parameterAuditorHandler) CanHandleTokenEndpointRequest(ctx context.Context, requester fosite.AccessRequester) bool { - p.auditLogger.Audit(auditevent.HTTPRequestParameters, ctx, plog.NoSessionPersisted(), - auditevent.SanitizeParams(requester.GetRequestForm(), paramsSafeToLogTokenEndpoint())...) - + p.auditLogger.Audit(auditevent.HTTPRequestParameters, &plog.AuditParams{ + ReqCtx: ctx, + KeysAndValues: auditevent.SanitizeParams(requester.GetRequestForm(), paramsSafeToLogTokenEndpoint()), + }) return false } diff --git a/internal/federationdomain/requestlogger/request_logger.go b/internal/federationdomain/requestlogger/request_logger.go index 44c8c089c..b73a34cd4 100644 --- a/internal/federationdomain/requestlogger/request_logger.go +++ b/internal/federationdomain/requestlogger/request_logger.go @@ -109,17 +109,18 @@ func (rl *requestLogger) logRequestReceived() { } // Always log all other requests, including 404's caused by bad paths, for debugging purposes. - rl.auditLogger.Audit(auditevent.HTTPRequestReceived, - r.Context(), - plog.NoSessionPersisted(), - "proto", r.Proto, - "method", r.Method, - "host", r.Host, - "serverName", requestutil.SNIServerName(r), - "path", r.URL.Path, - "userAgent", rl.userAgent, - "remoteAddr", r.RemoteAddr, - ) + rl.auditLogger.Audit(auditevent.HTTPRequestReceived, &plog.AuditParams{ + ReqCtx: r.Context(), + KeysAndValues: []any{ + "proto", r.Proto, + "method", r.Method, + "host", r.Host, + "serverName", requestutil.SNIServerName(r), + "path", r.URL.Path, + "userAgent", rl.userAgent, + "remoteAddr", r.RemoteAddr, + }, + }) } func getLocationForAuditLogs(location string) string { @@ -158,14 +159,15 @@ func (rl *requestLogger) logRequestComplete() { return } - rl.auditLogger.Audit(auditevent.HTTPRequestCompleted, - r.Context(), - plog.NoSessionPersisted(), - "path", r.URL.Path, // include the path again to make it easy to "grep -v healthz" to watch all other audit events - "latency", rl.clock.Since(rl.startTime), - "responseStatus", rl.status, - "location", getLocationForAuditLogs(rl.Header().Get("Location")), - ) + rl.auditLogger.Audit(auditevent.HTTPRequestCompleted, &plog.AuditParams{ + ReqCtx: r.Context(), + KeysAndValues: []any{ + "path", r.URL.Path, + "latency", rl.clock.Since(rl.startTime), + "responseStatus", rl.status, + "location", getLocationForAuditLogs(rl.Header().Get("Location")), + }, + }) } // Unwrap implements responsewriter.UserProvidedDecorator. diff --git a/internal/plog/plog.go b/internal/plog/plog.go index 1915b0302..a80031997 100644 --- a/internal/plog/plog.go +++ b/internal/plog/plog.go @@ -30,6 +30,7 @@ package plog import ( "context" "os" + "reflect" "slices" "github.com/go-logr/logr" @@ -56,14 +57,31 @@ func NoHTTPRequestAvailable() context.Context { return nil } -// AuditLogger is only the audit logging part of Logger. There is no global function for Audit because +type AuditParams struct { + // ReqCtx may be nil. When possible, pass the http request's context as ReqCtx, + // so we may read the audit ID from the context. + ReqCtx context.Context + + // Session may be nil. When possible, pass the fosite.Requester or fosite.Request as the Session, + // so we can log the session ID. + Session SessionIDGetter + + // PIIKeysAndValues can optionally be used to pass along more keys are values. + // Use these when the values might contain personally identifiable information (PII). + // These values may be redacted by configuration. + // They must come in alternating pairs of string keys and any values. + PIIKeysAndValues []any + + // KeysAndValues can optionally be used to pass along more keys are values. + // These values are never redacted and therefore should never contain PII. + // They must come in alternating pairs of string keys and any values. + KeysAndValues []any +} + +// AuditLogger is the interface for audit logging. There is no global function for Audit because // that would make unit testing of audit logs harder. type AuditLogger interface { - // Audit writes an audit event to the log. - // reqCtx and session may be null. - // When possible, pass the http request's context as reqCtx, so we may read the audit ID from the context. - // When possible, pass the fosite.Requester or fosite.Request as the session, so we can log the session ID. - Audit(msg auditevent.Message, reqCtx context.Context, session SessionIDGetter, keysAndValues ...any) + Audit(msg auditevent.Message, p *AuditParams) } // Logger implements the plog logging convention described above. The global functions in this package @@ -133,27 +151,82 @@ func NewAuditLogger(cfg AuditLogConfig) AuditLogger { // Audit logs cannot be suppressed by the global log level configuration. This is because Audit logs should always // be printed, regardless of global log level. Audit logs offer their own configuration options, such as a way to // avoid potential PII (e.g. usernames and group names) in their pod logs. -func (a *auditLogger) Audit(msg auditevent.Message, reqCtx context.Context, session SessionIDGetter, keysAndValues ...any) { +// msg is required. All fields of p, and p itself, are optional. +func (a *auditLogger) Audit(msg auditevent.Message, p *AuditParams) { // Always add a key/value auditEvent=true. - keysAndValues = slices.Concat([]any{"auditEvent", true}, keysAndValues) + allKV := []any{"auditEvent", true} var auditID string - if reqCtx != nil { - auditID = audit.GetAuditIDTruncated(reqCtx) + if p != nil && p.ReqCtx != nil { + auditID = audit.GetAuditIDTruncated(p.ReqCtx) } if len(auditID) > 0 { - keysAndValues = slices.Concat([]any{"auditID", auditID}, keysAndValues) + allKV = slices.Concat(allKV, []any{"auditID", auditID}) } var sessionID string - if session != nil { - sessionID = session.GetID() + if p != nil && p.Session != nil { + sessionID = p.Session.GetID() } if len(sessionID) > 0 { - keysAndValues = slices.Concat([]any{"sessionID", sessionID}, keysAndValues) + allKV = slices.Concat(allKV, []any{"sessionID", sessionID}) } - a.logger.audit(string(msg), keysAndValues...) + if p != nil && len(p.PIIKeysAndValues) > 0 { + allKV = slices.Concat(allKV, []any{ + "personalInfo", a.nestedPIIKeysAndValues(p.PIIKeysAndValues, a.cfg.LogUsernamesAndGroupNames), + }) + } + + if p != nil && p.KeysAndValues != nil { + allKV = slices.Concat(allKV, p.KeysAndValues) + } + + a.logger.audit(string(msg), allKV...) +} + +func (a *auditLogger) nestedPIIKeysAndValues(values []any, logUsernamesAndGroupNames bool) map[string]any { + // TODO: This implementation alphabetizes the keys because it builds a map to nest all key/values deeper. Could we keep the original order instead? Do we care? + kvMap := map[string]any{} + var k string + + for i, v := range values { + if i%2 == 0 { + // Interpret even indices (0, 2, 4, etc.) as a key. + // Just remember its value for the next loop iteration. + k = valueAsKey(v) + } else { + // Interpret odd indices as a value. + // Save it using the key from the previous loop iteration. + kvMap[k] = valueAsValue(v, logUsernamesAndGroupNames) + } + } + + return kvMap +} + +func valueAsKey(v any) string { + vStr, ok := v.(string) + if !ok { + // Indicates programmer error that will hopefully be caught by unit tests. + vStr = "cannotCastKeyNameToString" + } + return vStr +} + +func valueAsValue(v any, logUsernamesAndGroupNames bool) any { + if logUsernamesAndGroupNames { + return v // use the original value without redacting + } else { + rt := reflect.TypeOf(v) + if rt.Kind() == reflect.Slice { + // For any slice, replace it by a redacted slice. + return []string{"redacted"} + } else { + // For anything else, just redact it without keeping any hint of the original type. + return "redacted" + } + } } // audit is used internally by AuditLogger to print an audit log event to the pLogger's output. diff --git a/internal/plog/plog_test.go b/internal/plog/plog_test.go index 894a28c22..7b5b3b4e1 100644 --- a/internal/plog/plog_test.go +++ b/internal/plog/plog_test.go @@ -4,6 +4,7 @@ package plog import ( + "context" "fmt" "runtime" "strings" @@ -12,8 +13,154 @@ import ( "github.com/coreos/go-semver/semver" "github.com/stretchr/testify/require" + "k8s.io/apiserver/pkg/audit" + + "go.pinniped.dev/internal/here" ) +type fakeSessionGetter struct{} + +func (f fakeSessionGetter) GetID() string { + return "fake-session-id" +} + +func TestAudit(t *testing.T) { + fakeReqContext := audit.WithAuditContext(context.Background()) + audit.WithAuditID(fakeReqContext, "fake-audit-id") + + tests := []struct { + name string + redactPII bool + run func(AuditLogger) + want string + }{ + { + name: "only message, with both nil and empty audit params", + run: func(a AuditLogger) { + a.Audit("fake event type 1", nil) + a.Audit("fake event type 2", &AuditParams{}) + }, + want: here.Doc(` + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.(*auditLogger).Audit","message":"fake event type 1","auditEvent":true} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.(*auditLogger).Audit","message":"fake event type 2","auditEvent":true} + `), + }, + { + name: "with request context which has no audit ID", + run: func(a AuditLogger) { + a.Audit("fake event type", &AuditParams{ReqCtx: context.Background()}) + }, + want: here.Doc(` + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.(*auditLogger).Audit","message":"fake event type","auditEvent":true} + `), + }, + { + name: "with request context which has audit ID", + run: func(a AuditLogger) { + a.Audit("fake event type", &AuditParams{ReqCtx: fakeReqContext}) + }, + want: here.Doc(` + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.(*auditLogger).Audit","message":"fake event type","auditEvent":true,"auditID":"fake-audit-id"} + `), + }, + { + name: "with session getter", + run: func(a AuditLogger) { + a.Audit("fake event type", &AuditParams{Session: &fakeSessionGetter{}}) + }, + want: here.Doc(` + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.(*auditLogger).Audit","message":"fake event type","auditEvent":true,"sessionID":"fake-session-id"} + `), + }, + { + name: "with an even number of PII keys and values", + run: func(a AuditLogger) { + a.Audit("fake event type", &AuditParams{PIIKeysAndValues: []any{"username", "ryan", "groups", []string{"g1", "g2"}, "foo", 42}}) + }, + want: here.Doc(` + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.(*auditLogger).Audit","message":"fake event type","auditEvent":true,"personalInfo":{"foo":42,"groups":["g1","g2"],"username":"ryan"}} + `), + }, + { + name: "with an even number of PII keys and values and PII configured to be redacted", + redactPII: true, + run: func(a AuditLogger) { + a.Audit("fake event type", &AuditParams{PIIKeysAndValues: []any{"username", "ryan", "groups", []string{"g1", "g2"}, "foo", 42}}) + }, + want: here.Doc(` + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.(*auditLogger).Audit","message":"fake event type","auditEvent":true,"personalInfo":{"foo":"redacted","groups":["redacted"],"username":"redacted"}} + `), + }, + { + name: "with an illegal odd number of PII keys and values, quietly ignores the last one", + run: func(a AuditLogger) { + a.Audit("fake event type", &AuditParams{PIIKeysAndValues: []any{"foo", 42, "bar"}}) + }, + want: here.Doc(` + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.(*auditLogger).Audit","message":"fake event type","auditEvent":true,"personalInfo":{"foo":42}} + `), + }, + { + name: "with a PII keys that is not a string, converts it to an error-looking key name rather than having the function return errors or panic", + run: func(a AuditLogger) { + a.Audit("fake event type", &AuditParams{PIIKeysAndValues: []any{42, "foo", "bar", "baz"}}) + }, + want: here.Doc(` + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.(*auditLogger).Audit","message":"fake event type","auditEvent":true,"personalInfo":{"bar":"baz","cannotCastKeyNameToString":"foo"}} + `), + }, + { + name: "with arbitrary keys and values", + run: func(a AuditLogger) { + a.Audit("fake event type", &AuditParams{KeysAndValues: []any{"foo", 42, "bar", "baz"}}) + }, + want: here.Doc(` + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.(*auditLogger).Audit","message":"fake event type","auditEvent":true,"foo":42,"bar":"baz"} + `), + }, + { + name: "with everything, showing order of keys printed in log", + run: func(a AuditLogger) { + a.Audit("fake event type", &AuditParams{ + ReqCtx: fakeReqContext, + Session: &fakeSessionGetter{}, + PIIKeysAndValues: []any{"username", "ryan", "groups", []string{"g1", "g2"}, "bat", 14}, + KeysAndValues: []any{"foo", 42, "bar", "baz"}, + }) + }, + want: here.Doc(` + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.(*auditLogger).Audit","message":"fake event type","auditEvent":true,"auditID":"fake-audit-id","sessionID":"fake-session-id","personalInfo":{"bat":14,"groups":["g1","g2"],"username":"ryan"},"foo":42,"bar":"baz"} + `), + }, + { + name: "with everything, when PII is redacted, showing order of keys printed in log", + redactPII: true, + run: func(a AuditLogger) { + a.Audit("fake event type", &AuditParams{ + ReqCtx: fakeReqContext, + Session: &fakeSessionGetter{}, + PIIKeysAndValues: []any{"username", "ryan", "groups", []string{"g1", "g2"}, "bat", 14}, + KeysAndValues: []any{"foo", 42, "bar", "baz"}, + }) + }, + want: here.Doc(` + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.(*auditLogger).Audit","message":"fake event type","auditEvent":true,"auditID":"fake-audit-id","sessionID":"fake-session-id","personalInfo":{"bat":"redacted","groups":["redacted"],"username":"redacted"},"foo":42,"bar":"baz"} + `), + }, + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + t.Parallel() + + l, actualAuditLogs := TestAuditLoggerWithConfig(t, AuditLogConfig{LogUsernamesAndGroupNames: !test.redactPII}) + test.run(l) + + require.Equal(t, strings.TrimSpace(test.want), strings.TrimSpace(actualAuditLogs.String())) + }) + } +} + func TestPlog(t *testing.T) { runtimeVersion := runtime.Version() if strings.HasPrefix(runtimeVersion, "go") { @@ -30,246 +177,247 @@ func TestPlog(t *testing.T) { { name: "basic", run: testAllPlogMethods, - want: ` -{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"e","panda":2,"error":"some err"} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"w","warning":true,"panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"we","warning":true,"error":"some err","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"i","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"ie","error":"some err","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"d","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"de","error":"some err","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"t","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"te","error":"some err","panda":2} -{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"all","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"always","panda":2} -`, + want: here.Doc(` + {"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"e","panda":2,"error":"some err"} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"w","warning":true,"panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"we","warning":true,"error":"some err","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"i","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"ie","error":"some err","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"d","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"de","error":"some err","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"t","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"te","error":"some err","panda":2} + {"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"all","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"always","panda":2} + `), }, { name: "with values", run: func(l Logger) { testAllPlogMethods(l.WithValues("hi", 42)) }, - want: ` -{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"e","hi":42,"panda":2,"error":"some err"} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"w","hi":42,"warning":true,"panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"we","hi":42,"warning":true,"error":"some err","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"i","hi":42,"panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"ie","hi":42,"error":"some err","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"d","hi":42,"panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"de","hi":42,"error":"some err","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"t","hi":42,"panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"te","hi":42,"error":"some err","panda":2} -{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"all","hi":42,"panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"always","hi":42,"panda":2} -`, + want: here.Doc(` + {"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"e","hi":42,"panda":2,"error":"some err"} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"w","hi":42,"warning":true,"panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"we","hi":42,"warning":true,"error":"some err","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"i","hi":42,"panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"ie","hi":42,"error":"some err","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"d","hi":42,"panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"de","hi":42,"error":"some err","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"t","hi":42,"panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"te","hi":42,"error":"some err","panda":2} + {"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"all","hi":42,"panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"always","hi":42,"panda":2} + `), }, { name: "with values conflict", // duplicate key is included twice ... run: func(l Logger) { testAllPlogMethods(l.WithValues("panda", false)) }, - want: ` -{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"e","panda":false,"panda":2,"error":"some err"} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"w","panda":false,"warning":true,"panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"we","panda":false,"warning":true,"error":"some err","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"i","panda":false,"panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"ie","panda":false,"error":"some err","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"d","panda":false,"panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"de","panda":false,"error":"some err","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"t","panda":false,"panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"te","panda":false,"error":"some err","panda":2} -{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"all","panda":false,"panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"always","panda":false,"panda":2} -`, + want: here.Doc(` + {"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"e","panda":false,"panda":2,"error":"some err"} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"w","panda":false,"warning":true,"panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"we","panda":false,"warning":true,"error":"some err","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"i","panda":false,"panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"ie","panda":false,"error":"some err","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"d","panda":false,"panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"de","panda":false,"error":"some err","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"t","panda":false,"panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"te","panda":false,"error":"some err","panda":2} + {"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"all","panda":false,"panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"always","panda":false,"panda":2} + `), }, { name: "with values nested", run: func(l Logger) { testAllPlogMethods(l.WithValues("hi", 42).WithValues("not", time.Hour)) }, - want: ` -{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"e","hi":42,"not":"1h0m0s","panda":2,"error":"some err"} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"w","hi":42,"not":"1h0m0s","warning":true,"panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"we","hi":42,"not":"1h0m0s","warning":true,"error":"some err","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"i","hi":42,"not":"1h0m0s","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"ie","hi":42,"not":"1h0m0s","error":"some err","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"d","hi":42,"not":"1h0m0s","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"de","hi":42,"not":"1h0m0s","error":"some err","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"t","hi":42,"not":"1h0m0s","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"te","hi":42,"not":"1h0m0s","error":"some err","panda":2} -{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"all","hi":42,"not":"1h0m0s","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"always","hi":42,"not":"1h0m0s","panda":2} -`, + want: here.Doc(` + {"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"e","hi":42,"not":"1h0m0s","panda":2,"error":"some err"} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"w","hi":42,"not":"1h0m0s","warning":true,"panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"we","hi":42,"not":"1h0m0s","warning":true,"error":"some err","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"i","hi":42,"not":"1h0m0s","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"ie","hi":42,"not":"1h0m0s","error":"some err","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"d","hi":42,"not":"1h0m0s","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"de","hi":42,"not":"1h0m0s","error":"some err","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"t","hi":42,"not":"1h0m0s","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"te","hi":42,"not":"1h0m0s","error":"some err","panda":2} + {"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"all","hi":42,"not":"1h0m0s","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"always","hi":42,"not":"1h0m0s","panda":2} + `), }, { name: "with name", run: func(l Logger) { testAllPlogMethods(l.WithName("yoyo")) }, - want: ` -{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"e","panda":2,"error":"some err"} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"w","warning":true,"panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"we","warning":true,"error":"some err","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"i","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"ie","error":"some err","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"d","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"de","error":"some err","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"t","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"te","error":"some err","panda":2} -{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"all","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"always","panda":2} -`, + want: here.Doc(` + {"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"e","panda":2,"error":"some err"} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"w","warning":true,"panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"we","warning":true,"error":"some err","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"i","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"ie","error":"some err","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"d","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"de","error":"some err","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"t","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"te","error":"some err","panda":2} + {"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"all","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"always","panda":2} + `), }, { name: "with name nested", run: func(l Logger) { testAllPlogMethods(l.WithName("yoyo").WithName("gold")) }, - want: ` -{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"e","panda":2,"error":"some err"} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"w","warning":true,"panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"we","warning":true,"error":"some err","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"i","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"ie","error":"some err","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"d","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"de","error":"some err","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"t","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"te","error":"some err","panda":2} -{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"all","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"always","panda":2} -`, + want: here.Doc(` + {"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"e","panda":2,"error":"some err"} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"w","warning":true,"panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"we","warning":true,"error":"some err","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"i","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"ie","error":"some err","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"d","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"de","error":"some err","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"t","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"te","error":"some err","panda":2} + {"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"all","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"always","panda":2} + `), }, { name: "depth 3", run: func(l Logger) { testAllPlogMethods(l.withDepth(3)) }, - want: ` -{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"e","panda":2,"error":"some err"} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"w","warning":true,"panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"we","warning":true,"error":"some err","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"i","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"ie","error":"some err","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"d","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"de","error":"some err","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"t","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"te","error":"some err","panda":2} -{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"all","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"always","panda":2} -`, + want: here.Doc(` + {"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"e","panda":2,"error":"some err"} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"w","warning":true,"panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"we","warning":true,"error":"some err","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"i","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"ie","error":"some err","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"d","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"de","error":"some err","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"t","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"te","error":"some err","panda":2} + {"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"all","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:$testing.tRunner","message":"always","panda":2} + `), }, { name: "depth 2", run: func(l Logger) { testAllPlogMethods(l.withDepth(2)) }, - want: ` -{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"e","panda":2,"error":"some err"} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"w","warning":true,"panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"we","warning":true,"error":"some err","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"i","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"ie","error":"some err","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"d","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"de","error":"some err","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"t","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"te","error":"some err","panda":2} -{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"all","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"always","panda":2} -`, + want: here.Doc(` + {"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"e","panda":2,"error":"some err"} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"w","warning":true,"panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"we","warning":true,"error":"some err","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"i","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"ie","error":"some err","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"d","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"de","error":"some err","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"t","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"te","error":"some err","panda":2} + {"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"all","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func16","message":"always","panda":2} + `), }, { name: "depth 1", run: func(l Logger) { testAllPlogMethods(l.withDepth(1)) }, - want: ` -{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"e","panda":2,"error":"some err"} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"w","warning":true,"panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"we","warning":true,"error":"some err","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"i","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"ie","error":"some err","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"d","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"de","error":"some err","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"t","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"te","error":"some err","panda":2} -{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"all","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"always","panda":2} -`, + want: here.Doc(` + {"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"e","panda":2,"error":"some err"} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"w","warning":true,"panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"we","warning":true,"error":"some err","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"i","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"ie","error":"some err","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"d","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"de","error":"some err","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"t","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"te","error":"some err","panda":2} + {"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"all","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.func8","message":"always","panda":2} + `), }, { name: "depth 0", run: func(l Logger) { testAllPlogMethods(l.withDepth(0)) }, - want: ` -{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"e","panda":2,"error":"some err"} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"w","warning":true,"panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"we","warning":true,"error":"some err","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"i","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"ie","error":"some err","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"d","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"de","error":"some err","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"t","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"te","error":"some err","panda":2} -{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"all","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"always","panda":2} -`, + want: here.Doc(` + {"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"e","panda":2,"error":"some err"} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"w","warning":true,"panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"we","warning":true,"error":"some err","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"i","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"ie","error":"some err","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"d","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"de","error":"some err","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"t","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"te","error":"some err","panda":2} + {"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"all","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.testAllPlogMethods","message":"always","panda":2} + `), }, { name: "depth -1", run: func(l Logger) { testAllPlogMethods(l.withDepth(-1)) }, - want: ` -{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Error","message":"e","panda":2,"error":"some err"} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Warning","message":"w","warning":true,"panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.WarningErr","message":"we","warning":true,"error":"some err","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Info","message":"i","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.InfoErr","message":"ie","error":"some err","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Debug","message":"d","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.DebugErr","message":"de","error":"some err","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Trace","message":"t","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.TraceErr","message":"te","error":"some err","panda":2} -{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.All","message":"all","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Always","message":"always","panda":2} -`, + want: here.Doc(` + {"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Error","message":"e","panda":2,"error":"some err"} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Warning","message":"w","warning":true,"panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.WarningErr","message":"we","warning":true,"error":"some err","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Info","message":"i","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.InfoErr","message":"ie","error":"some err","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Debug","message":"d","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.DebugErr","message":"de","error":"some err","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Trace","message":"t","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.TraceErr","message":"te","error":"some err","panda":2} + {"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.All","message":"all","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Always","message":"always","panda":2} + `), }, { name: "depth -2", run: func(l Logger) { testAllPlogMethods(l.withDepth(-2)) }, - want: ` -{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:$logr.Logger.Error","message":"e","panda":2,"error":"some err"} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.warningDepth","message":"w","warning":true,"panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.warningDepth","message":"we","warning":true,"error":"some err","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.infoDepth","message":"i","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.infoDepth","message":"ie","error":"some err","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.debugDepth","message":"d","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.debugDepth","message":"de","error":"some err","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.traceDepth","message":"t","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.traceDepth","message":"te","error":"some err","panda":2} -{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:$logr.Logger.Info","message":"all","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:$logr.Logger.Info","message":"always","panda":2} -`, + want: here.Doc(` + {"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:$logr.Logger.Error","message":"e","panda":2,"error":"some err"} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.warningDepth","message":"w","warning":true,"panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.warningDepth","message":"we","warning":true,"error":"some err","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.infoDepth","message":"i","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.infoDepth","message":"ie","error":"some err","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.debugDepth","message":"d","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.debugDepth","message":"de","error":"some err","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.traceDepth","message":"t","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.traceDepth","message":"te","error":"some err","panda":2} + {"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:$logr.Logger.Info","message":"all","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:$logr.Logger.Info","message":"always","panda":2} + `), }, { name: "depth -3", run: func(l Logger) { testAllPlogMethods(l.withDepth(-3)) }, - want: ` -{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"zapr@v1.3.0/zapr.go:$zapr.(*zapLogger).Error","message":"e","panda":2,"error":"some err"} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:$logr.Logger.Info","message":"w","warning":true,"panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:$logr.Logger.Info","message":"we","warning":true,"error":"some err","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:$logr.Logger.Info","message":"i","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:$logr.Logger.Info","message":"ie","error":"some err","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:$logr.Logger.Info","message":"d","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:$logr.Logger.Info","message":"de","error":"some err","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:$logr.Logger.Info","message":"t","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:$logr.Logger.Info","message":"te","error":"some err","panda":2} -{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"zapr@v1.3.0/zapr.go:$zapr.(*zapLogger).Info","message":"all","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"zapr@v1.3.0/zapr.go:$zapr.(*zapLogger).Info","message":"always","panda":2}`, + want: here.Doc(` + {"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"zapr@v1.3.0/zapr.go:$zapr.(*zapLogger).Error","message":"e","panda":2,"error":"some err"} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:$logr.Logger.Info","message":"w","warning":true,"panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:$logr.Logger.Info","message":"we","warning":true,"error":"some err","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:$logr.Logger.Info","message":"i","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:$logr.Logger.Info","message":"ie","error":"some err","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:$logr.Logger.Info","message":"d","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:$logr.Logger.Info","message":"de","error":"some err","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:$logr.Logger.Info","message":"t","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:$logr.Logger.Info","message":"te","error":"some err","panda":2} + {"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"zapr@v1.3.0/zapr.go:$zapr.(*zapLogger).Info","message":"all","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"zapr@v1.3.0/zapr.go:$zapr.(*zapLogger).Info","message":"always","panda":2} + `), }, { name: "closure", @@ -292,19 +440,19 @@ func TestPlog(t *testing.T) { }() }() }, - want: fmt.Sprintf(` -{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"e","panda":2,"error":"some err"} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"w","warning":true,"panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"we","warning":true,"error":"some err","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"i","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"ie","error":"some err","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"d","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"de","error":"some err","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"t","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"te","error":"some err","panda":2} -{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"all","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"always","panda":2} -`, func() string { + want: here.Docf(` + {"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"e","panda":2,"error":"some err"} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"w","warning":true,"panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"we","warning":true,"error":"some err","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"i","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"ie","error":"some err","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"d","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"de","error":"some err","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"t","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"te","error":"some err","panda":2} + {"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"all","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestPlog.%[1]s","message":"always","panda":2} + `, func() string { switch { case runtimeVersionSemver.Major == 1 && runtimeVersionSemver.Minor == 21: // Format of string for Go 1.21 @@ -340,19 +488,19 @@ func TestPlog(t *testing.T) { }() }() }, - want: ` -{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Error","message":"e","panda":2,"error":"some err"} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Warning","message":"w","warning":true,"panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.WarningErr","message":"we","warning":true,"error":"some err","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Info","message":"i","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.InfoErr","message":"ie","error":"some err","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Debug","message":"d","panda":2} -{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.DebugErr","message":"de","error":"some err","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Trace","message":"t","panda":2} -{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.TraceErr","message":"te","error":"some err","panda":2} -{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.All","message":"all","panda":2} -{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Always","message":"always","panda":2} -`, + want: here.Doc(` + {"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Error","message":"e","panda":2,"error":"some err"} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Warning","message":"w","warning":true,"panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.WarningErr","message":"we","warning":true,"error":"some err","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Info","message":"i","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.InfoErr","message":"ie","error":"some err","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Debug","message":"d","panda":2} + {"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.DebugErr","message":"de","error":"some err","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Trace","message":"t","panda":2} + {"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.TraceErr","message":"te","error":"some err","panda":2} + {"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.All","message":"all","panda":2} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.pLogger.Always","message":"always","panda":2} + `), }, } for _, test := range tests { diff --git a/internal/plog/testing.go b/internal/plog/testing.go index 121dbc0f7..ab0ca0057 100644 --- a/internal/plog/testing.go +++ b/internal/plog/testing.go @@ -72,10 +72,14 @@ func TestLogger(t *testing.T) (Logger, *bytes.Buffer) { } func TestAuditLogger(t *testing.T) (AuditLogger, *bytes.Buffer) { + return TestAuditLoggerWithConfig(t, AuditLogConfig{LogUsernamesAndGroupNames: true}) +} + +func TestAuditLoggerWithConfig(t *testing.T, cfg AuditLogConfig) (AuditLogger, *bytes.Buffer) { t.Helper() underlyingLogger, logBuf := TestLogger(t) - return &auditLogger{logger: underlyingLogger, cfg: AuditLogConfig{LogUsernamesAndGroupNames: true}}, logBuf + return &auditLogger{logger: underlyingLogger, cfg: cfg}, logBuf } func TestConsoleLogger(t *testing.T, w io.Writer) Logger { diff --git a/internal/registry/credentialrequest/rest.go b/internal/registry/credentialrequest/rest.go index 2ca645ce1..5d78658ff 100644 --- a/internal/registry/credentialrequest/rest.go +++ b/internal/registry/credentialrequest/rest.go @@ -132,11 +132,15 @@ func (r *REST) Create(ctx context.Context, obj runtime.Object, createValidation traceSuccess(t, userInfo, true) - r.auditLogger.Audit(auditevent.TokenCredentialRequest, ctx, nil, - "username", userInfo.GetName(), - "groups", userInfo.GetGroups(), - "authenticated", true, - "expires", expires.Format(time.RFC3339)) + r.auditLogger.Audit(auditevent.TokenCredentialRequest, &plog.AuditParams{ + ReqCtx: ctx, + KeysAndValues: []any{ + "username", userInfo.GetName(), + "groups", userInfo.GetGroups(), + "authenticated", true, + "expires", expires.Format(time.RFC3339), + }, + }) return &loginapi.TokenCredentialRequest{ Status: loginapi.TokenCredentialRequestStatus{