From db3373c71dba87032336ac8aa276e5b7d4134c7a Mon Sep 17 00:00:00 2001 From: clawbot <35+clawbot@noreply.example.org> Date: Tue, 6 Oct 2026 15:10:23 +0200 Subject: [PATCH] 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 | 4 +- TODO.md | 3 + handler_errors_internal_test.go | 101 ++++++++++++++++++++++++++++++++ webhook_handler.go | 20 ++++++- 4 files changed, 126 insertions(+), 2 deletions(-) diff --git a/README.md b/README.md index 91d5631..387ac67 100644 --- a/README.md +++ b/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) diff --git a/TODO.md b/TODO.md index 5e15b59..f67cfb8 100644 --- a/TODO.md +++ b/TODO.md @@ -24,6 +24,9 @@ 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 diff --git a/handler_errors_internal_test.go b/handler_errors_internal_test.go index 5c4af86..743aca8 100644 --- a/handler_errors_internal_test.go +++ b/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) + } +} diff --git a/webhook_handler.go b/webhook_handler.go index a7cf9b5..a6e47c4 100644 --- a/webhook_handler.go +++ b/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)