diff --git a/docs/CHECKLIST.md b/docs/CHECKLIST.md index a32b82c..b48b3cb 100644 --- a/docs/CHECKLIST.md +++ b/docs/CHECKLIST.md @@ -55,6 +55,8 @@ Usage belongs in the utility guides. [Feature comparison](FEATURE_PARITY.md) map ## Logger +- [x] L-25: Reduce common Logger encoding and filtering overhead (#248) while preserving root order, omission rules, hooks, caller ownership, error atomicity and the main-only stack Preview. Logger regression tests, its packaged-module/standalone-consumer checks and the native Lambda SDK Logger fixture pass; the composed Lambda example builds as static Linux amd64/arm64 ELF binaries with CGO disabled. Same-source local Windows benchmarks retain output sizes: the small emitted case drops from 118 to 34 allocations, invocation-bound INFO from 193 to 53, and both unbuffered filtered cases reach zero allocations. Timing observations, source hashes and scope are recorded in [PERFORMANCE_LOGGER_248.json](PERFORMANCE_LOGGER_248.json); no AWS performance improvement or universal budget is claimed (2026-10-15). + - [x] L-24: Implement main-only structured error stacks and handler panic logging Preview (#241). Verify error-chain identity, independent join branches, lazy 64-frame stacks, opt-outs/hooks, single-line JSON, nested/concurrent cleanup, and original panic preservation under diagnostic failures. Actual typed/raw Lambda SDK and OTel exporter composition passes; [PR #242 CI](https://github.com/rambow-cloud/powertools-lambda-go/actions/runs/38706578552) passes packaged Logger/examples/integration tests, vet, tidy/isolation, consumers, Linux amd64/arm64 cross-builds and Docker Linux amd64 Lambda/streaming/Valkey acceptance. Local Docker startup was unavailable; hosted Docker supplies platform evidence. Fresh public v1.2.0 consumption retains the old behavior and rejects all three Preview APIs. A public SHA consumer and a post-merge direct-origin `@main` consumer verify the Preview; main resolves to `a179f0373577` (proxy branch caching is documented). Cloudflare Pages and GitHub Pages deployments succeed for that source. All Go checks use CGO disabled; no AWS tests or Go version publication (2026-10-15). - [x] AUDIT-LOGGER-181-LOCAL: Complete the finite [Logger boundary matrix](reference/LOGGER.md#finite-boundary-audit-181), reusing 48 pinned action cases and adding 26 timezone/environment/sink cases plus native marshaler and short-write regressions. Reproduce and fix ignored container TextMarshaler values/errors and duplicate failed JSON/streaming marshaler calls during replacement. Preserve Go JSON v2, native diagnostic and zero-offset differences explicitly. Packaged Logger tests/vet/tidy/isolation and an independent consumer pass with CGO disabled; broader L-08/L-09, resource and multi-worker/platform gates remain separate (2026-10-13). diff --git a/docs/PERFORMANCE.md b/docs/PERFORMANCE.md index 8cc743d..759f4a3 100644 --- a/docs/PERFORMANCE.md +++ b/docs/PERFORMANCE.md @@ -38,6 +38,46 @@ only to investigate a meaningful change or unresolved variability. Review allocations and output sizes alongside time; this single-run baseline does not define statistically justified pass/fail percentages or universal latency budgets. +## Logger hot-path comparison (#248) + +The Logger optimization compares the same benchmark source against commit +`35f9d088e9ca96d5718f4ca1a793332c756c2f2c` and the updated implementation. +Both runs use Go 1.27.1, Windows amd64, `CGO_ENABLED=0`, `GOMAXPROCS=2`, a +counting writer and one 300ms measurement per case. The original baseline above +remains a separate historical measurement. + +| Operation | Before ns/op | After ns/op | Before B/op | After B/op | Before allocs/op | After allocs/op | +| --- | ---: | ---: | ---: | ---: | ---: | ---: | +| Logger emitted, 208 output bytes | 9,771 | 5,249 | 5,592 | 2,752 | 118 | 34 | +| Invocation-bound INFO, 404 output bytes | 14,750 | 6,939 | 9,417 | 4,448 | 193 | 53 | +| Bind context and INFO, 404 output bytes | 14,812 | 7,764 | 9,704 | 4,737 | 194 | 54 | +| Complete wrapper and INFO, 404 output bytes | 15,696 | 7,715 | 11,377 | 6,409 | 208 | 68 | +| Logger filtered | 544.2 | 15.68 | 528 | 0 | 4 | 0 | +| Invocation-bound filtered | 285.3 | 16.45 | 432 | 0 | 5 | 0 | + +All emitted cases retain their output size. The invocation benchmark also includes +a direct JSON control with identical enriched fields: 47 allocations and 2,773 +bytes per operation in both runs. That control omits Logger normalization, root +ordering and synchronization. The Logger cases preserve those behaviors, error +atomicity, formatter/replacer hooks and the main-only stack Preview. + +The improvements come from sharing one JSON v2 encoder, processing ordinary maps +and scalars without reflective iteration, reducing ordering/output copies, and +avoiding unused trace lookup on filtered/unbuffered paths. Source hashes and all +seven raw benchmark summaries are recorded in +[PERFORMANCE_LOGGER_248.json](PERFORMANCE_LOGGER_248.json). + +Run from `logger` with CGO disabled: + +```sh +CGO_ENABLED=0 GOMAXPROCS=2 go test -p 1 -run '^$' -bench '^BenchmarkLogger($|Invocation)' -benchmem -benchtime=300ms -count=1 . +``` + +These single-run local observations locate overhead; they do not establish a +statistical regression budget or predict Linux Lambda latency. CloudWatch/stdout +I/O, CPU quotas, GC under large-event workloads and cold starts require separate +measurements. No AWS benchmark was run for this change. + ## Measurement boundaries Construction and schema compilation happen outside the timed operations. Clocks diff --git a/docs/PERFORMANCE_LOGGER_248.json b/docs/PERFORMANCE_LOGGER_248.json new file mode 100644 index 0000000..58a9846 --- /dev/null +++ b/docs/PERFORMANCE_LOGGER_248.json @@ -0,0 +1,128 @@ +{ + "issue": 248, + "verified_at": "2026-10-15", + "baseline_commit": "35f9d088e9ca96d5718f4ca1a793332c756c2f2c", + "source_sha256": { + "logger/logger.go": "b4380ec8d13a43d0ca4c722cece19256db074d19ec6f10cd993008aeb98b61c3", + "logger/encoding.go": "f629d39a1068b0e97578082a225d4555e9f34bc40e9214677f10d9ac54dd9aee", + "logger/benchmark_test.go": "d6d07f03eaad83bf2ec7fa371d0d25b0a84fcdc1318139b1420156e760f773e1", + "logger/performance_regression_test.go": "145b1c348fa8ff5e4b477c2cc354924ba386b275c71e1ad105c1071e00d97dc8" + }, + "environment": { + "go": "go1.27.1", + "os": "windows", + "architecture": "amd64", + "CGO_ENABLED": "0", + "GOMAXPROCS": "2", + "cpu": "12th Gen Intel Core i5-12500H" + }, + "command": "go test -p 1 -run '^$' -bench '^BenchmarkLogger($|Invocation)' -benchmem -benchtime=300ms -count=1 .", + "scope": "Single local measurements of the same benchmark source before and after; counting writer, no AWS runtime or stdout I/O latency. DirectJSON shares enrichment and fields but omits Logger normalization, ordering and synchronization. This does not establish Lambda latency or statistical performance budgets.", + "results": [ + { + "benchmark": "BenchmarkLoggerInvocation/DirectJSON-2", + "before": { + "ns_per_op": 5613.0, + "output_bytes_per_op": 404.0, + "bytes_per_op": 2773, + "allocations_per_op": 47 + }, + "after": { + "ns_per_op": 4984.0, + "output_bytes_per_op": 404.0, + "bytes_per_op": 2773, + "allocations_per_op": 47 + } + }, + { + "benchmark": "BenchmarkLoggerInvocation/BoundINFO-2", + "before": { + "ns_per_op": 14750.0, + "output_bytes_per_op": 404.0, + "bytes_per_op": 9417, + "allocations_per_op": 193 + }, + "after": { + "ns_per_op": 6939.0, + "output_bytes_per_op": 404.0, + "bytes_per_op": 4448, + "allocations_per_op": 53 + } + }, + { + "benchmark": "BenchmarkLoggerInvocation/BindAndINFO-2", + "before": { + "ns_per_op": 14812.0, + "output_bytes_per_op": 404.0, + "bytes_per_op": 9704, + "allocations_per_op": 194 + }, + "after": { + "ns_per_op": 7764.0, + "output_bytes_per_op": 404.0, + "bytes_per_op": 4737, + "allocations_per_op": 54 + } + }, + { + "benchmark": "BenchmarkLoggerInvocation/WrappedINFO-2", + "before": { + "ns_per_op": 15696.0, + "output_bytes_per_op": 404.0, + "bytes_per_op": 11377, + "allocations_per_op": 208 + }, + "after": { + "ns_per_op": 7715.0, + "output_bytes_per_op": 404.0, + "bytes_per_op": 6409, + "allocations_per_op": 68 + } + }, + { + "benchmark": "BenchmarkLoggerInvocation/Filtered-2", + "before": { + "ns_per_op": 285.3, + "output_bytes_per_op": 0.0, + "bytes_per_op": 432, + "allocations_per_op": 5 + }, + "after": { + "ns_per_op": 16.45, + "output_bytes_per_op": 0.0, + "bytes_per_op": 0, + "allocations_per_op": 0 + } + }, + { + "benchmark": "BenchmarkLogger/Emitted-2", + "before": { + "ns_per_op": 9771.0, + "output_bytes_per_op": 208.0, + "bytes_per_op": 5592, + "allocations_per_op": 118 + }, + "after": { + "ns_per_op": 5249.0, + "output_bytes_per_op": 208.0, + "bytes_per_op": 2752, + "allocations_per_op": 34 + } + }, + { + "benchmark": "BenchmarkLogger/Filtered-2", + "before": { + "ns_per_op": 544.2, + "output_bytes_per_op": 0.0, + "bytes_per_op": 528, + "allocations_per_op": 4 + }, + "after": { + "ns_per_op": 15.68, + "output_bytes_per_op": 0.0, + "bytes_per_op": 0, + "allocations_per_op": 0 + } + } + ] +} diff --git a/logger/benchmark_test.go b/logger/benchmark_test.go index bc8ecb0..cfb8500 100644 --- a/logger/benchmark_test.go +++ b/logger/benchmark_test.go @@ -1,9 +1,13 @@ package logger import ( + "context" + json "encoding/json/v2" "errors" "testing" "time" + + "github.com/aws/aws-lambda-go/lambdacontext" ) type benchmarkWriter struct{ bytes int64 } @@ -13,6 +17,82 @@ func (w *benchmarkWriter) Write(p []byte) (int, error) { return len(p), nil } +// Compare identical invocation fields and output sinks. DirectJSON shares record +// enrichment but omits Logger normalization and ordered-root encoding. +func BenchmarkLoggerInvocation(b *testing.B) { + for _, mode := range []string{"DirectJSON", "BoundINFO", "BindAndINFO", "WrappedINFO", "Filtered"} { + b.Run(mode, func(b *testing.B) { + for _, key := range []string{"POWERTOOLS_DEV", "POWERTOOLS_LOG_LEVEL", "POWERTOOLS_LOGGER_SAMPLE_RATE", "AWS_LAMBDA_LOG_LEVEL", "POWERTOOLS_LOGGER_LOG_EVENT"} { + b.Setenv(key, "") + } + b.Setenv("AWS_LAMBDA_FUNCTION_NAME", "benchmark") + b.Setenv("AWS_LAMBDA_FUNCTION_MEMORY_SIZE", "256") + ctx := lambdacontext.NewContext(context.Background(), &lambdacontext.LambdaContext{ + AwsRequestID: "request-123", InvokedFunctionArn: "arn:aws:lambda:ap-east-1:123456789012:function:benchmark", + }) + ctx = context.WithValue(ctx, "x-amzn-trace-id", "Root=1-12345678-123456789012345678901234;Sampled=0") + var out benchmarkWriter + level := InfoLevel + if mode == "Filtered" { + level = WarnLevel + } + log := New(WithOutput(&out), WithLevel(level), WithSampleRate(0), WithServiceName("benchmark"), WithClock(func() time.Time { + return time.Date(2026, 10, 15, 0, 0, 0, 0, time.UTC) + })) + // All modes compare warm invocation records, including cold_start=false. + warmup := WrapHandler(log, func(context.Context, int) (int, error) { return 0, nil }) + if _, err := warmup(ctx, 0); err != nil { + b.Fatal(err) + } + fields := Fields{"case_id": "case-123", "records": 3, "checksum": 210} + write := func(bound *Logger) error { + if mode == "DirectJSON" { + data, err := json.Marshal(bound.record(InfoLevel, "benchmark", fields)) + if err != nil { + return err + } + _, err = out.Write(append(data, '\n')) + return err + } + return bound.Info("benchmark", fields) + } + b.ReportAllocs() + if mode == "WrappedINFO" { + handler := WrapHandler(log, func(ctx context.Context, _ int) (int, error) { + return 0, write(log.WithContext(ctx)) + }) + b.ResetTimer() + for b.Loop() { + if _, err := handler(ctx, 0); err != nil { + b.Fatal(err) + } + } + } else { + handler := WrapHandler(log, func(ctx context.Context, _ int) (int, error) { + bound := log.WithContext(ctx) + b.ResetTimer() + for b.Loop() { + current := bound + if mode == "BindAndINFO" { + current = log.WithContext(ctx) + } + if err := write(current); err != nil { + b.Fatal(err) + } + } + b.StopTimer() + return 0, nil + }) + if _, err := handler(ctx, 0); err != nil { + b.Fatal(err) + } + } + b.StopTimer() + b.ReportMetric(float64(out.bytes)/float64(b.N), "output-B/op") + }) + } +} + func BenchmarkErrorStack(b *testing.B) { for _, mode := range []string{"disabled", "logging", "attached", "capture-and-log", "filtered"} { b.Run(mode, func(b *testing.B) { diff --git a/logger/encoding.go b/logger/encoding.go index 4c8f282..d6f1586 100644 --- a/logger/encoding.go +++ b/logger/encoding.go @@ -1,7 +1,6 @@ package logger import ( - "bytes" "encoding" jsonv1 "encoding/json" "encoding/json/jsontext" @@ -103,6 +102,22 @@ func (n *normalizer) normalizeValue(key string, value any, depth int) (any, erro if depth > 100 { return "[Truncated]", nil } + // Plain scalars cannot have custom methods or contain circular references. + // Named types continue through the marshaler and reflection checks below. + switch value := value.(type) { + case string, bool, int, int8, int16, int32, int64, uint, uint8, uint16, uint32, uint64, uintptr: + return value, nil + case float32: + if math.IsNaN(float64(value)) || math.IsInf(float64(value), 0) { + return nil, nil + } + return value, nil + case float64: + if math.IsNaN(value) || math.IsInf(value, 0) { + return nil, nil + } + return value, nil + } // Number implements MarshalJSONTo in Go 1.27. Its scalar representation // must not re-enter the custom-marshaler traversal after decoding. if _, ok := value.(jsonv1.Number); ok { @@ -180,6 +195,17 @@ func (n *normalizer) normalizeValue(key string, value any, depth int) (any, erro if _, ok := value.(encoding.TextMarshaler); ok { return value, nil } + if fields, ok := asFields(value); ok { + result := make(Fields, len(fields)) + for key, value := range fields { + encoded, err := n.normalize(key, value, depth+1) + if err != nil { + return nil, err + } + result[key] = encoded + } + return result, nil + } switch v.Kind() { case reflect.Struct: return n.normalizeJSON(key, value, depth) @@ -255,6 +281,13 @@ func prepareForPrint(value any) any { if _, ok := value.(encoding.TextMarshaler); ok { return value } + switch fields := value.(type) { + case Fields: + return prepareFields(fields) + case map[string]any: + // Preserve the root's concrete type for user replacers. + return map[string]any(prepareFields(Fields(fields))) + } v := reflect.ValueOf(value) if !v.IsValid() || v.Kind() != reflect.Map || v.Type().Key().Kind() != reflect.String { return value @@ -289,6 +322,40 @@ func prepareForPrint(value any) any { return result.Interface() } +func prepareFields(fields Fields) Fields { + result := make(Fields, len(fields)) + for key, value := range fields { + if value == nil { + continue + } + if text, ok := value.(string); ok { + if text != "" { + result[key] = value + } + continue + } + // A named nil container can implement a marshaler; preserve its method. + _, jsonCustom := value.(json.Marshaler) + _, streamingCustom := value.(json.MarshalerTo) + _, textCustom := value.(encoding.TextMarshaler) + if !jsonCustom && !streamingCustom && !textCustom { + v := reflect.ValueOf(value) + switch v.Kind() { + case reflect.String: + if v.Len() == 0 { + continue + } + case reflect.Pointer, reflect.Map, reflect.Slice, reflect.Interface: + if v.IsNil() { + continue + } + } + } + result[key] = value + } + return result +} + func encode(fields Fields, c config) ([]byte, error) { n := normalizer{replacer: c.replacer, active: map[visit]bool{}, stacks: c.stackTrace, source: c.stackSource} return n.encode(fields, c) @@ -309,44 +376,14 @@ func (n *normalizer) encode(fields Fields, c config) ([]byte, error) { } var data []byte if object, ok := asFields(value); ok { - order := append(append([]string(nil), c.order...), standardOrder...) - remaining := make([]string, 0, len(object)) - for k := range object { - remaining = append(remaining, k) - } - sort.Strings(remaining) - order = append(order, remaining...) - seen := map[string]bool{} - var out bytes.Buffer - out.WriteByte('{') - for _, key := range order { - v, exists := object[key] - if !exists || seen[key] { - continue - } - if len(seen) > 0 { - out.WriteByte(',') - } - seen[key] = true - k, e := marshal(key) - if e != nil { - return nil, e - } - b, e := marshal(v) - if e != nil { - return nil, e - } - out.Write(k) - out.WriteByte(':') - out.Write(b) - } - out.WriteByte('}') - data = out.Bytes() + // Normalization owns this root map. The encoder may consume its keys + // without changing formatter/replacer inputs or caller-owned maps. + data, err = marshal(&orderedFields{fields: object, order: c.order}) } else { data, err = marshal(value) - if err != nil { - return nil, err - } + } + if err != nil { + return nil, err } if c.pretty { pretty := jsontext.Value(data) @@ -357,3 +394,49 @@ func (n *normalizer) encode(fields Fields, c config) ([]byte, error) { } return data, nil } + +// orderedFields writes one complete document through a single JSON v2 encoder. +// Marshal retains private buffering, so failed values never reach the log sink. +type orderedFields struct { + fields Fields + order []string +} + +func (o *orderedFields) MarshalJSONTo(enc *jsontext.Encoder) error { + if err := enc.WriteToken(jsontext.BeginObject); err != nil { + return err + } + for _, order := range [][]string{o.order, standardOrder} { + for _, key := range order { + if err := o.writeField(enc, key); err != nil { + return err + } + } + } + remaining := make([]string, 0, len(o.fields)) + for key := range o.fields { + remaining = append(remaining, key) + } + sort.Strings(remaining) + for _, key := range remaining { + if err := o.writeField(enc, key); err != nil { + return err + } + } + return enc.WriteToken(jsontext.EndObject) +} + +func (o *orderedFields) writeField(enc *jsontext.Encoder, key string) error { + value, exists := o.fields[key] + if !exists { + return nil + } + if err := enc.WriteToken(jsontext.String(key)); err != nil { + return err + } + if err := json.MarshalEncode(enc, value); err != nil { + return err + } + delete(o.fields, key) + return nil +} diff --git a/logger/logger.go b/logger/logger.go index d70bd89..02f77c4 100644 --- a/logger/logger.go +++ b/logger/logger.go @@ -32,7 +32,9 @@ func (o *output) write(level Level, data []byte) error { if level >= WarnLevel { w = o.stderr } - line := append(append([]byte(nil), data...), '\n') + // Encoded records own their bytes; neither encoding nor buffered entries + // reuse them after delivery. Writers must obey io.Writer's ownership rule. + line := append(data, '\n') n, err := w.Write(line) if err == nil && n != len(line) { err = io.ErrShortWrite @@ -252,14 +254,14 @@ func (l *Logger) record(level Level, message string, extra ...any) Fields { fields["tenant_id"] = lc.TenantID } } - if id := invocation.TraceID(l.ctx); id != "" { - fields["xray_trace_id"] = id - } if span := trace.SpanContextFromContext(l.ctx); span.IsValid() { - fields["trace_id"] = span.TraceID().String() + id := span.TraceID().String() + fields["trace_id"] = id fields["span_id"] = span.SpanID().String() // Active OTel context takes precedence over stale runtime/process headers. - fields["xray_trace_id"] = commons.FormatXRayTraceID(span.TraceID().String()) + fields["xray_trace_id"] = commons.FormatXRayTraceID(id) + } else if id := invocation.TraceID(l.ctx); id != "" { + fields["xray_trace_id"] = id } l.current.mu.Lock() for k, v := range l.current.persistent { @@ -310,8 +312,11 @@ func (l *Logger) Log(level Level, message string, extra ...any) error { if l.cfg.buffer.MaxBytes > 0 && !l.cfg.buffer.DisableFlushOnError && level >= ErrorLevel { flushErr = l.FlushBuffer() } - traceID := l.bufferTraceID() - buffer := l.cfg.buffer.MaxBytes > 0 && traceID != "" && level <= l.cfg.buffer.BufferAt + var traceID string + if l.cfg.buffer.MaxBytes > 0 && level <= l.cfg.buffer.BufferAt { + traceID = l.bufferTraceID() + } + buffer := traceID != "" if !buffer && level < threshold { return flushErr } diff --git a/logger/performance_regression_test.go b/logger/performance_regression_test.go new file mode 100644 index 0000000..3607753 --- /dev/null +++ b/logger/performance_regression_test.go @@ -0,0 +1,136 @@ +package logger + +import ( + "bytes" + "context" + "encoding/json/jsontext" + json "encoding/json/v2" + "errors" + "reflect" + "strings" + "testing" + + "go.opentelemetry.io/otel/trace" +) + +func TestOrderedEncodingPreservesFormatterInput(t *testing.T) { + cleanEnv(t) + for _, plainMap := range []bool{false, true} { + fields := Fields{"z": 3, "message": "formatted", "empty": "", "nil": nil, "a\"\n": "中\n文", "nested": Fields{"empty": "", "nil": nil}} + var input any = fields + if plainMap { + input = map[string]any(fields) + } + var out bytes.Buffer + rootCalls := 0 + log := New(WithOutput(&out), WithRecordOrder("z", "missing", "z", "message", "a\"\n"), + WithFormatter(func(Fields) (any, error) { return input, nil }), + WithReplacer(func(key string, value any) any { + if key == "" { + rootCalls++ + if reflect.TypeOf(value) != reflect.TypeOf(input) { + t.Fatalf("root type changed from %T to %T", input, value) + } + } + return value + })) + for range 2 { + if err := log.Info("original"); err != nil { + t.Fatal(err) + } + } + want := "{\"z\":3,\"message\":\"formatted\",\"a\\\"\\n\":\"中\\n文\",\"nested\":{" + lines := strings.Split(strings.TrimSuffix(out.String(), "\n"), "\n") + if len(lines) != 2 || !strings.HasPrefix(lines[0], want) || !strings.HasPrefix(lines[1], want) || rootCalls != 2 { + t.Fatalf("order, framing or replacer changed: calls=%d output=%s", rootCalls, &out) + } + for _, record := range records(t, &out) { + nested := record["nested"].(map[string]any) + if len(record) != 4 || nested["empty"] != "" || len(nested) != 2 { + t.Fatalf("omission rules changed: %v", record) + } + } + if len(fields) != 6 || fields["empty"] != "" || fields["nil"] != nil || fields["message"] != "formatted" { + t.Fatal("encoder consumed formatter-owned fields") + } + } +} + +type partialDocumentMarshaler struct{ calls int } + +var partialDocumentError = errors.New("failed after writing a large JSON value") + +func (m *partialDocumentMarshaler) MarshalJSONTo(enc *jsontext.Encoder) error { + m.calls++ + if err := enc.WriteToken(jsontext.String(strings.Repeat("x", 8192))); err != nil { + return err + } + return partialDocumentError +} + +func TestOrderedEncoderFailureRemainsAtomic(t *testing.T) { + cleanEnv(t) + var out bytes.Buffer + value := &partialDocumentMarshaler{} + log := New(WithOutput(&out), WithRecordOrder("before", "failure", "after")) + err := log.Info("failure", Fields{"before": strings.Repeat("y", 8192), "failure": value, "after": "unwritten"}) + var semantic *json.SemanticError + if !errors.Is(err, partialDocumentError) || !errors.As(err, &semantic) || value.calls != 1 || out.Len() != 0 { + t.Fatalf("partial output or changed failure: writes=%d bytes=%d error=%v", value.calls, out.Len(), err) + } + if err := log.Info("recovered"); err != nil || len(records(t, &out)) != 1 { + t.Fatalf("failed encoder poisoned subsequent writes: %v", err) + } +} + +type traceLookupContext struct { + context.Context + header string + lookups int +} + +func (ctx *traceLookupContext) Value(key any) any { + if text, ok := key.(string); ok && text == "x-amzn-trace-id" { + ctx.lookups++ + return ctx.header + } + return ctx.Context.Value(key) +} + +func TestUnbufferedTraceLookupAndFiltering(t *testing.T) { + cleanEnv(t) + ctx := &traceLookupContext{Context: context.Background(), header: "Root=1-11111111-111111111111111111111111;Sampled=0"} + var out bytes.Buffer + log := New(WithOutput(&out)).WithContext(ctx) + fields := Fields{"value": 1} + allocs := testing.AllocsPerRun(100, func() { + if err := log.Debug("filtered", fields); err != nil { + panic(err) + } + }) + if ctx.lookups != 0 || out.Len() != 0 || allocs != 0 { + t.Fatalf("filtered log enriched: lookups=%d bytes=%d allocations=%v", ctx.lookups, out.Len(), allocs) + } + for _, header := range []string{"Root=1-11111111-111111111111111111111111;Sampled=0", "Root=1-22222222-222222222222222222222222;Sampled=0"} { + ctx.header = header + if err := log.Info("visible"); err != nil { + t.Fatal(err) + } + } + got := records(t, &out) + if ctx.lookups != 2 || got[0]["xray_trace_id"] == got[1]["xray_trace_id"] { + t.Fatalf("trace was repeated or cached across records: lookups=%d records=%v", ctx.lookups, got) + } + span := trace.NewSpanContext(trace.SpanContextConfig{ + TraceID: trace.TraceID{1}, SpanID: trace.SpanID{1}, + }) + if err := log.WithContext(trace.ContextWithSpanContext(ctx, span)).Info("otel"); err != nil || ctx.lookups != 2 { + t.Fatalf("active OTel context looked up the unused fallback: lookups=%d error=%v", ctx.lookups, err) + } + log.current.mu.Lock() + log.current.closed = true + log.current.mu.Unlock() + if err := log.Debug("closed"); !errors.Is(err, ErrInvocationClosed) { + t.Fatalf("filtering bypassed invocation closure: %v", err) + } +}