Jakub Zych
4660f95e5c
A client that goes away mid-request cancels the context; a handler then fails on context.Canceled and writes a 500 nobody receives. The request log now records it as 499 (client closed request) so a grep for 5xx shows real server errors only.
72 lines
4.4 KiB
Markdown
72 lines
4.4 KiB
Markdown
---
|
|
title: Logging
|
|
description: Log through log/slog with sunscreen, the redacting handler every generated main installs, and keep tokens, keys and request bodies out of log records.
|
|
section: services
|
|
order: 105
|
|
---
|
|
# Logging
|
|
|
|
SummerCMS logs through the standard library's `log/slog`. Where a WinterCMS plugin calls `Log::error` and relies on a Monolog tap to scrub credentials, a SummerCMS plugin logs through a `*slog.Logger`, and [sunscreen](../../modules/sunscreen/README.md) does the scrubbing.
|
|
|
|
## The redacting default logger
|
|
|
|
Every application `main` that `summer build` generates calls `sunscreen.InstallDefault(os.Stderr)` as the first statement of `run`, before the configuration is loaded and before any plugin is activated. From then on `slog.Default`, the package-level `slog` functions and the standard `log` package all write through a text handler wrapped by `sunscreen.Wrap`.
|
|
|
|
The handler rewrites every record before it is written:
|
|
|
|
- The value of an attribute whose key is one of `sunscreen.RedactedKeys` becomes `[REDACTED]`, at any group depth and whatever the letter case: `api_key`, `apikey`, `authorization`, `bearer`, `password`, `secret`, `token`, `webhook_secret`, `admin_password` and the `openai_api_key`, `anthropic_api_key` and `perplexity_api_key` variants.
|
|
- The message, string values, error values and the formatted text of other values are passed through `sunscreen.Scrub`, which replaces `Bearer <token>`, `sk-` style API keys and `x-api-key: <value>`.
|
|
- `slog.LogValuer` values are resolved first, and maps such as `http.Header` are redacted key by key.
|
|
|
|
```go src=modules/sunscreen/example_test.go#ExampleWrap
|
|
// Drop the time so the output is stable; a real application keeps it.
|
|
plain := slog.NewTextHandler(os.Stdout, &slog.HandlerOptions{
|
|
ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr {
|
|
if len(groups) == 0 && a.Key == slog.TimeKey {
|
|
return slog.Attr{}
|
|
}
|
|
return a
|
|
},
|
|
})
|
|
logger := slog.New(sunscreen.Wrap(plain))
|
|
|
|
logger.Info("vendor call failed",
|
|
"api_key", "live-key-123",
|
|
slog.Group("request", slog.String("Authorization", "Bearer abc.def")),
|
|
"err", errors.New("401 for key sk-abcdefghijklmnopqrstuvwx"),
|
|
)
|
|
// Output:
|
|
// level=INFO msg="vendor call failed" api_key=[REDACTED] request.Authorization=[REDACTED] err="401 for key sk-[REDACTED]"
|
|
```
|
|
|
|
## Logging from a plugin
|
|
|
|
A plugin resolves a `*slog.Logger` from the application with `backpack.Lookup` and falls back to `slog.Default` when none is published, as the framework modules do. Either way the record goes through the redacting handler.
|
|
|
|
Redaction is a safety net for mistakes, not a way to log secrets on purpose. Log identifiers and outcomes: the record id, the vendor, the status code, how long it took. Never log request arguments, tokens, credentials or request and response bodies, which can carry personal data the patterns do not recognise.
|
|
|
|
## Request log
|
|
|
|
The router can log every request. It is off by default; turn it on with the `http.access_log` key (environment `SUMMER_HTTP__ACCESS_LOG=true`):
|
|
|
|
```yaml
|
|
# config/http.yaml
|
|
access_log: true
|
|
```
|
|
|
|
Each request then writes one Info record with the message `http request` once it has been served:
|
|
|
|
| Attribute | Value |
|
|
|-----------|-------|
|
|
| `method` | The request method. |
|
|
| `pattern` | The matched route, method and path pattern, for example `GET /posts/{id}`. Empty when no route matched. |
|
|
| `status` | The response status; a handler that writes without setting one counts as 200. A 5xx written after the client cancelled the request is logged as 499 (client closed request), since the error came from the cancellation and no client received it. |
|
|
| `duration_ms` | Time spent serving the request, in whole milliseconds. |
|
|
| `path` | Only when no route matched (a 404 or 405 from the router, or a CORS preflight answered before routing): the URL path without the query string. |
|
|
|
|
The record never carries the query string, request or response headers, the client address or the raw path of a matched route, because tokens often travel in paths and query strings. It goes to the published `*slog.Logger` or `slog.Default`, so the redacting handler still applies. Grep for the empty `pattern` to find requests that reached no route.
|
|
|
|
## Panics
|
|
|
|
The router recovers a panicking handler and answers with an opaque 500: the JSON groups send `{"error":true,"message":"Internal server error"}` and the raw groups an empty body. The panic value never reaches the client. See [Routing](routing.md).
|