mirrors/pinniped
1
0
Fork 0
mirror of https://github.com/vmware-tanzu/pinniped.git synced 2026-01-06 21:47:45 +00:00
Code Issues Actions Packages Projects Releases Wiki Activity

make Audit() take struct as param for all optional params and redact PII

Browse Source
This commit is contained in:
Ryan Richard
2024-11-11 18:05:00 -08:00
committed by Joshua Casey
parent ced8686d11
commit c5f4cce3ae
12 changed files with 562 additions and 285 deletions
Download Patch File Download Diff File Expand all files Collapse all files

18
internal/controller/supervisorstorage/garbage_collector.go
View File

@@ -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},
})
}
}

41
internal/federationdomain/downstreamsession/downstream_session.go
View File

@@ -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
}

38
internal/federationdomain/endpoints/auth/auth_handler.go
View File

@@ -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 {

8
internal/federationdomain/endpoints/callback/callback_handler.go
View File

@@ -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 {

6
internal/federationdomain/endpoints/login/login_handler.go
View File

@@ -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):

30
internal/federationdomain/endpoints/token/token_handler.go
View File

@@ -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
}

7
internal/federationdomain/endpoints/tokenendpointauditor/parameter_auditor.go
View File

@@ -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
}

40
internal/federationdomain/requestlogger/request_logger.go
View File

@@ -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.

103
internal/plog/plog.go
View File

@@ -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.

536
internal/plog/plog_test.go
View File

@@ -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:<line>$plog.(*auditLogger).Audit","message":"fake event type 1","auditEvent":true}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$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:<line>$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:<line>$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:<line>$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:<line>$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:<line>$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:<line>$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:<line>$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:<line>$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:<line>$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:<line>$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:<line>$plog.testAllPlogMethods","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"always","panda":2}
`,
want: here.Doc(`
{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$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:<line>$plog.testAllPlogMethods","message":"w","hi":42,"warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"i","hi":42,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"d","hi":42,"panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"t","hi":42,"panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"all","hi":42,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$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:<line>$plog.testAllPlogMethods","message":"w","hi":42,"warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"i","hi":42,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"d","hi":42,"panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"t","hi":42,"panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"all","hi":42,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$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:<line>$plog.testAllPlogMethods","message":"w","panda":false,"warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"i","panda":false,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"d","panda":false,"panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"t","panda":false,"panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"all","panda":false,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$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:<line>$plog.testAllPlogMethods","message":"w","panda":false,"warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"i","panda":false,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"d","panda":false,"panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"t","panda":false,"panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"all","panda":false,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$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:<line>$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:<line>$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:<line>$plog.testAllPlogMethods","message":"i","hi":42,"not":"1h0m0s","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"d","hi":42,"not":"1h0m0s","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"t","hi":42,"not":"1h0m0s","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"all","hi":42,"not":"1h0m0s","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$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:<line>$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:<line>$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:<line>$plog.testAllPlogMethods","message":"i","hi":42,"not":"1h0m0s","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"d","hi":42,"not":"1h0m0s","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"t","hi":42,"not":"1h0m0s","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"all","hi":42,"not":"1h0m0s","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$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:<line>$plog.testAllPlogMethods","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:<line>$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:<line>$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:<line>$plog.testAllPlogMethods","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo","caller":"plog/plog_test.go:<line>$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:<line>$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:<line>$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:<line>$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:<line>$plog.testAllPlogMethods","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:<line>$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:<line>$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:<line>$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:<line>$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:<line>$plog.testAllPlogMethods","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","logger":"yoyo.gold","caller":"plog/plog_test.go:<line>$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:<line>$testing.tRunner","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"we","warning":true,"error":"some err","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"always","panda":2}
`,
want: here.Doc(`
{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"we","warning":true,"error":"some err","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$testing.tRunner","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"testing/testing.go:<line>$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:<line>$plog.TestPlog.func16","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func16","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.TestPlog.func16","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func16","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func16","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func16","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func16","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func16","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func16","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func16","message":"always","panda":2}
`,
want: here.Doc(`
{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func16","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func16","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.TestPlog.func16","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func16","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func16","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func16","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func16","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func16","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func16","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.TestPlog.func8","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.TestPlog.func8","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"always","panda":2}
`,
want: here.Doc(`
{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.TestPlog.func8","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.TestPlog.func8","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"always","panda":2}
`,
want: here.Doc(`
{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.testAllPlogMethods","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$plog.testAllPlogMethods","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.pLogger.Error","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Warning","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$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:<line>$plog.pLogger.Info","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.InfoErr","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Debug","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.DebugErr","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Trace","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.TraceErr","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.All","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Always","message":"always","panda":2}
`,
want: here.Doc(`
{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Error","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Warning","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$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:<line>$plog.pLogger.Info","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.InfoErr","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Debug","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.DebugErr","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Trace","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.TraceErr","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.All","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$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:<line>$logr.Logger.Error","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.warningDepth","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$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:<line>$plog.pLogger.infoDepth","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.infoDepth","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.debugDepth","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.debugDepth","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.traceDepth","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$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:<line>$logr.Logger.Info","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:<line>$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:<line>$logr.Logger.Error","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.warningDepth","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$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:<line>$plog.pLogger.infoDepth","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.infoDepth","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.debugDepth","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.debugDepth","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.traceDepth","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$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:<line>$logr.Logger.Info","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:<line>$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:<line>$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:<line>$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:<line>$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:<line>$logr.Logger.Info","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:<line>$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:<line>$logr.Logger.Info","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:<line>$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:<line>$logr.Logger.Info","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:<line>$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:<line>$zapr.(*zapLogger).Info","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"zapr@v1.3.0/zapr.go:<line>$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:<line>$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:<line>$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:<line>$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:<line>$logr.Logger.Info","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:<line>$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:<line>$logr.Logger.Info","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:<line>$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:<line>$logr.Logger.Info","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"logr@v1.4.2/logr.go:<line>$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:<line>$zapr.(*zapLogger).Info","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"zapr@v1.3.0/zapr.go:<line>$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:<line>$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:<line>$plog.TestPlog.%[1]s","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.TestPlog.%[1]s","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.TestPlog.%[1]s","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.TestPlog.%[1]s","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.TestPlog.%[1]s","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$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:<line>$plog.TestPlog.%[1]s","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.TestPlog.%[1]s","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.TestPlog.%[1]s","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.TestPlog.%[1]s","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.TestPlog.%[1]s","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:<line>$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:<line>$plog.pLogger.Error","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Warning","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$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:<line>$plog.pLogger.Info","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.InfoErr","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Debug","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.DebugErr","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Trace","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.TraceErr","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.All","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Always","message":"always","panda":2}
`,
want: here.Doc(`
{"level":"error","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Error","message":"e","panda":2,"error":"some err"}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Warning","message":"w","warning":true,"panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$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:<line>$plog.pLogger.Info","message":"i","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.InfoErr","message":"ie","error":"some err","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Debug","message":"d","panda":2}
{"level":"debug","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.DebugErr","message":"de","error":"some err","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Trace","message":"t","panda":2}
{"level":"trace","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.TraceErr","message":"te","error":"some err","panda":2}
{"level":"all","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.All","message":"all","panda":2}
{"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:<line>$plog.pLogger.Always","message":"always","panda":2}
`),
},
}
for _, test := range tests {

6
internal/plog/testing.go
View File

@@ -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 {

14
internal/registry/credentialrequest/rest.go
View File

@@ -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{