Give the webhook handler a timeout (closes #38)
check / check (push) Successful in 52s
check / check (pull_request) Successful in 35s

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
This commit is contained in:
2026-10-06 10:47:54 +00:00
committed by sneak
parent 8e53530434
commit bbd92df20f
4 changed files with 126 additions and 2 deletions
+3 -1
View File
@@ -116,7 +116,9 @@ the record:
stdout, wrapped, so `errors.Is` still matches the original stdout, wrapped, so `errors.Is` still matches the original
- `WebhookHandler` returns an error when the request fails, and also when - `WebhookHandler` returns an error when the request fails, and also when
the server answers with a status outside 2xx, a redirect included, 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 - `MultiplexHandler`, which simplelog installs as the default, passes the
record to every handler it holds even after one of them fails, then 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) returns all their errors joined with `errors.Join` (nil if none failed)
+3
View File
@@ -24,6 +24,9 @@ files it depends on: .golangci.yml, REPO_POLICIES.md, .editorconfig,
# Completed Steps # 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 linter runs only in Docker: `script/lint` builds the * 2026-10-06: the linter runs only in Docker: `script/lint` builds the
`lint` stage of the `Dockerfile`, every `docker build` in `script/` `lint` stage of the `Dockerfile`, every `docker build` in `script/`
runs without the build cache, and `script/bootstrap` no longer runs without the build cache, and `script/bootstrap` no longer
+101
View File
@@ -5,6 +5,7 @@ import (
"context" "context"
"errors" "errors"
"log/slog" "log/slog"
"net"
"net/http" "net/http"
"net/http/httptest" "net/http/httptest"
"strings" "strings"
@@ -160,3 +161,103 @@ func TestWebhookHandlerReturnsErrorOnRedirect(t *testing.T) {
t.Fatalf("Handle returned %v, want an error for the redirect", err) 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)
}
}
+19 -1
View File
@@ -6,15 +6,22 @@ import (
"encoding/json" "encoding/json"
"errors" "errors"
"fmt" "fmt"
"io"
"log/slog" "log/slog"
"net/http" "net/http"
"net/url" "net/url"
"time"
) )
// errWebhookStatus is returned when the webhook answers with a status // errWebhookStatus is returned when the webhook answers with a status
// outside 2xx. // outside 2xx.
var errWebhookStatus = errors.New("webhook did not accept the record") 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 // WebhookHandler POSTs each log record as JSON to a configured webhook
// URL. // URL.
type WebhookHandler struct { type WebhookHandler struct {
@@ -34,6 +41,7 @@ func NewWebhookHandler(webhookURL string) (*WebhookHandler, error) {
return &WebhookHandler{ return &WebhookHandler{
webhookURL: webhookURL, webhookURL: webhookURL,
client: &http.Client{ client: &http.Client{
Timeout: webhookTimeout,
// Following a redirect can resend the request as a GET // Following a redirect can resend the request as a GET
// without the record, so Handle gets the redirect answer // without the record, so Handle gets the redirect answer
// itself and returns it as an error. // 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 // 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 // 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 { func (w *WebhookHandler) Handle(ctx context.Context, record slog.Record) error {
jsonData, err := json.Marshal(recordToMap(record, w.attrs)) jsonData, err := json.Marshal(recordToMap(record, w.attrs))
if err != nil { if err != nil {
@@ -106,6 +115,15 @@ func (w *WebhookHandler) Handle(ctx context.Context, record slog.Record) error {
defer func() { _ = response.Body.Close() }() 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 err
}
if response.StatusCode < http.StatusOK || if response.StatusCode < http.StatusOK ||
response.StatusCode >= http.StatusMultipleChoices { response.StatusCode >= http.StatusMultipleChoices {
return fmt.Errorf("%w: %s", errWebhookStatus, response.Status) return fmt.Errorf("%w: %s", errWebhookStatus, response.Status)