From de7781b7f9b476fec751931347da4c5a7fb2c848 Mon Sep 17 00:00:00 2001 From: Joshua Casey Date: Wed, 13 Nov 2024 14:42:10 -0600 Subject: [PATCH] Use correct caller when generating audit events --- internal/plog/plog.go | 2 +- internal/plog/plog_test.go | 26 +++++++++++++------------- 2 files changed, 14 insertions(+), 14 deletions(-) diff --git a/internal/plog/plog.go b/internal/plog/plog.go index 1f612c70e..1bdbfb763 100644 --- a/internal/plog/plog.go +++ b/internal/plog/plog.go @@ -182,7 +182,7 @@ func (a *auditLogger) Audit(msg auditevent.Message, p *AuditParams) { func (p pLogger) audit(msg string, keysAndValues ...any) { // Always print log message (klogLevelWarning cannot be suppressed by configuration), // and always use the Info function because audit logs are not warnings or errors. - p.logr().V(klogLevelWarning).WithCallDepth(p.depth+1).Info(msg, keysAndValues...) + p.logr().V(klogLevelWarning).WithCallDepth(p.depth+2).Info(msg, keysAndValues...) } // Error logs show in the pod log output as `"level":"error","message":"some error msg"` diff --git a/internal/plog/plog_test.go b/internal/plog/plog_test.go index b87daf34f..8af8cb3af 100644 --- a/internal/plog/plog_test.go +++ b/internal/plog/plog_test.go @@ -41,8 +41,8 @@ func TestAudit(t *testing.T) { a.Audit("fake event type 2", &AuditParams{}) }, want: here.Doc(` - {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.(*auditLogger).Audit","message":"fake event type 1","auditEvent":true} - {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.(*auditLogger).Audit","message":"fake event type 2","auditEvent":true} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestAudit.func1","message":"fake event type 1","auditEvent":true} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestAudit.func1","message":"fake event type 2","auditEvent":true} `), }, { @@ -51,7 +51,7 @@ func TestAudit(t *testing.T) { a.Audit("fake event type", &AuditParams{ReqCtx: context.Background()}) }, want: here.Doc(` - {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.(*auditLogger).Audit","message":"fake event type","auditEvent":true} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestAudit.func2","message":"fake event type","auditEvent":true} `), }, { @@ -60,7 +60,7 @@ func TestAudit(t *testing.T) { a.Audit("fake event type", &AuditParams{ReqCtx: fakeReqContext}) }, want: here.Doc(` - {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.(*auditLogger).Audit","message":"fake event type","auditEvent":true,"auditID":"fake-audit-id"} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestAudit.func3","message":"fake event type","auditEvent":true,"auditID":"fake-audit-id"} `), }, { @@ -69,7 +69,7 @@ func TestAudit(t *testing.T) { a.Audit("fake event type", &AuditParams{Session: &fakeSessionGetter{}}) }, want: here.Doc(` - {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.(*auditLogger).Audit","message":"fake event type","auditEvent":true,"sessionID":"fake-session-id"} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestAudit.func4","message":"fake event type","auditEvent":true,"sessionID":"fake-session-id"} `), }, { @@ -91,7 +91,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,"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}} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestAudit.func5","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}} `), }, { @@ -114,7 +114,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,"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"}} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestAudit.func6","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"}} `), }, { @@ -123,7 +123,7 @@ func TestAudit(t *testing.T) { 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} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestAudit.func7","message":"fake event type","auditEvent":true} `), }, { @@ -132,7 +132,7 @@ func TestAudit(t *testing.T) { a.Audit("fake event type", &AuditParams{PIIKeysAndValues: []any{"foo", 42, "bar"}}) }, want: here.Doc(` - {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.(*auditLogger).Audit","message":"fake event type","auditEvent":true,"personalInfo":{"foo":42}} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestAudit.func8","message":"fake event type","auditEvent":true,"personalInfo":{"foo":42}} `), }, { @@ -141,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":{"cannotCastKeyNameToString":"foo","bar":"baz"}} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestAudit.func9","message":"fake event type","auditEvent":true,"personalInfo":{"cannotCastKeyNameToString":"foo","bar":"baz"}} `), }, { @@ -150,7 +150,7 @@ func TestAudit(t *testing.T) { a.Audit("fake event type", &AuditParams{KeysAndValues: []any{"foo", 42, "bar", "baz"}}) }, want: here.Doc(` - {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog.go:$plog.(*auditLogger).Audit","message":"fake event type","auditEvent":true,"foo":42,"bar":"baz"} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestAudit.func10","message":"fake event type","auditEvent":true,"foo":42,"bar":"baz"} `), }, { @@ -164,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":{"username":"ryan","groups":["g1","g2"],"bat":14},"foo":42,"bar":"baz"} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestAudit.func11","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"} `), }, { @@ -179,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":{"username":"redacted","groups":["redacted 2 values"],"bat":"redacted"},"foo":42,"bar":"baz"} + {"level":"info","timestamp":"2099-08-08T13:57:36.123456Z","caller":"plog/plog_test.go:$plog.TestAudit.func12","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"} `), }, }