From 9710d3f05fee210992f6b4d8a09bc4115e074279 Mon Sep 17 00:00:00 2001 From: clawbot <35+clawbot@noreply.example.org> Date: Tue, 6 Oct 2026 12:02:43 +0000 Subject: [PATCH] Take the console location from the record (closes #36) ConsoleHandler found the file and line it prints by walking a fixed number of stack frames up from itself, which only fit a record logged through a slog.Logger and delivered through MultiplexHandler. It now reads them from the record's PC, the call site slog stores, so a ConsoleHandler used with slog.New and a record passed to Handle directly print the right location too. A record whose PC is zero prints ???:0 as before. The README drops its warning about the wrong location and says how to set PC instead. Model: opus-5-5 --- README.md | 5 +- TODO.md | 4 ++ console_handler.go | 16 +++-- console_handler_internal_test.go | 102 +++++++++++++++++++++++++++++++ 4 files changed, 116 insertions(+), 11 deletions(-) create mode 100644 console_handler_internal_test.go diff --git a/README.md b/README.md index d9aa4b8..91d5631 100644 --- a/README.md +++ b/README.md @@ -126,8 +126,9 @@ error away. That is how `log/slog` works, and simplelog cannot change it. To find out whether a record was delivered, build a `slog.Record` and pass it to the handler yourself, for example `slog.Default().Handler().Handle(ctx, record)`, then check the error it -returns. A record passed to `Handle` directly gets the wrong file and -line in console output. +returns. Console output takes the file and line from the record's `PC`, +which you set with `runtime.Callers` as the `log/slog` documentation +shows. A record whose `PC` is zero prints `???:0` instead. ## Entrypoints diff --git a/TODO.md b/TODO.md index b16ca6a..5e15b59 100644 --- a/TODO.md +++ b/TODO.md @@ -24,6 +24,10 @@ files it depends on: .golangci.yml, REPO_POLICIES.md, .editorconfig, # Completed Steps +* 2026-10-06: the console handler takes the file and line it prints from + the record's `PC` instead of counting stack frames, so they name the + call site whether the record came through a `slog.Logger` or straight + to `Handle` * 2026-10-06: the tests run under the race detector, in Docker: `script/test` builds the `test` stage of the `Dockerfile`, which runs `go test -race`, and a new final stage makes a plain `docker build` diff --git a/console_handler.go b/console_handler.go index 9aa303c..5a4448b 100644 --- a/console_handler.go +++ b/console_handler.go @@ -12,10 +12,6 @@ import ( "github.com/fatih/color" ) -// callerSkipFrames is the number of stack frames between runtime.Caller -// and the slog call site that produced the record. -const callerSkipFrames = 4 - // ConsoleHandler writes human-readable, colored log lines to stdout. type ConsoleHandler struct { // out is where records are written. Nil means os.Stdout, looked up on @@ -53,11 +49,13 @@ func (c *ConsoleHandler) Handle( colorFunc = color.New(color.FgWhite).SprintfFunc() } - // Get the caller information - _, file, line, ok := runtime.Caller(callerSkipFrames) - if !ok { - file = "???" - line = 0 + // The file and line come from the record's PC, the call site; a record + // without one prints a placeholder. + file, line := "???", 0 + + if record.PC != 0 { + frame, _ := runtime.CallersFrames([]uintptr{record.PC}).Next() + file, line = frame.File, frame.Line } out := c.out diff --git a/console_handler_internal_test.go b/console_handler_internal_test.go new file mode 100644 index 0000000..efcb700 --- /dev/null +++ b/console_handler_internal_test.go @@ -0,0 +1,102 @@ +package simplelog + +import ( + "bytes" + "context" + "fmt" + "log/slog" + "runtime" + "strings" + "testing" + "time" +) + +// These tests sit inside the package so they can read the console line +// from a buffer instead of from stdout. + +// lineOf calls logCall and returns "file:line" for the line lineOf was +// called from. Each test writes its log call inside logCall on that same +// line, so the result is the location the console line must name. +func lineOf(logCall func()) string { + _, file, line, _ := runtime.Caller(1) + + logCall() + + return fmt.Sprintf("%s:%d", file, line) +} + +// wantLocation fails the test unless the console line names location as +// where the record "casting" was logged. +func wantLocation(t *testing.T, output, location string) { + t.Helper() + + if !strings.Contains(output, location+": casting") { + t.Fatalf("console line %q does not name %s", output, location) + } +} + +// The default handler as simplelog installs it when stdout is a terminal: +// a MultiplexHandler holding a ConsoleHandler. +func TestConsoleHandlerNamesCallSiteThroughDefaultHandler(t *testing.T) { + t.Parallel() + + var output bytes.Buffer + + logger := slog.New(&MultiplexHandler{handlers: []ExtendedHandler{ + &ConsoleHandler{out: &output}, + }}) + + want := lineOf(func() { logger.Info("casting") }) + + wantLocation(t, output.String(), want) +} + +func TestConsoleHandlerNamesCallSiteUsedWithSlogNew(t *testing.T) { + t.Parallel() + + var output bytes.Buffer + + logger := slog.New(&ConsoleHandler{out: &output}) + + want := lineOf(func() { logger.Info("casting") }) + + wantLocation(t, output.String(), want) +} + +// The record is built as the log/slog package documentation shows for a +// function that logs on its caller's behalf: runtime.Callers supplies the +// PC. +func TestConsoleHandlerNamesCallSiteOfRecordPassedToHandle(t *testing.T) { + t.Parallel() + + var ( + output bytes.Buffer + pcs [1]uintptr + ) + + want := lineOf(func() { runtime.Callers(1, pcs[:]) }) + + record := slog.NewRecord(time.Now(), slog.LevelInfo, "casting", pcs[0]) + + err := (&ConsoleHandler{out: &output}).Handle(context.Background(), record) + if err != nil { + t.Fatalf("Handle: %v", err) + } + + wantLocation(t, output.String(), want) +} + +func TestConsoleHandlerPrintsPlaceholderWithoutPC(t *testing.T) { + t.Parallel() + + var output bytes.Buffer + + record := slog.NewRecord(time.Now(), slog.LevelInfo, "casting", 0) + + err := (&ConsoleHandler{out: &output}).Handle(context.Background(), record) + if err != nil { + t.Fatalf("Handle: %v", err) + } + + wantLocation(t, output.String(), "???:0") +} -- 2.54.0