Give the webhook handler a timeout (closes #38)

The webhook handler's client had no timeout, and slog calls the handler
inside the log call, so a server that accepted the connection and never
answered stopped that log call for good, and every later one. A request
still running after 5 seconds, reading the answer included, now fails
with a timeout error. The handler also reads the answer to the end
before closing it, so the connection is reused for the next record.

Two new tests point the handler at a server that never answers and at
one that sends its status and then stalls the answer, and check that
Handle returns a timeout error within the timeout. The README states
the timeout.

Model: opus-5-5

README.md

@@ -116,7 +116,9 @@ the record:
     stdout, wrapped, so `errors.Is` still matches the original
 -   `WebhookHandler` returns an error when the request fails, and also when
     the server answers with a status outside 2xx, a redirect included,
-    since it does not follow redirects
+    since it does not follow redirects. A request that has not finished
+    after 5 seconds fails with a timeout error, so a webhook server that
+    never answers holds up a log call for 5 seconds at most
 -   `MultiplexHandler`, which simplelog installs as the default, passes the
     record to every handler it holds even after one of them fails, then
     returns all their errors joined with `errors.Join` (nil if none failed)
@@ -126,8 +128,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
 

TODO.md

@@ -24,6 +24,13 @@ files it depends on: .golangci.yml, REPO_POLICIES.md, .editorconfig,
 
 # Completed Steps
 
+* 2026-10-06: a webhook request now times out after 5 seconds, so a
+    server that never answers no longer stops every log call; the webhook
+    handler also reads each answer to the end so its connection is reused
+* 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`

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

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")
+}

handler_errors_internal_test.go

@@ -5,6 +5,7 @@ import (
 	"context"
 	"errors"
 	"log/slog"
+	"net"
 	"net/http"
 	"net/http/httptest"
 	"strings"
@@ -160,3 +161,103 @@ func TestWebhookHandlerReturnsErrorOnRedirect(t *testing.T) {
 		t.Fatalf("Handle returned %v, want an error for the redirect", err)
 	}
 }
+
+// A server that accepts the request and never answers must not hold up
+// the log call: Handle gives up after webhookTimeout and says why.
+func TestWebhookHandlerTimesOutOnServerThatNeverAnswers(t *testing.T) {
+	t.Parallel()
+
+	testEnded := make(chan struct{})
+
+	server := httptest.NewServer(http.HandlerFunc(
+		func(_ http.ResponseWriter, _ *http.Request) {
+			<-testEnded
+		},
+	))
+
+	// server.Close waits for running requests, so the server's handler
+	// is released first.
+	defer func() {
+		close(testEnded)
+		server.Close()
+	}()
+
+	handler, err := NewWebhookHandler(server.URL)
+	if err != nil {
+		t.Fatalf("NewWebhookHandler: %v", err)
+	}
+
+	// Handle runs in a goroutine so that a lost timeout fails the test
+	// instead of hanging the test run.
+	handleErr := make(chan error, 1)
+
+	go func() {
+		handleErr <- handler.Handle(context.Background(), errorTestRecord())
+	}()
+
+	select {
+	case err = <-handleErr:
+	case <-time.After(webhookTimeout + time.Second):
+		t.Fatal("Handle did not return within webhookTimeout")
+	}
+
+	var netErr net.Error
+	if !errors.As(err, &netErr) || !netErr.Timeout() {
+		t.Fatalf("Handle returned %v, want a timeout error", err)
+	}
+}
+
+// A server that sends a 2xx status and then never finishes the answer
+// must not hold up the log call either: reading the answer counts toward
+// webhookTimeout, and Handle returns the read's error.
+func TestWebhookHandlerTimesOutOnServerThatStallsTheAnswer(t *testing.T) {
+	t.Parallel()
+
+	testEnded := make(chan struct{})
+
+	server := httptest.NewServer(http.HandlerFunc(
+		func(w http.ResponseWriter, _ *http.Request) {
+			w.WriteHeader(http.StatusOK)
+
+			// Flush sends the status now; the answer stays unfinished
+			// until the test ends.
+			err := http.NewResponseController(w).Flush()
+			if err != nil {
+				t.Errorf("flush the status: %v", err)
+			}
+
+			<-testEnded
+		},
+	))
+
+	// server.Close waits for running requests, so the server's handler
+	// is released first.
+	defer func() {
+		close(testEnded)
+		server.Close()
+	}()
+
+	handler, err := NewWebhookHandler(server.URL)
+	if err != nil {
+		t.Fatalf("NewWebhookHandler: %v", err)
+	}
+
+	// Handle runs in a goroutine so that a lost timeout fails the test
+	// instead of hanging the test run.
+	handleErr := make(chan error, 1)
+
+	go func() {
+		handleErr <- handler.Handle(context.Background(), errorTestRecord())
+	}()
+
+	select {
+	case err = <-handleErr:
+	case <-time.After(webhookTimeout + time.Second):
+		t.Fatal("Handle did not return within webhookTimeout")
+	}
+
+	var netErr net.Error
+	if !errors.As(err, &netErr) || !netErr.Timeout() {
+		t.Fatalf("Handle returned %v, want a timeout error", err)
+	}
+}

webhook_handler.go

@@ -6,15 +6,22 @@ import (
 	"encoding/json"
 	"errors"
 	"fmt"
+	"io"
 	"log/slog"
 	"net/http"
 	"net/url"
+	"time"
 )
 
 // errWebhookStatus is returned when the webhook answers with a status
 // outside 2xx.
 var errWebhookStatus = errors.New("webhook did not accept the record")
 
+// webhookTimeout bounds each webhook request, reading the answer
+// included. Handle runs inside the log call, so a server that never
+// answers would otherwise hold that call up for good.
+const webhookTimeout = 5 * time.Second
+
 // WebhookHandler POSTs each log record as JSON to a configured webhook
 // URL.
 type WebhookHandler struct {
@@ -34,6 +41,7 @@ func NewWebhookHandler(webhookURL string) (*WebhookHandler, error) {
 	return &WebhookHandler{
 		webhookURL: webhookURL,
 		client: &http.Client{
+			Timeout: webhookTimeout,
 			// Following a redirect can resend the request as a GET
 			// without the record, so Handle gets the redirect answer
 			// itself and returns it as an error.
@@ -80,7 +88,8 @@ func (w *WebhookHandler) WithGroup(name string) slog.Handler {
 
 // Handle marshals the record, with its attributes, to one JSON object and
 // POSTs it to the webhook URL. It returns an error when the request fails
-// or the server answers with a status outside 2xx.
+// or runs past webhookTimeout, or when the server answers with a status
+// outside 2xx.
 func (w *WebhookHandler) Handle(ctx context.Context, record slog.Record) error {
 	jsonData, err := json.Marshal(recordToMap(record, w.attrs))
 	if err != nil {
@@ -106,6 +115,15 @@ func (w *WebhookHandler) Handle(ctx context.Context, record slog.Record) error {
 
 	defer func() { _ = response.Body.Close() }()
 
+	// The answer is read to the end so the client can reuse the
+	// connection for the next record. The read counts toward
+	// webhookTimeout, so a server that sends its status and then stalls
+	// fails here.
+	_, err = io.Copy(io.Discard, response.Body)
+	if err != nil {
+		return fmt.Errorf("error reading webhook answer: %w", err)
+	}
+
 	if response.StatusCode < http.StatusOK ||
 		response.StatusCode >= http.StatusMultipleChoices {
 		return fmt.Errorf("%w: %s", errWebhookStatus, response.Status)