diff --git a/.github/workflows/test.yaml b/.github/workflows/test.yaml index f195282..a86c72b 100644 --- a/.github/workflows/test.yaml +++ b/.github/workflows/test.yaml @@ -22,7 +22,7 @@ jobs: - name: Set up Go uses: actions/setup-go@v5 with: - go-version: 1.25.x + go-version: 1.26.x - name: Checkout Code uses: actions/checkout@v4 @@ -41,7 +41,7 @@ jobs: strategy: fail-fast: true matrix: - go-version: [1.24.x, 1.25.x] + go-version: [1.24.x, 1.25.x, 1.26.x] env: GOPATH: ${{ github.workspace }}/go GOBIN: ${{ github.workspace }}/go/bin diff --git a/rlog/README.md b/rlog/README.md index 73f7420..0623c2e 100644 --- a/rlog/README.md +++ b/rlog/README.md @@ -1,20 +1,48 @@ # rlog -The `r` is for “Rotational”! This package extends [`log/slog`](https://pkg.go.dev/log/slog) with **Trace**, **Fatal**, and **Panic**, and helpers in the usual shapes (key/value, `*Context`, `*Attrs`). See [`go doc`](https://pkg.go.dev/go.rtnl.ai/x/rlog) for the full API. +The `r` is for “Rotational”! This module extends [`log/slog`](https://pkg.go.dev/log/slog) with **Trace**, **Fatal**, and **Panic**, options so those levels print with sensible names, and helpers to keep a global level in sync. The root package is [`go.rtnl.ai/x/rlog`](https://pkg.go.dev/go.rtnl.ai/x/rlog). Subpackages add a dev-friendly console handler, test capture helpers, and logging to multiple handlers at once. See [`go doc`](https://pkg.go.dev/go.rtnl.ai/x/rlog) and the subpackage docs for the full API. + +## `rlog.Logger` + +[`Logger`](https://pkg.go.dev/go.rtnl.ai/x/rlog#Logger) wraps [`*slog.Logger`](https://pkg.go.dev/log/slog#Logger) and adds **Trace**, **Fatal**, and **Panic** (with `Context` and `Attrs` variants), plus **DebugAttrs**, **InfoAttrs**, **WarnAttrs**, and **ErrorAttrs** for the built-in levels. [`New`](https://pkg.go.dev/go.rtnl.ai/x/rlog#New) builds one from an `*slog.Logger`; `nil` selects [`Default`](https://pkg.go.dev/go.rtnl.ai/x/rlog#Default). + +[`With`](https://pkg.go.dev/go.rtnl.ai/x/rlog#Logger.With) and [`WithGroup`](https://pkg.go.dev/go.rtnl.ai/x/rlog#Logger.WithGroup) behave like slog’s. Package-level helpers delegate to the default logger. - **Fatal** runs [`SetFatalHook`](https://pkg.go.dev/go.rtnl.ai/x/rlog#SetFatalHook) after logging if set; otherwise [`os.Exit(1)`](https://pkg.go.dev/os#Exit). **Panic** logs then panics with the message. -- [`MergeWithCustomLevels`](https://pkg.go.dev/go.rtnl.ai/x/rlog#MergeWithCustomLevels) maps custom levels to names `TRACE`, `FATAL`, `PANIC` in JSON/text output. [`ReplaceLevelKey`](https://pkg.go.dev/go.rtnl.ai/x/rlog#ReplaceLevelKey) does only the level mapping if you compose `ReplaceAttr` yourself. [`WithGlobalLevel`](https://pkg.go.dev/go.rtnl.ai/x/rlog#WithGlobalLevel) helps keep the global logging level synced. -- [`Logger.With`](https://pkg.go.dev/go.rtnl.ai/x/rlog#Logger.With) / [`WithGroup`](https://pkg.go.dev/go.rtnl.ai/x/rlog#Logger.WithGroup) keep a `*rlog.Logger` (same args as [`slog.Logger.With`](https://pkg.go.dev/log/slog#Logger.With)). Package-level [`With`](https://pkg.go.dev/go.rtnl.ai/x/rlog#With), [`WithGroup`](https://pkg.go.dev/go.rtnl.ai/x/rlog#WithGroup), [`Log`](https://pkg.go.dev/go.rtnl.ai/x/rlog#Log), and [`LogAttrs`](https://pkg.go.dev/go.rtnl.ai/x/rlog#LogAttrs) use the default logger. -- [`NewFanOut`](https://pkg.go.dev/go.rtnl.ai/x/rlog#NewFanOut) returns a [`slog.Handler`](https://pkg.go.dev/log/slog#Handler) that forwards each record to every child handler (multi-sink logging). -- [`NewCapturingTestHandler`](https://pkg.go.dev/go.rtnl.ai/x/rlog#NewCapturingTestHandler) helps tests capture records and JSON lines; pass `nil` or a [`testing.TB`](https://pkg.go.dev/testing#TB) to print test logs to the console. Helpers include [`ParseJSONLine`](https://pkg.go.dev/go.rtnl.ai/x/rlog#ParseJSONLine), [`ResultMaps`](https://pkg.go.dev/go.rtnl.ai/x/rlog#CapturingTestHandler.ResultMaps), and [`RecordsAndLines`](https://pkg.go.dev/go.rtnl.ai/x/rlog#CapturingTestHandler.RecordsAndLines) which returns a mutex-locked snapshot of current logs. -- [`LevelDecoder`](https://pkg.go.dev/go.rtnl.ai/x/rlog#LevelDecoder) parses level strings, including the added `TRACE`, `FATAL`, and `PANIC`. -## Default logger and Custom Handlers +## Package `rlog` (core) + +- [`MergeWithCustomLevels`](https://pkg.go.dev/go.rtnl.ai/x/rlog#MergeWithCustomLevels) labels custom severities as `TRACE`, `FATAL`, and `PANIC` in output. [`WithGlobalLevel`](https://pkg.go.dev/go.rtnl.ai/x/rlog#WithGlobalLevel) ties a handler’s threshold to [`SetLevel`](https://pkg.go.dev/go.rtnl.ai/x/rlog#SetLevel). [`ReplaceLevelKey`](https://pkg.go.dev/go.rtnl.ai/x/rlog#ReplaceLevelKey) is there if you build your own `ReplaceAttr` pipeline. +- [`LevelDecoder`](https://pkg.go.dev/go.rtnl.ai/x/rlog#LevelDecoder) parses level strings, including the extra severities. + +## Subpackage `console` + +[`go.rtnl.ai/x/rlog/console`](https://pkg.go.dev/go.rtnl.ai/x/rlog/console) provides a [`slog.Handler`](https://pkg.go.dev/log/slog#Handler) that prints **readable lines**: optional file/line, time, level (colors optional), message, and a JSON blob of attributes unless you turn that off. Meant for local dev and tests, not maximum throughput. + +[`console.New`](https://pkg.go.dev/go.rtnl.ai/x/rlog/console#New) and [`console.Options`](https://pkg.go.dev/go.rtnl.ai/x/rlog/console#Options) cover the usual slog options plus color, JSON layout, and UTC time. Use [`(*Options).MergeWithCustomLevels`](https://pkg.go.dev/go.rtnl.ai/x/rlog/console#Options.MergeWithCustomLevels) so TRACE/FATAL/PANIC match the rest of rlog. + +Demo from this repo: `go run ./rlog/console/cmd/`. + +## Subpackage `testing` + +[`go.rtnl.ai/x/rlog/testing`](https://pkg.go.dev/go.rtnl.ai/x/rlog/testing) — import with an alias (e.g. `rlogtesting "go.rtnl.ai/x/rlog/testing"`) so it does not clash with the standard [`testing`](https://pkg.go.dev/testing) package. + +[`NewCapturingTestHandler`](https://pkg.go.dev/go.rtnl.ai/x/rlog/testing#NewCapturingTestHandler) captures each log as JSON; pass `t` to also print lines in the test output, or `nil` for silent capture. Use [`Records`](https://pkg.go.dev/go.rtnl.ai/x/rlog/testing#CapturingTestHandler.Records), [`Lines`](https://pkg.go.dev/go.rtnl.ai/x/rlog/testing#CapturingTestHandler.Lines), [`RecordsAndLines`](https://pkg.go.dev/go.rtnl.ai/x/rlog/testing#CapturingTestHandler.RecordsAndLines), [`ResultMaps`](https://pkg.go.dev/go.rtnl.ai/x/rlog/testing#CapturingTestHandler.ResultMaps), and [`Reset`](https://pkg.go.dev/go.rtnl.ai/x/rlog/testing#CapturingTestHandler.Reset) in assertions. [`ParseJSONLine`](https://pkg.go.dev/go.rtnl.ai/x/rlog/testing#ParseJSONLine) / [`MustParseJSONLine`](https://pkg.go.dev/go.rtnl.ai/x/rlog/testing#MustParseJSONLine) help parse lines. + +Use [`rlog.New`](https://pkg.go.dev/go.rtnl.ai/x/rlog#New) on top when you need `*rlog.Logger` in tests. + +## Subpackage `fanout` + +[`go.rtnl.ai/x/rlog/fanout`](https://pkg.go.dev/go.rtnl.ai/x/rlog/fanout) sends **every log to every** child [`slog.Handler`](https://pkg.go.dev/log/slog#Handler). Build one with [`fanout.New`](https://pkg.go.dev/go.rtnl.ai/x/rlog/fanout#New). + +On **Go 1.26+**, use [`slog.MultiHandler`](https://pkg.go.dev/log/slog#MultiHandler) instead; this package covers the same idea on **Go 1.25 and earlier**. + +## Default logger and custom handlers -- The package default logs JSON to stdout at **Info**. -- [`SetDefault`](https://pkg.go.dev/go.rtnl.ai/x/rlog#SetDefault) replaces rlog’s global logger and updates [`slog.Default`](https://pkg.go.dev/log/slog#Default) via [`slog.SetDefault`](https://pkg.go.dev/log/slog#SetDefault). -- [`SetLevel`](https://pkg.go.dev/go.rtnl.ai/x/rlog#SetLevel), [`Level`](https://pkg.go.dev/go.rtnl.ai/x/rlog#Level), and [`LevelString`](https://pkg.go.dev/go.rtnl.ai/x/rlog#LevelString) read or set the shared [`slog.LevelVar`](https://pkg.go.dev/log/slog#LevelVar) wired into the default install. -- Handlers you build yourself should use `MergeWithCustomLevels(WithGlobalLevel(opts))` so they still honor that threshold after you call [`SetDefault`](https://pkg.go.dev/go.rtnl.ai/x/rlog#SetDefault); see [`WithGlobalLevel`](https://pkg.go.dev/go.rtnl.ai/x/rlog#WithGlobalLevel). +- Default: JSON on stdout at **Info**. +- [`SetDefault`](https://pkg.go.dev/go.rtnl.ai/x/rlog#SetDefault) replaces rlog’s default and keeps [`slog.Default`](https://pkg.go.dev/log/slog#Default) aligned. +- [`SetLevel`](https://pkg.go.dev/go.rtnl.ai/x/rlog#SetLevel), [`Level`](https://pkg.go.dev/go.rtnl.ai/x/rlog#Level), and [`LevelString`](https://pkg.go.dev/go.rtnl.ai/x/rlog#LevelString) control the default logger’s threshold. +- For your own handlers, combine `MergeWithCustomLevels` and `WithGlobalLevel` so they respect the same global level after `SetDefault` (see [`WithGlobalLevel`](https://pkg.go.dev/go.rtnl.ai/x/rlog#WithGlobalLevel)). ## Example @@ -48,7 +76,7 @@ func main() { // Without a hook, Fatal would os.Exit(1) and the rest of main would not run. rlog.SetFatalHook(func() {}) // demo only — replace with test hook or omit in production - defer rlog.SetFatalHook(nil) // setting the fatal hook to nil causes future Fatal calls to use os.Exit(1) + defer rlog.SetFatalHook(nil) log.Fatal("fatal-msg") // Output example: {"time":"…","level":"FATAL","msg":"fatal-msg"} — then runs the fatal hook (no exit here) diff --git a/rlog/benchmark_test.go b/rlog/benchmark_test.go new file mode 100644 index 0000000..40b0ee6 --- /dev/null +++ b/rlog/benchmark_test.go @@ -0,0 +1,461 @@ +package rlog_test + +import ( + "context" + "fmt" + "log/slog" + "math" + "os" + "runtime" + "testing" + "time" + + "go.rtnl.ai/x/rlog" +) + +// envRunLoggerVsSlogCompare must be set to "1" to run [TestLoggerVsSlogCompare]. That keeps plain +// go test and IDE "run test" (which pass -run by name) from executing this slow comparison unless +// you opt in from a real shell. +const envRunLoggerVsSlogCompare = "RLOG_LOGGER_VS_SLOG_COMPARE" + +// BenchmarkLoggerVsSlog compares *rlog.Logger with *slog.Logger on identical nop handlers. +// +// # What every logging sub-benchmark measures +// +// Each “slog/…” and “rlog/…” pair uses the same [nopHandler]: Enabled always true, Handle a no-op. +// So the cost is almost entirely: capture caller PC (when applicable), build [slog.Record], merge +// attrs, dispatch to Handle—no I/O, no JSON, no locks in the handler. +// +// Sub-benchmark names: +// - LogAttrs-none — LogAttrs with message only (no extra attributes). +// - Info-kv — Info with one string key and int value ("a", 1). +// - Log-kv — Log with the same key/value pair. +// - *+pollute — same as above, but each iteration calls [benchPolluteCache] first (full rationale +// in the helpers section under “Cache pollution”). +// - paired/Info-kv-interleaved — one slog.Info then one rlog.Info per b.N iteration; ns/op is time +// for both calls together (not per logger). Useful to see both code paths in one hot loop. +// - rlog/Trace-none — custom TRACE level (no slog analogue with the same name). +// - runtime.Callers/skip2 — isolated cost of Callers(2), matching rlog’s wrapper depth. +// - runtime.Callers/skip3 — isolated cost of Callers(3), matching slog.Logger.log’s depth. +// - directHandle-pc0 — NewRecord + Handle with PC=0, no Callers (rough lower bound if source were free). +// +// # Why rlog can look faster than slog in the plain pairs +// +// Back-to-back sub-benchmarks are separate [testing.Benchmark] timing windows. The second side +// often hits warmer I-cache and branch history. rlog also uses Callers(2) at its API vs slog’s +// Callers(3) inside log—not identical work. So “rlog faster” on an isolated pair is not proof the +// wrapper is free; use [TestLoggerVsSlogCompare] or *+pollute for a less misleading picture. +// +// # How to run +// +// Skip other tests (avoids concurrent tests printing JSON and competing for CPU): +// +// go test -run=^$ -bench=BenchmarkLoggerVsSlog -benchmem ./rlog +// +// Percentage summary (slower/faster), with order averaging and a polluted section: +// +// RLOG_LOGGER_VS_SLOG_COMPARE=1 go test ./rlog -run TestLoggerVsSlogCompare -v +// +// rlog cannot use [log/slog/internal.IgnorePC] (stdlib-only); slog’s -nopc benchmark flag does not apply here. +func BenchmarkLoggerVsSlog(b *testing.B) { + b.Run("slog/LogAttrs-none", benchSlogLogAttrsNone) + b.Run("rlog/LogAttrs-none", benchRlogLogAttrsNone) + b.Run("slog/Info-kv", benchSlogInfoKV) + b.Run("rlog/Info-kv", benchRlogInfoKV) + b.Run("slog/Log-kv", benchSlogLogKV) + b.Run("rlog/Log-kv", benchRlogLogKV) + b.Run("slog/LogAttrs-none+pollute", benchSlogLogAttrsNonePollute) + b.Run("rlog/LogAttrs-none+pollute", benchRlogLogAttrsNonePollute) + b.Run("slog/Info-kv+pollute", benchSlogInfoKVPollute) + b.Run("rlog/Info-kv+pollute", benchRlogInfoKVPollute) + b.Run("slog/Log-kv+pollute", benchSlogLogKVPollute) + b.Run("rlog/Log-kv+pollute", benchRlogLogKVPollute) + b.Run("paired/Info-kv-interleaved", benchPairedInfoKVInterleaved) + b.Run("rlog/Trace-none", benchRlogTraceNone) + b.Run("runtime.Callers/skip2", benchRuntimeCallersSkip2) + b.Run("runtime.Callers/skip3", benchRuntimeCallersSkip3) + b.Run("directHandle-pc0", benchDirectHandlePC0) +} + +// TestLoggerVsSlogCompare runs the same benchmark bodies as [BenchmarkLoggerVsSlog] and prints +// how much slower or faster rlog is versus slog as a percentage of slog’s ns/op. +// +// # Why not just compare two bench outputs by hand? +// +// A single run of “slog bench then rlog bench” biases whoever runs second (hotter caches for that +// binary path). This test uses [nsPerOpOrderAvg] for each pair: it runs slog→rlog, then rlog→slog, +// and averages each side’s ns/op so neither implementation always benefits from running after the other. +// +// # Two sections: isolated vs +pollute +// +// The first block is the plain benchmarks (tight loop, log call only). The second block uses the +// *+pollute functions: before each log call they run [benchPolluteCache] to touch a large, strided +// region of memory. That makes “everything fits in L1 and stays hot” less likely and often widens +// the gap when one path does more work (e.g. extra indirection in rlog). It still does not simulate +// real app contention; it is only a harsher microbench knob. +// +// # Baselines +// +// The final lines log rlog-only and PC-only benchmarks so you can sanity-check Callers cost vs full log. +// +// Skipped under -short (this test runs many benchmarks and can take tens of seconds). +// Skipped unless [envRunLoggerVsSlogCompare] is set to "1" (avoids IDE "run test" and plain go test). +// Run: RLOG_LOGGER_VS_SLOG_COMPARE=1 go test ./rlog -run TestLoggerVsSlogCompare -v +func TestLoggerVsSlogCompare(t *testing.T) { + if testing.Short() { + t.Skip("skip bench comparison in short mode") + } + if os.Getenv(envRunLoggerVsSlogCompare) != "1" { + t.Skipf("set %s=1 to run this comparison (IDE and default go test skip)", envRunLoggerVsSlogCompare) + } + + pairs := []struct { + name string + slogFn func(*testing.B) + rlogFn func(*testing.B) + }{ + {"LogAttrs-none", benchSlogLogAttrsNone, benchRlogLogAttrsNone}, + {"Info-kv", benchSlogInfoKV, benchRlogInfoKV}, + {"Log-kv", benchSlogLogKV, benchRlogLogKV}, + } + pairsPollute := []struct { + name string + slogFn func(*testing.B) + rlogFn func(*testing.B) + }{ + {"LogAttrs-none+pollute", benchSlogLogAttrsNonePollute, benchRlogLogAttrsNonePollute}, + {"Info-kv+pollute", benchSlogInfoKVPollute, benchRlogInfoKVPollute}, + {"Log-kv+pollute", benchSlogLogKVPollute, benchRlogLogKVPollute}, + } + + t.Log("rlog vs slog — isolated runs (positive % = rlog slower; negative = rlog faster)") + var sumPct float64 + for _, p := range pairs { + sNs, rNs := nsPerOpOrderAvg(p.slogFn, p.rlogFn) + pct := pctRlogVsSlog(sNs, rNs) + sumPct += pct + dir := "slower" + if pct < 0 { + dir = "faster" + } + t.Logf("%s: slog %s/op rlog %s/op → rlog is %.1f%% %s than slog (order-averaged SR+RS)", + p.name, + formatNs(sNs), + formatNs(rNs), + math.Abs(pct), + dir, + ) + } + avg := sumPct / float64(len(pairs)) + t.Logf("mean signed difference (rlog vs slog): %+.1f%%", avg) + + t.Log("same pairs with cache pollution each iteration (order-averaged SR+RS)") + var sumPctP float64 + for _, p := range pairsPollute { + sNs, rNs := nsPerOpOrderAvg(p.slogFn, p.rlogFn) + pct := pctRlogVsSlog(sNs, rNs) + sumPctP += pct + dir := "slower" + if pct < 0 { + dir = "faster" + } + t.Logf("%s: slog %s/op rlog %s/op → rlog is %.1f%% %s than slog", + p.name, + formatNs(sNs), + formatNs(rNs), + math.Abs(pct), + dir, + ) + } + t.Logf("mean signed difference (+pollute): %+.1f%%", sumPctP/float64(len(pairsPollute))) + + // Baselines: single-purpose benchmarks (no slog/rlog pair). Help interpret how much of the + // full log path is Callers vs Trace-only vs a minimal Handle with PC=0. + t.Log("baselines (not compared to slog):") + for _, c := range []struct { + name string + fn func(*testing.B) + }{ + {"rlog/Trace-none", benchRlogTraceNone}, + {"runtime.Callers/skip2", benchRuntimeCallersSkip2}, + {"runtime.Callers/skip3", benchRuntimeCallersSkip3}, + {"directHandle-pc0", benchDirectHandlePC0}, + } { + res := testing.Benchmark(c.fn) + t.Logf(" %s: %s/op", c.name, formatNs(nsPerOp(res))) + } +} + +//============================================================================== +// Helpers (nop handler, benchmark bodies, small utilities) +//============================================================================== +// +// # Cache pollution (benchScratch + benchPolluteCache) +// +// Microbenchmarks that only call logging in a tight loop keep the logger’s code and small stack +// data in fast CPU caches (L1/L2) and train the branch predictor. That can hide real costs and +// make two similar paths look arbitrarily close—or make the second timed path look faster. +// +// benchPolluteCache is a deliberate “dirty the cache a bit” step: +// - benchScratch is 1 MiB (1<<20 bytes), larger than typical L1 and often larger than L2, so +// sequential or random touches can evict or replace lines that held logging code or stack. +// - We do not try to flush caches portably (no CLFLUSH, no privileged instructions); this is +// best-effort noise, not a hardware-level cache clear. +// - Each call performs 256 byte reads at indices spread with a prime stride (4093) and a per-iter +// mix (j). That scatters accesses across the buffer instead of hammering one cache line, which +// would be a different artifact. +// - The XOR accumulator is written to sink so the reads are not dead and the compiler keeps the loop. +// +// Limitations: other cores, prefetchers, and OS scheduling still dominate on some machines; results +// should be interpreted with [testing.B] variance and tools like benchstat, not as absolute truth. +// +// # Order averaging (nsPerOpOrderAvg) +// +// Four separate [testing.Benchmark] invocations per pair: SR (slog then rlog), RS (rlog then slog). +// Slog’s ns/op is (s1+s2)/2 and rlog’s is (r1+r2)/2 so each side is measured once as “first” and once +// as “second” after the competitor’s benchmark has run. + +// sink prevents the compiler from optimizing away benchmark bodies (Callers PC, pollution XOR). +var sink uintptr + +// benchScratch is the backing store for cache pollution; see package comment and benchPolluteCache. +var benchScratch []byte + +func init() { + // Non-zero contents so the buffer is not all zero pages with special OS behavior; also makes + // XOR depend on data the compiler cannot fold away. + benchScratch = make([]byte, 1<<20) + for i := range benchScratch { + benchScratch[i] = byte(i) + } +} + +// benchPolluteCache performs the read traffic described in the helpers section header. iter varies +// the starting phase so consecutive benchmark iterations do not hit the exact same addresses every time. +func benchPolluteCache(iter int) { + if len(benchScratch) == 0 { + return + } + // 256 loads, indices wrapped with &(len-1) because len is a power of two (cheap mask). + j := iter * 1103515245 // mix iteration index (linear congruential-style spread) + var s byte + for k := 0; k < 256; k++ { + s ^= benchScratch[(j+k*4093)&(len(benchScratch)-1)] + } + sink = uintptr(s) +} + +// nsPerOpOrderAvg returns averaged ns/op for slogFn and rlogFn after running SR then RS sequences. +func nsPerOpOrderAvg(slogFn, rlogFn func(*testing.B)) (slogNs, rlogNs float64) { + s1 := nsPerOp(testing.Benchmark(slogFn)) + r1 := nsPerOp(testing.Benchmark(rlogFn)) + r2 := nsPerOp(testing.Benchmark(rlogFn)) + s2 := nsPerOp(testing.Benchmark(slogFn)) + return (s1 + s2) / 2, (r1 + r2) / 2 +} + +// nopHandler is a slog.Handler that accepts every record and does nothing in Handle. All logging +// cost stays in the Logger wrapper and record construction—ideal for comparing rlog vs slog shape. +type nopHandler struct{} + +func (nopHandler) Enabled(context.Context, slog.Level) bool { return true } + +func (nopHandler) Handle(context.Context, slog.Record) error { return nil } + +func (nopHandler) WithAttrs([]slog.Attr) slog.Handler { return nopHandler{} } + +func (nopHandler) WithGroup(string) slog.Handler { return nopHandler{} } + +// benchEnv builds a fresh context and two loggers sharing the same nop handler: a raw *slog.Logger +// and an *rlog.Logger wrapping slog.New(same handler). Call once per benchmark function, not per b.N. +func benchEnv() (ctx context.Context, slogL *slog.Logger, rlogL *rlog.Logger, h nopHandler) { + ctx = context.Background() + h = nopHandler{} + slogL = slog.New(h) + rlogL = rlog.New(slog.New(h)) + return ctx, slogL, rlogL, h +} + +// --- Plain pairs (no pollution): tight loop, one log API call per iteration. --- + +func benchSlogLogAttrsNone(b *testing.B) { + ctx, slogL, _, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + slogL.LogAttrs(ctx, slog.LevelInfo, "msg") + } +} + +func benchRlogLogAttrsNone(b *testing.B) { + ctx, _, rlogL, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + rlogL.LogAttrs(ctx, slog.LevelInfo, "msg") + } +} + +func benchSlogInfoKV(b *testing.B) { + _, slogL, _, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + slogL.Info("msg", "a", 1) + } +} + +func benchRlogInfoKV(b *testing.B) { + _, _, rlogL, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + rlogL.Info("msg", "a", 1) + } +} + +func benchSlogLogKV(b *testing.B) { + ctx, slogL, _, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + slogL.Log(ctx, slog.LevelInfo, "msg", "a", 1) + } +} + +func benchRlogLogKV(b *testing.B) { + ctx, _, rlogL, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + rlogL.Log(ctx, slog.LevelInfo, "msg", "a", 1) + } +} + +// --- Polluted pairs: benchPolluteCache(i) runs immediately before each log call (same i as loop). --- + +func benchSlogLogAttrsNonePollute(b *testing.B) { + ctx, slogL, _, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + benchPolluteCache(i) + slogL.LogAttrs(ctx, slog.LevelInfo, "msg") + } +} + +func benchRlogLogAttrsNonePollute(b *testing.B) { + ctx, _, rlogL, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + benchPolluteCache(i) + rlogL.LogAttrs(ctx, slog.LevelInfo, "msg") + } +} + +func benchSlogInfoKVPollute(b *testing.B) { + _, slogL, _, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + benchPolluteCache(i) + slogL.Info("msg", "a", 1) + } +} + +func benchRlogInfoKVPollute(b *testing.B) { + _, _, rlogL, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + benchPolluteCache(i) + rlogL.Info("msg", "a", 1) + } +} + +func benchSlogLogKVPollute(b *testing.B) { + ctx, slogL, _, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + benchPolluteCache(i) + slogL.Log(ctx, slog.LevelInfo, "msg", "a", 1) + } +} + +func benchRlogLogKVPollute(b *testing.B) { + ctx, _, rlogL, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + benchPolluteCache(i) + rlogL.Log(ctx, slog.LevelInfo, "msg", "a", 1) + } +} + +// benchPairedInfoKVInterleaved runs slog.Info then rlog.Info every iteration, fixed order. +// Reported ns/op = total time / b.N, i.e. per pair of calls, not per single log. Useful to see both +// implementations in one loop (shared iteration overhead); the number is not directly comparable +// to the per-side sub-benchmarks without dividing by two and accounting for interaction effects. +func benchPairedInfoKVInterleaved(b *testing.B) { + _, slogL, rlogL, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + slogL.Info("msg", "a", 1) + rlogL.Info("msg", "a", 1) + } +} + +// --- rlog-only and PC baselines (no slog equivalent for Trace). --- + +func benchRlogTraceNone(b *testing.B) { + _, _, rlogL, _ := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + rlogL.Trace("msg") + } +} + +// benchRuntimeCallersSkip2 measures a single Callers(2) per iteration (rlog-style skip depth). +func benchRuntimeCallersSkip2(b *testing.B) { + var pcs [1]uintptr + b.ReportAllocs() + for i := 0; i < b.N; i++ { + runtime.Callers(2, pcs[:]) + } + sink = pcs[0] +} + +// benchRuntimeCallersSkip3 measures a single Callers(3) per iteration (slog.Logger.log depth). +func benchRuntimeCallersSkip3(b *testing.B) { + var pcs [1]uintptr + b.ReportAllocs() + for i := 0; i < b.N; i++ { + runtime.Callers(3, pcs[:]) + } + sink = pcs[0] +} + +// benchDirectHandlePC0 bypasses Logger and Callers: builds a Record with PC==0 and invokes the nop +// handler. Approximates “if we did not capture source at all” plus minimal record + Handle overhead. +func benchDirectHandlePC0(b *testing.B) { + ctx, _, _, h := benchEnv() + b.ReportAllocs() + for i := 0; i < b.N; i++ { + r := slog.NewRecord(time.Now(), slog.LevelInfo, "msg", 0) + _ = h.Handle(ctx, r) + } +} + +// nsPerOp converts [testing.BenchmarkResult] to nanoseconds per iteration. +func nsPerOp(r testing.BenchmarkResult) float64 { + if r.N == 0 { + return 0 + } + return float64(r.T.Nanoseconds()) / float64(r.N) +} + +// pctRlogVsSlog returns (rlog-slog)/slog * 100. Positive means rlog is slower than slog. +func pctRlogVsSlog(slogNs, rlogNs float64) float64 { + if slogNs == 0 { + return math.NaN() + } + return 100 * (rlogNs - slogNs) / slogNs +} + +// formatNs picks a readable precision for logging ns/op in test output. +func formatNs(ns float64) string { + if ns < 10 { + return fmt.Sprintf("%.2f ns", ns) + } + return fmt.Sprintf("%.1f ns", ns) +} diff --git a/rlog/console/cmd/main.go b/rlog/console/cmd/main.go new file mode 100644 index 0000000..0ab4a40 --- /dev/null +++ b/rlog/console/cmd/main.go @@ -0,0 +1,112 @@ +// Command console demonstrates [console.Handler] and [console.Options] through +// [rlog.Logger], including custom levels (TRACE, FATAL, PANIC). +package main + +import ( + "fmt" + "log/slog" + "os" + "time" + + "go.rtnl.ai/x/rlog" + "go.rtnl.ai/x/rlog/console" +) + +func main() { + // Fatal would normally exit; keep the demo running through all sections. + rlog.SetFatalHook(func() {}) + defer rlog.SetFatalHook(nil) + + // One pattern everywhere: banner → newConsole(opts) → standardDemo (optional extra / derive). + run := func(title string, opts *console.Options, extra func(log *rlog.Logger)) { + banner(title) + log := newConsole(opts) + standardDemo(log) + if extra != nil { + extra(log) + } + } + runDerived := func(title string, opts *console.Options, derive func(*rlog.Logger) *rlog.Logger, extra func(log *rlog.Logger)) { + banner(title) + log := derive(newConsole(opts)) + standardDemo(log) + if extra != nil { + extra(log) + } + } + + run("nil *Options — defaults: INFO floor, color, compact JSON, local time", nil, nil) + + run("NoJSON — message only, no attribute object", &console.Options{NoJSON: true}, nil) + + run("HandlerOptions.Level — TRACE floor (debug/trace on)", + &console.Options{HandlerOptions: &slog.HandlerOptions{Level: rlog.LevelTrace}}, nil) + + run("HandlerOptions.AddSource — [file:line] before timestamp", + &console.Options{HandlerOptions: &slog.HandlerOptions{AddSource: true}}, nil) + + run("ReplaceAttr + NoColor + UTCTime — drop keys, wrap message; plain text, UTC clock", + &console.Options{ + HandlerOptions: &slog.HandlerOptions{ + Level: rlog.LevelTrace, + AddSource: true, + ReplaceAttr: replaceAttrDemo, + }, + NoColor: true, + UTCTime: true, + }, + func(log *rlog.Logger) { + log.Info("'secret' key redacted", "secret", "NOT REDACTED!!!", "public", "visible") + log.Trace("trace after merge still uses rlog level string (TRACE)") + }, + ) + + runDerived("IndentJSON — multi-line trailer; With / WithGroup; time, duration, maps; level Error", + &console.Options{IndentJSON: true, HandlerOptions: &slog.HandlerOptions{Level: rlog.LevelError}}, + func(log *rlog.Logger) *rlog.Logger { + return log.With("service", "demo"). + WithGroup("http"). + With(slog.String("method", "GET")) + }, + func(log *rlog.Logger) { + log.Info("request", slog.String("path", "/v1/status"), "status", 200) + log.Info("structured attrs", + slog.Time("when", time.Now()), + slog.Duration("elapsed", 123*time.Millisecond), + slog.Any("nested", map[string]int{"a": 1}), + ) + }, + ) +} + +func newConsole(opts *console.Options) *rlog.Logger { + return rlog.New(slog.New(console.New(os.Stdout, opts.MergeWithCustomLevels()))) +} + +func banner(title string) { + fmt.Println() + fmt.Println("---", title, "---") +} + +func standardDemo(log *rlog.Logger) { + log.Trace("trace") + log.Debug("debug") + log.Info("hello console", "count", 3, "ok", true) + log.Warn("something odd", slog.Duration("wait", 50*time.Millisecond)) + log.Error("failed", "err", "boom", "code", 500) + log.Fatal("fatal") + func() { + defer func() { recover() }() + log.Panic("panic") + }() +} + +func replaceAttrDemo(groups []string, a slog.Attr) slog.Attr { + if a.Key == "secret" { + return slog.Attr{} + } + if len(groups) == 0 && a.Key == slog.MessageKey { + return slog.String(slog.MessageKey, "[wrapped] "+a.Value.String()) + } + return a +} diff --git a/rlog/console/color.go b/rlog/console/color.go new file mode 100644 index 0000000..cfbebaf --- /dev/null +++ b/rlog/console/color.go @@ -0,0 +1,22 @@ +package console + +import ( + "fmt" + "io" +) + +// SGR foreground codes for the handler prefix (see colorize). +const ( + red = 31 + cyan = 36 + lightGray = 37 + lightRed = 91 + lightGreen = 92 + lightYellow = 93 + white = 97 +) + +// colorize wraps text in ANSI foreground + reset. +func colorize(w io.Writer, color uint8, text string) { + fmt.Fprintf(w, "\033[%dm%s\033[0m", color, text) +} diff --git a/rlog/console/console.go b/rlog/console/console.go new file mode 100644 index 0000000..948a74c --- /dev/null +++ b/rlog/console/console.go @@ -0,0 +1,374 @@ +// Package console implements a [slog.Handler] that pretty-prints log lines with optional colors +// and a trailing JSON object of attributes. For development and tests, not high-throughput logging. +// +// The command `go run ./rlog/console/cmd/` gives a demo of the handler with various options. +package console + +import ( + "bytes" + "context" + "encoding/json" + "fmt" + "io" + "log/slog" + "path/filepath" + "slices" + "sync" + + "go.rtnl.ai/x/rlog" +) + +const timeFormat = "[15:04:05.000]" + +// Handler writes a text prefix ([basename:line] when AddSource, bracketed time, level, message) and optional JSON attributes. +type Handler struct { + w io.Writer + mu *sync.Mutex + opts Options + topAttrs []slog.Attr + segments []segment +} + +// segment is one [slog.Handler.WithGroup] name plus attributes. +type segment struct { + name string + attrs []slog.Attr +} + +// New creates a [Handler] writing to w. If opts is nil, all defaults are used. +func New(w io.Writer, opts *Options) *Handler { + if opts == nil { + opts = &Options{} + } + + return &Handler{ + w: w, + opts: *opts, + mu: &sync.Mutex{}, + } +} + +// Ensure that Handler implements the slog.Handler interface. +var _ slog.Handler = (*Handler)(nil) + +// Enabled reports whether the handler is enabled for the given level. +func (h *Handler) Enabled(_ context.Context, level slog.Level) bool { + if h.opts.HandlerOptions == nil || h.opts.Level == nil { + return level >= slog.LevelInfo + } + return level >= h.opts.Level.Level() +} + +// WithAttrs returns a new handler with the given attributes. +func (h *Handler) WithAttrs(attrs []slog.Attr) slog.Handler { + if len(attrs) == 0 { + return h + } + if len(h.segments) == 0 { + top := h.topAttrs + if len(top) > 0 { + top = append(slices.Clone(top), attrs...) + } else { + top = attrs + } + return &Handler{w: h.w, mu: h.mu, opts: h.opts, topAttrs: top, segments: h.segments} + } + segs := slices.Clone(h.segments) + last := len(segs) - 1 + if len(segs[last].attrs) > 0 { + segs[last].attrs = append(slices.Clone(segs[last].attrs), attrs...) + } else { + segs[last].attrs = attrs + } + return &Handler{w: h.w, mu: h.mu, opts: h.opts, topAttrs: h.topAttrs, segments: segs} +} + +// WithGroup returns a new handler with the given group. +func (h *Handler) WithGroup(name string) slog.Handler { + if name == "" { + return h + } + segs := append(slices.Clone(h.segments), segment{name: name}) + return &Handler{w: h.w, mu: h.mu, opts: h.opts, topAttrs: h.topAttrs, segments: segs} +} + +// Handle writes the record to the handler's writer. +func (h *Handler) Handle(_ context.Context, r slog.Record) error { + var buf bytes.Buffer + + // ReplaceAttr (slog.HandlerOptions) can rename, drop, or rewrite built-in keys before we render. + // Built-ins use a nil group path, matching slog's convention for top-level keys. + var repl func([]string, slog.Attr) slog.Attr + if h.opts.HandlerOptions != nil { + repl = h.opts.ReplaceAttr + } + + // Time: normalize to UTC when requested, build a TimeKey attr, then run ReplaceAttr so output + // can omit or alter the timestamp without changing r.Time itself. + tm := r.Time + if h.opts.UTCTime { + tm = tm.UTC() + } + var timeAttr slog.Attr + if !tm.IsZero() { + timeAttr = slog.Time(slog.TimeKey, tm) + if repl != nil { + timeAttr = repl(nil, timeAttr) + } + } + + // Level: wrap the record level as LevelKey and pass through ReplaceAttr (e.g. custom labels). + levelAttr := slog.Any(slog.LevelKey, r.Level) + if repl != nil { + levelAttr = repl(nil, levelAttr) + } + + // Message: wrap r.Message as MessageKey and pass through ReplaceAttr. + msgAttr := slog.String(slog.MessageKey, r.Message) + if repl != nil { + msgAttr = repl(nil, msgAttr) + } + + // Source: when AddSource is on and the record has a PC, build SourceKey and allow ReplaceAttr + // to strip it (empty attr). If still present, emit [basename:line] before the rest of the prefix. + showSource := false + var srcAttr slog.Attr + if h.opts.HandlerOptions != nil && h.opts.AddSource && r.PC != 0 { + if src := r.Source(); src != nil { + srcAttr = slog.Any(slog.SourceKey, src) + if repl != nil { + srcAttr = repl(nil, srcAttr) + } + showSource = !srcAttr.Equal(slog.Attr{}) + } + } + if showSource { + writeSourcePrefix(&buf, h.opts.NoColor, srcAttr) + } + + // Prefix: bracketed time (light gray) when ReplaceAttr left a non-zero time value. + if !timeAttr.Equal(slog.Attr{}) && timeAttr.Value.Kind() == slog.KindTime && !timeAttr.Value.Time().IsZero() { + tm2 := timeAttr.Value.Time() + if h.opts.UTCTime { + tm2 = tm2.UTC() + } + writePlainOrColor(&buf, h.opts.NoColor, lightGray, tm2.Format(timeFormat)) + buf.WriteRune(' ') + } + + // Level prefix: when ReplaceAttr rewrites [slog.LevelKey] to a string (e.g. TRACE via + // [rlog.MergeWithCustomLevels]), print that text plus ":" so the line matches other + // handlers; otherwise use [slog.Level.String] from levelForOutput. ANSI color still + // uses the resolved [slog.Level] (lv), not the string label. + lv := levelForOutput(levelAttr, r.Level) + var level string + if levelAttr.Key == slog.LevelKey && !levelAttr.Equal(slog.Attr{}) && levelAttr.Value.Kind() == slog.KindString { + if s := levelAttr.Value.String(); s != "" { + level = s + ":" + } else { + level = lv.String() + ":" + } + } else { + level = lv.String() + ":" + } + if code, ok := levelANSICode(lv); h.opts.NoColor || !ok { + fmt.Fprint(&buf, level) + } else { + colorize(&buf, code, level) + } + + buf.WriteRune(' ') + + // Message: use ReplaceAttr's string if still valid; otherwise fall back to r.Message. + msg := r.Message + if !msgAttr.Equal(slog.Attr{}) && msgAttr.Value.Kind() == slog.KindString { + msg = msgAttr.Value.String() + } + writePlainOrColor(&buf, h.opts.NoColor, white, msg) + + // User attributes: everything on the record except the built-in keys (already shown in the prefix), + // merged with handler-scoped attrs from WithAttrs / WithGroup. + var recAttrs []slog.Attr + r.Attrs(func(a slog.Attr) bool { + if a.Key == slog.LevelKey || a.Key == slog.MessageKey || a.Key == slog.TimeKey { + return true + } + recAttrs = append(recAttrs, a) + return true + }) + merged := buildMergedUserAttrs(h.topAttrs, h.segments, recAttrs) + + // Trailer: one JSON object (Encode adds a trailing newline) or plain newline when NoJSON. + if !h.opts.NoJSON { + buf.WriteRune(' ') + attrs := make(map[string]any) + for _, a := range merged { + mergeAttrJSON(attrs, nil, a, repl) + } + enc := json.NewEncoder(&buf) + if h.opts.IndentJSON { + enc.SetIndent("", " ") + } + if err := enc.Encode(attrs); err != nil { + return err + } + } else { + buf.WriteRune('\n') + } + + // Single Write call per log line; mu coordinates output when multiple handlers share one writer. + h.mu.Lock() + defer h.mu.Unlock() + _, err := h.w.Write(buf.Bytes()) + return err +} + +// writePlainOrColor prints text with or without ANSI color. +func writePlainOrColor(buf *bytes.Buffer, noColor bool, color uint8, text string) { + if noColor { + fmt.Fprint(buf, text) + } else { + colorize(buf, color, text) + } +} + +// writeSourcePrefix prints [basename:line] when srcAttr carries *slog.Source (same bracket style as time). +func writeSourcePrefix(buf *bytes.Buffer, noColor bool, srcAttr slog.Attr) { + if srcAttr.Value.Kind() != slog.KindAny { + return + } + s, ok := srcAttr.Value.Any().(*slog.Source) + if !ok || s == nil || (s.File == "" && s.Line == 0) { + return + } + writePlainOrColor(buf, noColor, lightGray, fmt.Sprintf("[%s:%d]", filepath.Base(s.File), s.Line)) + buf.WriteRune(' ') +} + +// levelForOutput prefers a slog.Level inside levelAttr after ReplaceAttr. +func levelForOutput(levelAttr slog.Attr, fallback slog.Level) slog.Level { + if levelAttr.Equal(slog.Attr{}) { + return fallback + } + if levelAttr.Value.Kind() == slog.KindAny { + if l, ok := levelAttr.Value.Any().(slog.Level); ok { + return l + } + } + return fallback +} + +// levelANSICode maps standard and rlog levels to a color; ok false means uncolored. +func levelANSICode(lv slog.Level) (code uint8, ok bool) { + switch lv { + case rlog.LevelTrace: + return lightGray, true + case slog.LevelDebug: + return cyan, true + case slog.LevelInfo: + return lightGreen, true + case slog.LevelWarn: + return lightYellow, true + case slog.LevelError: + return lightRed, true + case rlog.LevelFatal: + return red, true + case rlog.LevelPanic: + return red, true + default: + return 0, false + } +} + +// buildMergedUserAttrs wraps record attrs in innermost→outermost groups, then appends top attrs. +func buildMergedUserAttrs(top []slog.Attr, segs []segment, record []slog.Attr) []slog.Attr { + inner := slices.Clone(record) + for i := len(segs) - 1; i >= 0; i-- { + s := segs[i] + args := make([]any, 0, len(s.attrs)+len(inner)) + for _, a := range s.attrs { + args = append(args, a) + } + for _, a := range inner { + args = append(args, a) + } + inner = []slog.Attr{slog.Group(s.name, args...)} + } + return append(slices.Clone(top), inner...) +} + +// mergeAttrJSON flattens attrs into a JSON-ready map; ReplaceAttr gets the group path for leaves. +func mergeAttrJSON(attrs map[string]any, groups []string, a slog.Attr, repl func([]string, slog.Attr) slog.Attr) { + a.Value = a.Value.Resolve() + if a.Equal(slog.Attr{}) { + return + } + switch a.Value.Kind() { + // Recurse into group members; extend groups for named groups. + case slog.KindGroup: + gattrs := a.Value.Group() + if len(gattrs) == 0 { + return + } + if a.Key != "" { + g := append(slices.Clone(groups), a.Key) + sub := ensureSubmap(attrs, a.Key) + for _, ga := range gattrs { + mergeAttrJSON(sub, g, ga, repl) + } + } else { + for _, ga := range gattrs { + mergeAttrJSON(attrs, groups, ga, repl) + } + } + default: + // Leaf: ReplaceAttr, then store or re-enter if ReplaceAttr produced a group. + leaf := a + if repl != nil { + leaf = repl(groups, a) + } + if leaf.Equal(slog.Attr{}) { + return + } + leaf.Value = leaf.Value.Resolve() + if leaf.Value.Kind() == slog.KindGroup { + mergeAttrJSON(attrs, groups, leaf, nil) + return + } + attrs[leaf.Key] = slogValueToJSON(leaf.Value) + } +} + +// ensureSubmap returns attrs[key] as a nested map, creating it if needed. +func ensureSubmap(attrs map[string]any, key string) map[string]any { + if existing, ok := attrs[key].(map[string]any); ok { + return existing + } + sub := make(map[string]any) + attrs[key] = sub + return sub +} + +// slogValueToJSON converts a resolved [slog.Value] for encoding/json. +func slogValueToJSON(v slog.Value) any { + switch v.Kind() { + case slog.KindString: + return v.String() + case slog.KindInt64: + return v.Int64() + case slog.KindUint64: + return v.Uint64() + case slog.KindFloat64: + return v.Float64() + case slog.KindBool: + return v.Bool() + case slog.KindTime: + return v.Time() + case slog.KindDuration: + return v.Duration() + case slog.KindAny: + return v.Any() + default: + return v.String() + } +} diff --git a/rlog/console/console_test.go b/rlog/console/console_test.go new file mode 100644 index 0000000..184ddc1 --- /dev/null +++ b/rlog/console/console_test.go @@ -0,0 +1,208 @@ +package console_test + +import ( + "bytes" + "context" + "log/slog" + "regexp" + "runtime" + "strings" + "testing" + "testing/slogtest" + "testing/synctest" + "time" + + "go.rtnl.ai/x/assert" + "go.rtnl.ai/x/rlog" + "go.rtnl.ai/x/rlog/console" +) + +// TestHandler_GoldenTest tests the [Handler] with various options and verifies +// the output matches the golden bytes. NOTE: [slog.HandlerOptions.AddSource] is +// not tested here because it is hard to verify the output matches the golden bytes; +// we have a separate test for [slog.HandlerOptions.AddSource] called +// [TestHandler_AddSource_prefix]. +func TestHandler_GoldenTest(t *testing.T) { + testCases := []struct { + name string + opts *console.Options + want []byte + }{ + { + name: "Default", + opts: nil, + want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {\"req\":{\"foo\":\"bar\",\"id\":\"1\",\"user\":\"alice\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {\"req\":{\"code\":404,\"error\":\"not found\",\"id\":\"1\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {\"req\":{\"code\":400,\"error\":\"uncapped jar\",\"id\":\"1\"},\"svc\":\"api\"}\n"), + }, + { + name: "NoColor", + opts: &console.Options{NoColor: true}, + want: []byte("[00:00:00.000] INFO: info {\"req\":{\"foo\":\"bar\",\"id\":\"1\",\"user\":\"alice\"},\"svc\":\"api\"}\n[00:00:00.000] WARN: warning {\"req\":{\"code\":404,\"error\":\"not found\",\"id\":\"1\"},\"svc\":\"api\"}\n[00:00:00.000] ERROR: error {\"req\":{\"code\":400,\"error\":\"uncapped jar\",\"id\":\"1\"},\"svc\":\"api\"}\n"), + }, + { + name: "NoJSON", + opts: &console.Options{NoJSON: true}, + want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m\n"), + }, + { + name: "Plain", + opts: &console.Options{NoColor: true, NoJSON: true}, + want: []byte("[00:00:00.000] INFO: info\n[00:00:00.000] WARN: warning\n[00:00:00.000] ERROR: error\n"), + }, + { + name: "IndentJSON", + opts: &console.Options{IndentJSON: true}, + want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {\n \"req\": {\n \"foo\": \"bar\",\n \"id\": \"1\",\n \"user\": \"alice\"\n },\n \"svc\": \"api\"\n}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {\n \"req\": {\n \"code\": 404,\n \"error\": \"not found\",\n \"id\": \"1\"\n },\n \"svc\": \"api\"\n}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {\n \"req\": {\n \"code\": 400,\n \"error\": \"uncapped jar\",\n \"id\": \"1\"\n },\n \"svc\": \"api\"\n}\n"), + }, + { + name: "IndentJSONNoColor", + opts: &console.Options{IndentJSON: true, NoColor: true}, + want: []byte("[00:00:00.000] INFO: info {\n \"req\": {\n \"foo\": \"bar\",\n \"id\": \"1\",\n \"user\": \"alice\"\n },\n \"svc\": \"api\"\n}\n[00:00:00.000] WARN: warning {\n \"req\": {\n \"code\": 404,\n \"error\": \"not found\",\n \"id\": \"1\"\n },\n \"svc\": \"api\"\n}\n[00:00:00.000] ERROR: error {\n \"req\": {\n \"code\": 400,\n \"error\": \"uncapped jar\",\n \"id\": \"1\"\n },\n \"svc\": \"api\"\n}\n"), + }, + { + name: "Trace", + opts: &console.Options{HandlerOptions: &slog.HandlerOptions{Level: rlog.LevelTrace}}, + want: []byte("\x1b[37m[00:00:00.000]\x1b[0m \x1b[37mTRACE:\x1b[0m \x1b[97mtracing\x1b[0m {\"req\":{\"foo\":\"bar\",\"id\":\"1\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m DEBUG-3: \x1b[97mtrace+1\x1b[0m {\"req\":{\"id\":\"1\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[36mDEBUG:\x1b[0m \x1b[97mdebugging\x1b[0m {\"req\":{\"foo\":\"bar\",\"id\":\"1\",\"user\":\"bob\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[92mINFO:\x1b[0m \x1b[97minfo\x1b[0m {\"req\":{\"foo\":\"bar\",\"id\":\"1\",\"user\":\"alice\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[93mWARN:\x1b[0m \x1b[97mwarning\x1b[0m {\"req\":{\"code\":404,\"error\":\"not found\",\"id\":\"1\"},\"svc\":\"api\"}\n\x1b[37m[00:00:00.000]\x1b[0m \x1b[91mERROR:\x1b[0m \x1b[97merror\x1b[0m {\"req\":{\"code\":400,\"error\":\"uncapped jar\",\"id\":\"1\"},\"svc\":\"api\"}\n"), + }, + } + + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + synctest.Test(t, func(t *testing.T) { + var buf bytes.Buffer + opts := tc.opts + if opts == nil { + opts = &console.Options{} + } + opts.HandlerOptions = rlog.MergeWithCustomLevels(opts.HandlerOptions) + opts.UTCTime = true + base := rlog.New(slog.New(console.New(&buf, opts))) + log := base.With(slog.String("svc", "api")).WithGroup("req").With(slog.String("id", "1")) + ctx := context.Background() + + log.TraceAttrs(ctx, "tracing", slog.String("foo", "bar")) + log.Log(ctx, rlog.LevelTrace+1, "trace+1") + log.DebugAttrs(ctx, "debugging", slog.String("foo", "bar"), slog.String("user", "bob")) + log.InfoAttrs(ctx, "info", slog.String("foo", "bar"), slog.String("user", "alice")) + log.WarnAttrs(ctx, "warning", slog.String("error", "not found"), slog.Int("code", 404)) + log.ErrorAttrs(ctx, "error", slog.String("error", "uncapped jar"), slog.Int("code", 400)) + + assert.True(t, bytes.Equal(buf.Bytes(), tc.want), "got:\n%q \nwant:\n%q", buf.Bytes(), tc.want) + }) + }) + } +} + +// TestHandler_slogtest runs [testing/slogtest.TestHandler] against [console.Handler]; each emitted line +// is parsed with [console.ParseLogLine] to build the result maps. Options use plain text and compact JSON +// so one line equals one log record. +func TestHandler_slogtest(t *testing.T) { + var buf bytes.Buffer + opts := &console.Options{ + HandlerOptions: &slog.HandlerOptions{Level: slog.LevelInfo}, + NoColor: true, + UTCTime: true, + } + h := console.New(&buf, opts) + err := slogtest.TestHandler(h, func() []map[string]any { + var maps []map[string]any + for _, line := range strings.Split(strings.TrimSpace(buf.String()), "\n") { + if line == "" { + continue + } + m, e := console.ParseLogLine(line) + if e != nil { + t.Fatalf("ParseLogLine(%q): %v", line, e) + } + maps = append(maps, m) + } + return maps + }) + assert.Ok(t, err, "handler should satisfy slogtest when each line is round-tripped through ParseLogLine") +} + +// TestHandler_WithGroup_mergedIntoJSON checks that logger.With("a","b").WithGroup("G") nests record attrs +// under G in the JSON tail and that [console.ParseLogLine] sees the same shape. +func TestHandler_WithGroup_mergedIntoJSON(t *testing.T) { + synctest.Test(t, func(t *testing.T) { + var buf bytes.Buffer + opts := &console.Options{NoColor: true, UTCTime: true} + log := slog.New(console.New(&buf, opts)).With("a", "b").WithGroup("G") + log.Info("msg", "k", "v") + + m, err := console.ParseLogLine(strings.TrimSpace(buf.String())) + assert.Ok(t, err, "single Info line with group should parse") + g, ok := m["G"].(map[string]any) + assert.True(t, ok, `top-level key "G" should be a nested map from WithGroup`) + assert.Equal(t, "v", g["k"], "record attr k should appear inside group G") + assert.Equal(t, "msg", m[slog.MessageKey], "msg should be the log message text") + }) +} + +// TestHandler_ReplaceAttr_dropsKey verifies [slog.HandlerOptions.ReplaceAttr] removes a user key from +// the JSON object while leaving other attrs (JSON numbers decode as float64 in the parsed map). +func TestHandler_ReplaceAttr_dropsKey(t *testing.T) { + synctest.Test(t, func(t *testing.T) { + var buf bytes.Buffer + opts := &console.Options{ + NoColor: true, + UTCTime: true, + HandlerOptions: &slog.HandlerOptions{ + Level: slog.LevelInfo, + ReplaceAttr: func(_ []string, a slog.Attr) slog.Attr { + if a.Key == "drop" { + return slog.Attr{} + } + return a + }, + }, + } + log := slog.New(console.New(&buf, opts)) + log.Info("x", "keep", 1, "drop", "gone") + + m, err := console.ParseLogLine(strings.TrimSpace(buf.String())) + assert.Ok(t, err, "line with ReplaceAttr should still parse") + _, hasDrop := m["drop"] + assert.False(t, hasDrop, "ReplaceAttr should strip key drop from output") + assert.Equal(t, float64(1), m["keep"], "keep should remain and match JSON-decoded int") + }) +} + +// TestHandler_AddSource_prefix ensures AddSource adds a [basename:line] prefix and ParseLogLine exposes +// [slog.SourceKey] with File and Line when Handle receives a record built with a non-zero PC. +func TestHandler_AddSource_prefix(t *testing.T) { + synctest.Test(t, func(t *testing.T) { + var buf bytes.Buffer + opts := &console.Options{ + NoColor: true, + UTCTime: true, + HandlerOptions: &slog.HandlerOptions{ + Level: slog.LevelInfo, + AddSource: true, + }, + } + h := console.New(&buf, opts) + pc := callerPC(2) + r := slog.NewRecord(time.Now(), slog.LevelInfo, "hello", pc) + assert.Ok(t, h.Handle(context.Background(), r), "Handle with AddSource should not error") + + line := strings.TrimSpace(buf.String()) + assert.True(t, regexp.MustCompile(`^\[[^\]]+:\d+\]\s+`).MatchString(line), + "AddSource should print [basename:line] before the rest of the line; got %q", line) + + m, err := console.ParseLogLine(line) + assert.Ok(t, err, "line with source prefix should parse") + src, ok := m[slog.SourceKey].(map[string]any) + assert.True(t, ok, "SourceKey should be a map[string]any like JSON source objects") + _, hasFile := src["File"] + assert.True(t, hasFile, "parsed source should include File") + _, hasLine := src["Line"] + assert.True(t, hasLine, "parsed source should include Line") + }) +} + +// callerPC returns the PC at the given skip depth; skip=2 yields the test frame so [slog.Record] carries a real line. +func callerPC(skip int) uintptr { + var pcs [1]uintptr + runtime.Callers(skip, pcs[:]) + return pcs[0] +} diff --git a/rlog/console/options.go b/rlog/console/options.go new file mode 100644 index 0000000..1d0dfd4 --- /dev/null +++ b/rlog/console/options.go @@ -0,0 +1,41 @@ +package console + +import ( + "log/slog" + + "go.rtnl.ai/x/rlog" +) + +// Options are used for the [console.Handler] a nil or zero valued Options consists +// entirely of default values. +type Options struct { + // The [slog.HandlerOptions] to use for the [console.Handler]. + *slog.HandlerOptions + + // Marking true causes the handler to format the logs without terminal colors. + NoColor bool + + // Marking true causes the handler to indent the JSON dictionary on multiple lines. + IndentJSON bool + + // Marking true causes the handler to format the logs without JSON dictionary of attributes. + NoJSON bool + + // Marking true causes the handler to format the time using the UTC timezone. + UTCTime bool +} + +// MergeWithCustomLevels merges the options with the custom rlog.Level* keys. +// If o is nil, returns a new Options with the default values. +func (o *Options) MergeWithCustomLevels() *Options { + if o == nil { + o = &Options{} + } + return &Options{ + HandlerOptions: rlog.MergeWithCustomLevels(o.HandlerOptions), + NoColor: o.NoColor, + IndentJSON: o.IndentJSON, + NoJSON: o.NoJSON, + UTCTime: o.UTCTime, + } +} diff --git a/rlog/console/parse.go b/rlog/console/parse.go new file mode 100644 index 0000000..afdf324 --- /dev/null +++ b/rlog/console/parse.go @@ -0,0 +1,122 @@ +package console + +import ( + "encoding/json" + "fmt" + "log/slog" + "maps" + "regexp" + "strconv" + "strings" + "time" +) + +// Line layout: optional [basename:line], optional [HH:MM:SS.mmm], LEVEL: message [JSON]. +var ( + ansiRegexp = regexp.MustCompile(`\x1b\[[0-9;]*m`) + sourcePrefixRx = regexp.MustCompile(`^\[([^\]]+:\d+)\]\s+`) + timeBracketRx = regexp.MustCompile(`^\[(\d{2}:\d{2}:\d{2}\.\d{3})\]\s+`) + levelPrefixRx = regexp.MustCompile(`^([A-Za-z0-9+-]+):\s+`) +) + +// ParseLogLine parses a single line from [Handler] into a map, e.g. for [testing/slogtest.TestHandler]. +// Expects one line per record (no IndentJSON); strips ANSI escapes. +func ParseLogLine(line string) (map[string]any, error) { + s := strings.TrimSpace(stripAnsi(line)) + if s == "" { + return nil, fmt.Errorf("empty line") + } + + m := make(map[string]any) + + // Parse optional [basename:line] (bracketed like the time prefix). + if sm := sourcePrefixRx.FindStringSubmatch(s); sm != nil { + file, lineNum, ok := parseSourceToken(sm[1]) + if ok { + m[slog.SourceKey] = map[string]any{ + "File": file, + "Line": float64(lineNum), + } + } + s = strings.TrimSpace(s[len(sm[0]):]) + } + + // Parse optional time bracket. + if tm := timeBracketRx.FindStringSubmatch(s); tm != nil { + clock, err := time.ParseInLocation("15:04:05.000", tm[1], time.UTC) + if err != nil { + return nil, fmt.Errorf("time bracket: %w", err) + } + t := time.Date(2000, 1, 1, clock.Hour(), clock.Minute(), clock.Second(), clock.Nanosecond(), time.UTC) + m[slog.TimeKey] = t + s = strings.TrimSpace(s[len(tm[0]):]) + } + + // Parse level. + lm := levelPrefixRx.FindStringSubmatch(s) + if lm == nil { + return nil, fmt.Errorf("no level prefix in %q", s) + } + levelStr := lm[1] + m[slog.LevelKey] = levelStr + s = strings.TrimSpace(s[len(lm[0]):]) + + // Parse JSON tail. + jsonPart, jStart, ok := extractOuterJSONObject(s) + if ok { + // Parse message. + m[slog.MessageKey] = strings.TrimSpace(s[:jStart]) + + // Parse JSON. + var obj map[string]any + if err := json.Unmarshal([]byte(jsonPart), &obj); err != nil { + return nil, fmt.Errorf("json tail: %w", err) + } + maps.Copy(m, obj) + } else { + // Parse message. + m[slog.MessageKey] = strings.TrimSpace(s) + } + + return m, nil +} + +// stripAnsi removes SGR sequences from s. +func stripAnsi(s string) string { + return ansiRegexp.ReplaceAllString(s, "") +} + +// extractOuterJSONObject finds the last top-level {...} in s (handles nested braces). +func extractOuterJSONObject(s string) (json string, start int, ok bool) { + end := strings.LastIndex(s, "}") + if end < 0 { + return "", 0, false + } + depth := 0 + for i := end; i >= 0; i-- { + switch s[i] { + case '}': + depth++ + case '{': + depth-- + if depth == 0 { + return strings.TrimSpace(s[i : end+1]), i, true + } + } + } + return "", 0, false +} + +// parseSourceToken splits "file:line" (basename may contain ':' on some platforms — last ':' wins). +func parseSourceToken(tok string) (file string, line int, ok bool) { + i := strings.LastIndex(tok, ":") + if i <= 0 || i == len(tok)-1 { + return "", 0, false + } + file = tok[:i] + n, err := strconv.Atoi(tok[i+1:]) + if err != nil { + return "", 0, false + } + return file, n, true +} diff --git a/rlog/doc.go b/rlog/doc.go deleted file mode 100644 index 8b6c0c8..0000000 --- a/rlog/doc.go +++ /dev/null @@ -1,68 +0,0 @@ -// Package rlog wraps [log/slog] with extra levels (Trace, Fatal, Panic), test -// capture helpers, and small slog utilities (handler options, global level sync, -// multi-sink fan-out). See [README.md in the repo], or [rlog on pkg.go.dev], for -// API summary and usage notes. -// -// package main -// -// import ( -// "context" -// "log/slog" -// "os" -// -// "go.rtnl.ai/x/rlog" -// ) -// -// func main() { -// // Global default logger (JSON stdout): allow Trace. -// rlog.SetLevel(rlog.LevelTrace) -// rlog.Info("hello") -// // Output example: {"time":"2026-03-25T12:00:00.000-00:00","level":"INFO","msg":"hello"} -// rlog.Trace("verbose") -// // Output example: {"time":"…","level":"TRACE","msg":"verbose"} -// -// // Custom logger: MergeWithCustomLevels names TRACE/FATAL/PANIC; WithGlobalLevel ties -// // level to rlog.SetLevel so this handler follows the same threshold as the default. -// opts := rlog.MergeWithCustomLevels(rlog.WithGlobalLevel(nil)) -// log := rlog.New(slog.New(slog.NewJSONHandler(os.Stdout, opts))) -// -// // rlog-only level + key/value fields (Trace also has TraceContext, TraceAttrs, …). -// log.Trace("trace-msg", "k", "v") -// // Output example: {"time":"…","level":"TRACE","msg":"trace-msg","k":"v"} -// -// // Without a hook, Fatal would os.Exit(1) and the rest of main would not run. -// rlog.SetFatalHook(func() {}) // demo only — replace with test hook or omit in production -// defer rlog.SetFatalHook(nil) // setting the fatal hook to nil causes future Fatal calls to use os.Exit(1) -// log.Fatal("fatal-msg") -// // Output example: {"time":"…","level":"FATAL","msg":"fatal-msg"} — then runs the fatal hook (no exit here) -// -// // Panic levels call panic("panic-msg") after logging -// func() { -// defer func() { recover() }() -// log.Panic("panic-msg") -// // Output example: {"time":"…","level":"PANIC","msg":"panic-msg"} — then panic("panic-msg") -// }() -// -// // WithGroup/With return *rlog.Logger and work the same as for a slog.Logger. -// sub := log.WithGroup("svc").With("name", "api") -// sub.Info("scoped") -// // Output example: {"time":"…","level":"INFO","msg":"scoped","svc":{"name":"api"}} -// -// // Stdlib-style context and slog.Attr APIs on *rlog.Logger. -// log.DebugContext(context.Background(), "debug-msg", "k", "v") -// // Output example: {"time":"…","level":"DEBUG","msg":"debug-msg","k":"v"} -// log.InfoAttrs(context.Background(), "info-msg", slog.String("k", "v")) -// // Output example: {"time":"…","level":"INFO","msg":"info-msg","k":"v"} -// -// // Package-level helpers and slog.Default now use this logger. -// new := log.With(slog.String("new", "logger")) -// rlog.SetDefault(new) -// rlog.Warn("via package after SetDefault") -// // Output example: {"time":"…","level":"WARN","msg":"via package after SetDefault","new":"logger"} -// rlog.FatalAttrs("fatal-msg", slog.String("fatal", "attr")) -// // Output example: {"time":"…","level":"FATAL","msg":"fatal-msg","new":"logger","fatal":"attr"} — then runs the fatal hook (no exit here) -// } -// -// [README.md in the repo]: https://github.com/rotationalio/x/blob/main/rlog/README.md -// [rlog on pkg.go.dev]: https://pkg.go.dev/go.rtnl.ai/x/rlog -package rlog diff --git a/rlog/fanout.go b/rlog/fanout/fanout.go similarity index 54% rename from rlog/fanout.go rename to rlog/fanout/fanout.go index 9c5ec4c..84124a3 100644 --- a/rlog/fanout.go +++ b/rlog/fanout/fanout.go @@ -1,4 +1,4 @@ -package rlog +package fanout import ( "context" @@ -6,24 +6,24 @@ import ( "log/slog" ) -// FanOut is a [slog.Handler] that forwards each record to every child handler, -// using a fresh [slog.Record.Clone] per child. For Go 1.26 or later, use the -// standard library's [slog.MultiHandler] instead; this is a clone of the -// functionality for Go 1.25 and earlier. -type FanOut struct { +// The fanout handler is a [slog.Handler] that forwards each record to every +// child handler, using a fresh [slog.Record.Clone] per child. For Go 1.26 or +// later, use the standard library's [slog.MultiHandler] instead; this is a clone +// of the functionality for Go 1.25 and earlier. +type Handler struct { handlers []slog.Handler } -// NewFanOut returns a new [FanOut] that forwards each record to every child +// New returns a new fanout [Handler] that forwards each record to every child // handler. For Go 1.26 or later, use [slog.MultiHandler] instead; this is a // clone of the functionality for Go 1.25 and earlier. -func NewFanOut(handlers ...slog.Handler) *FanOut { +func New(handlers ...slog.Handler) *Handler { hs := append([]slog.Handler(nil), handlers...) - return &FanOut{handlers: hs} + return &Handler{handlers: hs} } // Enabled reports whether any child handler accepts the given level. -func (f *FanOut) Enabled(ctx context.Context, level slog.Level) bool { +func (f *Handler) Enabled(ctx context.Context, level slog.Level) bool { for _, h := range f.handlers { if h.Enabled(ctx, level) { return true @@ -34,7 +34,7 @@ func (f *FanOut) Enabled(ctx context.Context, level slog.Level) bool { // Handle forwards a clone of r to each child that [slog.Handler.Enabled] accepts // for r's level, and joins any non-nil errors. -func (f *FanOut) Handle(ctx context.Context, r slog.Record) error { +func (f *Handler) Handle(ctx context.Context, r slog.Record) error { if len(f.handlers) == 0 { return nil } @@ -53,8 +53,8 @@ func (f *FanOut) Handle(ctx context.Context, r slog.Record) error { return errors.Join(errs...) } -// WithAttrs returns a [FanOut] whose children are wrapped with the same attrs. -func (f *FanOut) WithAttrs(attrs []slog.Attr) slog.Handler { +// WithAttrs returns a [Handler] whose children are wrapped with the same attrs. +func (f *Handler) WithAttrs(attrs []slog.Attr) slog.Handler { if len(attrs) == 0 { return f } @@ -65,11 +65,11 @@ func (f *FanOut) WithAttrs(attrs []slog.Attr) slog.Handler { next[i] = h.WithAttrs(attrs) } - return &FanOut{handlers: next} + return &Handler{handlers: next} } -// WithGroup returns a [FanOut] whose children are wrapped with the same group. -func (f *FanOut) WithGroup(name string) slog.Handler { +// WithGroup returns a [Handler] whose children are wrapped with the same group. +func (f *Handler) WithGroup(name string) slog.Handler { if name == "" { return f } @@ -80,5 +80,5 @@ func (f *FanOut) WithGroup(name string) slog.Handler { next[i] = h.WithGroup(name) } - return &FanOut{handlers: next} + return &Handler{handlers: next} } diff --git a/rlog/fanout_test.go b/rlog/fanout/fanout_test.go similarity index 90% rename from rlog/fanout_test.go rename to rlog/fanout/fanout_test.go index 1c7d8ec..a4aae97 100644 --- a/rlog/fanout_test.go +++ b/rlog/fanout/fanout_test.go @@ -1,4 +1,4 @@ -package rlog_test +package fanout_test import ( "bytes" @@ -11,6 +11,8 @@ import ( "go.rtnl.ai/x/assert" "go.rtnl.ai/x/rlog" + "go.rtnl.ai/x/rlog/fanout" + rlogtesting "go.rtnl.ai/x/rlog/testing" ) // Each sink receives the same logical record when levels allow. @@ -18,7 +20,7 @@ func TestFanOut_Handle_clonesToEachSink(t *testing.T) { var a, b bytes.Buffer ha := slog.NewJSONHandler(&a, rlog.MergeWithCustomLevels(&slog.HandlerOptions{Level: slog.LevelInfo})) hb := slog.NewJSONHandler(&b, rlog.MergeWithCustomLevels(&slog.HandlerOptions{Level: slog.LevelInfo})) - f := rlog.NewFanOut(ha, hb) + f := fanout.New(ha, hb) ctx := context.Background() r := slog.NewRecord(time.Now(), slog.LevelInfo, "hello", 0) @@ -33,7 +35,7 @@ func TestFanOut_Enabled_OR(t *testing.T) { var quiet, loud bytes.Buffer hQuiet := slog.NewJSONHandler(&quiet, &slog.HandlerOptions{Level: slog.LevelError}) hLoud := slog.NewJSONHandler(&loud, &slog.HandlerOptions{Level: slog.LevelDebug}) - f := rlog.NewFanOut(hQuiet, hLoud) + f := fanout.New(hQuiet, hLoud) ctx := context.Background() assert.True(t, f.Enabled(ctx, slog.LevelInfo), "loud child accepts Info") @@ -45,7 +47,7 @@ func TestFanOut_Handle_skipsDisabledChildren(t *testing.T) { var quiet, loud bytes.Buffer hQuiet := slog.NewJSONHandler(&quiet, &slog.HandlerOptions{Level: slog.LevelError}) hLoud := slog.NewJSONHandler(&loud, &slog.HandlerOptions{Level: slog.LevelDebug}) - f := rlog.NewFanOut(hQuiet, hLoud) + f := fanout.New(hQuiet, hLoud) ctx := context.Background() r := slog.NewRecord(time.Now(), slog.LevelInfo, "hello", 0) @@ -60,7 +62,7 @@ func TestFanOut_WithGroup_propagates(t *testing.T) { var a, b bytes.Buffer ha := slog.NewJSONHandler(&a, rlog.MergeWithCustomLevels(&slog.HandlerOptions{Level: slog.LevelInfo})) hb := slog.NewJSONHandler(&b, rlog.MergeWithCustomLevels(&slog.HandlerOptions{Level: slog.LevelInfo})) - f := rlog.NewFanOut(ha, hb).WithGroup("outer").(*rlog.FanOut) + f := fanout.New(ha, hb).WithGroup("outer").(*fanout.Handler) ctx := context.Background() r := slog.NewRecord(time.Now(), slog.LevelInfo, "msg", 0) @@ -77,7 +79,7 @@ func TestFanOut_WithGroup_propagates(t *testing.T) { func TestFanOut_slogtest_singleChild(t *testing.T) { var buf bytes.Buffer h := slog.NewJSONHandler(&buf, &slog.HandlerOptions{Level: slog.LevelInfo}) - fan := rlog.NewFanOut(h) + fan := fanout.New(h) err := slogtest.TestHandler(fan, func() []map[string]any { var maps []map[string]any @@ -85,7 +87,7 @@ func TestFanOut_slogtest_singleChild(t *testing.T) { if line == "" { continue } - m, e := rlog.ParseJSONLine(line) + m, e := rlogtesting.ParseJSONLine(line) assert.Ok(t, e) maps = append(maps, m) } diff --git a/rlog/level.go b/rlog/level.go index fb58785..efb9b70 100644 --- a/rlog/level.go +++ b/rlog/level.go @@ -14,11 +14,15 @@ const ( LevelTrace slog.Level = slog.LevelDebug - 4 LevelTraceKey string = "TRACE" - // [slog.Level] keys (unavailable from slog package) - LevelDebugKey string = "DEBUG" // for [slog.LevelDebug] - LevelInfoKey string = "INFO" // for [slog.LevelInfo] - LevelWarnKey string = "WARN" // for [slog.LevelWarn] - LevelErrorKey string = "ERROR" // for [slog.LevelError] + // Mirrors [slog.Level] and adds keys + LevelDebug slog.Level = slog.LevelDebug + LevelDebugKey string = "DEBUG" // for [slog.LevelDebug] + LevelInfo slog.Level = slog.LevelInfo + LevelInfoKey string = "INFO" // for [slog.LevelInfo] + LevelWarn slog.Level = slog.LevelWarn + LevelWarnKey string = "WARN" // for [slog.LevelWarn] + LevelError slog.Level = slog.LevelError + LevelErrorKey string = "ERROR" // for [slog.LevelError] // LevelFatal is more severe than [slog.LevelError]. LevelFatal slog.Level = slog.LevelError + 4 @@ -70,13 +74,13 @@ func (ll LevelDecoder) Encode() (string, error) { switch slog.Level(ll) { case LevelTrace: return LevelTraceKey, nil - case slog.LevelDebug: + case LevelDebug: return LevelDebugKey, nil - case slog.LevelInfo: + case LevelInfo: return LevelInfoKey, nil - case slog.LevelWarn: + case LevelWarn: return LevelWarnKey, nil - case slog.LevelError: + case LevelError: return LevelErrorKey, nil case LevelFatal: return LevelFatalKey, nil diff --git a/rlog/logger.go b/rlog/logger.go index 28f2a85..36f3fbf 100644 --- a/rlog/logger.go +++ b/rlog/logger.go @@ -1,11 +1,80 @@ +// Package rlog wraps [log/slog] with extra levels (Trace, Fatal, Panic), test +// capture helpers, and small slog utilities (handler options, global level sync, +// multi-sink fan-out). See [README.md in the repo], or [rlog on pkg.go.dev], for +// API summary and usage notes. +// +// package main +// +// import ( +// "context" +// "log/slog" +// "os" +// +// "go.rtnl.ai/x/rlog" +// ) +// +// func main() { +// // Global default logger (JSON stdout): allow Trace. +// rlog.SetLevel(rlog.LevelTrace) +// rlog.Info("hello") +// // Output example: {"time":"2026-03-25T12:00:00.000-00:00","level":"INFO","msg":"hello"} +// rlog.Trace("verbose") +// // Output example: {"time":"…","level":"TRACE","msg":"verbose"} +// +// // Custom logger: MergeWithCustomLevels names TRACE/FATAL/PANIC; WithGlobalLevel ties +// // level to rlog.SetLevel so this handler follows the same threshold as the default. +// opts := rlog.MergeWithCustomLevels(rlog.WithGlobalLevel(nil)) +// log := rlog.New(slog.New(slog.NewJSONHandler(os.Stdout, opts))) +// +// // rlog-only level + key/value fields (Trace also has TraceContext, TraceAttrs, …). +// log.Trace("trace-msg", "k", "v") +// // Output example: {"time":"…","level":"TRACE","msg":"trace-msg","k":"v"} +// +// // Without a hook, Fatal would os.Exit(1) and the rest of main would not run. +// rlog.SetFatalHook(func() {}) // demo only — replace with test hook or omit in production +// defer rlog.SetFatalHook(nil) // setting the fatal hook to nil causes future Fatal calls to use os.Exit(1) +// log.Fatal("fatal-msg") +// // Output example: {"time":"…","level":"FATAL","msg":"fatal-msg"} — then runs the fatal hook (no exit here) +// +// // Panic levels call panic("panic-msg") after logging +// func() { +// defer func() { recover() }() +// log.Panic("panic-msg") +// // Output example: {"time":"…","level":"PANIC","msg":"panic-msg"} — then panic("panic-msg") +// }() +// +// // WithGroup/With return *rlog.Logger and work the same as for a slog.Logger. +// sub := log.WithGroup("svc").With("name", "api") +// sub.Info("scoped") +// // Output example: {"time":"…","level":"INFO","msg":"scoped","svc":{"name":"api"}} +// +// // Stdlib-style context and slog.Attr APIs on *rlog.Logger. +// log.DebugContext(context.Background(), "debug-msg", "k", "v") +// // Output example: {"time":"…","level":"DEBUG","msg":"debug-msg","k":"v"} +// log.InfoAttrs(context.Background(), "info-msg", slog.String("k", "v")) +// // Output example: {"time":"…","level":"INFO","msg":"info-msg","k":"v"} +// +// // Package-level helpers and slog.Default now use this logger. +// new := log.With(slog.String("new", "logger")) +// rlog.SetDefault(new) +// rlog.Warn("via package after SetDefault") +// // Output example: {"time":"…","level":"WARN","msg":"via package after SetDefault","new":"logger"} +// rlog.FatalAttrs("fatal-msg", slog.String("fatal", "attr")) +// // Output example: {"time":"…","level":"FATAL","msg":"fatal-msg","new":"logger","fatal":"attr"} — then runs the fatal hook (no exit here) +// } +// +// [README.md in the repo]: https://github.com/rotationalio/x/blob/main/rlog/README.md +// [rlog on pkg.go.dev]: https://pkg.go.dev/go.rtnl.ai/x/rlog package rlog import ( "context" "log/slog" "os" + "runtime" "sync" "sync/atomic" + "time" ) //============================================================================= @@ -41,6 +110,34 @@ func (l *Logger) WithGroup(name string) *Logger { return &Logger{Logger: l.Logger.WithGroup(name)} } +// emit writes a record using a caller PC already captured at the public API +// boundary; behavior matches [slog.Logger]'s internal log path (nil ctx, Enabled, +// NewRecord, Handle). +func (l *Logger) emit(ctx context.Context, level slog.Level, msg string, pc uintptr, args ...any) { + if ctx == nil { + ctx = context.Background() + } + if !l.Enabled(ctx, level) { + return + } + r := slog.NewRecord(time.Now(), level, msg, pc) + r.Add(args...) + _ = l.Handler().Handle(ctx, r) +} + +// emitAttrs is like [Logger.emit] but for attribute-only records. +func (l *Logger) emitAttrs(ctx context.Context, level slog.Level, msg string, pc uintptr, attrs ...slog.Attr) { + if ctx == nil { + ctx = context.Background() + } + if !l.Enabled(ctx, level) { + return + } + r := slog.NewRecord(time.Now(), level, msg, pc) + r.AddAttrs(attrs...) + _ = l.Handler().Handle(ctx, r) +} + //============================================================================= // Global Logger Init and Management //============================================================================= @@ -120,263 +217,411 @@ func exitFatal() { } //============================================================================= -// Global Logger Functions -// NOTE: These functions are aliases for the [Logger] methods with the default [Logger]. +// Logger logging methods //============================================================================= -// With returns a derived [Logger] with the given attributes. -func With(args ...any) *Logger { - return Default().With(args...) +// Log emits a log record with the given level and message. Arguments are handled like +// [slog.Logger.Log]. +func (l *Logger) Log(ctx context.Context, level slog.Level, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(ctx, level, msg, pcs[0], args...) } -// WithGroup returns a derived [Logger] with the given group. -func WithGroup(name string) *Logger { - return Default().WithGroup(name) +// LogAttrs is like [Logger.Log] but accepts attrs only; attribute handling matches +// [slog.Logger.LogAttrs]. +func (l *Logger) LogAttrs(ctx context.Context, level slog.Level, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emitAttrs(ctx, level, msg, pcs[0], attrs...) } -// Log emits a log record with the given level and message using the [Default] logger. -// Arguments are handled like [slog.Logger.Log]. -func Log(ctx context.Context, level slog.Level, msg string, args ...any) { - Default().Log(ctx, level, msg, args...) +// Trace logs at [LevelTrace]. Arguments are handled like [slog.Logger.Log]; you can pass any +// number of key/value pairs or [slog.Attr] objects. +func (l *Logger) Trace(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(context.Background(), LevelTrace, msg, pcs[0], args...) } -// LogAttrs is like [Log] but accepts attrs only; it uses [slog.LogAttrs] for efficiency. -func LogAttrs(ctx context.Context, level slog.Level, msg string, attrs ...slog.Attr) { - Default().LogAttrs(ctx, level, msg, attrs...) +// TraceAttrs logs at [LevelTrace] with ctx and attrs. Attribute handling matches +// [slog.Logger.LogAttrs]. +func (l *Logger) TraceAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emitAttrs(ctx, LevelTrace, msg, pcs[0], attrs...) } -// Trace logs at [LevelTrace] using the [Default] logger. Arguments are handled like -// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. -func Trace(msg string, args ...any) { - Default().Trace(msg, args...) +// TraceContext logs at [LevelTrace] with ctx. Arguments are handled like [slog.Logger.Log]; you +// can pass any number of key/value pairs or [slog.Attr] objects. +func (l *Logger) TraceContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(ctx, LevelTrace, msg, pcs[0], args...) } -// Debug logs at [slog.LevelDebug] using the [Default] logger. Arguments are handled like -// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. -func Debug(msg string, args ...any) { - Default().Debug(msg, args...) +// Debug logs at [slog.LevelDebug]. Arguments are handled like [slog.Logger.Log]; you can pass +// any number of key/value pairs or [slog.Attr] objects. +func (l *Logger) Debug(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(context.Background(), slog.LevelDebug, msg, pcs[0], args...) } -// Info logs at [slog.LevelInfo] using the [Default] logger. Arguments are handled like -// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. -func Info(msg string, args ...any) { - Default().Info(msg, args...) +// DebugAttrs logs at [slog.LevelDebug] with ctx and attrs. Attribute handling matches +// [slog.Logger.LogAttrs]. +func (l *Logger) DebugAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emitAttrs(ctx, slog.LevelDebug, msg, pcs[0], attrs...) } -// Warn logs at [slog.LevelWarn] using the [Default] logger. Arguments are handled like -// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. -func Warn(msg string, args ...any) { - Default().Warn(msg, args...) +// DebugContext logs at [slog.LevelDebug] with ctx. Arguments are handled like [slog.Logger.Log]; +// you can pass any number of key/value pairs or [slog.Attr] objects. +func (l *Logger) DebugContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(ctx, slog.LevelDebug, msg, pcs[0], args...) } -// Error logs at [slog.LevelError] using the [Default] logger. Arguments are handled like -// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. -func Error(msg string, args ...any) { - Default().Error(msg, args...) +// Info logs at [slog.LevelInfo]. Arguments are handled like [slog.Logger.Log]; you can pass any +// number of key/value pairs or [slog.Attr] objects. +func (l *Logger) Info(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(context.Background(), slog.LevelInfo, msg, pcs[0], args...) } -// Fatal logs at [LevelFatal] using the [Default] logger, then runs the global fatal hook -// from [SetFatalHook] if set, otherwise [os.Exit](1). It does not return. Arguments are -// handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. -func Fatal(msg string, args ...any) { - Default().Fatal(msg, args...) +// InfoAttrs logs at [slog.LevelInfo] with ctx and attrs. Attribute handling matches +// [slog.Logger.LogAttrs]. +func (l *Logger) InfoAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emitAttrs(ctx, slog.LevelInfo, msg, pcs[0], attrs...) } -// Panic logs at [LevelPanic] using the [Default] logger, then panics with msg. Arguments are -// handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] -// objects. -func Panic(msg string, args ...any) { - Default().Panic(msg, args...) +// InfoContext logs at [slog.LevelInfo] with ctx. Arguments are handled like [slog.Logger.Log]; +// you can pass any number of key/value pairs or [slog.Attr] objects. +func (l *Logger) InfoContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(ctx, slog.LevelInfo, msg, pcs[0], args...) } -// TraceContext logs at [LevelTrace] with ctx using the [Default] logger. Arguments are handled -// like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. -func TraceContext(ctx context.Context, msg string, args ...any) { - Default().TraceContext(ctx, msg, args...) +// Warn logs at [slog.LevelWarn]. Arguments are handled like [slog.Logger.Log]; you can pass any +// number of key/value pairs or [slog.Attr] objects. +func (l *Logger) Warn(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(context.Background(), slog.LevelWarn, msg, pcs[0], args...) } -// DebugContext logs at [slog.LevelDebug] with ctx using the [Default] logger. Arguments are -// handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] -// objects. -func DebugContext(ctx context.Context, msg string, args ...any) { - Default().DebugContext(ctx, msg, args...) +// WarnAttrs logs at [slog.LevelWarn] with ctx and attrs. Attribute handling matches +// [slog.Logger.LogAttrs]. +func (l *Logger) WarnAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emitAttrs(ctx, slog.LevelWarn, msg, pcs[0], attrs...) } -// InfoContext logs at [slog.LevelInfo] with ctx using the [Default] logger. Arguments are -// handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] -// objects. -func InfoContext(ctx context.Context, msg string, args ...any) { - Default().InfoContext(ctx, msg, args...) +// WarnContext logs at [slog.LevelWarn] with ctx. Arguments are handled like [slog.Logger.Log]; +// you can pass any number of key/value pairs or [slog.Attr] objects. +func (l *Logger) WarnContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(ctx, slog.LevelWarn, msg, pcs[0], args...) } -// WarnContext logs at [slog.LevelWarn] with ctx using the [Default] logger. Arguments are -// handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] -// objects. -func WarnContext(ctx context.Context, msg string, args ...any) { - Default().WarnContext(ctx, msg, args...) +// Error logs at [slog.LevelError]. Arguments are handled like [slog.Logger.Log]; you can pass any +// number of key/value pairs or [slog.Attr] objects. +func (l *Logger) Error(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(context.Background(), slog.LevelError, msg, pcs[0], args...) } -// ErrorContext logs at [slog.LevelError] with ctx using the [Default] logger. Arguments are -// handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] -// objects. -func ErrorContext(ctx context.Context, msg string, args ...any) { - Default().ErrorContext(ctx, msg, args...) +// ErrorAttrs logs at [slog.LevelError] with ctx and attrs. Attribute handling matches +// [slog.Logger.LogAttrs]. +func (l *Logger) ErrorAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emitAttrs(ctx, slog.LevelError, msg, pcs[0], attrs...) } -// FatalContext logs at [LevelFatal] with ctx using the [Default] logger, then runs the global -// fatal hook from [SetFatalHook] if set, otherwise [os.Exit](1). It does not return. Arguments -// are handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. -func FatalContext(ctx context.Context, msg string, args ...any) { - Default().FatalContext(ctx, msg, args...) +// ErrorContext logs at [slog.LevelError] with ctx. Arguments are handled like [slog.Logger.Log]; +// you can pass any number of key/value pairs or [slog.Attr] objects. +func (l *Logger) ErrorContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(ctx, slog.LevelError, msg, pcs[0], args...) } -// PanicContext logs at [LevelPanic] with ctx using the [Default] logger, then panics with msg. -// Arguments are handled like [slog.Logger.Log]; you can pass any number of key/value pairs or -// [slog.Attr] objects. -func PanicContext(ctx context.Context, msg string, args ...any) { - Default().PanicContext(ctx, msg, args...) +// Fatal logs at [LevelFatal], then runs the global fatal hook from [SetFatalHook] if set, +// otherwise [os.Exit](1). It does not return. Arguments are handled like [slog.Logger.Log]; you +// can pass any number of key/value pairs or [slog.Attr] objects. +func (l *Logger) Fatal(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(context.Background(), LevelFatal, msg, pcs[0], args...) + exitFatal() } -// TraceAttrs logs at [LevelTrace] with ctx and attrs using the [Default] logger. Uses -// [slog.LogAttrs] for efficiency. -func TraceAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - Default().TraceAttrs(ctx, msg, attrs...) +// FatalAttrs logs at [LevelFatal] with ctx and attrs, then runs the global fatal hook from +// [SetFatalHook] if set, otherwise [os.Exit](1). It does not return. Attribute handling matches +// [slog.Logger.LogAttrs]. +func (l *Logger) FatalAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emitAttrs(ctx, LevelFatal, msg, pcs[0], attrs...) + exitFatal() } -// DebugAttrs logs at [slog.LevelDebug] with ctx and attrs using the [Default] logger. Uses -// [slog.LogAttrs] for efficiency. -func DebugAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - Default().DebugAttrs(ctx, msg, attrs...) +// FatalContext logs at [LevelFatal] with ctx, then runs the global fatal hook from [SetFatalHook] +// if set, otherwise [os.Exit](1). It does not return. Arguments are handled like +// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. +func (l *Logger) FatalContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(ctx, LevelFatal, msg, pcs[0], args...) + exitFatal() } -// InfoAttrs logs at [slog.LevelInfo] with ctx and attrs using the [Default] logger. Uses -// [slog.LogAttrs] for efficiency. -func InfoAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - Default().InfoAttrs(ctx, msg, attrs...) +// Panic logs at [LevelPanic], then panics with msg. Arguments are handled like [slog.Logger.Log]; +// you can pass any number of key/value pairs or [slog.Attr] objects. +func (l *Logger) Panic(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(context.Background(), LevelPanic, msg, pcs[0], args...) + panic(msg) } -// WarnAttrs logs at [slog.LevelWarn] with ctx and attrs using the [Default] logger. Uses -// [slog.LogAttrs] for efficiency. -func WarnAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - Default().WarnAttrs(ctx, msg, attrs...) +// PanicAttrs logs at [LevelPanic] with ctx and attrs, then panics with msg. Attribute handling +// matches [slog.Logger.LogAttrs]. +func (l *Logger) PanicAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emitAttrs(ctx, LevelPanic, msg, pcs[0], attrs...) + panic(msg) } -// ErrorAttrs logs at [slog.LevelError] with ctx and attrs using the [Default] logger. Uses -// [slog.LogAttrs] for efficiency. -func ErrorAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - Default().ErrorAttrs(ctx, msg, attrs...) +// PanicContext logs at [LevelPanic] with ctx, then panics with msg. Arguments are handled like +// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. +func (l *Logger) PanicContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + l.emit(ctx, LevelPanic, msg, pcs[0], args...) + panic(msg) } -// FatalAttrs logs at [LevelFatal] with attrs using the [Default] logger, then runs the global -// fatal hook from [SetFatalHook] if set, otherwise [os.Exit](1). It does not return. Uses -// [slog.LogAttrs] for efficiency. -func FatalAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - Default().FatalAttrs(ctx, msg, attrs...) +//============================================================================= +// Global Logger Functions +// NOTE: These functions are aliases for the [Logger] methods with the [Default] [Logger]. +//============================================================================= + +// With returns a derived [Logger] with the given attributes. +func With(args ...any) *Logger { + return Default().With(args...) } -// PanicAttrs logs at [LevelPanic] with attrs using the [Default] logger, then panics with msg. -// Uses [slog.LogAttrs] for efficiency. -func PanicAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - Default().PanicAttrs(ctx, msg, attrs...) +// WithGroup returns a derived [Logger] with the given group. +func WithGroup(name string) *Logger { + return Default().WithGroup(name) } -//============================================================================= -// Attrs Functions for default slog levels -//============================================================================= +// Log emits a log record with the given level and message using the [Default] logger. +// Arguments are handled like [slog.Logger.Log]. +func Log(ctx context.Context, level slog.Level, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(ctx, level, msg, pcs[0], args...) +} -// DebugAttrs logs at slog.LevelDebug with ctx and attrs. Uses slog.LogAttrs for efficiency. -func (l *Logger) DebugAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - l.Logger.LogAttrs(ctx, slog.LevelDebug, msg, attrs...) +// LogAttrs is like [Log] but accepts attrs only; it uses [slog.LogAttrs] for efficiency. +func LogAttrs(ctx context.Context, level slog.Level, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emitAttrs(ctx, level, msg, pcs[0], attrs...) } -// InfoAttrs logs at slog.LevelInfo with ctx and attrs. Uses slog.LogAttrs for efficiency. -func (l *Logger) InfoAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - l.Logger.LogAttrs(ctx, slog.LevelInfo, msg, attrs...) +// Trace logs at [LevelTrace] using the [Default] logger. Arguments are handled like +// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. +func Trace(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(context.Background(), LevelTrace, msg, pcs[0], args...) } -// WarnAttrs logs at slog.LevelWarn with ctx and attrs. Uses slog.LogAttrs for efficiency. -func (l *Logger) WarnAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - l.Logger.LogAttrs(ctx, slog.LevelWarn, msg, attrs...) +// TraceAttrs logs at [LevelTrace] with ctx and attrs using the [Default] logger. Uses +// [slog.LogAttrs] for efficiency. +func TraceAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emitAttrs(ctx, LevelTrace, msg, pcs[0], attrs...) } -// ErrorAttrs logs at slog.LevelError with ctx and attrs. Uses slog.LogAttrs for efficiency. -func (l *Logger) ErrorAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - l.Logger.LogAttrs(ctx, slog.LevelError, msg, attrs...) +// TraceContext logs at [LevelTrace] with ctx using the [Default] logger. Arguments are handled +// like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. +func TraceContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(ctx, LevelTrace, msg, pcs[0], args...) } -//============================================================================= -// Trace Functions -//============================================================================= +// Debug logs at [slog.LevelDebug] using the [Default] logger. Arguments are handled like +// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. +func Debug(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(context.Background(), slog.LevelDebug, msg, pcs[0], args...) +} -// Trace logs at [LevelTrace]. Arguments are handled like [slog.Logger.Log]; you -// can pass any number of key/value pairs or [slog.Attr] objects. -func (l *Logger) Trace(msg string, args ...any) { - l.TraceContext(context.Background(), msg, args...) +// DebugAttrs logs at [slog.LevelDebug] with ctx and attrs using the [Default] logger. Uses +// [slog.LogAttrs] for efficiency. +func DebugAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emitAttrs(ctx, slog.LevelDebug, msg, pcs[0], attrs...) } -// TraceContext logs at [LevelTrace] with ctx. Arguments are handled like -// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] +// DebugContext logs at [slog.LevelDebug] with ctx using the [Default] logger. Arguments are +// handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] // objects. -func (l *Logger) TraceContext(ctx context.Context, msg string, args ...any) { - l.Logger.Log(ctx, LevelTrace, msg, args...) +func DebugContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(ctx, slog.LevelDebug, msg, pcs[0], args...) } -// TraceAttrs logs at [LevelTrace] with ctx and attrs. Uses [slog.LogAttrs] for -// efficiency. -func (l *Logger) TraceAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - l.Logger.LogAttrs(ctx, LevelTrace, msg, attrs...) +// Info logs at [slog.LevelInfo] using the [Default] logger. Arguments are handled like +// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. +func Info(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(context.Background(), slog.LevelInfo, msg, pcs[0], args...) } -//============================================================================= -// Fatal Functions -//============================================================================= +// InfoAttrs logs at [slog.LevelInfo] with ctx and attrs using the [Default] logger. Uses +// [slog.LogAttrs] for efficiency. +func InfoAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emitAttrs(ctx, slog.LevelInfo, msg, pcs[0], attrs...) +} -// Fatal logs at [LevelFatal] then runs the global fatal hook from [SetFatalHook] if set, -// otherwise [os.Exit](1). It does not return. Arguments are handled like [slog.Logger.Log]; -// you can pass any number of key/value pairs or [slog.Attr] objects. -func (l *Logger) Fatal(msg string, args ...any) { - l.FatalContext(context.Background(), msg, args...) +// InfoContext logs at [slog.LevelInfo] with ctx using the [Default] logger. Arguments are +// handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] +// objects. +func InfoContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(ctx, slog.LevelInfo, msg, pcs[0], args...) } -// FatalContext logs at [LevelFatal] with ctx then runs the global fatal hook from [SetFatalHook] -// if set, otherwise [os.Exit](1). It does not return. Arguments are handled like -// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] +// Warn logs at [slog.LevelWarn] using the [Default] logger. Arguments are handled like +// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. +func Warn(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(context.Background(), slog.LevelWarn, msg, pcs[0], args...) +} + +// WarnAttrs logs at [slog.LevelWarn] with ctx and attrs using the [Default] logger. Uses +// [slog.LogAttrs] for efficiency. +func WarnAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emitAttrs(ctx, slog.LevelWarn, msg, pcs[0], attrs...) +} + +// WarnContext logs at [slog.LevelWarn] with ctx using the [Default] logger. Arguments are +// handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] // objects. -func (l *Logger) FatalContext(ctx context.Context, msg string, args ...any) { - l.Logger.Log(ctx, LevelFatal, msg, args...) +func WarnContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(ctx, slog.LevelWarn, msg, pcs[0], args...) +} + +// Error logs at [slog.LevelError] using the [Default] logger. Arguments are handled like +// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. +func Error(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(context.Background(), slog.LevelError, msg, pcs[0], args...) +} + +// ErrorAttrs logs at [slog.LevelError] with ctx and attrs using the [Default] logger. Uses +// [slog.LogAttrs] for efficiency. +func ErrorAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emitAttrs(ctx, slog.LevelError, msg, pcs[0], attrs...) +} + +// ErrorContext logs at [slog.LevelError] with ctx using the [Default] logger. Arguments are +// handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] +// objects. +func ErrorContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(ctx, slog.LevelError, msg, pcs[0], args...) +} + +// Fatal logs at [LevelFatal] using the [Default] logger, then runs the global fatal hook +// from [SetFatalHook] if set, otherwise [os.Exit](1). It does not return. Arguments are +// handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. +func Fatal(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(context.Background(), LevelFatal, msg, pcs[0], args...) exitFatal() } -// FatalAttrs logs at [LevelFatal] with attrs then runs the global fatal hook from [SetFatalHook] -// if set, otherwise [os.Exit](1). It does not return. Uses [slog.LogAttrs] for -// efficiency. -func (l *Logger) FatalAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - l.Logger.LogAttrs(ctx, LevelFatal, msg, attrs...) +// FatalAttrs logs at [LevelFatal] with attrs using the [Default] logger, then runs the global +// fatal hook from [SetFatalHook] if set, otherwise [os.Exit](1). It does not return. Uses +// [slog.LogAttrs] for efficiency. +func FatalAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emitAttrs(ctx, LevelFatal, msg, pcs[0], attrs...) exitFatal() } -//============================================================================= -// Panic Functions -//============================================================================= +// FatalContext logs at [LevelFatal] with ctx using the [Default] logger, then runs the global +// fatal hook from [SetFatalHook] if set, otherwise [os.Exit](1). It does not return. Arguments +// are handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] objects. +func FatalContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(ctx, LevelFatal, msg, pcs[0], args...) + exitFatal() +} -// Panic logs at [LevelPanic] then panics with msg. Arguments are handled like -// [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] +// Panic logs at [LevelPanic] using the [Default] logger, then panics with msg. Arguments are +// handled like [slog.Logger.Log]; you can pass any number of key/value pairs or [slog.Attr] // objects. -func (l *Logger) Panic(msg string, args ...any) { - l.PanicContext(context.Background(), msg, args...) +func Panic(msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(context.Background(), LevelPanic, msg, pcs[0], args...) + panic(msg) } -// PanicContext logs at [LevelPanic] with ctx then panics with msg. Arguments -// are handled like [slog.Logger.Log]; you can pass any number of key/value -// pairs or [slog.Attr] objects. -func (l *Logger) PanicContext(ctx context.Context, msg string, args ...any) { - l.Logger.Log(ctx, LevelPanic, msg, args...) +// PanicAttrs logs at [LevelPanic] with attrs using the [Default] logger, then panics with msg. +// Uses [slog.LogAttrs] for efficiency. +func PanicAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emitAttrs(ctx, LevelPanic, msg, pcs[0], attrs...) panic(msg) } -// PanicAttrs logs at [LevelPanic] with attrs then panics with msg. Uses -// [slog.LogAttrs] for efficiency. -func (l *Logger) PanicAttrs(ctx context.Context, msg string, attrs ...slog.Attr) { - l.Logger.LogAttrs(ctx, LevelPanic, msg, attrs...) +// PanicContext logs at [LevelPanic] with ctx using the [Default] logger, then panics with msg. +// Arguments are handled like [slog.Logger.Log]; you can pass any number of key/value pairs or +// [slog.Attr] objects. +func PanicContext(ctx context.Context, msg string, args ...any) { + var pcs [1]uintptr + runtime.Callers(2, pcs[:]) + Default().emit(ctx, LevelPanic, msg, pcs[0], args...) panic(msg) } diff --git a/rlog/logger_test.go b/rlog/logger_test.go index 452282a..36a25ad 100644 --- a/rlog/logger_test.go +++ b/rlog/logger_test.go @@ -3,8 +3,10 @@ package rlog_test import ( "bytes" "context" + "encoding/json" "io" "log/slog" + "path/filepath" "sync" "sync/atomic" "testing" @@ -175,6 +177,53 @@ func TestPanic(t *testing.T) { }) } +// AddSource should attribute the call site in test code, not rlog.go (wrapper frames). +func TestAddSourceSkipsRlogWrapper(t *testing.T) { + type sourceRow struct { + Source struct { + File string `json:"file"` + } `json:"source"` + } + + var buf bytes.Buffer + opts := &slog.HandlerOptions{Level: rlog.LevelTrace, AddSource: true} + log := newTestLogger(t, &buf, opts) + + prev := rlog.Default() + t.Cleanup(func() { rlog.SetDefault(prev) }) + rlog.SetDefault(log) + + t.Run("Logger.Trace", func(t *testing.T) { + buf.Reset() + log.Trace("m") + var r sourceRow + assert.Ok(t, json.Unmarshal(buf.Bytes(), &r)) + base := filepath.Base(r.Source.File) + assert.NotEqual(t, "rlog.go", base, "source must not be rlog implementation file") + assert.Equal(t, "logger_test.go", base) + }) + + t.Run("Logger.Info", func(t *testing.T) { + buf.Reset() + log.Info("m") + var r sourceRow + assert.Ok(t, json.Unmarshal(buf.Bytes(), &r)) + base := filepath.Base(r.Source.File) + assert.NotEqual(t, "rlog.go", base) + assert.Equal(t, "logger_test.go", base) + }) + + t.Run("package_Info", func(t *testing.T) { + buf.Reset() + rlog.Info("m") + var r sourceRow + assert.Ok(t, json.Unmarshal(buf.Bytes(), &r)) + base := filepath.Base(r.Source.File) + assert.NotEqual(t, "rlog.go", base) + assert.Equal(t, "logger_test.go", base) + }) +} + // Concurrent SetDefault, Default, and package-level logging (run with -race). func TestDefaultSetDefault_concurrent(t *testing.T) { // Pool of loggers to rotate under SetDefault. diff --git a/rlog/options.go b/rlog/options.go index 19f37a3..906c1e1 100644 --- a/rlog/options.go +++ b/rlog/options.go @@ -29,15 +29,15 @@ func MergeWithCustomLevels(opts *slog.HandlerOptions) *slog.HandlerOptions { merged = *opts } - next := merged.ReplaceAttr - merged.ReplaceAttr = func(groups []string, a slog.Attr) slog.Attr { - a = ReplaceLevelKey(groups, a) - - if next != nil { + // If ReplaceAttr is nil, set it to ReplaceLevelKey, otherwise chain it. + if merged.ReplaceAttr == nil { + merged.ReplaceAttr = ReplaceLevelKey + } else { + next := merged.ReplaceAttr + merged.ReplaceAttr = func(groups []string, a slog.Attr) slog.Attr { + a = ReplaceLevelKey(groups, a) return next(groups, a) } - - return a } return &merged diff --git a/rlog/testing.go b/rlog/testing/testing.go similarity index 81% rename from rlog/testing.go rename to rlog/testing/testing.go index e41eda1..fe95846 100644 --- a/rlog/testing.go +++ b/rlog/testing/testing.go @@ -1,4 +1,39 @@ -package rlog +// Package testing provides helpers for testing slog handlers and other +// logging-related functionality. +// +// Example usage: +// +// func TestSomething(t *testing.T) { +// // Captures slog.Record and JSON lines, also outputting to the test log +// h := NewCapturingTestHandler(t) +// +// // Can use with slog directly, or wrap with rlog.New to get rlog.Logger. +// slogLogger := slog.New(h) +// slogLogger.Info("hello", "k", "v") +// rlogLogger := rlog.New(slogLogger) +// rlogLogger.Trace("traced", "k2", "v2") +// +// // Parse the JSON line into a map for assertions +// lines := h.Lines() +// m, err := ParseJSONLine(lines[0]) +// assert.Ok(t, err) +// assert.Equal(t, "INFO", m["level"]) +// assert.Equal(t, "hello", m["msg"]) +// assert.Equal(t, "v", m["k"]) +// +// // MustParseJSONLine panics on error +// m2 := MustParseJSONLine(lines[0]) +// assert.Equal(t, m, m2) +// +// // Get a mutex-locked snapshot of records and lines +// records, err := h.RecordsAndLines() +// assert.Ok(t, err) +// assert.Equal(t, 2, len(records)) +// assert.Equal(t, "TRACE", records[1].Level()) +// assert.Equal(t, "traced", records[1].Message()) +// assert.Equal(t, "v2", records[1].Attrs()[0].Value.String()) +// } +package testing import ( "bytes" @@ -9,11 +44,13 @@ import ( "strings" "sync" "testing" + + "go.rtnl.ai/x/rlog" ) // capturingJSONOpts is reused by [CapturingTestHandler.Handle] so every log line -// does not rebuild [MergeWithCustomLevels](nil) (closure + [slog.HandlerOptions] escape). -var capturingJSONOpts = MergeWithCustomLevels(nil) +// does not rebuild [rlog.MergeWithCustomLevels](nil) (closure + [slog.HandlerOptions] escape). +var capturingJSONOpts = rlog.MergeWithCustomLevels(nil) // captureState holds lines and records shared by all derived handlers from the same root. type captureState struct { diff --git a/rlog/testing_test.go b/rlog/testing/testing_test.go similarity index 81% rename from rlog/testing_test.go rename to rlog/testing/testing_test.go index 64bdf87..4c4ac35 100644 --- a/rlog/testing_test.go +++ b/rlog/testing/testing_test.go @@ -1,4 +1,4 @@ -package rlog_test +package testing_test import ( "context" @@ -11,12 +11,12 @@ import ( "time" "go.rtnl.ai/x/assert" - "go.rtnl.ai/x/rlog" + rlogtesting "go.rtnl.ai/x/rlog/testing" ) // CapturingTestHandler should pass the standard slog handler tests. func TestCapturingTestHandler_slogtest(t *testing.T) { - cap := rlog.NewCapturingTestHandler(nil) + cap := rlogtesting.NewCapturingTestHandler(nil) err := slogtest.TestHandler(cap, func() []map[string]any { maps, err := cap.ResultMaps() assert.Ok(t, err) @@ -27,15 +27,15 @@ func TestCapturingTestHandler_slogtest(t *testing.T) { // Groups nest attrs in JSON output and ResultMaps sees nested maps. func TestCapturingTestHandler_groupNesting(t *testing.T) { - h := rlog.NewCapturingTestHandler(nil).WithGroup("g").(*rlog.CapturingTestHandler) - h = h.WithAttrs([]slog.Attr{slog.String("inside", "yes")}).(*rlog.CapturingTestHandler) + h := rlogtesting.NewCapturingTestHandler(nil).WithGroup("g").(*rlogtesting.CapturingTestHandler) + h = h.WithAttrs([]slog.Attr{slog.String("inside", "yes")}).(*rlogtesting.CapturingTestHandler) ctx := context.Background() assert.Ok(t, h.Handle(ctx, slog.NewRecord(time.Now(), slog.LevelInfo, "hi", 0))) lines := h.Lines() assert.Equal(t, 1, len(lines)) - m := rlog.MustParseJSONLine(lines[0]) + m := rlogtesting.MustParseJSONLine(lines[0]) g, ok := m["g"].(map[string]any) assert.True(t, ok) assert.Equal(t, "yes", g["inside"]) @@ -44,17 +44,17 @@ func TestCapturingTestHandler_groupNesting(t *testing.T) { // ParseJSONLine and MustParseJSONLine round-trip a simple object. func TestParseJSONLine_helpers(t *testing.T) { const line = `{"level":"INFO","msg":"x","k":1}` - m, err := rlog.ParseJSONLine(line) + m, err := rlogtesting.ParseJSONLine(line) assert.Ok(t, err) assert.Equal(t, "INFO", m["level"]) assert.Equal(t, float64(1), m["k"]) - assert.Equal(t, m, rlog.MustParseJSONLine(line)) + assert.Equal(t, m, rlogtesting.MustParseJSONLine(line)) } // NewCapturingTestHandler links to [testing.TB] (only *testing.T / B / F satisfy TB outside stdlib). // Derived handlers still share capture state; slogtest exercises WithAttrs/WithGroup with tb set. func TestCapturingTestHandler_slogtest_withTB(t *testing.T) { - cap := rlog.NewCapturingTestHandler(t) + cap := rlogtesting.NewCapturingTestHandler(t) err := slogtest.TestHandler(cap, func() []map[string]any { maps, err := cap.ResultMaps() assert.Ok(t, err) @@ -65,7 +65,7 @@ func TestCapturingTestHandler_slogtest_withTB(t *testing.T) { // Concurrent Handle calls must keep the same index aligned in records and lines. func TestCapturingTestHandler_concurrentHandle_recordsMatchLines(t *testing.T) { - h := rlog.NewCapturingTestHandler(nil) + h := rlogtesting.NewCapturingTestHandler(nil) ctx := context.Background() const n = 64 var wg sync.WaitGroup @@ -89,11 +89,11 @@ func TestCapturingTestHandler_concurrentHandle_recordsMatchLines(t *testing.T) { // Derived handlers share the same capture buffers. func TestCapturingTestHandler_derivedSharesLines(t *testing.T) { - h := rlog.NewCapturingTestHandler(nil) + h := rlogtesting.NewCapturingTestHandler(nil) ctx := context.Background() assert.Ok(t, h.Handle(ctx, slog.NewRecord(time.Now(), slog.LevelInfo, "one", 0))) - h2 := h.WithAttrs([]slog.Attr{slog.String("k", "v")}).(*rlog.CapturingTestHandler) + h2 := h.WithAttrs([]slog.Attr{slog.String("k", "v")}).(*rlogtesting.CapturingTestHandler) assert.Ok(t, h2.Handle(ctx, slog.NewRecord(time.Now(), slog.LevelWarn, "two", 0))) lines := h.Lines()