diff --git a/README.md b/README.md index 4cd1a4f..9a07db5 100644 --- a/README.md +++ b/README.md @@ -25,6 +25,9 @@ Released v1.0.0 2024-06-14. Works as intended. No known bugs. in console output they are appended as `key=value` pairs, with grouped keys written as `group.key=value`. See [Attribute output](#attribute-output) for the details worth knowing +- reports a record that could not be delivered as an error from the + handler's `Handle` method. See + [When delivery fails](#when-delivery-fails) for how to receive it ## Planned Features @@ -104,6 +107,28 @@ ignored, an empty group is elided along with its key, a group with an empty key is inlined into its parent, and `WithGroup("")` returns the handler unchanged. +## When delivery fails + +Every handler returns an error from `Handle` when it could not deliver +the record: + +- `ConsoleHandler` and `JSONHandler` return the error from their write to + 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 +- `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) + +`slog.Info`, `slog.Error` and the other `slog.Logger` methods throw that +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. + ## Entrypoints This repository adheres to the diff --git a/TODO.md b/TODO.md index 7cfdd45..a5344d9 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: every handler now returns a failed delivery from `Handle` + instead of discarding it: console and JSON return the stdout write + error, the webhook also fails on a non-2xx answer, and the multiplex + delivers to every handler and returns their errors joined * 2026-08-10: fixed every handler discarding slog attributes: console, JSON and webhook handlers now emit record attributes, accumulate WithAttrs without mutating the receiver, and honour WithGroup; diff --git a/console_handler.go b/console_handler.go index f26c209..9aa303c 100644 --- a/console_handler.go +++ b/console_handler.go @@ -3,6 +3,7 @@ package simplelog import ( "context" "fmt" + "io" "log/slog" "os" "runtime" @@ -17,6 +18,9 @@ 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 + // every write so that a reassigned os.Stdout is followed. + out io.Writer attrs handlerAttrs } @@ -27,7 +31,7 @@ func NewConsoleHandler() *ConsoleHandler { // Handle writes the record to stdout as a colored, timestamped line // including the caller file and line, followed by the attributes as -// key=value pairs. +// key=value pairs. A failed write is returned as an error. func (c *ConsoleHandler) Handle( _ context.Context, record slog.Record, @@ -56,8 +60,13 @@ func (c *ConsoleHandler) Handle( line = 0 } - _, _ = fmt.Fprintln( - os.Stdout, + out := c.out + if out == nil { + out = os.Stdout + } + + _, err := fmt.Fprintln( + out, colorFunc( "%s [%s] %s:%d: %s%s", timestamp, @@ -68,6 +77,9 @@ func (c *ConsoleHandler) Handle( attrsToText(c.attrs.forRecord(record)), ), ) + if err != nil { + return fmt.Errorf("error writing log record: %w", err) + } return nil } @@ -88,7 +100,7 @@ func (c *ConsoleHandler) WithAttrs(attrs []slog.Attr) slog.Handler { return c } - return &ConsoleHandler{attrs: c.attrs.withAttrs(attrs)} + return &ConsoleHandler{out: c.out, attrs: c.attrs.withAttrs(attrs)} } // WithGroup returns a new handler that qualifies later attributes with @@ -98,5 +110,5 @@ func (c *ConsoleHandler) WithGroup(name string) slog.Handler { return c } - return &ConsoleHandler{attrs: c.attrs.withGroup(name)} + return &ConsoleHandler{out: c.out, attrs: c.attrs.withGroup(name)} } diff --git a/handler_errors_internal_test.go b/handler_errors_internal_test.go new file mode 100644 index 0000000..5c4af86 --- /dev/null +++ b/handler_errors_internal_test.go @@ -0,0 +1,162 @@ +package simplelog + +import ( + "bytes" + "context" + "errors" + "log/slog" + "net/http" + "net/http/httptest" + "strings" + "testing" + "time" +) + +// These tests sit inside the package so they can point a handler at a sink +// that fails, which callers outside the package cannot do. + +// errSinkFailed is what failingWriter returns from every write. +var errSinkFailed = errors.New("sink failed") + +// failingWriter is a sink whose every write fails. +type failingWriter struct{} + +func (failingWriter) Write(_ []byte) (int, error) { + return 0, errSinkFailed +} + +func errorTestRecord() slog.Record { + return slog.NewRecord(time.Now(), slog.LevelInfo, "casting", 0) +} + +// The handler is derived with WithAttrs and WithGroup, so the test also +// fails if either of them drops the sink. +func TestJSONHandlerReturnsWriteError(t *testing.T) { + t.Parallel() + + handler := (&JSONHandler{out: failingWriter{}}). + WithAttrs([]slog.Attr{slog.String("service", "cattbox")}). + WithGroup("cast") + + err := handler.Handle(context.Background(), errorTestRecord()) + if !errors.Is(err, errSinkFailed) { + t.Fatalf("Handle returned %v, want the sink's error", err) + } +} + +func TestConsoleHandlerReturnsWriteError(t *testing.T) { + t.Parallel() + + handler := (&ConsoleHandler{out: failingWriter{}}). + WithAttrs([]slog.Attr{slog.String("service", "cattbox")}). + WithGroup("cast") + + err := handler.Handle(context.Background(), errorTestRecord()) + if !errors.Is(err, errSinkFailed) { + t.Fatalf("Handle returned %v, want the sink's error", err) + } +} + +// A failing handler must not stop the record reaching the handlers after +// it, and its error must still reach the caller. +func TestMultiplexHandlerDeliversPastFailingHandler(t *testing.T) { + t.Parallel() + + var delivered bytes.Buffer + + handler := &MultiplexHandler{handlers: []ExtendedHandler{ + &JSONHandler{out: failingWriter{}}, + &JSONHandler{out: &delivered}, + }} + + err := handler.Handle(context.Background(), errorTestRecord()) + if !errors.Is(err, errSinkFailed) { + t.Fatalf("Handle returned %v, want the failing handler's error", err) + } + + if !strings.Contains(delivered.String(), `"Message":"casting"`) { + t.Fatalf( + "second handler did not receive the record: %q", + delivered.String(), + ) + } +} + +// When more than one handler fails, the caller gets every failure, not +// only the first. +func TestMultiplexHandlerReturnsEveryFailure(t *testing.T) { + t.Parallel() + + server := httptest.NewServer(http.HandlerFunc( + func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusInternalServerError) + }, + )) + defer server.Close() + + webhook, err := NewWebhookHandler(server.URL) + if err != nil { + t.Fatalf("NewWebhookHandler: %v", err) + } + + handler := &MultiplexHandler{handlers: []ExtendedHandler{ + &JSONHandler{out: failingWriter{}}, + webhook, + }} + + err = handler.Handle(context.Background(), errorTestRecord()) + if !errors.Is(err, errSinkFailed) { + t.Fatalf("Handle returned %v, want the JSON handler's error", err) + } + + if !errors.Is(err, errWebhookStatus) { + t.Fatalf("Handle returned %v, want the webhook's error", err) + } +} + +func TestWebhookHandlerReturnsErrorOnServerError(t *testing.T) { + t.Parallel() + + server := httptest.NewServer(http.HandlerFunc( + func(w http.ResponseWriter, _ *http.Request) { + w.WriteHeader(http.StatusInternalServerError) + }, + )) + defer server.Close() + + handler, err := NewWebhookHandler(server.URL) + if err != nil { + t.Fatalf("NewWebhookHandler: %v", err) + } + + err = handler.Handle(context.Background(), errorTestRecord()) + if !errors.Is(err, errWebhookStatus) { + t.Fatalf("Handle returned %v, want an error for the 500 answer", err) + } +} + +// Following the redirect would resend the request as a GET without the +// record, and the GET is answered with 200, so only an error for the +// redirect itself tells the caller the record was lost. +func TestWebhookHandlerReturnsErrorOnRedirect(t *testing.T) { + t.Parallel() + + server := httptest.NewServer(http.HandlerFunc( + func(w http.ResponseWriter, r *http.Request) { + if r.URL.Path != "/moved" { + http.Redirect(w, r, "/moved", http.StatusFound) + } + }, + )) + defer server.Close() + + handler, err := NewWebhookHandler(server.URL) + if err != nil { + t.Fatalf("NewWebhookHandler: %v", err) + } + + err = handler.Handle(context.Background(), errorTestRecord()) + if !errors.Is(err, errWebhookStatus) { + t.Fatalf("Handle returned %v, want an error for the redirect", err) + } +} diff --git a/json_handler.go b/json_handler.go index 093e503..e0f2a1c 100644 --- a/json_handler.go +++ b/json_handler.go @@ -4,12 +4,16 @@ import ( "context" "encoding/json" "fmt" + "io" "log/slog" "os" ) // JSONHandler writes each log record to stdout as a JSON document. type JSONHandler struct { + // out is where records are written. Nil means os.Stdout, looked up on + // every write so that a reassigned os.Stdout is followed. + out io.Writer attrs handlerAttrs } @@ -19,14 +23,22 @@ func NewJSONHandler() *JSONHandler { } // Handle marshals the record, with its attributes, to one JSON object and -// writes it to stdout. +// writes it to stdout. A failed write is returned as an error. func (j *JSONHandler) Handle(_ context.Context, record slog.Record) error { jsonData, err := json.Marshal(recordToMap(record, j.attrs)) if err != nil { return err } - _, _ = fmt.Fprintln(os.Stdout, string(jsonData)) + out := j.out + if out == nil { + out = os.Stdout + } + + _, err = fmt.Fprintln(out, string(jsonData)) + if err != nil { + return fmt.Errorf("error writing log record: %w", err) + } return nil } @@ -44,7 +56,7 @@ func (j *JSONHandler) WithAttrs(attrs []slog.Attr) slog.Handler { return j } - return &JSONHandler{attrs: j.attrs.withAttrs(attrs)} + return &JSONHandler{out: j.out, attrs: j.attrs.withAttrs(attrs)} } // WithGroup returns a new handler that nests later attributes in an @@ -54,5 +66,5 @@ func (j *JSONHandler) WithGroup(name string) slog.Handler { return j } - return &JSONHandler{attrs: j.attrs.withGroup(name)} + return &JSONHandler{out: j.out, attrs: j.attrs.withGroup(name)} } diff --git a/simplelog.go b/simplelog.go index 8fe77dc..9012dff 100644 --- a/simplelog.go +++ b/simplelog.go @@ -7,6 +7,7 @@ package simplelog import ( "context" "encoding/json" + "errors" "log" "log/slog" "os" @@ -62,20 +63,23 @@ func NewMultiplexHandler() slog.Handler { return cl } -// Handle forwards the record to every underlying handler, stopping at -// the first error. +// Handle forwards the record to every underlying handler, including the +// ones after a handler that fails. It returns the failures joined with +// errors.Join, or nil when every handler succeeded. func (cl *MultiplexHandler) Handle( ctx context.Context, record slog.Record, ) error { + var errs []error + for _, handler := range cl.handlers { err := handler.Handle(ctx, record) if err != nil { - return err + errs = append(errs, err) } } - return nil + return errors.Join(errs...) } // Enabled reports whether the handler processes records at the given diff --git a/webhook_handler.go b/webhook_handler.go index d73f9ad..a7cf9b5 100644 --- a/webhook_handler.go +++ b/webhook_handler.go @@ -4,16 +4,22 @@ import ( "bytes" "context" "encoding/json" + "errors" "fmt" "log/slog" "net/http" "net/url" ) +// errWebhookStatus is returned when the webhook answers with a status +// outside 2xx. +var errWebhookStatus = errors.New("webhook did not accept the record") + // WebhookHandler POSTs each log record as JSON to a configured webhook // URL. type WebhookHandler struct { webhookURL string + client *http.Client attrs handlerAttrs } @@ -25,7 +31,17 @@ func NewWebhookHandler(webhookURL string) (*WebhookHandler, error) { return nil, fmt.Errorf("invalid webhook URL: %w", err) } - return &WebhookHandler{webhookURL: webhookURL}, nil + return &WebhookHandler{ + webhookURL: webhookURL, + client: &http.Client{ + // 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. + CheckRedirect: func(*http.Request, []*http.Request) error { + return http.ErrUseLastResponse + }, + }, + }, nil } // Enabled reports whether the handler processes records at the given @@ -43,6 +59,7 @@ func (w *WebhookHandler) WithAttrs(attrs []slog.Attr) slog.Handler { return &WebhookHandler{ webhookURL: w.webhookURL, + client: w.client, attrs: w.attrs.withAttrs(attrs), } } @@ -56,12 +73,14 @@ func (w *WebhookHandler) WithGroup(name string) slog.Handler { return &WebhookHandler{ webhookURL: w.webhookURL, + client: w.client, attrs: w.attrs.withGroup(name), } } // Handle marshals the record, with its attributes, to one JSON object and -// POSTs it to the webhook URL. +// POSTs it to the webhook URL. It returns an error when the request fails +// or 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 { @@ -80,12 +99,17 @@ func (w *WebhookHandler) Handle(ctx context.Context, record slog.Record) error { request.Header.Set("Content-Type", "application/json") - response, err := http.DefaultClient.Do(request) + response, err := w.client.Do(request) if err != nil { return err } defer func() { _ = response.Body.Close() }() + if response.StatusCode < http.StatusOK || + response.StatusCode >= http.StatusMultipleChoices { + return fmt.Errorf("%w: %s", errWebhookStatus, response.Status) + } + return nil }