From a6350208df477173fbd0fdbf4a3ac4b0e5d7c04a Mon Sep 17 00:00:00 2001 From: park285 Date: Tue, 11 Aug 2026 14:33:18 +0900 Subject: [PATCH 01/14] perf(logging): eliminate hot-path attr allocations --- pkg/logging/log.go | 34 +++++++++++++++++++++++----------- 1 file changed, 23 insertions(+), 11 deletions(-) diff --git a/pkg/logging/log.go b/pkg/logging/log.go index cbbb911..9f548a0 100644 --- a/pkg/logging/log.go +++ b/pkg/logging/log.go @@ -3,26 +3,37 @@ package logging import ( "context" "log/slog" + "runtime" "strings" + "time" ) func Debug(ctx context.Context, logger *slog.Logger, event, message string, attrs ...slog.Attr) { - Log(ctx, logger, slog.LevelDebug, event, message, attrs...) + log(ctx, logger, slog.LevelDebug, event, message, attrs...) } func Info(ctx context.Context, logger *slog.Logger, event, message string, attrs ...slog.Attr) { - Log(ctx, logger, slog.LevelInfo, event, message, attrs...) + log(ctx, logger, slog.LevelInfo, event, message, attrs...) } func Warn(ctx context.Context, logger *slog.Logger, event, message string, attrs ...slog.Attr) { - Log(ctx, logger, slog.LevelWarn, event, message, attrs...) + log(ctx, logger, slog.LevelWarn, event, message, attrs...) } func Error(ctx context.Context, logger *slog.Logger, event, message string, attrs ...slog.Attr) { - Log(ctx, logger, slog.LevelError, event, message, attrs...) + log(ctx, logger, slog.LevelError, event, message, attrs...) } func Log(ctx context.Context, logger *slog.Logger, level slog.Level, event, message string, attrs ...slog.Attr) { + log(ctx, logger, level, event, message, attrs...) +} + +// log는 level gate 뒤 Record를 직접 구성해 전달한다. Logger.LogAttrs의 두 번째 Enabled +// 호출과 임시 attr 병합 slice를 피하고, Record의 inline attr 저장소를 그대로 활용한다. +// +// runtime.Callers의 skip 3은 이 함수 바로 위의 exported logging wrapper 호출자를 가리킨다. +// 따라서 일반적인 Debug/Info/Warn/Error/Log 사용에서는 실제 애플리케이션 호출 위치가 남는다. +func log(ctx context.Context, logger *slog.Logger, level slog.Level, event, message string, attrs ...slog.Attr) { if logger == nil { return } @@ -33,15 +44,16 @@ func Log(ctx context.Context, logger *slog.Logger, level slog.Level, event, mess return } - contextAttrs := ContextAttrs(ctx) - merged := make([]slog.Attr, 0, 1+len(contextAttrs)+len(attrs)) + var pcs [1]uintptr + runtime.Callers(3, pcs[:]) + + record := slog.NewRecord(time.Now(), level, logMessage(event, message), pcs[0]) if strings.TrimSpace(event) != "" { - merged = append(merged, Event(event)) + record.AddAttrs(Event(event)) } - merged = append(merged, contextAttrs...) - merged = append(merged, attrs...) - - logger.LogAttrs(ctx, level, logMessage(event, message), merged...) + contextValuesFrom(ctx).addToRecord(&record) + record.AddAttrs(attrs...) + _ = logger.Handler().Handle(ctx, record) } func logMessage(event, message string) string { From 66584c07eb0fe3050a1e8e3c8a269f9d8683ab9d Mon Sep 17 00:00:00 2001 From: park285 Date: Tue, 11 Aug 2026 14:33:35 +0900 Subject: [PATCH 02/14] perf(logging): eliminate context lookup allocations --- pkg/logging/context.go | 86 ++++++++++++++++++++++++++++++++++-------- 1 file changed, 71 insertions(+), 15 deletions(-) diff --git a/pkg/logging/context.go b/pkg/logging/context.go index 554a26a..3e33e7c 100644 --- a/pkg/logging/context.go +++ b/pkg/logging/context.go @@ -6,15 +6,22 @@ import ( "strings" ) -type contextKey string +type contextKey uint8 const ( - requestIDContextKey contextKey = "hololive.logging.request_id" - jobIDContextKey contextKey = "hololive.logging.job_id" - runtimeContextKey contextKey = "hololive.logging.runtime" - componentContextKey contextKey = "hololive.logging.component" + requestIDContextKey contextKey = iota + jobIDContextKey + runtimeContextKey + componentContextKey ) +type contextValues struct { + runtime string + component string + requestID string + jobID string +} + func WithRequestID(ctx context.Context, requestID string) context.Context { return withString(ctx, requestIDContextKey, requestID) } @@ -48,27 +55,76 @@ func componentFromContext(ctx context.Context) string { } func ContextAttrs(ctx context.Context) []slog.Attr { - if ctx == nil { + values := contextValuesFrom(ctx) + count := values.count() + if count == 0 { return nil } - attrs := make([]slog.Attr, 0, 4) - if value := runtimeFromContext(ctx); value != "" { - attrs = append(attrs, Runtime(value)) + return values.appendTo(make([]slog.Attr, 0, count)) +} + +func contextValuesFrom(ctx context.Context) contextValues { + if ctx == nil { + return contextValues{} + } + + return contextValues{ + runtime: runtimeFromContext(ctx), + component: componentFromContext(ctx), + requestID: requestIDFromContext(ctx), + jobID: jobIDFromContext(ctx), + } +} + +func (v contextValues) count() int { + count := 0 + if v.runtime != "" { + count++ } - if value := componentFromContext(ctx); value != "" { - attrs = append(attrs, componentAttr(value)) + if v.component != "" { + count++ } - if value := requestIDFromContext(ctx); value != "" { - attrs = append(attrs, RequestID(value)) + if v.requestID != "" { + count++ } - if value := jobIDFromContext(ctx); value != "" { - attrs = append(attrs, jobIDAttr(value)) + if v.jobID != "" { + count++ } + return count +} +func (v contextValues) appendTo(attrs []slog.Attr) []slog.Attr { + if v.runtime != "" { + attrs = append(attrs, Runtime(v.runtime)) + } + if v.component != "" { + attrs = append(attrs, componentAttr(v.component)) + } + if v.requestID != "" { + attrs = append(attrs, RequestID(v.requestID)) + } + if v.jobID != "" { + attrs = append(attrs, jobIDAttr(v.jobID)) + } return attrs } +func (v contextValues) addToRecord(record *slog.Record) { + if v.runtime != "" { + record.AddAttrs(Runtime(v.runtime)) + } + if v.component != "" { + record.AddAttrs(componentAttr(v.component)) + } + if v.requestID != "" { + record.AddAttrs(RequestID(v.requestID)) + } + if v.jobID != "" { + record.AddAttrs(jobIDAttr(v.jobID)) + } +} + func withString(ctx context.Context, key contextKey, value string) context.Context { if ctx == nil { ctx = context.Background() From ed6c6ed58822e0c27e008832a381e9320e649530 Mon Sep 17 00:00:00 2001 From: park285 Date: Tue, 11 Aug 2026 14:33:46 +0900 Subject: [PATCH 03/14] perf(logging): reuse slog source values --- pkg/logging/format.go | 7 ++----- 1 file changed, 2 insertions(+), 5 deletions(-) diff --git a/pkg/logging/format.go b/pkg/logging/format.go index 7cb6aea..f394b95 100644 --- a/pkg/logging/format.go +++ b/pkg/logging/format.go @@ -38,11 +38,8 @@ func shortenSource(groups []string, attr slog.Attr) slog.Attr { if !ok { return attr } - return slog.Any(slog.SourceKey, &slog.Source{ - Function: source.Function, - File: lastPathSegments(source.File), - Line: source.Line, - }) + source.File = lastPathSegments(source.File) + return attr } // filepath.Join은 Clean 때문에 record마다 할당한다. 여기서는 substring slice로 충분하다. From c4db4be5362fa99f0099de68079207d7b4ca807e Mon Sep 17 00:00:00 2001 From: park285 Date: Tue, 11 Aug 2026 14:34:13 +0900 Subject: [PATCH 04/14] test(logging): lock hot-path allocation contracts --- pkg/logging/hotpath_test.go | 121 ++++++++++++++++++++++++++++++++++++ 1 file changed, 121 insertions(+) create mode 100644 pkg/logging/hotpath_test.go diff --git a/pkg/logging/hotpath_test.go b/pkg/logging/hotpath_test.go new file mode 100644 index 0000000..79a617c --- /dev/null +++ b/pkg/logging/hotpath_test.go @@ -0,0 +1,121 @@ +package logging + +import ( + "context" + "log/slog" + "runtime" + "strings" + "testing" +) + +type hotpathCaptureHandler struct { + enabledCalls int + handled int + record slog.Record +} + +func (h *hotpathCaptureHandler) Enabled(context.Context, slog.Level) bool { + h.enabledCalls++ + return true +} + +func (h *hotpathCaptureHandler) Handle(_ context.Context, record slog.Record) error { + h.handled++ + h.record = record.Clone() + return nil +} + +func (h *hotpathCaptureHandler) WithAttrs([]slog.Attr) slog.Handler { return h } +func (h *hotpathCaptureHandler) WithGroup(string) slog.Handler { return h } + +type hotpathDiscardHandler struct{} + +func (hotpathDiscardHandler) Enabled(context.Context, slog.Level) bool { return true } +func (hotpathDiscardHandler) Handle(context.Context, slog.Record) error { return nil } +func (h hotpathDiscardHandler) WithAttrs([]slog.Attr) slog.Handler { return h } +func (h hotpathDiscardHandler) WithGroup(string) slog.Handler { return h } + +func TestLog_CommonPathZeroAlloc(t *testing.T) { + logger := slog.New(hotpathDiscardHandler{}) + ctx := WithRequestID(WithRuntime(context.Background(), "bot"), "req-1") + + got := testing.AllocsPerRun(1000, func() { + Log(ctx, logger, slog.LevelInfo, "request.completed", "request completed", + slog.String("method", "GET"), + slog.Int("status", 200), + ) + }) + if got != 0 { + t.Fatalf("Log common-path allocs = %v, want 0", got) + } +} + +func TestLog_CallsEnabledOnce(t *testing.T) { + handler := &hotpathCaptureHandler{} + logger := slog.New(handler) + + Info(context.Background(), logger, "event", "message") + + if handler.enabledCalls != 1 { + t.Fatalf("Enabled calls = %d, want 1", handler.enabledCalls) + } + if handler.handled != 1 { + t.Fatalf("Handle calls = %d, want 1", handler.handled) + } +} + +func TestLog_CapturesWrapperCaller(t *testing.T) { + handler := &hotpathCaptureHandler{} + logger := slog.New(handler) + + Info(context.Background(), logger, "event", "message") + + frames := runtime.CallersFrames([]uintptr{handler.record.PC}) + frame, _ := frames.Next() + if !strings.HasSuffix(frame.Function, ".TestLog_CapturesWrapperCaller") { + t.Fatalf("source function = %q, want test caller", frame.Function) + } + if !strings.HasSuffix(frame.File, "pkg/logging/hotpath_test.go") { + t.Fatalf("source file = %q, want hotpath_test.go", frame.File) + } +} + +func TestContextAttrs_EmptyZeroAlloc(t *testing.T) { + got := testing.AllocsPerRun(1000, func() { + if attrs := ContextAttrs(context.Background()); attrs != nil { + panic("empty context attrs must be nil") + } + }) + if got != 0 { + t.Fatalf("ContextAttrs(empty) allocs = %v, want 0", got) + } +} + +func TestShortenSource_ReusesSourceValue(t *testing.T) { + source := &slog.Source{ + Function: "main.run", + File: "/build/root/pkg/logging/file.go", + Line: 42, + } + attr := slog.Any(slog.SourceKey, source) + + out := shortenSource(nil, attr) + if out.Value.Any() != source { + t.Fatal("shortenSource replaced the source object") + } + if source.File != "logging/file.go" { + t.Fatalf("source file = %q, want %q", source.File, "logging/file.go") + } +} + +func BenchmarkLogCommonPath(b *testing.B) { + logger := slog.New(hotpathDiscardHandler{}) + ctx := WithRequestID(WithRuntime(context.Background(), "bot"), "req-1") + b.ReportAllocs() + for range b.N { + Log(ctx, logger, slog.LevelInfo, "request.completed", "request completed", + slog.String("method", "GET"), + slog.Int("status", 200), + ) + } +} From 74e70163f132129090f4a6e231d3e2c7a3574a1a Mon Sep 17 00:00:00 2001 From: park285 Date: Tue, 11 Aug 2026 14:36:12 +0900 Subject: [PATCH 05/14] perf(logging): make sanitizer groups copy-on-write --- pkg/logging/sanitize.go | 62 ++++++++++++++++++++++++++++------------- 1 file changed, 43 insertions(+), 19 deletions(-) diff --git a/pkg/logging/sanitize.go b/pkg/logging/sanitize.go index 1163264..4b1809d 100644 --- a/pkg/logging/sanitize.go +++ b/pkg/logging/sanitize.go @@ -296,9 +296,10 @@ func (h *sanitizeHandler) WithAttrs(attrs []slog.Attr) slog.Handler { // 열린 group 이름이 privacy·credential key면 그 아래 attr은 key가 무엇이든 값이 그 식별자나 // credential의 구성 요소다. func (h *sanitizeHandler) WithGroup(name string) slog.Handler { + normalizedName := normalizeSensitiveKey(name) return &sanitizeHandler{ inner: h.inner.WithGroup(name), - inMaskedGroup: h.inMaskedGroup || isPrivacyKey(name) || isSensitiveKey(name), + inMaskedGroup: h.inMaskedGroup || isMaskedNormalizedKey(normalizedName), } } @@ -325,38 +326,47 @@ func sanitizeAttrChanged(attr slog.Attr) (slog.Attr, bool) { attr.Value = attr.Value.Resolve() // key 기반 판정은 값을 읽지 않으므로 모든 값 분기(KindAny·KindGroup·KindString)보다 앞이어야 // 한다. 뒤에 두면 마스킹 여부가 값 타입이나 무관한 map 내용에 종속된다. - if isPrivacyKey(attr.Key) || isSensitiveKey(attr.Key) { + normalizedKey := normalizeSensitiveKey(attr.Key) + if isMaskedNormalizedKey(normalizedKey) { return slog.String(attr.Key, redactedValue), true } if attr.Value.Kind() == slog.KindAny { - if raw, ok := attr.Value.Any().(map[string]any); ok { + value := attr.Value.Any() + if raw, ok := value.(map[string]any); ok { if masked, mapChanged := maskPrivacyMap(raw); mapChanged { return slog.Any(attr.Key, masked), true } } - if err, ok := attr.Value.Any().(error); ok { + if err, ok := value.(error); ok { return slog.String(attr.Key, RedactDiagnostic(err.Error())), true } } if attr.Value.Kind() == slog.KindGroup { groupAttrs := attr.Value.Group() - sanitized := make([]any, 0, len(groupAttrs)) - for _, groupAttr := range groupAttrs { - out, c := sanitizeAttrChanged(groupAttr) - if c { - changed = true + for index, groupAttr := range groupAttrs { + out, childChanged := sanitizeAttrChanged(groupAttr) + if !childChanged { + continue + } + + sanitized := make([]slog.Attr, len(groupAttrs)) + copy(sanitized, groupAttrs[:index]) + sanitized[index] = out + for next := index + 1; next < len(groupAttrs); next++ { + sanitized[next] = sanitizeAttr(groupAttrs[next]) } - sanitized = append(sanitized, out) + attr.Value = slog.GroupValue(sanitized...) + return attr, true } - return slog.Group(attr.Key, sanitized...), changed + return attr, changed } if attr.Value.Kind() != slog.KindString { return attr, changed } - if isBroadValueKey(attr.Key) && isSecretLikeValue(attr.Value.String()) { + if isBroadValueNormalizedKey(normalizedKey) && isSecretLikeValue(attr.Value.String()) { return slog.String(attr.Key, redactedValue), true } @@ -368,15 +378,16 @@ func sanitizeAttrChanged(attr slog.Attr) (slog.Attr, bool) { } func isSensitiveKey(key string) bool { - normalized := normalizeSensitiveKey(key) + return isSensitiveNormalizedKey(normalizeSensitiveKey(key)) +} + +func isSensitiveNormalizedKey(normalized string) bool { if normalized == "" { return false } - if _, ok := sensitiveExactKeys[normalized]; ok { return true } - return strings.HasSuffix(normalized, "_token") || strings.HasSuffix(normalized, "_secret") || strings.HasSuffix(normalized, "_password") || @@ -387,6 +398,10 @@ func isSensitiveKey(key string) bool { strings.HasSuffix(normalized, "_secret_key") } +func isMaskedNormalizedKey(normalized string) bool { + return isPrivacyNormalizedKey(normalized) || isSensitiveNormalizedKey(normalized) +} + func normalizeSensitiveKey(key string) string { key = strings.ToLower(strings.TrimSpace(key)) key = strings.ReplaceAll(key, "-", "_") @@ -400,12 +415,20 @@ var broadValueKeys = map[string]struct{}{ } func isBroadValueKey(key string) bool { - _, ok := broadValueKeys[normalizeSensitiveKey(key)] + return isBroadValueNormalizedKey(normalizeSensitiveKey(key)) +} + +func isBroadValueNormalizedKey(normalized string) bool { + _, ok := broadValueKeys[normalized] return ok } func isPrivacyKey(key string) bool { - _, ok := privacyExactKeys[normalizeSensitiveKey(key)] + return isPrivacyNormalizedKey(normalizeSensitiveKey(key)) +} + +func isPrivacyNormalizedKey(normalized string) bool { + _, ok := privacyExactKeys[normalized] return ok } @@ -447,11 +470,12 @@ func maskPrivacyMapDepth(raw map[string]any, depth int) (map[string]any, bool) { } func shouldMaskStructuredMapValue(key string, value any) bool { - if isPrivacyKey(key) || isSensitiveKey(key) { + normalizedKey := normalizeSensitiveKey(key) + if isMaskedNormalizedKey(normalizedKey) { return true } text, ok := value.(string) - return ok && isBroadValueKey(key) && isSecretLikeValue(text) + return ok && isBroadValueNormalizedKey(normalizedKey) && isSecretLikeValue(text) } var secretLikePrefixes = []string{ From 3dfab00385b553c97aa8ce757034414bc8aec332 Mon Sep 17 00:00:00 2001 From: park285 Date: Tue, 11 Aug 2026 14:37:41 +0900 Subject: [PATCH 06/14] test(logging): cover sanitizer copy-on-write path --- pkg/logging/hotpath_test.go | 78 +++++++++++++++++++++++++++++++++++++ 1 file changed, 78 insertions(+) diff --git a/pkg/logging/hotpath_test.go b/pkg/logging/hotpath_test.go index 79a617c..904f69e 100644 --- a/pkg/logging/hotpath_test.go +++ b/pkg/logging/hotpath_test.go @@ -108,6 +108,67 @@ func TestShortenSource_ReusesSourceValue(t *testing.T) { } } +func TestSanitizeCleanGroup_ZeroAlloc(t *testing.T) { + attr := slog.Group("request", + slog.String("method", "GET"), + slog.String("path", "/api/users"), + slog.Int("status", 200), + ) + var ( + out slog.Attr + changed bool + ) + + got := testing.AllocsPerRun(1000, func() { + out, changed = sanitizeAttrChanged(attr) + }) + if got != 0 { + t.Fatalf("clean group sanitize allocs = %v, want 0", got) + } + if changed { + t.Fatal("clean group reported a change") + } + if !out.Equal(attr) { + t.Fatalf("clean group changed: got %v, want %v", out, attr) + } +} + +func TestSanitizeGroupCopyOnWrite_MasksNestedValue(t *testing.T) { + attr := slog.Group("request", + slog.String("method", "GET"), + slog.Group("headers", + slog.String("authorization", "Bearer secret"), + slog.String("accept", "application/json"), + ), + slog.Int("status", 200), + ) + + out, changed := sanitizeAttrChanged(attr) + if !changed { + t.Fatal("sensitive nested group reported no change") + } + + requestAttrs := out.Value.Group() + if len(requestAttrs) != 3 { + t.Fatalf("request attrs = %d, want 3", len(requestAttrs)) + } + headers := requestAttrs[1].Value.Group() + if len(headers) != 2 { + t.Fatalf("header attrs = %d, want 2", len(headers)) + } + if got := headers[0].Value.String(); got != redactedValue { + t.Fatalf("authorization = %q, want %q", got, redactedValue) + } + if got := headers[1].Value.String(); got != "application/json" { + t.Fatalf("accept = %q, want %q", got, "application/json") + } + + originalHeaders := attr.Value.Group()[1].Value.Group() + if got := originalHeaders[0].Value.String(); got != "Bearer secret" { + t.Fatalf("caller-owned group mutated: authorization = %q", got) + } +} + func BenchmarkLogCommonPath(b *testing.B) { logger := slog.New(hotpathDiscardHandler{}) ctx := WithRequestID(WithRuntime(context.Background(), "bot"), "req-1") @@ -119,3 +180,20 @@ func BenchmarkLogCommonPath(b *testing.B) { ) } } + +func BenchmarkSanitizeCleanGroup(b *testing.B) { + attr := slog.Group("request", + slog.String("method", "GET"), + slog.String("path", "/api/users"), + slog.Int("status", 200), + ) + var out slog.Attr + + b.ReportAllocs() + for range b.N { + out, _ = sanitizeAttrChanged(attr) + } + if !out.Equal(attr) { + b.Fatal("clean group changed") + } +} From 865f39b8e87b09d9e6eb58865cc38e457743ecbb Mon Sep 17 00:00:00 2001 From: park285 Date: Tue, 11 Aug 2026 14:41:21 +0900 Subject: [PATCH 07/14] style(logging): apply gofmt to hot-path tests --- pkg/logging/hotpath_test.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pkg/logging/hotpath_test.go b/pkg/logging/hotpath_test.go index 904f69e..ccae427 100644 --- a/pkg/logging/hotpath_test.go +++ b/pkg/logging/hotpath_test.go @@ -26,7 +26,7 @@ func (h *hotpathCaptureHandler) Handle(_ context.Context, record slog.Record) er } func (h *hotpathCaptureHandler) WithAttrs([]slog.Attr) slog.Handler { return h } -func (h *hotpathCaptureHandler) WithGroup(string) slog.Handler { return h } +func (h *hotpathCaptureHandler) WithGroup(string) slog.Handler { return h } type hotpathDiscardHandler struct{} From 777ccde943974338c74b04944b0a22c5d3aed816 Mon Sep 17 00:00:00 2001 From: park285 Date: Tue, 11 Aug 2026 14:43:30 +0900 Subject: [PATCH 08/14] fix(logging): preserve caller-owned source values --- pkg/logging/format.go | 7 +++++-- 1 file changed, 5 insertions(+), 2 deletions(-) diff --git a/pkg/logging/format.go b/pkg/logging/format.go index f394b95..7cb6aea 100644 --- a/pkg/logging/format.go +++ b/pkg/logging/format.go @@ -38,8 +38,11 @@ func shortenSource(groups []string, attr slog.Attr) slog.Attr { if !ok { return attr } - source.File = lastPathSegments(source.File) - return attr + return slog.Any(slog.SourceKey, &slog.Source{ + Function: source.Function, + File: lastPathSegments(source.File), + Line: source.Line, + }) } // filepath.Join은 Clean 때문에 record마다 할당한다. 여기서는 substring slice로 충분하다. From ad5233992ac254858c39f13633d3a03ec212fb4a Mon Sep 17 00:00:00 2001 From: park285 Date: Tue, 11 Aug 2026 14:43:55 +0900 Subject: [PATCH 09/14] test(logging): keep source shortening immutable --- pkg/logging/hotpath_test.go | 17 ----------------- 1 file changed, 17 deletions(-) diff --git a/pkg/logging/hotpath_test.go b/pkg/logging/hotpath_test.go index ccae427..044c844 100644 --- a/pkg/logging/hotpath_test.go +++ b/pkg/logging/hotpath_test.go @@ -91,23 +91,6 @@ func TestContextAttrs_EmptyZeroAlloc(t *testing.T) { } } -func TestShortenSource_ReusesSourceValue(t *testing.T) { - source := &slog.Source{ - Function: "main.run", - File: "/build/root/pkg/logging/file.go", - Line: 42, - } - attr := slog.Any(slog.SourceKey, source) - - out := shortenSource(nil, attr) - if out.Value.Any() != source { - t.Fatal("shortenSource replaced the source object") - } - if source.File != "logging/file.go" { - t.Fatalf("source file = %q, want %q", source.File, "logging/file.go") - } -} - func TestSanitizeCleanGroup_ZeroAlloc(t *testing.T) { attr := slog.Group("request", slog.String("method", "GET"), From 973dcd3d5988a0f121cc813b0aa715b87d5195a2 Mon Sep 17 00:00:00 2001 From: park285 Date: Tue, 11 Aug 2026 14:47:32 +0900 Subject: [PATCH 10/14] lint(logging): document ignored handler errors --- pkg/logging/log.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/pkg/logging/log.go b/pkg/logging/log.go index 9f548a0..6d96dd9 100644 --- a/pkg/logging/log.go +++ b/pkg/logging/log.go @@ -53,7 +53,7 @@ func log(ctx context.Context, logger *slog.Logger, level slog.Level, event, mess } contextValuesFrom(ctx).addToRecord(&record) record.AddAttrs(attrs...) - _ = logger.Handler().Handle(ctx, record) + _ = logger.Handler().Handle(ctx, record) //nolint:errcheck // slog.Logger의 public logging API도 handler error를 반환하지 않는다 } func logMessage(event, message string) string { From c4e48f58b90820105a4057cc995817b188898f23 Mon Sep 17 00:00:00 2001 From: park285 Date: Tue, 11 Aug 2026 14:49:17 +0900 Subject: [PATCH 11/14] test(logging): cover broad-value key normalization --- pkg/logging/hotpath_test.go | 9 +++++++++ 1 file changed, 9 insertions(+) diff --git a/pkg/logging/hotpath_test.go b/pkg/logging/hotpath_test.go index 044c844..cfbde15 100644 --- a/pkg/logging/hotpath_test.go +++ b/pkg/logging/hotpath_test.go @@ -91,6 +91,15 @@ func TestContextAttrs_EmptyZeroAlloc(t *testing.T) { } } +func TestBroadValueKeyNormalizesRawKeys(t *testing.T) { + if !isBroadValueKey(" KEY ") { + t.Fatal("raw broad-value key was not normalized") + } + if isBroadValueKey("api_key") { + t.Fatal("sensitive exact key must not be classified as a broad-value key") + } +} + func TestSanitizeCleanGroup_ZeroAlloc(t *testing.T) { attr := slog.Group("request", slog.String("method", "GET"), From 62bc2b0cb82fafe49493cd6e5ffa137d9c948be2 Mon Sep 17 00:00:00 2001 From: kapu Date: Tue, 11 Aug 2026 16:09:39 +0900 Subject: [PATCH 12/14] =?UTF-8?q?perf(logging):=20JSON=20source=EB=A5=BC?= =?UTF-8?q?=20file:line=20=EB=AC=B8=EC=9E=90=EC=97=B4=EB=A1=9C=20=ED=8F=89?= =?UTF-8?q?=ED=83=84=ED=99=94?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit AddSource가 켜진 formatter는 record마다 *slog.Source를 두 번 할당하고 slog이 그것을 3-attr group으로 전개하면서 또 할당했다. alloc 프로파일에서 이 세 지점이 실제 출력 경로 할당의 약 80%를 차지했다. shortenSource가 group 대신 "dir/file.go:line" 한 문자열을 돌려주도록 바꿔 Source 재할당과 group 전개를 함께 제거한다. PC 0 record는 빈 Source를 낳으므로 빈 Attr을 돌려주는 가드를 둔다. 이 가드가 없으면 ":0"이 실려, 지금까지 slog이 통째로 생략하던 합성 source가 async summary record에 되살아난다. JSON 출력 계약이 바뀐다. source가 객체에서 문자열이 되고 function 필드가 빠진다. 절대 경로 미노출과 line 보존은 그대로다. --- pkg/logging/format.go | 25 +++++++++++++++++-------- pkg/logging/format_test.go | 32 +++++++++++++++++++++++++------- 2 files changed, 42 insertions(+), 15 deletions(-) diff --git a/pkg/logging/format.go b/pkg/logging/format.go index 7cb6aea..6ac7235 100644 --- a/pkg/logging/format.go +++ b/pkg/logging/format.go @@ -4,6 +4,7 @@ import ( "fmt" "io" "log/slog" + "strconv" "strings" ) @@ -29,7 +30,9 @@ func newFormatHandler(level slog.Level, w io.Writer) slog.Handler { } // slog 기본값은 빌드 머신의 절대 경로를 모든 record에 싣는다. -// dir/file 축약으로 빌드 디렉터리 구조 노출과 record 크기를 함께 줄인다. +// dir/file 축약으로 빌드 디렉터리 구조 노출과 record 크기를 함께 줄이고, +// "dir/file.go:line" 한 문자열로 평탄화해 record마다 드는 *slog.Source 재할당과 +// slog의 source group 전개 할당을 함께 없앤다. func shortenSource(groups []string, attr slog.Attr) slog.Attr { if len(groups) > 0 || attr.Key != slog.SourceKey { return attr @@ -38,16 +41,22 @@ func shortenSource(groups []string, attr slog.Attr) slog.Attr { if !ok { return attr } - return slog.Any(slog.SourceKey, &slog.Source{ - Function: source.Function, - File: lastPathSegments(source.File), - Line: source.Line, - }) + // PC 0 record는 빈 Source를 낳는다. 빈 Attr을 돌려줘야 slog이 통째로 생략한다. + // 평탄화 판본은 이 가드가 없으면 ":0"을 실어 생략을 되살리지 못한다. + if source.File == "" && source.Line == 0 { + return slog.Attr{} + } + + var buf [128]byte + out := append(buf[:0], lastPathSegments(source.File)...) + out = append(out, ':') + out = strconv.AppendInt(out, int64(source.Line), 10) + return slog.String(slog.SourceKey, string(out)) } // filepath.Join은 Clean 때문에 record마다 할당한다. 여기서는 substring slice로 충분하다. -// 빈 경로에 ""를 돌려주는 것이 load-bearing이다. filepath 판본은 "."를 만들어, PC 0 record가 -// 낳는 빈 Source를 slog이 생략하지 못하게 되살린다. +// 빈 경로에 ""를 돌려주는 것이 load-bearing이다. filepath 판본은 "."를 만들어, File만 +// 비어 있고 Line이 살아 있는 record에 ".:42" 같은 허위 경로를 남긴다. func lastPathSegments(path string) string { base := strings.LastIndexByte(path, '/') if base < 0 { diff --git a/pkg/logging/format_test.go b/pkg/logging/format_test.go index a5e67c5..4428d65 100644 --- a/pkg/logging/format_test.go +++ b/pkg/logging/format_test.go @@ -2,6 +2,7 @@ package logging import ( "bytes" + "context" "encoding/json" "io" "log/slog" @@ -10,6 +11,7 @@ import ( "reflect" "strings" "testing" + "time" ) const ( @@ -356,19 +358,35 @@ func TestJSONFormat_ShortensSourcePath(t *testing.T) { slog.New(newFormatHandler(slog.LevelInfo, &buf)).Info("format_probe_source") record := probeJSONRecord(t, "json/source", buf.String()) - source, ok := record[slog.SourceKey].(map[string]any) + source, ok := record[slog.SourceKey].(string) if !ok { - t.Fatalf("source is not an object: %v", record[slog.SourceKey]) + t.Fatalf("source is not a string: %v", record[slog.SourceKey]) + } + file, line, found := strings.Cut(source, ":") + if !found { + t.Fatalf("source = %q, want \"file:line\"", source) } - file, _ := source["file"].(string) if filepath.IsAbs(file) { - t.Fatalf("source.file is an absolute build path: %q", file) + t.Fatalf("source file is an absolute build path: %q", file) } if want := "logging/format_test.go"; file != want { - t.Fatalf("source.file = %q, want %q", file, want) + t.Fatalf("source file = %q, want %q", file, want) + } + if line == "" || line == "0" { + t.Fatalf("source line dropped: %q", source) } - if _, ok := source["line"]; !ok { - t.Fatalf("source.line dropped: %v", source) +} + +func TestJSONFormat_OmitsSourceForZeroPC(t *testing.T) { + var buf bytes.Buffer + handler := newFormatHandler(slog.LevelInfo, &buf) + if err := handler.Handle(context.Background(), slog.NewRecord(time.Now(), slog.LevelInfo, "format_probe_zero_pc", 0)); err != nil { + t.Fatalf("handle zero-PC record: %v", err) + } + + record := probeJSONRecord(t, "json/zero-pc", buf.String()) + if value, ok := record[slog.SourceKey]; ok { + t.Fatalf("PC 0 record carries a source attr: %v", value) } } From 20468cf6983b73fdb3878c87faffb05a5c522be4 Mon Sep 17 00:00:00 2001 From: kapu Date: Tue, 11 Aug 2026 16:10:11 +0900 Subject: [PATCH 13/14] =?UTF-8?q?perf(logging):=20error=20helper=EC=9D=98?= =?UTF-8?q?=20attr=20=EB=B3=91=ED=95=A9=20slice=20=EC=A0=9C=EA=B1=B0?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit LogAndWrapError와 LogWarnWithErrorAttrs는 ErrorAttrs 결과와 호출자 attr을 mergedAttrs로 합쳐 넘겼다. log가 방금 없앤 병합 slice가 소비자들이 실제로 쓰는 진입점에 그대로 남아 있었다. logWith가 두 attr 묶음을 따로 받아 Record에 직접 넣도록 하고, runtime.Callers skip을 상수로 분리한다. helper 경유 경로의 source가 helper 본문이 아니라 실제 호출 지점을 가리키게 되는 것이 부수 효과다. alloc 상한은 race 빌드에서 값이 달라지므로 promptguard와 같은 !race 파일로 분리하고, CI가 race 없는 별도 스텝에서 돌리도록 확장한다. 이 스텝이 없으면 새 상한은 CI에서 아예 실행되지 않는다. --- .github/workflows/ci.yml | 6 ++-- pkg/logging/allocation_test.go | 52 ++++++++++++++++++++++++++++++++++ pkg/logging/hotpath_test.go | 24 ++++++++++++++++ pkg/logging/log.go | 26 ++++++++++++----- pkg/logging/log_and_wrap.go | 7 +---- pkg/logging/log_warn.go | 7 +---- 6 files changed, 101 insertions(+), 21 deletions(-) create mode 100644 pkg/logging/allocation_test.go diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index e96603d..07ab3fb 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -65,8 +65,10 @@ jobs: - name: golangci-lint run: make lint - - name: Deterministic guard allocation ceilings - run: go test -count=1 -run '^TestPromptGuardAllocationCeilings$' ./pkg/promptguard + - name: Deterministic allocation ceilings + run: | + go test -count=1 -run '^TestPromptGuardAllocationCeilings$' ./pkg/promptguard + go test -count=1 -run '^TestLoggingAllocationCeilings$' ./pkg/logging - name: go test race run: go test -race -count=1 ./... diff --git a/pkg/logging/allocation_test.go b/pkg/logging/allocation_test.go new file mode 100644 index 0000000..d5abd09 --- /dev/null +++ b/pkg/logging/allocation_test.go @@ -0,0 +1,52 @@ +//go:build !race + +package logging + +import ( + "context" + "io" + "log/slog" + "testing" +) + +func TestLoggingAllocationCeilings(t *testing.T) { + logger := slog.New(newFormatHandler(slog.LevelInfo, io.Discard)) + ctx := WithRequestID(WithRuntime(context.Background(), "bot"), "req-1") + + tests := []struct { + name string + maxAllocs float64 + call func() + }{ + { + name: "log common path", + maxAllocs: 5, + call: func() { + Log(ctx, logger, slog.LevelInfo, "request.completed", "request completed", + slog.String("method", "GET"), slog.Int("status", 200)) + }, + }, + { + name: "log and wrap error", + maxAllocs: 12, + call: func() { + _ = LogAndWrapError(ctx, logger, "op", context.DeadlineExceeded, slog.String("a", "b")) + }, + }, + { + name: "log warn with error attrs", + maxAllocs: 12, + call: func() { + LogWarnWithErrorAttrs(ctx, logger, "event", "message", context.DeadlineExceeded, slog.String("a", "b")) + }, + }, + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + if got := testing.AllocsPerRun(200, test.call); got > test.maxAllocs { + t.Fatalf("%s allocs = %v, want <= %v", test.name, got, test.maxAllocs) + } + }) + } +} diff --git a/pkg/logging/hotpath_test.go b/pkg/logging/hotpath_test.go index cfbde15..4b6edd3 100644 --- a/pkg/logging/hotpath_test.go +++ b/pkg/logging/hotpath_test.go @@ -161,6 +161,30 @@ func TestSanitizeGroupCopyOnWrite_MasksNestedValue(t *testing.T) { } } +func TestErrorHelpers_CaptureCallerSource(t *testing.T) { + cases := map[string]func(context.Context, *slog.Logger){ + "LogAndWrapError": func(ctx context.Context, logger *slog.Logger) { + _ = LogAndWrapError(ctx, logger, "op", context.DeadlineExceeded) + }, + "LogWarnWithErrorAttrs": func(ctx context.Context, logger *slog.Logger) { + LogWarnWithErrorAttrs(ctx, logger, "event", "message", context.DeadlineExceeded) + }, + } + + for name, call := range cases { + t.Run(name, func(t *testing.T) { + handler := &hotpathCaptureHandler{} + call(context.Background(), slog.New(handler)) + + frames := runtime.CallersFrames([]uintptr{handler.record.PC}) + frame, _ := frames.Next() + if !strings.HasSuffix(frame.File, "pkg/logging/hotpath_test.go") { + t.Fatalf("source file = %q, want the call site rather than the helper body", frame.File) + } + }) + } +} + func BenchmarkLogCommonPath(b *testing.B) { logger := slog.New(hotpathDiscardHandler{}) ctx := WithRequestID(WithRuntime(context.Background(), "bot"), "req-1") diff --git a/pkg/logging/log.go b/pkg/logging/log.go index 6d96dd9..04fb7fe 100644 --- a/pkg/logging/log.go +++ b/pkg/logging/log.go @@ -28,12 +28,23 @@ func Log(ctx context.Context, logger *slog.Logger, level slog.Level, event, mess log(ctx, logger, level, event, message, attrs...) } -// log는 level gate 뒤 Record를 직접 구성해 전달한다. Logger.LogAttrs의 두 번째 Enabled -// 호출과 임시 attr 병합 slice를 피하고, Record의 inline attr 저장소를 그대로 활용한다. -// -// runtime.Callers의 skip 3은 이 함수 바로 위의 exported logging wrapper 호출자를 가리킨다. -// 따라서 일반적인 Debug/Info/Warn/Error/Log 사용에서는 실제 애플리케이션 호출 위치가 남는다. +// runtime.Callers에 넘길 skip. logWith까지의 프레임 수가 경로마다 다르므로 상수로 고정한다. +const ( + // runtime.Callers → logWith → log → exported wrapper → 실제 호출자 + callerSkipViaWrapper = 4 + // runtime.Callers → logWith → 호출한 helper → 실제 호출자 + callerSkipViaHelper = 3 +) + func log(ctx context.Context, logger *slog.Logger, level slog.Level, event, message string, attrs ...slog.Attr) { + logWith(ctx, logger, level, event, message, callerSkipViaWrapper, attrs, nil) +} + +// logWith는 level gate 뒤 Record를 직접 구성해 전달한다. Logger.LogAttrs의 두 번째 Enabled +// 호출과 임시 attr 병합 slice를 피하고, Record의 inline attr 저장소를 그대로 활용한다. +// primary와 secondary를 따로 받는 것도 같은 이유다. 호출자가 두 attr 묶음을 미리 합치면 +// 그 병합 slice가 record마다 할당된다. +func logWith(ctx context.Context, logger *slog.Logger, level slog.Level, event, message string, skip int, primary, secondary []slog.Attr) { if logger == nil { return } @@ -45,14 +56,15 @@ func log(ctx context.Context, logger *slog.Logger, level slog.Level, event, mess } var pcs [1]uintptr - runtime.Callers(3, pcs[:]) + runtime.Callers(skip, pcs[:]) record := slog.NewRecord(time.Now(), level, logMessage(event, message), pcs[0]) if strings.TrimSpace(event) != "" { record.AddAttrs(Event(event)) } contextValuesFrom(ctx).addToRecord(&record) - record.AddAttrs(attrs...) + record.AddAttrs(primary...) + record.AddAttrs(secondary...) _ = logger.Handler().Handle(ctx, record) //nolint:errcheck // slog.Logger의 public logging API도 handler error를 반환하지 않는다 } diff --git a/pkg/logging/log_and_wrap.go b/pkg/logging/log_and_wrap.go index 146ca9f..e1146b0 100644 --- a/pkg/logging/log_and_wrap.go +++ b/pkg/logging/log_and_wrap.go @@ -12,11 +12,6 @@ func LogAndWrapError(ctx context.Context, logger *slog.Logger, op string, err er return nil } - errorAttrs := ErrorAttrs(err) - mergedAttrs := make([]slog.Attr, 0, len(errorAttrs)+len(attrs)) - mergedAttrs = append(mergedAttrs, errorAttrs...) - mergedAttrs = append(mergedAttrs, attrs...) - - Error(ctx, logger, op+".failed", op+": "+err.Error(), mergedAttrs...) + logWith(ctx, logger, slog.LevelError, op+".failed", op+": "+err.Error(), callerSkipViaHelper, ErrorAttrs(err), attrs) return fmt.Errorf("%s: %w", op, err) } diff --git a/pkg/logging/log_warn.go b/pkg/logging/log_warn.go index e0045ed..3b9c5de 100644 --- a/pkg/logging/log_warn.go +++ b/pkg/logging/log_warn.go @@ -11,10 +11,5 @@ func LogWarnWithErrorAttrs(ctx context.Context, logger *slog.Logger, event, mess return } - errorAttrs := ErrorAttrs(err) - mergedAttrs := make([]slog.Attr, 0, len(errorAttrs)+len(attrs)) - mergedAttrs = append(mergedAttrs, errorAttrs...) - mergedAttrs = append(mergedAttrs, attrs...) - - Warn(ctx, logger, event, message, mergedAttrs...) + logWith(ctx, logger, slog.LevelWarn, event, message, callerSkipViaHelper, ErrorAttrs(err), attrs) } From 72984698aa28765c8c083fa83d2317ba9dc53c3b Mon Sep 17 00:00:00 2001 From: kapu Date: Tue, 11 Aug 2026 16:12:07 +0900 Subject: [PATCH 14/14] =?UTF-8?q?style(logging):=20=EC=BD=94=EB=93=9C?= =?UTF-8?q?=EC=97=90=EC=84=9C=20=EC=9D=BD=ED=9E=88=EB=8A=94=20=EC=A3=BC?= =?UTF-8?q?=EC=84=9D=20=EC=A0=95=EB=A6=AC?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit shortenSource와 skip 상수 블록에서 시그니처와 아래 주석이 이미 말해주는 설명을 덜어낸다. PC 0 가드와 프레임 체인처럼 코드로 확인할 수 없는 설명은 그대로 둔다. --- pkg/logging/format.go | 4 +--- pkg/logging/log.go | 1 - 2 files changed, 1 insertion(+), 4 deletions(-) diff --git a/pkg/logging/format.go b/pkg/logging/format.go index 6ac7235..2783612 100644 --- a/pkg/logging/format.go +++ b/pkg/logging/format.go @@ -30,9 +30,7 @@ func newFormatHandler(level slog.Level, w io.Writer) slog.Handler { } // slog 기본값은 빌드 머신의 절대 경로를 모든 record에 싣는다. -// dir/file 축약으로 빌드 디렉터리 구조 노출과 record 크기를 함께 줄이고, -// "dir/file.go:line" 한 문자열로 평탄화해 record마다 드는 *slog.Source 재할당과 -// slog의 source group 전개 할당을 함께 없앤다. +// dir/file 축약으로 빌드 디렉터리 구조 노출과 record 크기를 함께 줄인다. func shortenSource(groups []string, attr slog.Attr) slog.Attr { if len(groups) > 0 || attr.Key != slog.SourceKey { return attr diff --git a/pkg/logging/log.go b/pkg/logging/log.go index 04fb7fe..125e86e 100644 --- a/pkg/logging/log.go +++ b/pkg/logging/log.go @@ -28,7 +28,6 @@ func Log(ctx context.Context, logger *slog.Logger, level slog.Level, event, mess log(ctx, logger, level, event, message, attrs...) } -// runtime.Callers에 넘길 skip. logWith까지의 프레임 수가 경로마다 다르므로 상수로 고정한다. const ( // runtime.Callers → logWith → log → exported wrapper → 실제 호출자 callerSkipViaWrapper = 4