audit log: keep key ordering in personalInfo, render nil slices and maps

This commit is contained in:
Ryan Richard
2024-11-12 11:35:59 -08:00
committed by Joshua Casey
parent c5f4cce3ae
commit a308f3f22a
2 changed files with 138 additions and 66 deletions

View File

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

View File

@@ -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:<line>$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:<line>$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:<line>$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:<line>$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:<line>$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:<line>$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:<line>$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:<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"}
{"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":{"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:<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"}
{"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":{"username":"redacted","groups":["redacted 2 values"],"bat":"redacted"},"foo":42,"bar":"baz"}
`),
},
}