diff --git a/internal/plog/plog.go b/internal/plog/plog.go index a80031997..1f612c70e 100644 --- a/internal/plog/plog.go +++ b/internal/plog/plog.go @@ -29,6 +29,8 @@ package plog import ( "context" + "encoding/json" + "fmt" "os" "reflect" "slices" @@ -45,18 +47,6 @@ type SessionIDGetter interface { GetID() string } -// NoSessionPersisted means do not associate this audit event with a session ID. -// The session has not yet "started" and may or may not ever be persisted to permanent storage. -func NoSessionPersisted() SessionIDGetter { - return nil -} - -// NoHTTPRequestAvailable means there is no request context for this audit event. -// Use this when an audit event is emitted from a controller or some other place that does not have a request context. -func NoHTTPRequestAvailable() context.Context { - return nil -} - 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. @@ -172,9 +162,12 @@ func (a *auditLogger) Audit(msg auditevent.Message, p *AuditParams) { allKV = slices.Concat(allKV, []any{"sessionID", sessionID}) } - if p != nil && len(p.PIIKeysAndValues) > 0 { + if p != nil && len(p.PIIKeysAndValues) > 1 { allKV = slices.Concat(allKV, []any{ - "personalInfo", a.nestedPIIKeysAndValues(p.PIIKeysAndValues, a.cfg.LogUsernamesAndGroupNames), + "personalInfo", &piiKeysAndValues{ + kv: p.PIIKeysAndValues, + logUsernamesAndGroupNames: a.cfg.LogUsernamesAndGroupNames, + }, }) } @@ -185,50 +178,6 @@ func (a *auditLogger) Audit(msg auditevent.Message, p *AuditParams) { 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. func (p pLogger) audit(msg string, keysAndValues ...any) { // Always print log message (klogLevelWarning cannot be suppressed by configuration), @@ -469,3 +418,91 @@ func Fatal(err error, keysAndValues ...any) { globalFlush() os.Exit(1) } + +// piiKeysAndValues can be used to serialize the keys and values as a JSON map without losing their order, +// and optionally redacting values. +type piiKeysAndValues struct { + kv []any + logUsernamesAndGroupNames bool +} + +func (p *piiKeysAndValues) MarshalJSON() ([]byte, error) { + var buf []byte + var k string + var wroteOne bool + + buf = append(buf, '{') + + for i, v := range p.kv { + if i%2 == 0 { + // Interpret even indices (0, 2, 4, etc.) as a key. + // Remember its value for the next loop iteration. + k = p.asJSONKey(v) + } else { + // Interpret odd indices as a value. + // Write it using the key from the previous loop iteration. + // First write a comma if needed. + if wroteOne { + buf = append(buf, ',') + } + buf = append(buf, []byte(k)...) + buf = append(buf, ':') + buf = append(buf, []byte(p.asJSONValue(v))...) + wroteOne = true + } + } + + buf = append(buf, '}') + + return buf, nil +} + +func (p *piiKeysAndValues) asJSONKey(v any) string { + vStr, ok := v.(string) + if !ok { + // Indicates programmer error that will hopefully be caught by unit tests of usages of Audit(). + return `"cannotCastKeyNameToString"` + } + // Encode the string to get proper JSON escaping if needed. + b, err := json.Marshal(vStr) + if err != nil { + // Shouldn't really happen because the argument to Marshal was a string. + return `"cannotMarshalKeyNameToJSON"` + } + return string(b) +} + +func (p *piiKeysAndValues) asJSONValue(v any) string { + rt := reflect.TypeOf(v) // note that rt can be nil when v is nil + if p.logUsernamesAndGroupNames { + // Encode the original value without redacting. + switch { + case v != nil && rt.Kind() == reflect.Slice && reflect.ValueOf(v).IsNil(): + // Handle the special case where v is a nil slice by showing it as an empty slice. + return "[]" + case v != nil && rt.Kind() == reflect.Map && reflect.ValueOf(v).IsNil(): + // Handle the special case where v is a nil map by showing it as an empty map. + return "{}" + default: + b, err := json.Marshal(v) + if err != nil { + // Hopefully this would be caught by unit tests of usages of Audit(). + return `"cannotMarshalValueToJSON"` + } + return string(b) + } + } else { + // Redact the value. + switch { + case rt != nil && rt.Kind() == reflect.Slice: + // Handle the special case where v is a slice by showing it as a slice with redacted values. + return fmt.Sprintf(`["redacted %d values"]`, reflect.ValueOf(v).Len()) + case rt != nil && rt.Kind() == reflect.Map: + // Handle the special case where v is a map by showing it as a map with redacted values. + return fmt.Sprintf(`{"redacted": "redacted %d keys"}`, reflect.ValueOf(v).Len()) + default: + // For anything else, just redact it without worrying about the original type. + return `"redacted"` + } + } +} diff --git a/internal/plog/plog_test.go b/internal/plog/plog_test.go index 7b5b3b4e1..b87daf34f 100644 --- a/internal/plog/plog_test.go +++ b/internal/plog/plog_test.go @@ -73,22 +73,57 @@ func TestAudit(t *testing.T) { `), }, { - name: "with an even number of PII keys and values", + name: "with an even number of PII keys and values, nests them under personalInfo and preserves their original order, without redacting PII", run: func(a AuditLogger) { - a.Audit("fake event type", &AuditParams{PIIKeysAndValues: []any{"username", "ryan", "groups", []string{"g1", "g2"}, "foo", 42}}) + a.Audit("fake event type", &AuditParams{PIIKeysAndValues: []any{ + "username", "ryan", + "groups", []string{"g1", "g2"}, + "int", 42, + "float", 42.75, + `specialJSONChars"👋\`, `hi"👋\`, + "map", map[string]int{"k1": 1, "k2": 2}, + "empty_list", []any{}, + "empty_map", map[string]any{}, + "nil_list", []any(nil), + "nil_map", map[string]any(nil), + "nil_ptr", (*int)(nil), + "nil", nil, + }}) }, 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"}} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.(*auditLogger).Audit","message":"fake event type","auditEvent":true,"personalInfo":{"username":"ryan","groups":["g1","g2"],"int":42,"float":42.75,"specialJSONChars\"👋\\":"hi\"👋\\","map":{"k1":1,"k2":2},"empty_list":[],"empty_map":{},"nil_list":[],"nil_map":{},"nil_ptr":null,"nil":null}} `), }, { 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}}) + a.Audit("fake event type", &AuditParams{PIIKeysAndValues: []any{ + "username", "ryan", + "groups", []string{"g1", "g2"}, + "int", 42, + "float", 42.75, + `specialJSONChars"👋\`, `hi"👋\`, + "map", map[string]int{"k1": 1, "k2": 2}, + "empty_list", []any{}, + "empty_map", map[string]any{}, + "nil_list", []any(nil), + "nil_map", map[string]any(nil), + "nil_ptr", (*int)(nil), + "nil", nil, + }}) }, 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"}} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.(*auditLogger).Audit","message":"fake event type","auditEvent":true,"personalInfo":{"username":"redacted","groups":["redacted 2 values"],"int":"redacted","float":"redacted","specialJSONChars\"👋\\":"redacted","map":{"redacted":"redacted 2 keys"},"empty_list":["redacted 0 values"],"empty_map":{"redacted":"redacted 0 keys"},"nil_list":["redacted 0 values"],"nil_map":{"redacted":"redacted 0 keys"},"nil_ptr":"redacted","nil":"redacted"}} + `), + }, + { + name: "with an illegal single PII keys and values, quietly ignores it", + run: func(a AuditLogger) { + a.Audit("fake event type", &AuditParams{PIIKeysAndValues: []any{"foo"}}) + }, + 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} `), }, { @@ -106,7 +141,7 @@ func TestAudit(t *testing.T) { 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"}} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.(*auditLogger).Audit","message":"fake event type","auditEvent":true,"personalInfo":{"cannotCastKeyNameToString":"foo","bar":"baz"}} `), }, { @@ -129,7 +164,7 @@ func TestAudit(t *testing.T) { }) }, 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"} + {"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":{"username":"ryan","groups":["g1","g2"],"bat":14},"foo":42,"bar":"baz"} `), }, { @@ -144,7 +179,7 @@ func TestAudit(t *testing.T) { }) }, 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"} + {"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":{"username":"redacted","groups":["redacted 2 values"],"bat":"redacted"},"foo":42,"bar":"baz"} `), }, }