From ce244c5ac1d91da3228355213d8599f94d380ea2 Mon Sep 17 00:00:00 2001 From: Fabian Esteban Ruiz Valdes Date: Sat, 7 Mar 2026 19:43:03 -0500 Subject: [PATCH 01/19] feat(interceptors): add logging request interceptor --- README.md | 40 +++++++++++++++++++++++++++++++++++++++- interceptors/auth.go | 6 +++--- interceptors/headers.go | 6 +++--- 3 files changed, 45 insertions(+), 7 deletions(-) diff --git a/README.md b/README.md index 6b14009..8b49d2a 100644 --- a/README.md +++ b/README.md @@ -11,10 +11,11 @@ go get github.com/fervbmx/interceptor ## Usage ```go -// Flow: HeaderInterceptor → BasicAuthInterceptor → http.DefaultTransport +// Flow: LoggingInterceptor → HeaderInterceptor → BasicAuthInterceptor → http.DefaultTransport client := &http.Client{ Transport: interceptor.NewTransportInterceptor( nil, + interceptors.LoggingInterceptor(nil), interceptors.HeaderInterceptor("X-API-KEY", "secret"), interceptors.BasicAuthInterceptor("user", "pass"), ), @@ -29,6 +30,43 @@ Pass `nil` as the first argument to use `http.DefaultTransport`, or provide your |---|---| | `HeaderInterceptor(key, value)` | Sets a header on every request | | `BasicAuthInterceptor(user, password)` | Sets Basic authentication | +| `LoggingInterceptor(opts)` | Logs request start/completion in JSON (default), logfmt, or text | + +### LoggingInterceptor examples + +```go +// Default JSON + flat keys + slog.Default(). +client := &http.Client{ + Transport: interceptor.NewTransportInterceptor( + nil, + interceptors.LoggingInterceptor(nil), + ), +} + +// Nested JSON keys for ECS-style pipelines. +client = &http.Client{ + Transport: interceptor.NewTransportInterceptor( + nil, + interceptors.LoggingInterceptor(&interceptors.LoggingOptions{ + Format: interceptors.LogFormatJSON, + KeyStyle: interceptors.KeyStyleNested, + }), + ), +} + +// logfmt format with explicit header allowlist and optional body logging. +client = &http.Client{ + Transport: interceptor.NewTransportInterceptor( + nil, + interceptors.LoggingInterceptor(&interceptors.LoggingOptions{ + Format: interceptors.LogFormatLogfmt, + HeadersToLog: []string{"X-Request-ID"}, + LogBody: true, + MaxBodyLogSize: 2048, + }), + ), +} +``` ## Custom interceptors diff --git a/interceptors/auth.go b/interceptors/auth.go index ba13c16..b3b7959 100644 --- a/interceptors/auth.go +++ b/interceptors/auth.go @@ -14,8 +14,8 @@ import ( // ) func BasicAuthInterceptor(username, password string) interceptor.InterceptorFunc { return func(req *http.Request, next interceptor.HandlerFunc) (*http.Response, error) { - req = req.Clone(req.Context()) - req.SetBasicAuth(username, password) - return next(req) + clonedReq := req.Clone(req.Context()) + clonedReq.SetBasicAuth(username, password) + return next(clonedReq) } } diff --git a/interceptors/headers.go b/interceptors/headers.go index f4fa84a..6503437 100644 --- a/interceptors/headers.go +++ b/interceptors/headers.go @@ -14,8 +14,8 @@ import ( // ) func HeaderInterceptor(key, value string) interceptor.InterceptorFunc { return func(req *http.Request, next interceptor.HandlerFunc) (*http.Response, error) { - req = req.Clone(req.Context()) - req.Header.Set(key, value) - return next(req) + clonedReq := req.Clone(req.Context()) + clonedReq.Header.Set(key, value) + return next(clonedReq) } } From 779bc2ea86af9636a92d8f565218970e2d3c4722 Mon Sep 17 00:00:00 2001 From: Fabian Esteban Ruiz Valdes Date: Sat, 7 Mar 2026 19:48:03 -0500 Subject: [PATCH 02/19] feat(interceptors): add logging request interceptor --- PRD.md | 383 ++++++++++++++++++++++++ interceptors/logging.go | 488 +++++++++++++++++++++++++++++++ interceptors/logging_test.go | 545 +++++++++++++++++++++++++++++++++++ 3 files changed, 1416 insertions(+) create mode 100644 PRD.md create mode 100644 interceptors/logging.go create mode 100644 interceptors/logging_test.go diff --git a/PRD.md b/PRD.md new file mode 100644 index 0000000..f0e7ca4 --- /dev/null +++ b/PRD.md @@ -0,0 +1,383 @@ +# PRD: Logging Request Interceptor + +## 1. Overview + +Add a built-in `LoggingInterceptor` to the `github.com/fervbmx/interceptor` package that captures and logs HTTP request/response details using industry-standard structured logging formats. The interceptor plugs into the existing `InterceptorFunc` chain and requires zero external dependencies. + +## 2. Problem Statement + +Developers using the interceptor package currently have no built-in way to observe outgoing HTTP traffic. Debugging failed API calls, auditing third-party service communication, and measuring response latency all require writing custom one-off logging interceptors. A first-class logging interceptor would eliminate boilerplate, enforce a consistent log schema, and align with widely adopted observability practices (structured JSON logs, OpenTelemetry semantic conventions). + +## 3. Goals + +- Provide a ready-to-use interceptor that logs every outgoing HTTP request and its corresponding response (or error). +- Use **structured JSON** as the default output format (the de-facto industry standard for machine-parseable logs). +- Support **logfmt** (`key=value` pairs) — the structured-yet-readable format widely adopted by Grafana Loki, Heroku, and the Go ecosystem. +- Support a **text/plain** human-readable format for local development. +- Follow field naming conventions from **OpenTelemetry HTTP semantic conventions** and **ECS (Elastic Common Schema)** so logs integrate seamlessly with Elasticsearch, Datadog, Grafana Loki, and similar platforms. +- Allow developers to supply their own `*slog.Logger` (Go 1.21+ standard library) to control output destination and level. +- Remain a **zero-dependency** addition — rely only on the Go standard library. + +## 4. Non-Goals + +- Metric collection (histograms, counters) — that belongs in a separate `MetricsInterceptor`. +- Distributed tracing propagation (trace-id injection) — that belongs in a `TracingInterceptor`. +- Request/response body logging by default (security and performance risk); this will be opt-in only. + +## 5. Logged Fields + +The following fields MUST be present in every log entry. The interceptor supports two JSON key styles, configurable via the `KeyStyle` option: + +- **Flat / dot notation (default)**: flat dotted keys (`"http.method"`). Field names follow [OpenTelemetry HTTP semantic conventions](https://opentelemetry.io/docs/specs/semconv/http/). Best for Datadog, Splunk, Grafana Loki, CloudWatch. +- **Nested**: hierarchical JSON objects (`"http": {"request": {"method": ...}}`). Field structure follows [Elastic Common Schema](https://www.elastic.co/guide/en/ecs/current/). Best for Elasticsearch and Kibana. + +### 5.1 Request Fields (logged before `next` is called) + +| Field | Flat Key (dot notation) | Nested Key | Type | Description | Example | +|---|---|---|---|---|---| +| Timestamp | `timestamp` | `@timestamp` | string (RFC 3339) | Time the request was initiated | `2026-03-07T12:00:00.000Z` | +| Log Level | `level` | `log.level` | string | Severity level | `INFO` | +| Message | `msg` | `message` | string | Human-readable event description | `http request started` | +| HTTP Method | `http.method` | `http.request.method` | string | Request method | `GET` | +| URL | `http.url` | `url.full` | string | Full request URL | `https://api.example.com/v1/users` | +| URL Path | `http.target` | `url.path` | string | Path + query string | `/v1/users?page=2` | +| Host | `http.host` | `url.domain` | string | Host header value | `api.example.com` | +| Scheme | `http.scheme` | `url.scheme` | string | `http` or `https` | `https` | +| Request Content-Length | `http.request_content_length` | `http.request.body.bytes` | int | Body size in bytes (if known) | `256` | +| User-Agent | `user_agent.original` | `user_agent.original` | string | User-Agent header | `Go-http-client/1.1` | +| Request ID | `http.request_id` | `http.request.id` | string | Value of `X-Request-ID` header (if present) | `abc-123` | + +### 5.2 Response Fields (logged after `next` returns) + +| Field | Flat Key (dot notation) | Nested Key | Type | Description | Example | +|---|---|---|---|---|---| +| Timestamp | `timestamp` | `@timestamp` | string (RFC 3339) | Time the response was received | `2026-03-07T12:00:00.150Z` | +| Log Level | `level` | `log.level` | string | `INFO` for 1xx–3xx, `WARN` for 4xx, `ERROR` for 5xx or transport errors | `WARN` | +| Message | `msg` | `message` | string | Human-readable event description | `http request completed` | +| HTTP Method | `http.method` | `http.request.method` | string | Echoed from request | `GET` | +| URL | `http.url` | `url.full` | string | Echoed from request | `https://api.example.com/v1/users` | +| Status Code | `http.status_code` | `http.response.status_code` | int | Response status code | `404` | +| Response Content-Length | `http.response_content_length` | `http.response.body.bytes` | int | Body size in bytes (if known) | `128` | +| Duration | `http.duration_ms` | `event.duration` | float64 | Round-trip time in milliseconds | `142.56` | +| Error | `error.message` | `error.message` | string | Error text (only on transport failure) | `dial tcp: connection refused` | + +### 5.3 Example JSON Log Lines — Flat / dot notation (default) + +**Request started:** + +```json +{ + "timestamp": "2026-03-07T12:00:00.000Z", + "level": "INFO", + "msg": "http request started", + "http.method": "POST", + "http.url": "https://api.example.com/v1/orders", + "http.target": "/v1/orders", + "http.host": "api.example.com", + "http.scheme": "https", + "http.request_content_length": 512, + "user_agent.original": "Go-http-client/1.1" +} +``` + +**Request completed (success):** + +```json +{ + "timestamp": "2026-03-07T12:00:00.150Z", + "level": "INFO", + "msg": "http request completed", + "http.method": "POST", + "http.url": "https://api.example.com/v1/orders", + "http.status_code": 201, + "http.response_content_length": 128, + "http.duration_ms": 150.32 +} +``` + +**Request completed (error):** + +```json +{ + "timestamp": "2026-03-07T12:00:00.050Z", + "level": "ERROR", + "msg": "http request failed", + "http.method": "GET", + "http.url": "https://api.example.com/v1/health", + "http.duration_ms": 50.10, + "error.message": "dial tcp 10.0.0.1:443: connect: connection refused" +} +``` + +### 5.4 Example JSON Log Lines — Nested style + +**Request started:** + +```json +{ + "@timestamp": "2026-03-07T12:00:00.000Z", + "log": { "level": "INFO" }, + "message": "http request started", + "http": { + "request": { + "method": "POST", + "body": { "bytes": 512 }, + "id": "abc-123" + } + }, + "url": { + "full": "https://api.example.com/v1/orders", + "path": "/v1/orders", + "domain": "api.example.com", + "scheme": "https" + }, + "user_agent": { + "original": "Go-http-client/1.1" + } +} +``` + +**Request completed (success):** + +```json +{ + "@timestamp": "2026-03-07T12:00:00.150Z", + "log": { "level": "INFO" }, + "message": "http request completed", + "http": { + "request": { "method": "POST" }, + "response": { + "status_code": 201, + "body": { "bytes": 128 } + } + }, + "url": { "full": "https://api.example.com/v1/orders" }, + "event": { "duration": 150.32 } +} +``` + +**Request completed (error):** + +```json +{ + "@timestamp": "2026-03-07T12:00:00.050Z", + "log": { "level": "ERROR" }, + "message": "http request failed", + "http": { + "request": { "method": "GET" } + }, + "url": { "full": "https://api.example.com/v1/health" }, + "event": { "duration": 50.10 }, + "error": { "message": "dial tcp 10.0.0.1:443: connect: connection refused" } +} +``` + +### 5.5 Example logfmt Log Lines + +logfmt uses space-separated `key=value` pairs. String values containing spaces are quoted. This format is natively parseable by Grafana Loki, Heroku Logplex, and most log aggregation pipelines. + +**Request started:** + +``` +timestamp=2026-03-07T12:00:00.000Z level=INFO msg="http request started" http.method=POST http.url="https://api.example.com/v1/orders" http.target="/v1/orders" http.host=api.example.com http.scheme=https http.request_content_length=512 user_agent.original="Go-http-client/1.1" +``` + +**Request completed (success):** + +``` +timestamp=2026-03-07T12:00:00.150Z level=INFO msg="http request completed" http.method=POST http.url="https://api.example.com/v1/orders" http.status_code=201 http.response_content_length=128 http.duration_ms=150.32 +``` + +**Request completed (error):** + +``` +timestamp=2026-03-07T12:00:00.050Z level=ERROR msg="http request failed" http.method=GET http.url="https://api.example.com/v1/health" http.duration_ms=50.10 error.message="dial tcp 10.0.0.1:443: connect: connection refused" +``` + +### 5.6 Example Text Log Line (development mode) + +``` +2026-03-07T12:00:00.150Z INFO http request completed POST https://api.example.com/v1/orders 201 150.32ms +2026-03-07T12:00:00.050Z ERROR http request failed GET https://api.example.com/v1/health — 50.10ms error="connection refused" +``` + +## 6. Public API + +All new code lives in the `interceptors` sub-package (`interceptors/logging.go`), consistent with the existing `auth.go` and `headers.go` placement. + +### 6.1 Types + +```go +// LogFormat controls the log output format. +type LogFormat int + +const ( + LogFormatJSON LogFormat = iota // Structured JSON (default) + LogFormatLogfmt // logfmt key=value pairs + LogFormatText // Human-readable plain text +) + +// KeyStyle controls the JSON key naming convention. +type KeyStyle int + +const ( + // KeyStyleFlat uses dot notation for keys (e.g. "http.method", + // "http.status_code"). Field names follow OpenTelemetry HTTP semantic + // conventions. Compatible with Datadog, Splunk, Grafana Loki, CloudWatch. + // This is the default. + KeyStyleFlat KeyStyle = iota + + // KeyStyleNested uses hierarchical JSON objects (e.g. + // {"http": {"request": {"method": "POST"}}}). Field structure follows + // the Elastic Common Schema. Compatible with Elasticsearch and Kibana. + KeyStyleNested +) + +// LoggingOptions configures the LoggingInterceptor. +type LoggingOptions struct { + // Logger is an *slog.Logger instance. If nil, slog.Default() is used. + Logger *slog.Logger + + // Format selects the output format. Default: LogFormatJSON. + Format LogFormat + + // KeyStyle selects the JSON key naming convention. Only applies when + // Format is LogFormatJSON. Default: KeyStyleFlat. + KeyStyle KeyStyle + + // LogBody enables request/response body capture up to MaxBodyLogSize. + // Disabled by default for security and performance. + LogBody bool + + // MaxBodyLogSize is the maximum number of bytes to capture from the + // request or response body when LogBody is true. Default: 1024. + MaxBodyLogSize int + + // HeadersToLog is an explicit allowlist of header names to include in + // log entries. Empty means no headers are logged beyond the defaults + // defined in section 5. Useful for capturing correlation IDs. + HeadersToLog []string + + // SensitiveHeaders lists header names whose values should be redacted + // (replaced with "***") when logged. Default: ["Authorization", "Cookie", + // "Set-Cookie"]. + SensitiveHeaders []string +} +``` + +### 6.2 Constructor + +```go +// LoggingInterceptor returns an InterceptorFunc that logs HTTP request and +// response details. +// +// interceptor.NewTransportInterceptor(nil, +// interceptors.LoggingInterceptor(nil), // default options +// ) +// +// // Nested keys for Elasticsearch: +// interceptors.LoggingInterceptor(&interceptors.LoggingOptions{ +// KeyStyle: interceptors.KeyStyleNested, +// }) +// +// // logfmt for Grafana Loki: +// interceptors.LoggingInterceptor(&interceptors.LoggingOptions{ +// Format: interceptors.LogFormatLogfmt, +// }) +// +// // Text for local development with body logging: +// interceptors.LoggingInterceptor(&interceptors.LoggingOptions{ +// Format: interceptors.LogFormatText, +// LogBody: true, +// }) +func LoggingInterceptor(opts *LoggingOptions) interceptor.InterceptorFunc +``` + +When `opts` is `nil`, the interceptor uses all default values (JSON format, flat key style, `slog.Default()`, no body logging, 1024-byte body limit). + +### 6.3 Format Comparison + +| Feature | JSON | logfmt | Text | +|---|---|---|---| +| Machine-parseable | Yes | Yes | No | +| Human-readable | Moderate | Good | Best | +| Native support | Elasticsearch, Datadog, Splunk, CloudWatch | Grafana Loki, Heroku, Prometheus | Terminal / local dev | +| Go slog handler | `slog.NewJSONHandler` | Custom formatter (std lib only) | `slog.NewTextHandler` | +| Recommended for | Production, log aggregation | Production, Kubernetes/cloud-native | Local development | + +## 7. Behavior Specification + +1. **Before calling `next`**: log a `"http request started"` entry at `INFO` level with all request fields from section 5.1. +2. **Record `time.Now()`** immediately before calling `next(req)`. +3. **After `next` returns**: compute duration and log a completion entry. + - If `err != nil`: log at `ERROR` level with `"http request failed"` message and the `error.message` field. + - If `resp.StatusCode >= 500`: log at `ERROR` level. + - If `resp.StatusCode >= 400`: log at `WARN` level. + - Otherwise: log at `INFO` level. +4. **Body logging** (opt-in): wrap `req.Body` and `resp.Body` with a `io.TeeReader` capped at `MaxBodyLogSize` bytes. Truncated bodies append `"...(truncated)"`. The original body streams remain intact for downstream consumers. +5. **Sensitive header redaction**: any header in `SensitiveHeaders` has its value replaced with `"***"` in the log output. +6. **Request cloning**: the interceptor MUST NOT mutate the original request. Follow the same `req.Clone(req.Context())` pattern used by the existing `HeaderInterceptor` and `BasicAuthInterceptor`. +7. **Thread safety**: the interceptor must be safe for concurrent use across goroutines sharing the same `http.Client`. + +## 8. File Structure + +``` +interceptors/ +├── auth.go # existing +├── auth_test.go # existing +├── headers.go # existing +├── headers_test.go # existing +├── logging.go # NEW — LoggingInterceptor + LoggingOptions +└── logging_test.go # NEW — tests +``` + +No new Go modules or dependencies are introduced. The implementation uses only `log/slog`, `time`, `io`, `bytes`, `fmt`, and `net/http` from the standard library. + +## 9. Test Plan + +### 9.1 Unit Tests (`interceptors/logging_test.go`) + +| Test Case | Description | +|---|---| +| `TestLoggingInterceptor_JSON_FlatKeys` | Verifies JSON output with flat dotted keys (`http.method`) contains all required fields for a successful 200 response. | +| `TestLoggingInterceptor_JSON_NestedKeys` | Verifies JSON output with nested keys (`http.request.method`) produces correct object hierarchy and uses `@timestamp` and `message` fields. | +| `TestLoggingInterceptor_LogfmtFormat` | Verifies logfmt output contains all required `key=value` pairs and properly quotes values with spaces. | +| `TestLoggingInterceptor_TextFormat` | Verifies text-format output for a successful request. | +| `TestLoggingInterceptor_StatusLevels` | Table-driven test covering 2xx → INFO, 4xx → WARN, 5xx → ERROR level mapping. | +| `TestLoggingInterceptor_TransportError` | Simulates a connection failure and asserts `error.message` is present at ERROR level. | +| `TestLoggingInterceptor_Duration` | Asserts `http.duration_ms` is a positive number within a reasonable tolerance. | +| `TestLoggingInterceptor_BodyLogging` | Enables `LogBody`, sends a request with a known body, and asserts the body content appears in the log and remains readable by downstream consumers. | +| `TestLoggingInterceptor_BodyTruncation` | Sends a body larger than `MaxBodyLogSize` and asserts truncation with `"...(truncated)"`. | +| `TestLoggingInterceptor_SensitiveHeaderRedaction` | Sends `Authorization` and `Cookie` headers and asserts their values are replaced with `"***"`. | +| `TestLoggingInterceptor_CustomHeaders` | Uses `HeadersToLog` to include `X-Request-ID` and asserts it appears in the output. | +| `TestLoggingInterceptor_NilOptions` | Passes `nil` and asserts defaults are applied without panic. | +| `TestLoggingInterceptor_ChainPosition` | Places the logging interceptor in a chain with `HeaderInterceptor` and `BasicAuthInterceptor` and asserts all three execute correctly. | +| `TestLoggingInterceptor_Concurrent` | Fires 50 concurrent requests through the interceptor and asserts no race conditions (run with `-race`). | + +### 9.2 Test Approach + +All tests use `httptest.NewServer` to create ephemeral HTTP servers (same pattern as existing tests in the repository). Log output is captured by injecting a custom `*slog.Logger` that writes to a `bytes.Buffer`, enabling assertion on exact field values without relying on stdout capture. + +## 10. Documentation Updates + +- **README.md**: add `LoggingInterceptor` to the "Built-in interceptors" table and include a usage example in the "Usage" section. +- **Go doc comments**: every exported type, constant, and function receives a doc comment following Go conventions. + +## 11. Acceptance Criteria + +1. `go test ./... -race` passes with all new tests green. +2. JSON log output with `KeyStyleFlat` (default) is parseable by `encoding/json.Unmarshal` into a flat map and contains every field listed in section 5.1/5.2 using dotted keys. +3. JSON log output with `KeyStyleNested` is parseable by `encoding/json.Unmarshal` into nested objects following the field structure shown in section 5.4. +4. logfmt log output produces valid `key=value` pairs parseable by standard logfmt libraries, with proper quoting of values containing spaces. +5. Text log output matches the format shown in section 5.6. +6. Body logging is disabled by default and does not impact performance when off. +7. Sensitive headers are redacted by default. +8. No new external dependencies are introduced (`go.mod` remains unchanged). +9. The interceptor is composable — it works correctly at any position in the chain. + +## 12. Future Considerations + +- **Sampling**: add a `SampleRate float64` option to log only a percentage of requests in high-throughput environments. +- **Conditional logging**: add a `ShouldLog func(*http.Request) bool` predicate to skip logging for health-check endpoints or internal traffic. +- **Metrics interceptor**: a separate `MetricsInterceptor` could share duration computation utilities with this logging interceptor. +- **Trace context**: log `trace_id` and `span_id` fields when OpenTelemetry context is present in the request. diff --git a/interceptors/logging.go b/interceptors/logging.go new file mode 100644 index 0000000..95e5e02 --- /dev/null +++ b/interceptors/logging.go @@ -0,0 +1,488 @@ +package interceptors + +import ( + "encoding/json" + "fmt" + "log/slog" + "net/http" + "net/textproto" + "sort" + "strconv" + "strings" + "time" + + "github.com/fervbmx/interceptor" +) + +var defaultSensitiveHeaders = []string{ + "Authorization", + "Cookie", + "Set-Cookie", +} + +// LogFormat controls the log output format. +type LogFormat int + +const ( + // LogFormatJSON writes structured JSON logs. + LogFormatJSON LogFormat = iota + // LogFormatLogfmt writes logs in key=value format. + LogFormatLogfmt + // LogFormatText writes human-readable plain text logs. + LogFormatText +) + +// KeyStyle controls the JSON key naming convention. +type KeyStyle int + +const ( + // KeyStyleFlat uses dotted keys like "http.method". + KeyStyleFlat KeyStyle = iota + // KeyStyleNested uses nested objects like "http.request.method". + KeyStyleNested +) + +// LoggingOptions configures LoggingInterceptor behavior. +type LoggingOptions struct { + // Logger receives rendered log lines. + // If nil, slog.Default() is used. + Logger *slog.Logger + + // Format selects log rendering format. + // Default: LogFormatJSON. + Format LogFormat + + // KeyStyle chooses JSON key style when Format is LogFormatJSON. + // Default: KeyStyleFlat. + KeyStyle KeyStyle + + // HeadersToLog is a request header allowlist. + // Empty means no additional headers are logged. + HeadersToLog []string + + // SensitiveHeaders lists header names to redact as "***". + // Defaults to Authorization, Cookie, and Set-Cookie. + SensitiveHeaders []string +} + +type loggingConfig struct { + logger *slog.Logger + format LogFormat + keyStyle KeyStyle + headersToLog map[string]struct{} + sensitiveHeaders map[string]struct{} +} + +type eventData struct { + timestamp time.Time + level slog.Level + message string + method string + url string + target string + host string + scheme string + statusCode *int + durationMS *float64 + userAgent string + requestID string + errorMessage string + requestContentLength *int64 + responseContentLength *int64 + requestHeaders map[string]string +} + +// LoggingInterceptor returns an interceptor that logs request lifecycle events. +func LoggingInterceptor(opts *LoggingOptions) interceptor.InterceptorFunc { + cfg := buildLoggingConfig(opts) + + return func(req *http.Request, next interceptor.HandlerFunc) (*http.Response, error) { + clonedReq := req.Clone(req.Context()) + + startEvent := buildStartEvent(clonedReq, cfg) + emitLog(clonedReq, cfg, startEvent) + + start := time.Now() + resp, err := next(clonedReq) + duration := time.Since(start) + + endEvent := buildEndEvent(clonedReq, resp, err, duration) + emitLog(clonedReq, cfg, endEvent) + + return resp, err + } +} + +func buildLoggingConfig(opts *LoggingOptions) loggingConfig { + cfg := loggingConfig{ + logger: slog.Default(), + format: LogFormatJSON, + keyStyle: KeyStyleFlat, + headersToLog: make(map[string]struct{}), + sensitiveHeaders: canonicalHeaderSet(defaultSensitiveHeaders), + } + + if opts == nil { + return cfg + } + + if opts.Logger != nil { + cfg.logger = opts.Logger + } + + if opts.Format != 0 { + cfg.format = opts.Format + } + + if opts.KeyStyle != 0 { + cfg.keyStyle = opts.KeyStyle + } + + if len(opts.HeadersToLog) > 0 { + cfg.headersToLog = canonicalHeaderSet(opts.HeadersToLog) + } + + if len(opts.SensitiveHeaders) > 0 { + cfg.sensitiveHeaders = canonicalHeaderSet(opts.SensitiveHeaders) + } + + return cfg +} + +func canonicalHeaderSet(headers []string) map[string]struct{} { + set := make(map[string]struct{}, len(headers)) + for _, h := range headers { + set[textproto.CanonicalMIMEHeaderKey(h)] = struct{}{} + } + return set +} + +func buildStartEvent(req *http.Request, cfg loggingConfig) eventData { + e := eventData{ + timestamp: time.Now().UTC(), + level: slog.LevelInfo, + message: "http request started", + method: req.Method, + url: req.URL.String(), + target: req.URL.RequestURI(), + host: req.URL.Hostname(), + scheme: req.URL.Scheme, + userAgent: req.Header.Get("User-Agent"), + requestID: req.Header.Get("X-Request-ID"), + requestHeaders: extractAllowedHeaders(req.Header, cfg.headersToLog, cfg.sensitiveHeaders), + } + + if req.ContentLength >= 0 { + e.requestContentLength = &req.ContentLength + } + + return e +} + +func buildEndEvent(req *http.Request, resp *http.Response, err error, duration time.Duration) eventData { + ms := float64(duration) / float64(time.Millisecond) + e := eventData{ + timestamp: time.Now().UTC(), + level: getLogLevel(resp, err), + method: req.Method, + url: req.URL.String(), + durationMS: &ms, + } + + if err != nil { + e.message = "http request failed" + e.errorMessage = err.Error() + return e + } + + e.message = "http request completed" + if resp != nil { + e.statusCode = &resp.StatusCode + if req.ContentLength >= 0 { + e.requestContentLength = &req.ContentLength + } + } + + return e +} + +func getLogLevel(resp *http.Response, err error) slog.Level { + if err != nil { + return slog.LevelError + } + if resp == nil { + return slog.LevelError + } + if resp.StatusCode >= http.StatusInternalServerError { + return slog.LevelError + } + if resp.StatusCode >= http.StatusBadRequest { + return slog.LevelWarn + } + return slog.LevelInfo +} + +func emitLog(req *http.Request, cfg loggingConfig, event eventData) { + line := renderEvent(cfg, event) + cfg.logger.Log(req.Context(), event.level, line) +} + +func renderEvent(cfg loggingConfig, event eventData) string { + switch cfg.format { + case LogFormatLogfmt: + return renderLogfmt(event) + case LogFormatText: + return renderText(event) + default: + if cfg.keyStyle == KeyStyleNested { + return renderJSONNested(event) + } + return renderJSONFlat(event) + } +} + +func renderJSONFlat(event eventData) string { + payload := map[string]any{ + "timestamp": event.timestamp.Format(time.RFC3339Nano), + "level": strings.ToUpper(event.level.String()), + "msg": event.message, + "http.method": event.method, + "http.url": event.url, + } + + if event.target != "" { + payload["http.target"] = event.target + } + if event.host != "" { + payload["http.host"] = event.host + } + if event.scheme != "" { + payload["http.scheme"] = event.scheme + } + if event.requestContentLength != nil { + payload["http.request_content_length"] = *event.requestContentLength + } + if event.responseContentLength != nil { + payload["http.response_content_length"] = *event.responseContentLength + } + if event.statusCode != nil { + payload["http.status_code"] = *event.statusCode + } + if event.durationMS != nil { + payload["http.duration_ms"] = *event.durationMS + } + if event.userAgent != "" { + payload["user_agent.original"] = event.userAgent + } + if event.requestID != "" { + payload["http.request_id"] = event.requestID + } + if event.errorMessage != "" { + payload["error.message"] = event.errorMessage + } + if len(event.requestHeaders) > 0 { + payload["http.request.headers"] = event.requestHeaders + } + + b, err := json.Marshal(payload) + if err != nil { + return "{}" + } + return string(b) +} + +func renderJSONNested(event eventData) string { + payload := map[string]any{ + "@timestamp": event.timestamp.Format(time.RFC3339Nano), + "log": map[string]any{ + "level": strings.ToUpper(event.level.String()), + }, + "message": event.message, + "http": map[string]any{ + "request": map[string]any{ + "method": event.method, + }, + }, + "url": map[string]any{ + "full": event.url, + }, + } + + httpMap := payload["http"].(map[string]any) + requestMap := httpMap["request"].(map[string]any) + urlMap := payload["url"].(map[string]any) + + if event.target != "" { + urlMap["path"] = event.target + } + if event.host != "" { + urlMap["domain"] = event.host + } + if event.scheme != "" { + urlMap["scheme"] = event.scheme + } + if event.requestContentLength != nil { + requestMap["body"] = map[string]any{"bytes": *event.requestContentLength} + } + if event.requestID != "" { + requestMap["id"] = event.requestID + } + if event.userAgent != "" { + payload["user_agent"] = map[string]any{"original": event.userAgent} + } + if event.statusCode != nil { + httpMap["response"] = map[string]any{"status_code": *event.statusCode} + } + if event.responseContentLength != nil { + responseMap, ok := httpMap["response"].(map[string]any) + if !ok { + responseMap = map[string]any{} + httpMap["response"] = responseMap + } + responseMap["body"] = map[string]any{"bytes": *event.responseContentLength} + } + if event.durationMS != nil { + payload["event"] = map[string]any{"duration": *event.durationMS} + } + if event.errorMessage != "" { + payload["error"] = map[string]any{"message": event.errorMessage} + } + if len(event.requestHeaders) > 0 { + requestMap["headers"] = event.requestHeaders + } + + b, err := json.Marshal(payload) + if err != nil { + return "{}" + } + return string(b) +} + +func renderLogfmt(event eventData) string { + parts := []string{ + "timestamp=" + encodeLogfmtValue(event.timestamp.Format(time.RFC3339Nano)), + "level=" + encodeLogfmtValue(strings.ToUpper(event.level.String())), + "msg=" + encodeLogfmtValue(event.message), + "http.method=" + encodeLogfmtValue(event.method), + "http.url=" + encodeLogfmtValue(event.url), + } + + if event.target != "" { + parts = append(parts, "http.target="+encodeLogfmtValue(event.target)) + } + if event.host != "" { + parts = append(parts, "http.host="+encodeLogfmtValue(event.host)) + } + if event.scheme != "" { + parts = append(parts, "http.scheme="+encodeLogfmtValue(event.scheme)) + } + if event.requestContentLength != nil { + parts = append(parts, "http.request_content_length="+strconv.FormatInt(*event.requestContentLength, 10)) + } + if event.responseContentLength != nil { + parts = append(parts, "http.response_content_length="+strconv.FormatInt(*event.responseContentLength, 10)) + } + if event.statusCode != nil { + parts = append(parts, "http.status_code="+strconv.Itoa(*event.statusCode)) + } + if event.durationMS != nil { + parts = append(parts, "http.duration_ms="+strconv.FormatFloat(*event.durationMS, 'f', 3, 64)) + } + if event.userAgent != "" { + parts = append(parts, "user_agent.original="+encodeLogfmtValue(event.userAgent)) + } + if event.requestID != "" { + parts = append(parts, "http.request_id="+encodeLogfmtValue(event.requestID)) + } + if event.errorMessage != "" { + parts = append(parts, "error.message="+encodeLogfmtValue(event.errorMessage)) + } + + if len(event.requestHeaders) > 0 { + headerKeys := make([]string, 0, len(event.requestHeaders)) + for k := range event.requestHeaders { + headerKeys = append(headerKeys, k) + } + sort.Strings(headerKeys) + for _, key := range headerKeys { + parts = append(parts, "http.request.header."+sanitizeHeaderFieldKey(key)+"="+encodeLogfmtValue(event.requestHeaders[key])) + } + } + + return strings.Join(parts, " ") +} + +func renderText(event eventData) string { + duration := "" + if event.durationMS != nil { + duration = fmt.Sprintf(" %.2fms", *event.durationMS) + } + + status := "" + if event.statusCode != nil { + status = fmt.Sprintf(" %d", *event.statusCode) + } + + line := fmt.Sprintf( + "%s %s %s %s %s%s%s", + event.timestamp.Format(time.RFC3339Nano), + strings.ToUpper(event.level.String()), + event.message, + event.method, + event.url, + status, + duration, + ) + + if event.errorMessage != "" { + line += fmt.Sprintf(" error=%q", event.errorMessage) + } + + return line +} + +func encodeLogfmtValue(value string) string { + if value == "" { + return "\"\"" + } + + if strings.ContainsAny(value, " \t\n\r\"=") { + replacer := strings.NewReplacer("\\", "\\\\", "\"", "\\\"") + return "\"" + replacer.Replace(value) + "\"" + } + + return value +} + +func sanitizeHeaderFieldKey(key string) string { + key = strings.ToLower(key) + key = strings.ReplaceAll(key, "-", "_") + return key +} + +func extractAllowedHeaders(headers http.Header, allowlist, sensitive map[string]struct{}) map[string]string { + if len(allowlist) == 0 { + return nil + } + + loggedHeaders := make(map[string]string) + for header := range allowlist { + value := headers.Get(header) + if value == "" { + continue + } + + if _, redact := sensitive[textproto.CanonicalMIMEHeaderKey(header)]; redact { + loggedHeaders[header] = "***" + continue + } + + loggedHeaders[header] = value + } + + if len(loggedHeaders) == 0 { + return nil + } + + return loggedHeaders +} diff --git a/interceptors/logging_test.go b/interceptors/logging_test.go new file mode 100644 index 0000000..47ed4ce --- /dev/null +++ b/interceptors/logging_test.go @@ -0,0 +1,545 @@ +package interceptors_test + +import ( + "context" + "encoding/json" + "errors" + "io" + "log/slog" + "net/http" + "net/http/httptest" + "strings" + "sync" + "testing" + "time" + + "github.com/fervbmx/interceptor" + "github.com/fervbmx/interceptor/interceptors" +) + +type capturedRecord struct { + level slog.Level + msg string +} + +type captureHandler struct { + mu sync.Mutex + records []capturedRecord +} + +func (h *captureHandler) Enabled(_ context.Context, _ slog.Level) bool { return true } + +func (h *captureHandler) Handle(_ context.Context, r slog.Record) error { + h.mu.Lock() + defer h.mu.Unlock() + h.records = append(h.records, capturedRecord{level: r.Level, msg: r.Message}) + return nil +} + +func (h *captureHandler) WithAttrs(_ []slog.Attr) slog.Handler { return h } + +func (h *captureHandler) WithGroup(_ string) slog.Handler { return h } + +func (h *captureHandler) snapshot() []capturedRecord { + h.mu.Lock() + defer h.mu.Unlock() + out := make([]capturedRecord, len(h.records)) + copy(out, h.records) + return out +} + +func newCaptureLogger() (*slog.Logger, *captureHandler) { + h := &captureHandler{} + return slog.New(h), h +} + +func TestLoggingInterceptor_JSON_FlatKeys(t *testing.T) { + logger, sink := newCaptureLogger() + + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header().Set("Content-Type", "application/json") + w.WriteHeader(http.StatusOK) + _, _ = w.Write([]byte(`{"ok":true}`)) + })) + t.Cleanup(server.Close) + + client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, + interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + )} + + req, err := http.NewRequest(http.MethodGet, server.URL+"/v1/users?page=2", nil) + if err != nil { + t.Fatalf("http.NewRequest error: %v", err) + } + req.Header.Set("User-Agent", "interceptor-tests/1.0") + req.Header.Set("X-Request-ID", "abc-123") + + resp, err := client.Do(req) + if err != nil { + t.Fatalf("client.Do error: %v", err) + } + _ = resp.Body.Close() + + records := sink.snapshot() + if len(records) != 2 { + t.Fatalf("len(records) = %d, want 2", len(records)) + } + + start := decodeJSONMap(t, records[0].msg) + if start["http.method"] != http.MethodGet { + t.Fatalf("http.method = %v, want %q", start["http.method"], http.MethodGet) + } + if start["http.url"] != server.URL+"/v1/users?page=2" { + t.Fatalf("http.url = %v", start["http.url"]) + } + if start["http.target"] != "/v1/users?page=2" { + t.Fatalf("http.target = %v", start["http.target"]) + } + if start["http.request_id"] != "abc-123" { + t.Fatalf("http.request_id = %v", start["http.request_id"]) + } + + finish := decodeJSONMap(t, records[1].msg) + if finish["http.status_code"] != float64(http.StatusOK) { + t.Fatalf("http.status_code = %v, want %d", finish["http.status_code"], http.StatusOK) + } + if _, ok := finish["http.duration_ms"]; !ok { + t.Fatal("http.duration_ms missing") + } +} + +func TestLoggingInterceptor_JSON_NestedKeys(t *testing.T) { + logger, sink := newCaptureLogger() + + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusCreated) + _, _ = w.Write([]byte("ok")) + })) + t.Cleanup(server.Close) + + client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, + interceptors.LoggingInterceptor(&interceptors.LoggingOptions{ + Logger: logger, + Format: interceptors.LogFormatJSON, + KeyStyle: interceptors.KeyStyleNested, + }), + )} + + resp, err := client.Post(server.URL+"/v1/orders", "text/plain", strings.NewReader("payload")) + if err != nil { + t.Fatalf("client.Post error: %v", err) + } + _ = resp.Body.Close() + + records := sink.snapshot() + if len(records) != 2 { + t.Fatalf("len(records) = %d, want 2", len(records)) + } + + start := decodeJSONMap(t, records[0].msg) + if _, ok := start["@timestamp"]; !ok { + t.Fatal("@timestamp missing") + } + if start["message"] != "http request started" { + t.Fatalf("message = %v", start["message"]) + } + + httpMap := start["http"].(map[string]any) + requestMap := httpMap["request"].(map[string]any) + if requestMap["method"] != http.MethodPost { + t.Fatalf("http.request.method = %v", requestMap["method"]) + } +} + +func TestLoggingInterceptor_LogfmtFormat(t *testing.T) { + logger, sink := newCaptureLogger() + + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + })) + t.Cleanup(server.Close) + + client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, + interceptors.LoggingInterceptor(&interceptors.LoggingOptions{ + Logger: logger, + Format: interceptors.LogFormatLogfmt, + }), + )} + + req, err := http.NewRequest(http.MethodGet, server.URL+"/q with space", nil) + if err != nil { + t.Fatalf("http.NewRequest error: %v", err) + } + + resp, err := client.Do(req) + if err != nil { + t.Fatalf("client.Do error: %v", err) + } + _ = resp.Body.Close() + + records := sink.snapshot() + if len(records) != 2 { + t.Fatalf("len(records) = %d, want 2", len(records)) + } + + line := records[0].msg + if !strings.Contains(line, "level=INFO") { + t.Fatalf("line missing level=INFO: %s", line) + } + if !strings.Contains(line, "msg=\"http request started\"") { + t.Fatalf("line missing quoted msg: %s", line) + } + if !strings.Contains(line, "http.url=") { + t.Fatalf("line missing http.url: %s", line) + } +} + +func TestLoggingInterceptor_TextFormat(t *testing.T) { + logger, sink := newCaptureLogger() + + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusNoContent) + })) + t.Cleanup(server.Close) + + client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, + interceptors.LoggingInterceptor(&interceptors.LoggingOptions{ + Logger: logger, + Format: interceptors.LogFormatText, + }), + )} + + resp, err := client.Get(server.URL) + if err != nil { + t.Fatalf("client.Get error: %v", err) + } + _ = resp.Body.Close() + + records := sink.snapshot() + if len(records) != 2 { + t.Fatalf("len(records) = %d, want 2", len(records)) + } + + line := records[1].msg + if !strings.Contains(line, "http request completed") { + t.Fatalf("line missing completion message: %s", line) + } + if !strings.Contains(line, "GET") { + t.Fatalf("line missing method: %s", line) + } + if !strings.Contains(line, "204") { + t.Fatalf("line missing status code: %s", line) + } +} + +func TestLoggingInterceptor_StatusLevels(t *testing.T) { + cases := []struct { + name string + status int + wantLevel slog.Level + }{ + {name: "2xx", status: http.StatusOK, wantLevel: slog.LevelInfo}, + {name: "4xx", status: http.StatusNotFound, wantLevel: slog.LevelWarn}, + {name: "5xx", status: http.StatusBadGateway, wantLevel: slog.LevelError}, + } + + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + logger, sink := newCaptureLogger() + + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(tc.status) + })) + t.Cleanup(server.Close) + + client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, + interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + )} + + resp, err := client.Get(server.URL) + if err != nil { + t.Fatalf("client.Get error: %v", err) + } + _ = resp.Body.Close() + + records := sink.snapshot() + if got := records[len(records)-1].level; got != tc.wantLevel { + t.Fatalf("final level = %v, want %v", got, tc.wantLevel) + } + }) + } +} + +func TestLoggingInterceptor_TransportError(t *testing.T) { + logger, sink := newCaptureLogger() + + transport := interceptor.NewTransportInterceptor(roundTripperFunc(func(req *http.Request) (*http.Response, error) { + return nil, errors.New("dial tcp: connection refused") + }), interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger})) + + client := &http.Client{Transport: transport} + _, err := client.Get("http://example.com") + if err == nil { + t.Fatal("expected error, got nil") + } + + records := sink.snapshot() + if len(records) != 2 { + t.Fatalf("len(records) = %d, want 2", len(records)) + } + + finish := decodeJSONMap(t, records[1].msg) + if finish["error.message"] == nil { + t.Fatalf("error.message missing: %v", finish) + } + if records[1].level != slog.LevelError { + t.Fatalf("level = %v, want ERROR", records[1].level) + } +} + +func TestLoggingInterceptor_Duration(t *testing.T) { + logger, sink := newCaptureLogger() + + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + time.Sleep(10 * time.Millisecond) + w.WriteHeader(http.StatusOK) + })) + t.Cleanup(server.Close) + + client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, + interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + )} + + resp, err := client.Get(server.URL) + if err != nil { + t.Fatalf("client.Get error: %v", err) + } + _ = resp.Body.Close() + + records := sink.snapshot() + finish := decodeJSONMap(t, records[1].msg) + duration, ok := finish["http.duration_ms"].(float64) + if !ok { + t.Fatalf("http.duration_ms has unexpected type: %T", finish["http.duration_ms"]) + } + if duration <= 0 { + t.Fatalf("http.duration_ms = %v, want > 0", duration) + } +} + +func TestLoggingInterceptor_SensitiveHeaderRedaction(t *testing.T) { + logger, sink := newCaptureLogger() + + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + })) + t.Cleanup(server.Close) + + client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, + interceptors.LoggingInterceptor(&interceptors.LoggingOptions{ + Logger: logger, + HeadersToLog: []string{"Authorization", "Cookie"}, + }), + )} + + req, _ := http.NewRequest(http.MethodGet, server.URL, nil) + req.Header.Set("Authorization", "Bearer top-secret") + req.Header.Set("Cookie", "session=secret") + + resp, err := client.Do(req) + if err != nil { + t.Fatalf("client.Do error: %v", err) + } + _ = resp.Body.Close() + + start := decodeJSONMap(t, sink.snapshot()[0].msg) + headers := start["http.request.headers"].(map[string]any) + if headers["Authorization"] != "***" { + t.Fatalf("Authorization = %v, want ***", headers["Authorization"]) + } + if headers["Cookie"] != "***" { + t.Fatalf("Cookie = %v, want ***", headers["Cookie"]) + } +} + +func TestLoggingInterceptor_CustomHeaders(t *testing.T) { + logger, sink := newCaptureLogger() + + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + })) + t.Cleanup(server.Close) + + client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, + interceptors.LoggingInterceptor(&interceptors.LoggingOptions{ + Logger: logger, + HeadersToLog: []string{"X-Correlation-ID"}, + }), + )} + + req, _ := http.NewRequest(http.MethodGet, server.URL, nil) + req.Header.Set("X-Correlation-ID", "corr-1") + + resp, err := client.Do(req) + if err != nil { + t.Fatalf("client.Do error: %v", err) + } + _ = resp.Body.Close() + + start := decodeJSONMap(t, sink.snapshot()[0].msg) + headers := start["http.request.headers"].(map[string]any) + if headers["X-Correlation-Id"] != "corr-1" { + t.Fatalf("X-Correlation-Id = %v, want corr-1", headers["X-Correlation-Id"]) + } +} + +func TestLoggingInterceptor_NilOptions(t *testing.T) { + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + })) + t.Cleanup(server.Close) + + client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, + interceptors.LoggingInterceptor(nil), + )} + + resp, err := client.Get(server.URL) + if err != nil { + t.Fatalf("client.Get error: %v", err) + } + _ = resp.Body.Close() +} + +func TestLoggingInterceptor_ChainPosition(t *testing.T) { + logger, sink := newCaptureLogger() + + var gotAuth string + var gotHeader string + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + gotAuth = r.Header.Get("Authorization") + gotHeader = r.Header.Get("X-Req-Id") + w.WriteHeader(http.StatusOK) + })) + t.Cleanup(server.Close) + + client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, + interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + interceptors.HeaderInterceptor("X-Req-Id", "req-1"), + interceptors.BasicAuthInterceptor("user", "pass"), + )} + + resp, err := client.Get(server.URL) + if err != nil { + t.Fatalf("client.Get error: %v", err) + } + _ = resp.Body.Close() + + if gotAuth == "" { + t.Fatal("Authorization header missing") + } + if gotHeader != "req-1" { + t.Fatalf("X-Req-Id = %q, want req-1", gotHeader) + } + if len(sink.snapshot()) != 2 { + t.Fatal("expected two logging events") + } +} + +func TestLoggingInterceptor_Concurrent(t *testing.T) { + logger, sink := newCaptureLogger() + + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + })) + t.Cleanup(server.Close) + + client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, + interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + )} + + const total = 50 + var wg sync.WaitGroup + for i := 0; i < total; i++ { + wg.Add(1) + go func() { + defer wg.Done() + resp, err := client.Get(server.URL) + if err == nil { + _ = resp.Body.Close() + } + }() + } + wg.Wait() + + records := sink.snapshot() + if len(records) != total*2 { + t.Fatalf("len(records) = %d, want %d", len(records), total*2) + } +} + +func TestLoggingInterceptor_RequestImmutability(t *testing.T) { + logger, _ := newCaptureLogger() + + originalReq, err := http.NewRequest(http.MethodPost, "http://example.com/v1/items", strings.NewReader("immutable-payload")) + if err != nil { + t.Fatalf("http.NewRequest error: %v", err) + } + originalReq.Header.Set("X-Original", "keep") + + transport := interceptor.NewTransportInterceptor( + roundTripperFunc(func(req *http.Request) (*http.Response, error) { + if req == originalReq { + t.Fatal("downstream received original request pointer; expected clone") + } + if req.Header.Get("X-Mutated") != "yes" { + t.Fatalf("X-Mutated header = %q, want yes", req.Header.Get("X-Mutated")) + } + if req.Method != http.MethodPut { + t.Fatalf("mutated request method = %q, want %q", req.Method, http.MethodPut) + } + if req.URL.Path != "/mutated" { + t.Fatalf("mutated request path = %q, want /mutated", req.URL.Path) + } + return &http.Response{StatusCode: http.StatusOK, Body: io.NopCloser(strings.NewReader("ok"))}, nil + }), + interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + func(req *http.Request, next interceptor.HandlerFunc) (*http.Response, error) { + req.Header.Set("X-Mutated", "yes") + req.Method = http.MethodPut + req.URL.Path = "/mutated" + return next(req) + }, + ) + + client := &http.Client{Transport: transport} + resp, err := client.Do(originalReq) + if err != nil { + t.Fatalf("client.Do error: %v", err) + } + _ = resp.Body.Close() + + if got := originalReq.Header.Get("X-Mutated"); got != "" { + t.Fatalf("original request header X-Mutated = %q, want empty", got) + } + if got := originalReq.Method; got != http.MethodPost { + t.Fatalf("original request method = %q, want %q", got, http.MethodPost) + } + if got := originalReq.URL.Path; got != "/v1/items" { + t.Fatalf("original request path = %q, want /v1/items", got) + } +} + +type roundTripperFunc func(req *http.Request) (*http.Response, error) + +func (f roundTripperFunc) RoundTrip(req *http.Request) (*http.Response, error) { + return f(req) +} + +func decodeJSONMap(t *testing.T, line string) map[string]any { + t.Helper() + var out map[string]any + if err := json.Unmarshal([]byte(line), &out); err != nil { + t.Fatalf("json.Unmarshal(%q) error: %v", line, err) + } + return out +} From e9707fdb66a9f388315a8db70cf30415647ab890 Mon Sep 17 00:00:00 2001 From: Fabian Esteban Ruiz Valdes Date: Sat, 7 Mar 2026 19:48:19 -0500 Subject: [PATCH 03/19] feat(interceptors): add logging request interceptor --- PRD.md | 383 --------------------------------------------------------- 1 file changed, 383 deletions(-) delete mode 100644 PRD.md diff --git a/PRD.md b/PRD.md deleted file mode 100644 index f0e7ca4..0000000 --- a/PRD.md +++ /dev/null @@ -1,383 +0,0 @@ -# PRD: Logging Request Interceptor - -## 1. Overview - -Add a built-in `LoggingInterceptor` to the `github.com/fervbmx/interceptor` package that captures and logs HTTP request/response details using industry-standard structured logging formats. The interceptor plugs into the existing `InterceptorFunc` chain and requires zero external dependencies. - -## 2. Problem Statement - -Developers using the interceptor package currently have no built-in way to observe outgoing HTTP traffic. Debugging failed API calls, auditing third-party service communication, and measuring response latency all require writing custom one-off logging interceptors. A first-class logging interceptor would eliminate boilerplate, enforce a consistent log schema, and align with widely adopted observability practices (structured JSON logs, OpenTelemetry semantic conventions). - -## 3. Goals - -- Provide a ready-to-use interceptor that logs every outgoing HTTP request and its corresponding response (or error). -- Use **structured JSON** as the default output format (the de-facto industry standard for machine-parseable logs). -- Support **logfmt** (`key=value` pairs) — the structured-yet-readable format widely adopted by Grafana Loki, Heroku, and the Go ecosystem. -- Support a **text/plain** human-readable format for local development. -- Follow field naming conventions from **OpenTelemetry HTTP semantic conventions** and **ECS (Elastic Common Schema)** so logs integrate seamlessly with Elasticsearch, Datadog, Grafana Loki, and similar platforms. -- Allow developers to supply their own `*slog.Logger` (Go 1.21+ standard library) to control output destination and level. -- Remain a **zero-dependency** addition — rely only on the Go standard library. - -## 4. Non-Goals - -- Metric collection (histograms, counters) — that belongs in a separate `MetricsInterceptor`. -- Distributed tracing propagation (trace-id injection) — that belongs in a `TracingInterceptor`. -- Request/response body logging by default (security and performance risk); this will be opt-in only. - -## 5. Logged Fields - -The following fields MUST be present in every log entry. The interceptor supports two JSON key styles, configurable via the `KeyStyle` option: - -- **Flat / dot notation (default)**: flat dotted keys (`"http.method"`). Field names follow [OpenTelemetry HTTP semantic conventions](https://opentelemetry.io/docs/specs/semconv/http/). Best for Datadog, Splunk, Grafana Loki, CloudWatch. -- **Nested**: hierarchical JSON objects (`"http": {"request": {"method": ...}}`). Field structure follows [Elastic Common Schema](https://www.elastic.co/guide/en/ecs/current/). Best for Elasticsearch and Kibana. - -### 5.1 Request Fields (logged before `next` is called) - -| Field | Flat Key (dot notation) | Nested Key | Type | Description | Example | -|---|---|---|---|---|---| -| Timestamp | `timestamp` | `@timestamp` | string (RFC 3339) | Time the request was initiated | `2026-03-07T12:00:00.000Z` | -| Log Level | `level` | `log.level` | string | Severity level | `INFO` | -| Message | `msg` | `message` | string | Human-readable event description | `http request started` | -| HTTP Method | `http.method` | `http.request.method` | string | Request method | `GET` | -| URL | `http.url` | `url.full` | string | Full request URL | `https://api.example.com/v1/users` | -| URL Path | `http.target` | `url.path` | string | Path + query string | `/v1/users?page=2` | -| Host | `http.host` | `url.domain` | string | Host header value | `api.example.com` | -| Scheme | `http.scheme` | `url.scheme` | string | `http` or `https` | `https` | -| Request Content-Length | `http.request_content_length` | `http.request.body.bytes` | int | Body size in bytes (if known) | `256` | -| User-Agent | `user_agent.original` | `user_agent.original` | string | User-Agent header | `Go-http-client/1.1` | -| Request ID | `http.request_id` | `http.request.id` | string | Value of `X-Request-ID` header (if present) | `abc-123` | - -### 5.2 Response Fields (logged after `next` returns) - -| Field | Flat Key (dot notation) | Nested Key | Type | Description | Example | -|---|---|---|---|---|---| -| Timestamp | `timestamp` | `@timestamp` | string (RFC 3339) | Time the response was received | `2026-03-07T12:00:00.150Z` | -| Log Level | `level` | `log.level` | string | `INFO` for 1xx–3xx, `WARN` for 4xx, `ERROR` for 5xx or transport errors | `WARN` | -| Message | `msg` | `message` | string | Human-readable event description | `http request completed` | -| HTTP Method | `http.method` | `http.request.method` | string | Echoed from request | `GET` | -| URL | `http.url` | `url.full` | string | Echoed from request | `https://api.example.com/v1/users` | -| Status Code | `http.status_code` | `http.response.status_code` | int | Response status code | `404` | -| Response Content-Length | `http.response_content_length` | `http.response.body.bytes` | int | Body size in bytes (if known) | `128` | -| Duration | `http.duration_ms` | `event.duration` | float64 | Round-trip time in milliseconds | `142.56` | -| Error | `error.message` | `error.message` | string | Error text (only on transport failure) | `dial tcp: connection refused` | - -### 5.3 Example JSON Log Lines — Flat / dot notation (default) - -**Request started:** - -```json -{ - "timestamp": "2026-03-07T12:00:00.000Z", - "level": "INFO", - "msg": "http request started", - "http.method": "POST", - "http.url": "https://api.example.com/v1/orders", - "http.target": "/v1/orders", - "http.host": "api.example.com", - "http.scheme": "https", - "http.request_content_length": 512, - "user_agent.original": "Go-http-client/1.1" -} -``` - -**Request completed (success):** - -```json -{ - "timestamp": "2026-03-07T12:00:00.150Z", - "level": "INFO", - "msg": "http request completed", - "http.method": "POST", - "http.url": "https://api.example.com/v1/orders", - "http.status_code": 201, - "http.response_content_length": 128, - "http.duration_ms": 150.32 -} -``` - -**Request completed (error):** - -```json -{ - "timestamp": "2026-03-07T12:00:00.050Z", - "level": "ERROR", - "msg": "http request failed", - "http.method": "GET", - "http.url": "https://api.example.com/v1/health", - "http.duration_ms": 50.10, - "error.message": "dial tcp 10.0.0.1:443: connect: connection refused" -} -``` - -### 5.4 Example JSON Log Lines — Nested style - -**Request started:** - -```json -{ - "@timestamp": "2026-03-07T12:00:00.000Z", - "log": { "level": "INFO" }, - "message": "http request started", - "http": { - "request": { - "method": "POST", - "body": { "bytes": 512 }, - "id": "abc-123" - } - }, - "url": { - "full": "https://api.example.com/v1/orders", - "path": "/v1/orders", - "domain": "api.example.com", - "scheme": "https" - }, - "user_agent": { - "original": "Go-http-client/1.1" - } -} -``` - -**Request completed (success):** - -```json -{ - "@timestamp": "2026-03-07T12:00:00.150Z", - "log": { "level": "INFO" }, - "message": "http request completed", - "http": { - "request": { "method": "POST" }, - "response": { - "status_code": 201, - "body": { "bytes": 128 } - } - }, - "url": { "full": "https://api.example.com/v1/orders" }, - "event": { "duration": 150.32 } -} -``` - -**Request completed (error):** - -```json -{ - "@timestamp": "2026-03-07T12:00:00.050Z", - "log": { "level": "ERROR" }, - "message": "http request failed", - "http": { - "request": { "method": "GET" } - }, - "url": { "full": "https://api.example.com/v1/health" }, - "event": { "duration": 50.10 }, - "error": { "message": "dial tcp 10.0.0.1:443: connect: connection refused" } -} -``` - -### 5.5 Example logfmt Log Lines - -logfmt uses space-separated `key=value` pairs. String values containing spaces are quoted. This format is natively parseable by Grafana Loki, Heroku Logplex, and most log aggregation pipelines. - -**Request started:** - -``` -timestamp=2026-03-07T12:00:00.000Z level=INFO msg="http request started" http.method=POST http.url="https://api.example.com/v1/orders" http.target="/v1/orders" http.host=api.example.com http.scheme=https http.request_content_length=512 user_agent.original="Go-http-client/1.1" -``` - -**Request completed (success):** - -``` -timestamp=2026-03-07T12:00:00.150Z level=INFO msg="http request completed" http.method=POST http.url="https://api.example.com/v1/orders" http.status_code=201 http.response_content_length=128 http.duration_ms=150.32 -``` - -**Request completed (error):** - -``` -timestamp=2026-03-07T12:00:00.050Z level=ERROR msg="http request failed" http.method=GET http.url="https://api.example.com/v1/health" http.duration_ms=50.10 error.message="dial tcp 10.0.0.1:443: connect: connection refused" -``` - -### 5.6 Example Text Log Line (development mode) - -``` -2026-03-07T12:00:00.150Z INFO http request completed POST https://api.example.com/v1/orders 201 150.32ms -2026-03-07T12:00:00.050Z ERROR http request failed GET https://api.example.com/v1/health — 50.10ms error="connection refused" -``` - -## 6. Public API - -All new code lives in the `interceptors` sub-package (`interceptors/logging.go`), consistent with the existing `auth.go` and `headers.go` placement. - -### 6.1 Types - -```go -// LogFormat controls the log output format. -type LogFormat int - -const ( - LogFormatJSON LogFormat = iota // Structured JSON (default) - LogFormatLogfmt // logfmt key=value pairs - LogFormatText // Human-readable plain text -) - -// KeyStyle controls the JSON key naming convention. -type KeyStyle int - -const ( - // KeyStyleFlat uses dot notation for keys (e.g. "http.method", - // "http.status_code"). Field names follow OpenTelemetry HTTP semantic - // conventions. Compatible with Datadog, Splunk, Grafana Loki, CloudWatch. - // This is the default. - KeyStyleFlat KeyStyle = iota - - // KeyStyleNested uses hierarchical JSON objects (e.g. - // {"http": {"request": {"method": "POST"}}}). Field structure follows - // the Elastic Common Schema. Compatible with Elasticsearch and Kibana. - KeyStyleNested -) - -// LoggingOptions configures the LoggingInterceptor. -type LoggingOptions struct { - // Logger is an *slog.Logger instance. If nil, slog.Default() is used. - Logger *slog.Logger - - // Format selects the output format. Default: LogFormatJSON. - Format LogFormat - - // KeyStyle selects the JSON key naming convention. Only applies when - // Format is LogFormatJSON. Default: KeyStyleFlat. - KeyStyle KeyStyle - - // LogBody enables request/response body capture up to MaxBodyLogSize. - // Disabled by default for security and performance. - LogBody bool - - // MaxBodyLogSize is the maximum number of bytes to capture from the - // request or response body when LogBody is true. Default: 1024. - MaxBodyLogSize int - - // HeadersToLog is an explicit allowlist of header names to include in - // log entries. Empty means no headers are logged beyond the defaults - // defined in section 5. Useful for capturing correlation IDs. - HeadersToLog []string - - // SensitiveHeaders lists header names whose values should be redacted - // (replaced with "***") when logged. Default: ["Authorization", "Cookie", - // "Set-Cookie"]. - SensitiveHeaders []string -} -``` - -### 6.2 Constructor - -```go -// LoggingInterceptor returns an InterceptorFunc that logs HTTP request and -// response details. -// -// interceptor.NewTransportInterceptor(nil, -// interceptors.LoggingInterceptor(nil), // default options -// ) -// -// // Nested keys for Elasticsearch: -// interceptors.LoggingInterceptor(&interceptors.LoggingOptions{ -// KeyStyle: interceptors.KeyStyleNested, -// }) -// -// // logfmt for Grafana Loki: -// interceptors.LoggingInterceptor(&interceptors.LoggingOptions{ -// Format: interceptors.LogFormatLogfmt, -// }) -// -// // Text for local development with body logging: -// interceptors.LoggingInterceptor(&interceptors.LoggingOptions{ -// Format: interceptors.LogFormatText, -// LogBody: true, -// }) -func LoggingInterceptor(opts *LoggingOptions) interceptor.InterceptorFunc -``` - -When `opts` is `nil`, the interceptor uses all default values (JSON format, flat key style, `slog.Default()`, no body logging, 1024-byte body limit). - -### 6.3 Format Comparison - -| Feature | JSON | logfmt | Text | -|---|---|---|---| -| Machine-parseable | Yes | Yes | No | -| Human-readable | Moderate | Good | Best | -| Native support | Elasticsearch, Datadog, Splunk, CloudWatch | Grafana Loki, Heroku, Prometheus | Terminal / local dev | -| Go slog handler | `slog.NewJSONHandler` | Custom formatter (std lib only) | `slog.NewTextHandler` | -| Recommended for | Production, log aggregation | Production, Kubernetes/cloud-native | Local development | - -## 7. Behavior Specification - -1. **Before calling `next`**: log a `"http request started"` entry at `INFO` level with all request fields from section 5.1. -2. **Record `time.Now()`** immediately before calling `next(req)`. -3. **After `next` returns**: compute duration and log a completion entry. - - If `err != nil`: log at `ERROR` level with `"http request failed"` message and the `error.message` field. - - If `resp.StatusCode >= 500`: log at `ERROR` level. - - If `resp.StatusCode >= 400`: log at `WARN` level. - - Otherwise: log at `INFO` level. -4. **Body logging** (opt-in): wrap `req.Body` and `resp.Body` with a `io.TeeReader` capped at `MaxBodyLogSize` bytes. Truncated bodies append `"...(truncated)"`. The original body streams remain intact for downstream consumers. -5. **Sensitive header redaction**: any header in `SensitiveHeaders` has its value replaced with `"***"` in the log output. -6. **Request cloning**: the interceptor MUST NOT mutate the original request. Follow the same `req.Clone(req.Context())` pattern used by the existing `HeaderInterceptor` and `BasicAuthInterceptor`. -7. **Thread safety**: the interceptor must be safe for concurrent use across goroutines sharing the same `http.Client`. - -## 8. File Structure - -``` -interceptors/ -├── auth.go # existing -├── auth_test.go # existing -├── headers.go # existing -├── headers_test.go # existing -├── logging.go # NEW — LoggingInterceptor + LoggingOptions -└── logging_test.go # NEW — tests -``` - -No new Go modules or dependencies are introduced. The implementation uses only `log/slog`, `time`, `io`, `bytes`, `fmt`, and `net/http` from the standard library. - -## 9. Test Plan - -### 9.1 Unit Tests (`interceptors/logging_test.go`) - -| Test Case | Description | -|---|---| -| `TestLoggingInterceptor_JSON_FlatKeys` | Verifies JSON output with flat dotted keys (`http.method`) contains all required fields for a successful 200 response. | -| `TestLoggingInterceptor_JSON_NestedKeys` | Verifies JSON output with nested keys (`http.request.method`) produces correct object hierarchy and uses `@timestamp` and `message` fields. | -| `TestLoggingInterceptor_LogfmtFormat` | Verifies logfmt output contains all required `key=value` pairs and properly quotes values with spaces. | -| `TestLoggingInterceptor_TextFormat` | Verifies text-format output for a successful request. | -| `TestLoggingInterceptor_StatusLevels` | Table-driven test covering 2xx → INFO, 4xx → WARN, 5xx → ERROR level mapping. | -| `TestLoggingInterceptor_TransportError` | Simulates a connection failure and asserts `error.message` is present at ERROR level. | -| `TestLoggingInterceptor_Duration` | Asserts `http.duration_ms` is a positive number within a reasonable tolerance. | -| `TestLoggingInterceptor_BodyLogging` | Enables `LogBody`, sends a request with a known body, and asserts the body content appears in the log and remains readable by downstream consumers. | -| `TestLoggingInterceptor_BodyTruncation` | Sends a body larger than `MaxBodyLogSize` and asserts truncation with `"...(truncated)"`. | -| `TestLoggingInterceptor_SensitiveHeaderRedaction` | Sends `Authorization` and `Cookie` headers and asserts their values are replaced with `"***"`. | -| `TestLoggingInterceptor_CustomHeaders` | Uses `HeadersToLog` to include `X-Request-ID` and asserts it appears in the output. | -| `TestLoggingInterceptor_NilOptions` | Passes `nil` and asserts defaults are applied without panic. | -| `TestLoggingInterceptor_ChainPosition` | Places the logging interceptor in a chain with `HeaderInterceptor` and `BasicAuthInterceptor` and asserts all three execute correctly. | -| `TestLoggingInterceptor_Concurrent` | Fires 50 concurrent requests through the interceptor and asserts no race conditions (run with `-race`). | - -### 9.2 Test Approach - -All tests use `httptest.NewServer` to create ephemeral HTTP servers (same pattern as existing tests in the repository). Log output is captured by injecting a custom `*slog.Logger` that writes to a `bytes.Buffer`, enabling assertion on exact field values without relying on stdout capture. - -## 10. Documentation Updates - -- **README.md**: add `LoggingInterceptor` to the "Built-in interceptors" table and include a usage example in the "Usage" section. -- **Go doc comments**: every exported type, constant, and function receives a doc comment following Go conventions. - -## 11. Acceptance Criteria - -1. `go test ./... -race` passes with all new tests green. -2. JSON log output with `KeyStyleFlat` (default) is parseable by `encoding/json.Unmarshal` into a flat map and contains every field listed in section 5.1/5.2 using dotted keys. -3. JSON log output with `KeyStyleNested` is parseable by `encoding/json.Unmarshal` into nested objects following the field structure shown in section 5.4. -4. logfmt log output produces valid `key=value` pairs parseable by standard logfmt libraries, with proper quoting of values containing spaces. -5. Text log output matches the format shown in section 5.6. -6. Body logging is disabled by default and does not impact performance when off. -7. Sensitive headers are redacted by default. -8. No new external dependencies are introduced (`go.mod` remains unchanged). -9. The interceptor is composable — it works correctly at any position in the chain. - -## 12. Future Considerations - -- **Sampling**: add a `SampleRate float64` option to log only a percentage of requests in high-throughput environments. -- **Conditional logging**: add a `ShouldLog func(*http.Request) bool` predicate to skip logging for health-check endpoints or internal traffic. -- **Metrics interceptor**: a separate `MetricsInterceptor` could share duration computation utilities with this logging interceptor. -- **Trace context**: log `trace_id` and `span_id` fields when OpenTelemetry context is present in the request. From bc36ac4acf00843d79f0a8c1bd6ed3cf89e12a3f Mon Sep 17 00:00:00 2001 From: Fabian Esteban Ruiz Valdes Date: Sat, 7 Mar 2026 19:50:36 -0500 Subject: [PATCH 04/19] feat(interceptors): add logging request interceptor --- README.md | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/README.md b/README.md index 8b49d2a..1544fd7 100644 --- a/README.md +++ b/README.md @@ -60,9 +60,7 @@ client = &http.Client{ nil, interceptors.LoggingInterceptor(&interceptors.LoggingOptions{ Format: interceptors.LogFormatLogfmt, - HeadersToLog: []string{"X-Request-ID"}, - LogBody: true, - MaxBodyLogSize: 2048, + HeadersToLog: []string{"X-Request-ID"} }), ), } From 0c281634e8516f362e0390bafefbfbacdef06487 Mon Sep 17 00:00:00 2001 From: Fabian Esteban Ruiz Valdes Date: Wed, 11 Mar 2026 09:13:41 -0500 Subject: [PATCH 05/19] feat(logging): improve logging --- README.md | 36 +-- interceptors/logging.go | 402 ++++++++---------------- interceptors/logging_test.go | 575 +++++++++++++++++++++++++---------- 3 files changed, 534 insertions(+), 479 deletions(-) diff --git a/README.md b/README.md index 1544fd7..e022180 100644 --- a/README.md +++ b/README.md @@ -30,41 +30,7 @@ Pass `nil` as the first argument to use `http.DefaultTransport`, or provide your |---|---| | `HeaderInterceptor(key, value)` | Sets a header on every request | | `BasicAuthInterceptor(user, password)` | Sets Basic authentication | -| `LoggingInterceptor(opts)` | Logs request start/completion in JSON (default), logfmt, or text | - -### LoggingInterceptor examples - -```go -// Default JSON + flat keys + slog.Default(). -client := &http.Client{ - Transport: interceptor.NewTransportInterceptor( - nil, - interceptors.LoggingInterceptor(nil), - ), -} - -// Nested JSON keys for ECS-style pipelines. -client = &http.Client{ - Transport: interceptor.NewTransportInterceptor( - nil, - interceptors.LoggingInterceptor(&interceptors.LoggingOptions{ - Format: interceptors.LogFormatJSON, - KeyStyle: interceptors.KeyStyleNested, - }), - ), -} - -// logfmt format with explicit header allowlist and optional body logging. -client = &http.Client{ - Transport: interceptor.NewTransportInterceptor( - nil, - interceptors.LoggingInterceptor(&interceptors.LoggingOptions{ - Format: interceptors.LogFormatLogfmt, - HeadersToLog: []string{"X-Request-ID"} - }), - ), -} -``` +| `LoggingInterceptor(opts)` | Emits structured `slog` attributes | ## Custom interceptors diff --git a/interceptors/logging.go b/interceptors/logging.go index 95e5e02..c82cb9e 100644 --- a/interceptors/logging.go +++ b/interceptors/logging.go @@ -1,12 +1,12 @@ package interceptors import ( - "encoding/json" - "fmt" + "errors" "log/slog" "net/http" "net/textproto" - "sort" + "net/url" + "reflect" "strconv" "strings" "time" @@ -20,42 +20,12 @@ var defaultSensitiveHeaders = []string{ "Set-Cookie", } -// LogFormat controls the log output format. -type LogFormat int - -const ( - // LogFormatJSON writes structured JSON logs. - LogFormatJSON LogFormat = iota - // LogFormatLogfmt writes logs in key=value format. - LogFormatLogfmt - // LogFormatText writes human-readable plain text logs. - LogFormatText -) - -// KeyStyle controls the JSON key naming convention. -type KeyStyle int - -const ( - // KeyStyleFlat uses dotted keys like "http.method". - KeyStyleFlat KeyStyle = iota - // KeyStyleNested uses nested objects like "http.request.method". - KeyStyleNested -) - // LoggingOptions configures LoggingInterceptor behavior. type LoggingOptions struct { - // Logger receives rendered log lines. + // Logger receives structured attributes. // If nil, slog.Default() is used. Logger *slog.Logger - // Format selects log rendering format. - // Default: LogFormatJSON. - Format LogFormat - - // KeyStyle chooses JSON key style when Format is LogFormatJSON. - // Default: KeyStyleFlat. - KeyStyle KeyStyle - // HeadersToLog is a request header allowlist. // Empty means no additional headers are logged. HeadersToLog []string @@ -67,29 +37,26 @@ type LoggingOptions struct { type loggingConfig struct { logger *slog.Logger - format LogFormat - keyStyle KeyStyle headersToLog map[string]struct{} sensitiveHeaders map[string]struct{} } type eventData struct { - timestamp time.Time - level slog.Level - message string - method string - url string - target string - host string - scheme string - statusCode *int - durationMS *float64 - userAgent string - requestID string - errorMessage string - requestContentLength *int64 - responseContentLength *int64 - requestHeaders map[string]string + level slog.Level + message string + method string + urlFull string + urlScheme string + serverAddress string + serverPort int + statusCode *int + userAgent string + errorType string + requestBodySize *int64 + responseBodySize *int64 + requestHeaders map[string]string + durationMS *float64 + requestID string } // LoggingInterceptor returns an interceptor that logs request lifecycle events. @@ -115,10 +82,8 @@ func LoggingInterceptor(opts *LoggingOptions) interceptor.InterceptorFunc { func buildLoggingConfig(opts *LoggingOptions) loggingConfig { cfg := loggingConfig{ - logger: slog.Default(), - format: LogFormatJSON, - keyStyle: KeyStyleFlat, - headersToLog: make(map[string]struct{}), + logger: slog.Default(), + headersToLog: make(map[string]struct{}), sensitiveHeaders: canonicalHeaderSet(defaultSensitiveHeaders), } @@ -130,14 +95,6 @@ func buildLoggingConfig(opts *LoggingOptions) loggingConfig { cfg.logger = opts.Logger } - if opts.Format != 0 { - cfg.format = opts.Format - } - - if opts.KeyStyle != 0 { - cfg.keyStyle = opts.KeyStyle - } - if len(opts.HeadersToLog) > 0 { cfg.headersToLog = canonicalHeaderSet(opts.HeadersToLog) } @@ -159,21 +116,20 @@ func canonicalHeaderSet(headers []string) map[string]struct{} { func buildStartEvent(req *http.Request, cfg loggingConfig) eventData { e := eventData{ - timestamp: time.Now().UTC(), level: slog.LevelInfo, message: "http request started", method: req.Method, - url: req.URL.String(), - target: req.URL.RequestURI(), - host: req.URL.Hostname(), - scheme: req.URL.Scheme, + urlFull: req.URL.String(), + urlScheme: req.URL.Scheme, + serverAddress: req.URL.Hostname(), + serverPort: extractServerPort(req.URL), userAgent: req.Header.Get("User-Agent"), requestID: req.Header.Get("X-Request-ID"), requestHeaders: extractAllowedHeaders(req.Header, cfg.headersToLog, cfg.sensitiveHeaders), } if req.ContentLength >= 0 { - e.requestContentLength = &req.ContentLength + e.requestBodySize = &req.ContentLength } return e @@ -182,24 +138,33 @@ func buildStartEvent(req *http.Request, cfg loggingConfig) eventData { func buildEndEvent(req *http.Request, resp *http.Response, err error, duration time.Duration) eventData { ms := float64(duration) / float64(time.Millisecond) e := eventData{ - timestamp: time.Now().UTC(), - level: getLogLevel(resp, err), - method: req.Method, - url: req.URL.String(), - durationMS: &ms, + level: getLogLevel(resp, err), + method: req.Method, + urlFull: req.URL.String(), + urlScheme: req.URL.Scheme, + serverAddress: req.URL.Hostname(), + serverPort: extractServerPort(req.URL), + durationMS: &ms, + } + + if req.ContentLength >= 0 { + e.requestBodySize = &req.ContentLength } if err != nil { e.message = "http request failed" - e.errorMessage = err.Error() + e.errorType = classifyErrorType(err) return e } e.message = "http request completed" if resp != nil { e.statusCode = &resp.StatusCode - if req.ContentLength >= 0 { - e.requestContentLength = &req.ContentLength + if resp.ContentLength >= 0 { + e.responseBodySize = &resp.ContentLength + } + if resp.StatusCode >= http.StatusBadRequest { + e.errorType = strconv.Itoa(resp.StatusCode) } } @@ -223,241 +188,126 @@ func getLogLevel(resp *http.Response, err error) slog.Level { } func emitLog(req *http.Request, cfg loggingConfig, event eventData) { - line := renderEvent(cfg, event) - cfg.logger.Log(req.Context(), event.level, line) + attrs := buildAttrs(event) + cfg.logger.LogAttrs(req.Context(), event.level, event.message, attrs...) } -func renderEvent(cfg loggingConfig, event eventData) string { - switch cfg.format { - case LogFormatLogfmt: - return renderLogfmt(event) - case LogFormatText: - return renderText(event) - default: - if cfg.keyStyle == KeyStyleNested { - return renderJSONNested(event) - } - return renderJSONFlat(event) - } +func sanitizeHeaderFieldKey(key string) string { + key = strings.ToLower(key) + return key } -func renderJSONFlat(event eventData) string { - payload := map[string]any{ - "timestamp": event.timestamp.Format(time.RFC3339Nano), - "level": strings.ToUpper(event.level.String()), - "msg": event.message, - "http.method": event.method, - "http.url": event.url, - } +func buildAttrs(event eventData) []slog.Attr { + attrs := make([]slog.Attr, 0, 6) - if event.target != "" { - payload["http.target"] = event.target - } - if event.host != "" { - payload["http.host"] = event.host - } - if event.scheme != "" { - payload["http.scheme"] = event.scheme - } - if event.requestContentLength != nil { - payload["http.request_content_length"] = *event.requestContentLength - } - if event.responseContentLength != nil { - payload["http.response_content_length"] = *event.responseContentLength - } - if event.statusCode != nil { - payload["http.status_code"] = *event.statusCode - } - if event.durationMS != nil { - payload["http.duration_ms"] = *event.durationMS - } - if event.userAgent != "" { - payload["user_agent.original"] = event.userAgent - } - if event.requestID != "" { - payload["http.request_id"] = event.requestID - } - if event.errorMessage != "" { - payload["error.message"] = event.errorMessage + requestAttrs := []any{slog.String("method", event.method)} + if event.requestBodySize != nil { + requestAttrs = append(requestAttrs, slog.Group("body", slog.Int64("size", *event.requestBodySize))) } if len(event.requestHeaders) > 0 { - payload["http.request.headers"] = event.requestHeaders + headerAttrs := make([]any, 0, len(event.requestHeaders)) + for key, value := range event.requestHeaders { + headerAttrs = append(headerAttrs, slog.String(sanitizeHeaderFieldKey(key), value)) + } + requestAttrs = append(requestAttrs, slog.Group("header", headerAttrs...)) } - b, err := json.Marshal(payload) - if err != nil { - return "{}" + httpAttrs := []any{slog.Group("request", requestAttrs...)} + if event.statusCode != nil || event.responseBodySize != nil { + responseAttrs := make([]any, 0, 2) + if event.statusCode != nil { + responseAttrs = append(responseAttrs, slog.Int("status_code", *event.statusCode)) + } + if event.responseBodySize != nil { + responseAttrs = append(responseAttrs, slog.Group("body", slog.Int64("size", *event.responseBodySize))) + } + httpAttrs = append(httpAttrs, slog.Group("response", responseAttrs...)) } - return string(b) -} + attrs = append(attrs, slog.Group("http", httpAttrs...)) -func renderJSONNested(event eventData) string { - payload := map[string]any{ - "@timestamp": event.timestamp.Format(time.RFC3339Nano), - "log": map[string]any{ - "level": strings.ToUpper(event.level.String()), - }, - "message": event.message, - "http": map[string]any{ - "request": map[string]any{ - "method": event.method, - }, - }, - "url": map[string]any{ - "full": event.url, - }, + urlAttrs := []any{slog.String("full", event.urlFull)} + if event.urlScheme != "" { + urlAttrs = append(urlAttrs, slog.String("scheme", event.urlScheme)) } + attrs = append(attrs, slog.Group("url", urlAttrs...)) - httpMap := payload["http"].(map[string]any) - requestMap := httpMap["request"].(map[string]any) - urlMap := payload["url"].(map[string]any) - - if event.target != "" { - urlMap["path"] = event.target - } - if event.host != "" { - urlMap["domain"] = event.host - } - if event.scheme != "" { - urlMap["scheme"] = event.scheme - } - if event.requestContentLength != nil { - requestMap["body"] = map[string]any{"bytes": *event.requestContentLength} - } - if event.requestID != "" { - requestMap["id"] = event.requestID + serverAttrs := []any{slog.String("address", event.serverAddress)} + if event.serverPort > 0 { + serverAttrs = append(serverAttrs, slog.Int("port", event.serverPort)) } + attrs = append(attrs, slog.Group("server", serverAttrs...)) + if event.userAgent != "" { - payload["user_agent"] = map[string]any{"original": event.userAgent} + attrs = append(attrs, slog.Group("user_agent", slog.String("original", event.userAgent))) } - if event.statusCode != nil { - httpMap["response"] = map[string]any{"status_code": *event.statusCode} - } - if event.responseContentLength != nil { - responseMap, ok := httpMap["response"].(map[string]any) - if !ok { - responseMap = map[string]any{} - httpMap["response"] = responseMap - } - responseMap["body"] = map[string]any{"bytes": *event.responseContentLength} + if event.errorType != "" { + attrs = append(attrs, slog.Group("error", slog.String("type", event.errorType))) } + + interceptorAttrs := make([]any, 0, 2) if event.durationMS != nil { - payload["event"] = map[string]any{"duration": *event.durationMS} + interceptorAttrs = append(interceptorAttrs, slog.Float64("duration_ms", *event.durationMS)) } - if event.errorMessage != "" { - payload["error"] = map[string]any{"message": event.errorMessage} + if event.requestID != "" { + interceptorAttrs = append(interceptorAttrs, slog.String("request_id", event.requestID)) } - if len(event.requestHeaders) > 0 { - requestMap["headers"] = event.requestHeaders + if len(interceptorAttrs) > 0 { + attrs = append(attrs, slog.Group("interceptor", interceptorAttrs...)) } - b, err := json.Marshal(payload) - if err != nil { - return "{}" - } - return string(b) + return attrs } -func renderLogfmt(event eventData) string { - parts := []string{ - "timestamp=" + encodeLogfmtValue(event.timestamp.Format(time.RFC3339Nano)), - "level=" + encodeLogfmtValue(strings.ToUpper(event.level.String())), - "msg=" + encodeLogfmtValue(event.message), - "http.method=" + encodeLogfmtValue(event.method), - "http.url=" + encodeLogfmtValue(event.url), - } - - if event.target != "" { - parts = append(parts, "http.target="+encodeLogfmtValue(event.target)) - } - if event.host != "" { - parts = append(parts, "http.host="+encodeLogfmtValue(event.host)) - } - if event.scheme != "" { - parts = append(parts, "http.scheme="+encodeLogfmtValue(event.scheme)) - } - if event.requestContentLength != nil { - parts = append(parts, "http.request_content_length="+strconv.FormatInt(*event.requestContentLength, 10)) - } - if event.responseContentLength != nil { - parts = append(parts, "http.response_content_length="+strconv.FormatInt(*event.responseContentLength, 10)) - } - if event.statusCode != nil { - parts = append(parts, "http.status_code="+strconv.Itoa(*event.statusCode)) +func extractServerPort(u *url.URL) int { + if u == nil { + return 0 } - if event.durationMS != nil { - parts = append(parts, "http.duration_ms="+strconv.FormatFloat(*event.durationMS, 'f', 3, 64)) - } - if event.userAgent != "" { - parts = append(parts, "user_agent.original="+encodeLogfmtValue(event.userAgent)) - } - if event.requestID != "" { - parts = append(parts, "http.request_id="+encodeLogfmtValue(event.requestID)) - } - if event.errorMessage != "" { - parts = append(parts, "error.message="+encodeLogfmtValue(event.errorMessage)) - } - - if len(event.requestHeaders) > 0 { - headerKeys := make([]string, 0, len(event.requestHeaders)) - for k := range event.requestHeaders { - headerKeys = append(headerKeys, k) - } - sort.Strings(headerKeys) - for _, key := range headerKeys { - parts = append(parts, "http.request.header."+sanitizeHeaderFieldKey(key)+"="+encodeLogfmtValue(event.requestHeaders[key])) + if port := u.Port(); port != "" { + value, err := strconv.Atoi(port) + if err == nil { + return value } } - - return strings.Join(parts, " ") + switch strings.ToLower(u.Scheme) { + case "http": + return 80 + case "https": + return 443 + default: + return 0 + } } -func renderText(event eventData) string { - duration := "" - if event.durationMS != nil { - duration = fmt.Sprintf(" %.2fms", *event.durationMS) +func classifyErrorType(err error) string { + if err == nil { + return "" } - status := "" - if event.statusCode != nil { - status = fmt.Sprintf(" %d", *event.statusCode) + root := err + for { + unwrapped := errors.Unwrap(root) + if unwrapped == nil { + break + } + root = unwrapped } - line := fmt.Sprintf( - "%s %s %s %s %s%s%s", - event.timestamp.Format(time.RFC3339Nano), - strings.ToUpper(event.level.String()), - event.message, - event.method, - event.url, - status, - duration, - ) - - if event.errorMessage != "" { - line += fmt.Sprintf(" error=%q", event.errorMessage) + t := reflect.TypeOf(root) + if t == nil { + return "error" } - - return line -} - -func encodeLogfmtValue(value string) string { - if value == "" { - return "\"\"" + for t.Kind() == reflect.Pointer { + t = t.Elem() } - - if strings.ContainsAny(value, " \t\n\r\"=") { - replacer := strings.NewReplacer("\\", "\\\\", "\"", "\\\"") - return "\"" + replacer.Replace(value) + "\"" + if name := t.Name(); name != "" { + return name } - return value -} - -func sanitizeHeaderFieldKey(key string) string { - key = strings.ToLower(key) - key = strings.ReplaceAll(key, "-", "_") - return key + typeName := t.String() + if idx := strings.LastIndex(typeName, "."); idx >= 0 { + return typeName[idx+1:] + } + return typeName } func extractAllowedHeaders(headers http.Header, allowlist, sensitive map[string]struct{}) map[string]string { diff --git a/interceptors/logging_test.go b/interceptors/logging_test.go index 47ed4ce..aa683c3 100644 --- a/interceptors/logging_test.go +++ b/interceptors/logging_test.go @@ -1,9 +1,11 @@ package interceptors_test import ( + "bytes" "context" "encoding/json" "errors" + "fmt" "io" "log/slog" "net/http" @@ -20,19 +22,30 @@ import ( type capturedRecord struct { level slog.Level msg string + attrs map[string]any } type captureHandler struct { mu sync.Mutex records []capturedRecord + level slog.Level } -func (h *captureHandler) Enabled(_ context.Context, _ slog.Level) bool { return true } +func (h *captureHandler) Enabled(_ context.Context, level slog.Level) bool { + return level >= h.level +} func (h *captureHandler) Handle(_ context.Context, r slog.Record) error { h.mu.Lock() defer h.mu.Unlock() - h.records = append(h.records, capturedRecord{level: r.Level, msg: r.Message}) + + attrs := make(map[string]any) + r.Attrs(func(a slog.Attr) bool { + resolveAttr(attrs, a) + return true + }) + + h.records = append(h.records, capturedRecord{level: r.Level, msg: r.Message, attrs: attrs}) return nil } @@ -48,12 +61,24 @@ func (h *captureHandler) snapshot() []capturedRecord { return out } +func resolveAttr(dest map[string]any, a slog.Attr) { + if a.Value.Kind() == slog.KindGroup { + group := make(map[string]any) + for _, ga := range a.Value.Group() { + resolveAttr(group, ga) + } + dest[a.Key] = group + return + } + dest[a.Key] = a.Value.Any() +} + func newCaptureLogger() (*slog.Logger, *captureHandler) { - h := &captureHandler{} + h := &captureHandler{level: slog.LevelDebug} return slog.New(h), h } -func TestLoggingInterceptor_JSON_FlatKeys(t *testing.T) { +func TestLoggingInterceptor_StructuredAttrs(t *testing.T) { logger, sink := newCaptureLogger() server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { @@ -85,150 +110,17 @@ func TestLoggingInterceptor_JSON_FlatKeys(t *testing.T) { t.Fatalf("len(records) = %d, want 2", len(records)) } - start := decodeJSONMap(t, records[0].msg) - if start["http.method"] != http.MethodGet { - t.Fatalf("http.method = %v, want %q", start["http.method"], http.MethodGet) - } - if start["http.url"] != server.URL+"/v1/users?page=2" { - t.Fatalf("http.url = %v", start["http.url"]) - } - if start["http.target"] != "/v1/users?page=2" { - t.Fatalf("http.target = %v", start["http.target"]) - } - if start["http.request_id"] != "abc-123" { - t.Fatalf("http.request_id = %v", start["http.request_id"]) - } + start := records[0].attrs + assertGroupPathString(t, start, "http.request.method", http.MethodGet) + assertGroupPathString(t, start, "url.full", server.URL+"/v1/users?page=2") + assertGroupPathString(t, start, "url.scheme", "http") + assertGroupPathString(t, start, "user_agent.original", "interceptor-tests/1.0") + assertGroupPathString(t, start, "interceptor.request_id", "abc-123") - finish := decodeJSONMap(t, records[1].msg) - if finish["http.status_code"] != float64(http.StatusOK) { - t.Fatalf("http.status_code = %v, want %d", finish["http.status_code"], http.StatusOK) - } - if _, ok := finish["http.duration_ms"]; !ok { - t.Fatal("http.duration_ms missing") - } -} - -func TestLoggingInterceptor_JSON_NestedKeys(t *testing.T) { - logger, sink := newCaptureLogger() - - server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - w.WriteHeader(http.StatusCreated) - _, _ = w.Write([]byte("ok")) - })) - t.Cleanup(server.Close) - - client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, - interceptors.LoggingInterceptor(&interceptors.LoggingOptions{ - Logger: logger, - Format: interceptors.LogFormatJSON, - KeyStyle: interceptors.KeyStyleNested, - }), - )} - - resp, err := client.Post(server.URL+"/v1/orders", "text/plain", strings.NewReader("payload")) - if err != nil { - t.Fatalf("client.Post error: %v", err) - } - _ = resp.Body.Close() - - records := sink.snapshot() - if len(records) != 2 { - t.Fatalf("len(records) = %d, want 2", len(records)) - } - - start := decodeJSONMap(t, records[0].msg) - if _, ok := start["@timestamp"]; !ok { - t.Fatal("@timestamp missing") - } - if start["message"] != "http request started" { - t.Fatalf("message = %v", start["message"]) - } - - httpMap := start["http"].(map[string]any) - requestMap := httpMap["request"].(map[string]any) - if requestMap["method"] != http.MethodPost { - t.Fatalf("http.request.method = %v", requestMap["method"]) - } -} - -func TestLoggingInterceptor_LogfmtFormat(t *testing.T) { - logger, sink := newCaptureLogger() - - server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - w.WriteHeader(http.StatusOK) - })) - t.Cleanup(server.Close) - - client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, - interceptors.LoggingInterceptor(&interceptors.LoggingOptions{ - Logger: logger, - Format: interceptors.LogFormatLogfmt, - }), - )} - - req, err := http.NewRequest(http.MethodGet, server.URL+"/q with space", nil) - if err != nil { - t.Fatalf("http.NewRequest error: %v", err) - } - - resp, err := client.Do(req) - if err != nil { - t.Fatalf("client.Do error: %v", err) - } - _ = resp.Body.Close() - - records := sink.snapshot() - if len(records) != 2 { - t.Fatalf("len(records) = %d, want 2", len(records)) - } - - line := records[0].msg - if !strings.Contains(line, "level=INFO") { - t.Fatalf("line missing level=INFO: %s", line) - } - if !strings.Contains(line, "msg=\"http request started\"") { - t.Fatalf("line missing quoted msg: %s", line) - } - if !strings.Contains(line, "http.url=") { - t.Fatalf("line missing http.url: %s", line) - } -} - -func TestLoggingInterceptor_TextFormat(t *testing.T) { - logger, sink := newCaptureLogger() - - server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - w.WriteHeader(http.StatusNoContent) - })) - t.Cleanup(server.Close) - - client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, - interceptors.LoggingInterceptor(&interceptors.LoggingOptions{ - Logger: logger, - Format: interceptors.LogFormatText, - }), - )} - - resp, err := client.Get(server.URL) - if err != nil { - t.Fatalf("client.Get error: %v", err) - } - _ = resp.Body.Close() - - records := sink.snapshot() - if len(records) != 2 { - t.Fatalf("len(records) = %d, want 2", len(records)) - } - - line := records[1].msg - if !strings.Contains(line, "http request completed") { - t.Fatalf("line missing completion message: %s", line) - } - if !strings.Contains(line, "GET") { - t.Fatalf("line missing method: %s", line) - } - if !strings.Contains(line, "204") { - t.Fatalf("line missing status code: %s", line) + finish := records[1].attrs + assertGroupPathInt64(t, finish, "http.response.status_code", int64(http.StatusOK)) + if _, ok := getGroupPath(finish, "interceptor.duration_ms").(float64); !ok { + t.Fatal("interceptor.duration_ms missing") } } @@ -266,6 +158,7 @@ func TestLoggingInterceptor_StatusLevels(t *testing.T) { if got := records[len(records)-1].level; got != tc.wantLevel { t.Fatalf("final level = %v, want %v", got, tc.wantLevel) } + assertGroupPathInt64(t, records[len(records)-1].attrs, "http.response.status_code", int64(tc.status)) }) } } @@ -288,15 +181,58 @@ func TestLoggingInterceptor_TransportError(t *testing.T) { t.Fatalf("len(records) = %d, want 2", len(records)) } - finish := decodeJSONMap(t, records[1].msg) - if finish["error.message"] == nil { - t.Fatalf("error.message missing: %v", finish) - } + assertGroupPathString(t, records[1].attrs, "error.type", "errorString") if records[1].level != slog.LevelError { t.Fatalf("level = %v, want ERROR", records[1].level) } } +func TestLoggingInterceptor_HTTPErrorStatusSetsErrorType(t *testing.T) { + logger, sink := newCaptureLogger() + + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusInternalServerError) + })) + t.Cleanup(server.Close) + + client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, + interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + )} + + resp, err := client.Get(server.URL) + if err != nil { + t.Fatalf("client.Get error: %v", err) + } + _ = resp.Body.Close() + + records := sink.snapshot() + assertGroupPathString(t, records[1].attrs, "error.type", "500") +} + +func TestLoggingInterceptor_NoErrorTypeOnSuccess(t *testing.T) { + logger, sink := newCaptureLogger() + + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusNoContent) + })) + t.Cleanup(server.Close) + + client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, + interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + )} + + resp, err := client.Get(server.URL) + if err != nil { + t.Fatalf("client.Get error: %v", err) + } + _ = resp.Body.Close() + + records := sink.snapshot() + if hasGroupPath(records[1].attrs, "error.type") { + t.Fatalf("error.type should not exist on successful response: %+v", records[1].attrs) + } +} + func TestLoggingInterceptor_Duration(t *testing.T) { logger, sink := newCaptureLogger() @@ -317,13 +253,12 @@ func TestLoggingInterceptor_Duration(t *testing.T) { _ = resp.Body.Close() records := sink.snapshot() - finish := decodeJSONMap(t, records[1].msg) - duration, ok := finish["http.duration_ms"].(float64) + duration, ok := getGroupPath(records[1].attrs, "interceptor.duration_ms").(float64) if !ok { - t.Fatalf("http.duration_ms has unexpected type: %T", finish["http.duration_ms"]) + t.Fatalf("interceptor.duration_ms has unexpected type: %T", getGroupPath(records[1].attrs, "interceptor.duration_ms")) } if duration <= 0 { - t.Fatalf("http.duration_ms = %v, want > 0", duration) + t.Fatalf("interceptor.duration_ms = %v, want > 0", duration) } } @@ -352,14 +287,9 @@ func TestLoggingInterceptor_SensitiveHeaderRedaction(t *testing.T) { } _ = resp.Body.Close() - start := decodeJSONMap(t, sink.snapshot()[0].msg) - headers := start["http.request.headers"].(map[string]any) - if headers["Authorization"] != "***" { - t.Fatalf("Authorization = %v, want ***", headers["Authorization"]) - } - if headers["Cookie"] != "***" { - t.Fatalf("Cookie = %v, want ***", headers["Cookie"]) - } + start := sink.snapshot()[0].attrs + assertGroupPathString(t, start, "http.request.header.authorization", "***") + assertGroupPathString(t, start, "http.request.header.cookie", "***") } func TestLoggingInterceptor_CustomHeaders(t *testing.T) { @@ -386,11 +316,8 @@ func TestLoggingInterceptor_CustomHeaders(t *testing.T) { } _ = resp.Body.Close() - start := decodeJSONMap(t, sink.snapshot()[0].msg) - headers := start["http.request.headers"].(map[string]any) - if headers["X-Correlation-Id"] != "corr-1" { - t.Fatalf("X-Correlation-Id = %v, want corr-1", headers["X-Correlation-Id"]) - } + start := sink.snapshot()[0].attrs + assertGroupPathString(t, start, "http.request.header.x-correlation-id", "corr-1") } func TestLoggingInterceptor_NilOptions(t *testing.T) { @@ -529,6 +456,232 @@ func TestLoggingInterceptor_RequestImmutability(t *testing.T) { } } +func TestLoggingInterceptor_WithJSONHandler(t *testing.T) { + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + })) + t.Cleanup(server.Close) + + var out bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&out, nil)) + + client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, + interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + )} + + resp, err := client.Get(server.URL + "/json") + if err != nil { + t.Fatalf("client.Get error: %v", err) + } + _ = resp.Body.Close() + + lines := splitLines(out.String()) + if len(lines) != 2 { + t.Fatalf("expected 2 log lines, got %d", len(lines)) + } + + first := decodeJSONMap(t, lines[0]) + httpMap, ok := first["http"].(map[string]any) + if !ok { + t.Fatalf("http group missing: %v", first) + } + requestMap := httpMap["request"].(map[string]any) + if requestMap["method"] != "GET" { + t.Fatalf("http.request.method = %v, want GET", requestMap["method"]) + } +} + +func TestLoggingInterceptor_WithTextHandler(t *testing.T) { + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + })) + t.Cleanup(server.Close) + + var out bytes.Buffer + logger := slog.New(slog.NewTextHandler(&out, nil)) + + client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, + interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + )} + + resp, err := client.Get(server.URL + "/text") + if err != nil { + t.Fatalf("client.Get error: %v", err) + } + _ = resp.Body.Close() + + output := out.String() + if !strings.Contains(output, "http.request.method=GET") { + t.Fatalf("TextHandler output missing grouped dotted key: %s", output) + } + if !strings.Contains(output, "url.full=") { + t.Fatalf("TextHandler output missing url.full: %s", output) + } +} + +func TestLoggingInterceptor_HandlerOptions_ReplaceAttr(t *testing.T) { + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + })) + t.Cleanup(server.Close) + + var out bytes.Buffer + seenHTTPRequestMethod := false + seenInterceptorDuration := false + + logger := slog.New(slog.NewJSONHandler(&out, &slog.HandlerOptions{ + ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { + if strings.Join(groups, ".") == "http.request" && a.Key == "method" { + seenHTTPRequestMethod = true + a.Value = slog.StringValue("OVERRIDDEN") + } + if strings.Join(groups, ".") == "interceptor" && a.Key == "duration_ms" { + seenInterceptorDuration = true + } + return a + }, + })) + + client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, + interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + )} + + resp, err := client.Get(server.URL) + if err != nil { + t.Fatalf("client.Get error: %v", err) + } + _ = resp.Body.Close() + + if !seenHTTPRequestMethod { + t.Fatal("ReplaceAttr did not receive [http request] method") + } + if !seenInterceptorDuration { + t.Fatal("ReplaceAttr did not receive [interceptor] duration_ms") + } + + lines := splitLines(out.String()) + first := decodeJSONMap(t, lines[0]) + httpMap := first["http"].(map[string]any) + requestMap := httpMap["request"].(map[string]any) + if requestMap["method"] != "OVERRIDDEN" { + t.Fatalf("http.request.method = %v, want OVERRIDDEN", requestMap["method"]) + } +} + +func TestLoggingInterceptor_HandlerOptions_Level(t *testing.T) { + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + })) + t.Cleanup(server.Close) + + var out bytes.Buffer + logger := slog.New(slog.NewJSONHandler(&out, &slog.HandlerOptions{Level: slog.LevelError})) + + client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, + interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + )} + + resp, err := client.Get(server.URL) + if err != nil { + t.Fatalf("client.Get error: %v", err) + } + _ = resp.Body.Close() + + if strings.TrimSpace(out.String()) != "" { + t.Fatalf("expected no logs at error level for successful request, got %q", out.String()) + } +} + +func TestLoggingInterceptor_OTelAttributeNames(t *testing.T) { + logger, sink := newCaptureLogger() + + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.Header().Set("Content-Length", "3") + w.WriteHeader(http.StatusAccepted) + _, _ = w.Write([]byte("ok!")) + })) + t.Cleanup(server.Close) + + client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, + interceptors.LoggingInterceptor(&interceptors.LoggingOptions{ + Logger: logger, + HeadersToLog: []string{"Content-Type"}, + }), + )} + + req, _ := http.NewRequest(http.MethodPost, server.URL+"/otel", strings.NewReader("abc")) + req.Header.Set("Content-Type", "application/json") + req.Header.Set("User-Agent", "otel-test/1.0") + + resp, err := client.Do(req) + if err != nil { + t.Fatalf("client.Do error: %v", err) + } + _ = resp.Body.Close() + + start := sink.snapshot()[0].attrs + assertGroupPathString(t, start, "http.request.method", "POST") + assertGroupPathInt64(t, start, "http.request.body.size", 3) + assertGroupPathString(t, start, "http.request.header.content-type", "application/json") + assertGroupPathString(t, start, "url.full", server.URL+"/otel") + assertGroupPathString(t, start, "url.scheme", "http") + assertGroupPathString(t, start, "server.address", "127.0.0.1") + assertGroupPathInt64(t, start, "server.port", int64(mustServerPort(t, server.URL))) + assertGroupPathString(t, start, "user_agent.original", "otel-test/1.0") + + finish := sink.snapshot()[1].attrs + assertGroupPathInt64(t, finish, "http.response.status_code", int64(http.StatusAccepted)) + assertGroupPathInt64(t, finish, "http.response.body.size", 3) + assertGroupPathInt64(t, finish, "http.request.body.size", 3) + if hasGroupPath(finish, "http.target") { + t.Fatalf("http.target must not be emitted: %+v", finish) + } +} + +func TestLoggingInterceptor_ServerAddressAndPort(t *testing.T) { + logger, sink := newCaptureLogger() + + t.Run("implicit http port", func(t *testing.T) { + server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) + })) + t.Cleanup(server.Close) + + client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, + interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + )} + + resp, err := client.Get(server.URL) + if err != nil { + t.Fatalf("client.Get error: %v", err) + } + _ = resp.Body.Close() + + records := sink.snapshot() + assertGroupPathString(t, records[len(records)-2].attrs, "server.address", "127.0.0.1") + assertGroupPathInt64(t, records[len(records)-2].attrs, "server.port", int64(mustServerPort(t, server.URL))) + }) + + t.Run("explicit https default port", func(t *testing.T) { + transport := interceptor.NewTransportInterceptor(roundTripperFunc(func(req *http.Request) (*http.Response, error) { + return &http.Response{StatusCode: http.StatusOK, Body: io.NopCloser(strings.NewReader("ok"))}, nil + }), interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger})) + + client := &http.Client{Transport: transport} + req, _ := http.NewRequest(http.MethodGet, "https://example.com/resource", nil) + resp, err := client.Do(req) + if err != nil { + t.Fatalf("client.Do error: %v", err) + } + _ = resp.Body.Close() + + records := sink.snapshot() + start := records[len(records)-2].attrs + assertGroupPathString(t, start, "server.address", "example.com") + assertGroupPathInt64(t, start, "server.port", 443) + }) +} + type roundTripperFunc func(req *http.Request) (*http.Response, error) func (f roundTripperFunc) RoundTrip(req *http.Request) (*http.Response, error) { @@ -543,3 +696,89 @@ func decodeJSONMap(t *testing.T, line string) map[string]any { } return out } + +func splitLines(s string) []string { + parts := strings.Split(strings.TrimSpace(s), "\n") + out := make([]string, 0, len(parts)) + for _, p := range parts { + p = strings.TrimSpace(p) + if p != "" { + out = append(out, p) + } + } + return out +} + +func getGroupPath(attrs map[string]any, path string) any { + current := any(attrs) + for _, segment := range strings.Split(path, ".") { + m, ok := current.(map[string]any) + if !ok { + return nil + } + current, ok = m[segment] + if !ok { + return nil + } + } + return current +} + +func hasGroupPath(attrs map[string]any, path string) bool { + return getGroupPath(attrs, path) != nil +} + +func assertGroupPathString(t *testing.T, attrs map[string]any, path, want string) { + t.Helper() + got, ok := getGroupPath(attrs, path).(string) + if !ok { + t.Fatalf("%s has unexpected type: %T", path, getGroupPath(attrs, path)) + } + if got != want { + t.Fatalf("%s = %q, want %q", path, got, want) + } +} + +func assertGroupPathInt64(t *testing.T, attrs map[string]any, path string, want int64) { + t.Helper() + value := getGroupPath(attrs, path) + var got int64 + switch v := value.(type) { + case int: + got = int64(v) + case int64: + got = v + case float64: + got = int64(v) + default: + t.Fatalf("%s has unexpected type: %T", path, value) + } + if got != want { + t.Fatalf("%s = %d, want %d", path, got, want) + } +} + +func mustServerPort(t *testing.T, rawURL string) int { + t.Helper() + var hostPort string + if strings.HasPrefix(rawURL, "http://") { + hostPort = strings.TrimPrefix(rawURL, "http://") + } else if strings.HasPrefix(rawURL, "https://") { + hostPort = strings.TrimPrefix(rawURL, "https://") + } else { + t.Fatalf("unsupported URL: %s", rawURL) + } + if idx := strings.Index(hostPort, "/"); idx >= 0 { + hostPort = hostPort[:idx] + } + parts := strings.Split(hostPort, ":") + if len(parts) != 2 { + t.Fatalf("expected host:port in URL: %s", rawURL) + } + var port int + _, err := fmt.Sscanf(parts[1], "%d", &port) + if err != nil { + t.Fatalf("failed parsing port from %q: %v", rawURL, err) + } + return port +} From 9fe499c042b38ac943f60ca6ff203625b5a1c224 Mon Sep 17 00:00:00 2001 From: Fabian Esteban Ruiz Valdes Date: Wed, 11 Mar 2026 10:09:25 -0500 Subject: [PATCH 06/19] feat(logging): improve logging --- README.md | 2 ++ interceptors/logging.go | 31 ++++++++++++++++++------------- interceptors/logging_test.go | 17 ++++++++++------- 3 files changed, 30 insertions(+), 20 deletions(-) diff --git a/README.md b/README.md index e022180..8d073f2 100644 --- a/README.md +++ b/README.md @@ -32,6 +32,8 @@ Pass `nil` as the first argument to use `http.DefaultTransport`, or provide your | `BasicAuthInterceptor(user, password)` | Sets Basic authentication | | `LoggingInterceptor(opts)` | Emits structured `slog` attributes | +`LoggingInterceptor` emits request duration as `http.client.request.duration` using seconds as the unit (UCUM `s`). + ## Custom interceptors Write your own `InterceptorFunc` to hook into the request/response lifecycle. Call `next` to continue the chain, or return early to short-circuit it. diff --git a/interceptors/logging.go b/interceptors/logging.go index c82cb9e..e3a9d54 100644 --- a/interceptors/logging.go +++ b/interceptors/logging.go @@ -55,7 +55,7 @@ type eventData struct { requestBodySize *int64 responseBodySize *int64 requestHeaders map[string]string - durationMS *float64 + durationSeconds *float64 requestID string } @@ -136,15 +136,15 @@ func buildStartEvent(req *http.Request, cfg loggingConfig) eventData { } func buildEndEvent(req *http.Request, resp *http.Response, err error, duration time.Duration) eventData { - ms := float64(duration) / float64(time.Millisecond) + seconds := duration.Seconds() e := eventData{ - level: getLogLevel(resp, err), - method: req.Method, - urlFull: req.URL.String(), - urlScheme: req.URL.Scheme, - serverAddress: req.URL.Hostname(), - serverPort: extractServerPort(req.URL), - durationMS: &ms, + level: getLogLevel(resp, err), + method: req.Method, + urlFull: req.URL.String(), + urlScheme: req.URL.Scheme, + serverAddress: req.URL.Hostname(), + serverPort: extractServerPort(req.URL), + durationSeconds: &seconds, } if req.ContentLength >= 0 { @@ -223,7 +223,6 @@ func buildAttrs(event eventData) []slog.Attr { } httpAttrs = append(httpAttrs, slog.Group("response", responseAttrs...)) } - attrs = append(attrs, slog.Group("http", httpAttrs...)) urlAttrs := []any{slog.String("full", event.urlFull)} if event.urlScheme != "" { @@ -244,10 +243,16 @@ func buildAttrs(event eventData) []slog.Attr { attrs = append(attrs, slog.Group("error", slog.String("type", event.errorType))) } - interceptorAttrs := make([]any, 0, 2) - if event.durationMS != nil { - interceptorAttrs = append(interceptorAttrs, slog.Float64("duration_ms", *event.durationMS)) + httpClientRequestAttrs := make([]any, 0, 1) + if event.durationSeconds != nil { + httpClientRequestAttrs = append(httpClientRequestAttrs, slog.Float64("duration", *event.durationSeconds)) + } + if len(httpClientRequestAttrs) > 0 { + httpAttrs = append(httpAttrs, slog.Group("client", slog.Group("request", httpClientRequestAttrs...))) } + attrs = append(attrs, slog.Group("http", httpAttrs...)) + + interceptorAttrs := make([]any, 0, 1) if event.requestID != "" { interceptorAttrs = append(interceptorAttrs, slog.String("request_id", event.requestID)) } diff --git a/interceptors/logging_test.go b/interceptors/logging_test.go index aa683c3..b49660d 100644 --- a/interceptors/logging_test.go +++ b/interceptors/logging_test.go @@ -119,8 +119,8 @@ func TestLoggingInterceptor_StructuredAttrs(t *testing.T) { finish := records[1].attrs assertGroupPathInt64(t, finish, "http.response.status_code", int64(http.StatusOK)) - if _, ok := getGroupPath(finish, "interceptor.duration_ms").(float64); !ok { - t.Fatal("interceptor.duration_ms missing") + if _, ok := getGroupPath(finish, "http.client.request.duration").(float64); !ok { + t.Fatal("http.client.request.duration missing") } } @@ -253,12 +253,15 @@ func TestLoggingInterceptor_Duration(t *testing.T) { _ = resp.Body.Close() records := sink.snapshot() - duration, ok := getGroupPath(records[1].attrs, "interceptor.duration_ms").(float64) + duration, ok := getGroupPath(records[1].attrs, "http.client.request.duration").(float64) if !ok { - t.Fatalf("interceptor.duration_ms has unexpected type: %T", getGroupPath(records[1].attrs, "interceptor.duration_ms")) + t.Fatalf("http.client.request.duration has unexpected type: %T", getGroupPath(records[1].attrs, "http.client.request.duration")) } if duration <= 0 { - t.Fatalf("interceptor.duration_ms = %v, want > 0", duration) + t.Fatalf("http.client.request.duration = %v, want > 0", duration) + } + if duration >= 1 { + t.Fatalf("http.client.request.duration = %v, want < 1 for a 10ms sleep", duration) } } @@ -535,7 +538,7 @@ func TestLoggingInterceptor_HandlerOptions_ReplaceAttr(t *testing.T) { seenHTTPRequestMethod = true a.Value = slog.StringValue("OVERRIDDEN") } - if strings.Join(groups, ".") == "interceptor" && a.Key == "duration_ms" { + if strings.Join(groups, ".") == "http.client.request" && a.Key == "duration" { seenInterceptorDuration = true } return a @@ -556,7 +559,7 @@ func TestLoggingInterceptor_HandlerOptions_ReplaceAttr(t *testing.T) { t.Fatal("ReplaceAttr did not receive [http request] method") } if !seenInterceptorDuration { - t.Fatal("ReplaceAttr did not receive [interceptor] duration_ms") + t.Fatal("ReplaceAttr did not receive [http client request] duration") } lines := splitLines(out.String()) From 6e5ea7e4e5a1995680e2563f952046045df0d6a8 Mon Sep 17 00:00:00 2001 From: Fabian Esteban Ruiz Valdes Date: Wed, 11 Mar 2026 14:07:13 -0500 Subject: [PATCH 07/19] feat(logging): improve logging --- PRD.md | 442 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 442 insertions(+) create mode 100644 PRD.md diff --git a/PRD.md b/PRD.md new file mode 100644 index 0000000..81cf444 --- /dev/null +++ b/PRD.md @@ -0,0 +1,442 @@ +# PRD — `github.com/fervbmx/interceptor` Code Quality Cleanup + +**Status:** Complete +**Author:** Fabian Ruiz +**Audience:** Repository maintainer(s) / contributing engineers +**Scope:** Post-review improvement pass — naming, documentation, testing, and implementation quality + +--- + +## 1. Background + +The `interceptor` library provides a composable HTTP middleware system for Go's `http.RoundTripper`. The library consists of a root package (`interceptor`) that defines the core chain-building infrastructure, and a sub-package (`interceptors`) that ships a set of ready-made implementations for auth, header injection, and structured logging. + +A full code review was conducted on the library. The review found it to be **functionally correct** and architecturally sound. However, several issues were identified across four categories — naming, documentation, testing, and implementation — that need to be addressed before the library can be considered idiomatic Go and ready for wider adoption. + +This document captures those findings as actionable engineering requirements organized into delivery phases. + +--- + +## 2. Goals + +- Bring the public API naming in line with idiomatic Go conventions. +- Ensure all exported symbols are properly documented. +- Eliminate test anti-patterns that hide failures or leak resources. +- Remove unnecessary abstractions and document non-obvious implementation choices. + +## 3. Non-Goals + +- Changing the library's architecture or adding new interceptors. +- Performance optimizations. +- Adding CI/CD pipelines or release automation. +- Any changes to behavior observable at runtime. + +--- + +## 4. Delivery Phases + +The requirements are grouped into four phases. Each phase is designed to be delivered as an independent unit — ideally a single pull request — with a clear rationale for the grouping. + +``` +Phase 1 → Public API + Docs (breaking, bump major version) +Phase 2 → Test Correctness (non-breaking, MUST fixes) +Phase 3 → Test Quality (non-breaking, CONSIDER fixes) +Phase 4 → Implementation Polish (non-breaking, CONSIDER fixes) +``` + +> **Note on breaking changes:** Phase 1 renames exported symbols. This is a semver-breaking change. Phases 2–4 are strictly internal and non-breaking for library consumers. + +--- + +## 5. Requirements + +Requirements are tagged with a severity tier: + +- **[MUST]** — Required for idiomatic Go and API correctness. These block a stable release. +- **[CONSIDER]** — Improvements that meaningfully reduce maintenance burden or test reliability. Strongly recommended. + +Each requirement includes an **Acceptance Criterion** that defines what "done" looks like. + +--- + +### Phase 1 — Public API & Documentation + +**Rationale:** All breaking changes to exported names are batched here so they land in a single semver bump. This phase should be merged before any other phase to avoid downstream churn. + +--- + +#### REQ-N-01 · [MUST] Remove redundant `Interceptor` suffix from `interceptors` sub-package exports + +**Category:** Naming +**Files:** `interceptors/auth.go`, `interceptors/headers.go`, `interceptors/logging.go` + +**Problem:** +The exported functions `BasicAuthInterceptor`, `HeaderInterceptor`, and `LoggingInterceptor` all include the word `Interceptor` as a suffix. Because these symbols live in the `interceptors` package, callers already write `interceptors.BasicAuthInterceptor(...)`. The suffix is redundant noise — it provides no additional information. Package-qualified names should not stutter. + +**Required Change:** + +| Before | After | +|---|---| +| `func BasicAuthInterceptor(...)` | `func BasicAuth(...)` | +| `func HeaderInterceptor(...)` | `func Header(...)` | +| `func LoggingInterceptor(...)` | `func Logging(...)` | + +**Acceptance Criterion:** +All three functions are renamed. No exported identifier in the `interceptors` package repeats the word "interceptor". All callers (including tests) are updated to use the new names. `go vet` and `go build ./...` pass with no errors. + +--- + +#### REQ-N-02 · [MUST] Remove redundant package-name repetition from root `interceptor` package types + +**Category:** Naming +**File:** `transport.go` + +**Problem:** +The root package is named `interceptor`. The types `InterceptorFunc` and `TransportInterceptor`, and the constructor `NewTransportInterceptor`, all contain the word "interceptor" — which is already provided by the package qualifier. Callers write `interceptor.InterceptorFunc` and `interceptor.TransportInterceptor`, making the names stutter. The Go standard library does not repeat the package name in type names (`http.Transport`, `http.Handler`, `http.HandlerFunc` — not `http.HTTPTransport`). `HandlerFunc` is **not** affected by this issue since `Handler` does not repeat the package name. + +**Required Change:** + +| Before | After | +|---|---| +| `type InterceptorFunc func(...)` | `type Func func(...)` | +| `type TransportInterceptor struct` | `type Transport struct` | +| `func NewTransportInterceptor(...)` | `func New(...)` or `func NewTransport(...)` | + +> **Note on constructor naming:** If more than one constructor is anticipated in the future, prefer `NewTransport`. If this is the sole constructor for the package's primary type, `New` is idiomatic (see `errors.New`, `ring.New`, `list.New`). + +**Acceptance Criterion:** +Types and constructor are renamed. All references across `transport.go`, `transport_test.go`, and the `interceptors` sub-package are updated. `go build ./...` and `go test ./...` pass. + +--- + +#### REQ-N-03 · [MUST] Rename loop variable `interceptor` in `RoundTrip` to avoid shadowing the package name + +**Category:** Naming +**File:** `transport.go`, `RoundTrip` method + +**Problem:** +Inside the reverse-iteration loop in `RoundTrip`, the code declares: + +```go +interceptor := t.interceptors[i] +``` + +This local variable shadows the imported package name `interceptor` for the remainder of the loop body. Any future developer adding a reference to the `interceptor` package inside that block would silently get the local variable instead, leading to a confusing compile error or incorrect behavior. Additionally, the IIFE parameter `i` shadows the loop counter `i`. + +**Required Change:** +Rename the loop variable to `fn` and the IIFE parameter accordingly: + +```go +for i := len(t.interceptors) - 1; i >= 0; i-- { + fn := t.interceptors[i] + next := handler + handler = func(fn Func, n HandlerFunc) HandlerFunc { + return func(r *http.Request) (*http.Response, error) { + return fn(r, n) + } + }(fn, next) +} +``` + +**Acceptance Criterion:** +No local variable in `transport.go` shadows an imported package name. `go vet ./...` passes. The chain-ordering behavior is unchanged and verified by existing tests. + +--- + +### Phase 2 — Test Correctness + +**Rationale:** These are the MUST-fix test issues. They either hide real failures (swallowed errors, unhandled panics) or leak resources (unclosed response bodies, invalid Go version). They should be fixed before Phase 3 so that the test suite is trustworthy as a baseline going forward. None of these changes are visible to library consumers. + +--- + +#### REQ-T-01 · [MUST] Close response bodies in all tests that make HTTP requests + +**Category:** Testing +**File:** `transport_test.go` + +**Problem:** +`TestTransportInterceptor` calls `client.Get(...)` but never closes `resp.Body`. This leaks the underlying connection back to the `httptest.Server`'s pool and can cause unpredictable behavior in parallel test runs. + +**Required Change:** +Add `defer resp.Body.Close()` immediately after verifying the error: + +```go +resp, err := client.Get(server.URL) +if err != nil { + t.Fatalf("client.Get() returned error: %v", err) +} +defer resp.Body.Close() +``` + +**Acceptance Criterion:** +All test functions that receive an `*http.Response` call `resp.Body.Close()` (via `defer` or explicit call before return). Running `go test -race ./...` produces no data-race warnings related to response body reads. + +--- + +#### REQ-T-02 · [MUST] Replace HTTP status code literals with named constants + +**Category:** Testing +**Files:** `transport_test.go`, `auth_test.go`, `headers_test.go` + +**Problem:** +Multiple test assertions compare `resp.StatusCode` against the integer literal `200`. The `net/http` package exports `http.StatusOK` precisely to avoid magic numbers in code. Using the literal reduces readability and diverges from the style used everywhere else in the codebase. + +**Required Change:** + +```go +// Before: +if resp.StatusCode != 200 { + +// After: +if resp.StatusCode != http.StatusOK { +``` + +**Acceptance Criterion:** +No integer literal HTTP status codes appear in any test file. All status comparisons use `http.Status*` constants. + +--- + +#### REQ-T-03 · [MUST] Handle errors from `http.NewRequest` in all tests + +**Category:** Testing +**File:** `logging_test.go` + +**Problem:** +At least four test cases silently discard the error return from `http.NewRequest` using the blank identifier (`req, _ := ...`). When `http.NewRequest` fails, `req` is `nil`, and the next line that uses `req` will panic with a nil pointer dereference. This results in a cryptic, non-actionable failure message instead of a clear test diagnostic. + +**Affected tests:** +- `TestLoggingInterceptor_SensitiveHeaderRedaction` +- `TestLoggingInterceptor_CustomHeaders` +- `TestLoggingInterceptor_OTelAttributeNames` +- `TestLoggingInterceptor_ServerAddressAndPort` + +**Required Change:** + +```go +// Before: +req, _ := http.NewRequest(http.MethodGet, server.URL, nil) + +// After: +req, err := http.NewRequest(http.MethodGet, server.URL, nil) +if err != nil { + t.Fatalf("http.NewRequest(%q) error: %v", server.URL, err) +} +``` + +**Acceptance Criterion:** +No test file uses `req, _` to discard errors from `http.NewRequest` or any other function that returns `error`. All such errors are checked and reported via `t.Fatalf`. + +--- + +### Phase 3 — Test Quality + +**Rationale:** These are the CONSIDER items scoped to the test layer. They improve consistency, safety, and speed of the test suite without altering any production code. Grouping them together makes for a clean, self-contained PR that is easy to review. + +--- + +#### REQ-T-04 · [CONSIDER] Unify table-driven test loop variable name to `tc` + +**Category:** Testing +**Files:** `auth_test.go`, `headers_test.go` (use `c`), `logging_test.go` (uses `tc`) + +**Problem:** +The two styles are inconsistent across the same test suite. The idiomatic Go convention for table-driven tests is `tc` (short for "test case"). + +**Required Change:** + +```go +// Before (auth_test.go, headers_test.go): +for _, c := range cases { + t.Run(c.name, func(t *testing.T) { ... c.key ... }) +} + +// After: +for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { ... tc.key ... }) +} +``` + +**Acceptance Criterion:** +All table-driven tests in all files use `tc` as the loop variable name. + +--- + +#### REQ-T-05 · [CONSIDER] Simplify `mustServerPort` using `net/url` + +**Category:** Testing +**File:** `logging_test.go` + +**Problem:** +The `mustServerPort` helper manually strips URL schemes with `strings.HasPrefix` / `strings.TrimPrefix` and then splits on `:` to find the port. This is fragile — it would silently break on URLs with user info or non-standard formatting. The standard library provides `url.Parse` precisely for this purpose. + +**Required Change:** + +```go +func mustServerPort(t *testing.T, rawURL string) int { + t.Helper() + u, err := url.Parse(rawURL) + if err != nil { + t.Fatalf("url.Parse(%q) error: %v", rawURL, err) + } + port, err := strconv.Atoi(u.Port()) + if err != nil { + t.Fatalf("strconv.Atoi(%q) error: %v", u.Port(), err) + } + return port +} +``` + +**Acceptance Criterion:** +`mustServerPort` uses `url.Parse` and `u.Port()` with no manual string manipulation. All existing tests that call `mustServerPort` continue to pass. + +--- + +#### REQ-T-06 · [CONSIDER] Use safe two-value type assertions in JSON-parsing tests + +**Category:** Testing +**File:** `logging_test.go` + +**Problem:** +`TestLoggingInterceptor_WithJSONHandler` and `TestLoggingInterceptor_HandlerOptions_ReplaceAttr` use single-value type assertions on `map[string]any` lookups: + +```go +requestMap := httpMap["request"].(map[string]any) +``` + +If the key is absent or the underlying type does not match, this will **panic** with no test context, making the failure very hard to diagnose. The idiomatic approach is to use the comma-ok form and call `t.Fatalf`. + +**Required Change:** + +```go +requestMap, ok := httpMap["request"].(map[string]any) +if !ok { + t.Fatalf("http[request] missing or wrong type, got: %T", httpMap["request"]) +} +``` + +**Acceptance Criterion:** +No unsafe (single-value) type assertions remain in test files for keys retrieved from `map[string]any`. All assertions use the comma-ok form and call `t.Fatal` on failure. + +--- + +#### REQ-T-07 · [CONSIDER] Remove `time.Sleep` from `TestLoggingInterceptor_Duration` + +**Category:** Testing +**File:** `logging_test.go` + +**Problem:** +The test makes the server sleep for 10ms before responding, then verifies that the logged duration is a float64 less than 1 second. The sleep adds unnecessary latency to the test suite and is sensitive to slow CI environments. The actual requirement — that duration is a positive float64 — does not need a sleep to be verified. + +**Required Change:** +Remove the `time.Sleep` from the handler and tighten the assertion to only check `duration > 0`: + +```go +// Server handler — remove the sleep: +server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + w.WriteHeader(http.StatusOK) +})) + +// Assertion — check only that duration is positive: +if duration <= 0 { + t.Fatalf("http.client.request.duration = %v, want > 0", duration) +} +``` + +**Acceptance Criterion:** +`TestLoggingInterceptor_Duration` contains no `time.Sleep` calls. The test verifies that duration is a positive float64 value. `go test -count=5 ./...` passes consistently. + +--- + +### Phase 4 — Implementation Polish + +**Rationale:** These are internal code quality improvements that do not touch the public API or the tests. They reduce future maintenance cost and improve the long-term readability of `interceptors/logging.go`. Because they are the lowest urgency and most self-contained, they are best left for last so they don't block any other work. + +--- + +#### REQ-I-01 · [CONSIDER] Inline or remove `sanitizeHeaderFieldKey` + +**Category:** Implementation +**File:** `interceptors/logging.go` + +**Problem:** +`sanitizeHeaderFieldKey` is a private function whose entire body is: + +```go +func sanitizeHeaderFieldKey(key string) string { + key = strings.ToLower(key) + return key +} +``` + +It wraps a single call to `strings.ToLower` with no additional logic. The name implies sanitization (validation, filtering) but performs only a case conversion. This is a misleading abstraction that adds indirection without value. + +**Required Change:** +Remove the function and call `strings.ToLower(key)` directly at the call site(s). + +**Acceptance Criterion:** +`sanitizeHeaderFieldKey` no longer exists. All former call sites use `strings.ToLower` directly. `go build ./...` passes. + +--- + +#### REQ-I-02 · [CONSIDER] Add a comment explaining the `reflect`-based error classification in `classifyErrorType` + +**Category:** Implementation +**File:** `interceptors/logging.go` + +**Problem:** +`classifyErrorType` uses `reflect.TypeOf` to derive a string label for the type of an error. This is functional but fragile: type names are implementation details that can change with refactoring, silently altering logged values in production. There is no comment explaining why this approach was chosen over alternatives (e.g., an `ErrorTyper` interface), which makes the decision invisible to future maintainers. + +**Required Change — Option A (minimum):** +Add a comment documenting the tradeoff: + +```go +// classifyErrorType derives a human-readable label for the concrete type of err. +// It uses reflection because error types are not required to self-describe their +// kind. Note: type names are implementation details and may change with refactors; +// callers relying on specific values in logs should define types that implement +// ErrorTyper instead. +``` + +**Required Change — Option B (recommended):** +Expose an `ErrorTyper` interface that error types can implement to opt into stable labels, and fall back to reflect only when the interface is not implemented: + +```go +// ErrorTyper can be implemented by error types to provide a stable, +// human-readable classification label for structured logs. +type ErrorTyper interface { + ErrorType() string +} +``` + +**Acceptance Criterion (Option A):** The function has a godoc comment explaining the reflect usage and its limitations. +**Acceptance Criterion (Option B):** An `ErrorTyper` interface is defined and checked before the reflect fallback. The interface is exported and documented. + +--- + +## 6. Out of Scope + +The following items were considered during the review and **deliberately excluded** from this document: + +- **Architectural changes** — The split between the root `interceptor` package and the `interceptors` sub-package is sound and will not be changed. +- **New interceptor implementations** — Adding new ready-made interceptors (e.g., retry, timeout, metrics) is a feature request, not a cleanup task. +- **API versioning strategy** — The renaming in REQ-N-01 and REQ-N-02 constitutes a breaking change to the public API. How this is communicated to users (semver, deprecation notices, migration guide) is outside the scope of this document. +- **`t.Parallel()`** — Adding parallel test execution is a valid improvement but is a separate concern from the quality issues identified here. + +--- + +## 7. Summary Table + +| Phase | ID | Severity | Category | Title | +|---|---|---|---|---| +| 1 | REQ-N-01 | MUST | Naming | Remove redundant `Interceptor` suffix from `interceptors` exports | +| 1 | REQ-N-02 | MUST | Naming | Remove package-name repetition from root `interceptor` types | +| 1 | REQ-N-03 | MUST | Naming | Rename loop variable `interceptor` to avoid package shadowing | +| 2 | REQ-T-01 | MUST | Testing | Close response bodies in all tests | +| 2 | REQ-T-02 | MUST | Testing | Replace HTTP status literals with `http.Status*` constants | +| 2 | REQ-T-03 | MUST | Testing | Handle errors from `http.NewRequest` in all tests | +| 3 | REQ-T-04 | CONSIDER | Testing | Unify table-driven test loop variable name to `tc` | +| 3 | REQ-T-05 | CONSIDER | Testing | Simplify `mustServerPort` using `net/url` | +| 3 | REQ-T-06 | CONSIDER | Testing | Use safe two-value type assertions in JSON-parsing tests | +| 3 | REQ-T-07 | CONSIDER | Testing | Remove `time.Sleep` from duration test | +| 4 | REQ-I-01 | CONSIDER | Implementation | Inline or remove `sanitizeHeaderFieldKey` | +| 4 | REQ-I-02 | CONSIDER | Implementation | Document or improve `classifyErrorType` reflect usage | From eeccd266fd42c89255f1af850ede909ed8c93c04 Mon Sep 17 00:00:00 2001 From: Fabian Esteban Ruiz Valdes Date: Wed, 11 Mar 2026 14:28:28 -0500 Subject: [PATCH 08/19] feat(logging): improve logging --- PRD.md | 4 +- README.md | 26 +++---- interceptors/auth.go | 8 +- interceptors/auth_test.go | 21 ++--- interceptors/headers.go | 8 +- interceptors/headers_test.go | 17 ++-- interceptors/logging.go | 26 ++++--- interceptors/logging_test.go | 147 ++++++++++++++++++----------------- transport.go | 36 ++++----- transport_test.go | 9 ++- 10 files changed, 159 insertions(+), 143 deletions(-) diff --git a/PRD.md b/PRD.md index 81cf444..797ff47 100644 --- a/PRD.md +++ b/PRD.md @@ -78,7 +78,7 @@ The exported functions `BasicAuthInterceptor`, `HeaderInterceptor`, and `Logging | Before | After | |---|---| | `func BasicAuthInterceptor(...)` | `func BasicAuth(...)` | -| `func HeaderInterceptor(...)` | `func Header(...)` | +| `func HeaderInterceptor(...)` | `func AddHeader(...)` | | `func LoggingInterceptor(...)` | `func Logging(...)` | **Acceptance Criterion:** @@ -98,7 +98,7 @@ The root package is named `interceptor`. The types `InterceptorFunc` and `Transp | Before | After | |---|---| -| `type InterceptorFunc func(...)` | `type Func func(...)` | +| `type InterceptorFunc func(...)` | `type Middleware func(...)` | | `type TransportInterceptor struct` | `type Transport struct` | | `func NewTransportInterceptor(...)` | `func New(...)` or `func NewTransport(...)` | diff --git a/README.md b/README.md index 8d073f2..1244d6a 100644 --- a/README.md +++ b/README.md @@ -11,13 +11,13 @@ go get github.com/fervbmx/interceptor ## Usage ```go -// Flow: LoggingInterceptor → HeaderInterceptor → BasicAuthInterceptor → http.DefaultTransport +// Flow: AddRequestLogging → AddHeader → AddBasicAuth → http.DefaultTransport client := &http.Client{ - Transport: interceptor.NewTransportInterceptor( + Transport: interceptor.NewTransport( nil, - interceptors.LoggingInterceptor(nil), - interceptors.HeaderInterceptor("X-API-KEY", "secret"), - interceptors.BasicAuthInterceptor("user", "pass"), + interceptors.AddRequestLogging(nil), + interceptors.AddHeader("X-API-KEY", "secret"), + interceptors.AddBasicAuth("user", "pass"), ), } ``` @@ -28,19 +28,19 @@ Pass `nil` as the first argument to use `http.DefaultTransport`, or provide your | Interceptor | Description | |---|---| -| `HeaderInterceptor(key, value)` | Sets a header on every request | -| `BasicAuthInterceptor(user, password)` | Sets Basic authentication | -| `LoggingInterceptor(opts)` | Emits structured `slog` attributes | +| `AddHeader(key, value)` | Sets a header on every request | +| `AddBasicAuth(user, password)` | Sets Basic authentication | +| `AddRequestLogging(opts)` | Emits structured `slog` attributes | -`LoggingInterceptor` emits request duration as `http.client.request.duration` using seconds as the unit (UCUM `s`). +`AddRequestLogging` emits request duration as `http.client.request.duration` using seconds as the unit (UCUM `s`). ## Custom interceptors -Write your own `InterceptorFunc` to hook into the request/response lifecycle. Call `next` to continue the chain, or return early to short-circuit it. +Write your own `interceptor.Middleware` to hook into the request/response lifecycle. Call `next` to continue the chain, or return early to short-circuit it. ```go // Log every request and its status code. -func LogginInterceptor(req *http.Request, next interceptor.HandlerFunc) (*http.Response, error) { +func Logging(req *http.Request, next interceptor.HandlerFunc) (*http.Response, error) { log.Printf("→ %s %s", req.Method, req.URL) resp, err := next(req) @@ -52,9 +52,9 @@ func LogginInterceptor(req *http.Request, next interceptor.HandlerFunc) (*http.R } client := &http.Client{ - Transport: interceptor.NewTransportInterceptor( + Transport: interceptor.NewTransport( http.DefaultTransport, - interceptor.LogginInterceptor + Logging ), } ``` diff --git a/interceptors/auth.go b/interceptors/auth.go index b3b7959..076eab2 100644 --- a/interceptors/auth.go +++ b/interceptors/auth.go @@ -6,13 +6,13 @@ import ( "github.com/fervbmx/interceptor" ) -// BasicAuthInterceptor returns an interceptor that sets Basic authentication on every +// AddBasicAuth returns an interceptor that sets Basic authentication on every // outgoing request. // -// interceptor.NewTransportInterceptor(nil, -// interceptors.BasicAuthInterceptor("username", "password"), +// interceptor.NewTransport(nil, +// interceptors.AddBasicAuth("username", "password"), // ) -func BasicAuthInterceptor(username, password string) interceptor.InterceptorFunc { +func AddBasicAuth(username, password string) interceptor.Middleware { return func(req *http.Request, next interceptor.HandlerFunc) (*http.Response, error) { clonedReq := req.Clone(req.Context()) clonedReq.SetBasicAuth(username, password) diff --git a/interceptors/auth_test.go b/interceptors/auth_test.go index 91cffa7..3adc882 100644 --- a/interceptors/auth_test.go +++ b/interceptors/auth_test.go @@ -10,7 +10,7 @@ import ( "github.com/fervbmx/interceptor/interceptors" ) -func TestBasicAuthInterceptor(t *testing.T) { +func TestAddBasicAuth(t *testing.T) { cases := []struct { name string username string @@ -28,8 +28,8 @@ func TestBasicAuthInterceptor(t *testing.T) { }, } - for _, c := range cases { - t.Run(c.name, func(t *testing.T) { + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { var username, password string var ok bool @@ -39,9 +39,9 @@ func TestBasicAuthInterceptor(t *testing.T) { t.Cleanup(server.Close) client := http.Client{ - Transport: interceptor.NewTransportInterceptor( + Transport: interceptor.NewTransport( http.DefaultTransport, - interceptors.BasicAuthInterceptor(c.username, c.password), + interceptors.AddBasicAuth(tc.username, tc.password), ), Timeout: 15 * time.Second, } @@ -50,8 +50,9 @@ func TestBasicAuthInterceptor(t *testing.T) { if err != nil { t.Fatalf("client.Get() returned error: %v", err) } + defer resp.Body.Close() - if resp.StatusCode != 200 { + if resp.StatusCode != http.StatusOK { t.Fatalf("unexpected status code: %d", resp.StatusCode) } @@ -59,12 +60,12 @@ func TestBasicAuthInterceptor(t *testing.T) { t.Fatal("BasicAuth() returned ok=false, want true") } - if username != c.username { - t.Errorf("username = %q, want %q", username, c.username) + if username != tc.username { + t.Errorf("username = %q, want %q", username, tc.username) } - if password != c.password { - t.Errorf("password = %q, want %q", password, c.password) + if password != tc.password { + t.Errorf("password = %q, want %q", password, tc.password) } }) } diff --git a/interceptors/headers.go b/interceptors/headers.go index 6503437..77a8690 100644 --- a/interceptors/headers.go +++ b/interceptors/headers.go @@ -6,13 +6,13 @@ import ( "github.com/fervbmx/interceptor" ) -// HeaderInterceptor returns an interceptor that sets a header on every outgoing +// AddHeader returns an interceptor that sets a header on every outgoing // request. // -// interceptor.NewTransportInterceptor(nil, -// interceptors.HeaderInterceptor("User-Agent", "MyApp/1.0"), +// interceptor.NewTransport(nil, +// interceptors.AddHeader("User-Agent", "MyApp/1.0"), // ) -func HeaderInterceptor(key, value string) interceptor.InterceptorFunc { +func AddHeader(key, value string) interceptor.Middleware { return func(req *http.Request, next interceptor.HandlerFunc) (*http.Response, error) { clonedReq := req.Clone(req.Context()) clonedReq.Header.Set(key, value) diff --git a/interceptors/headers_test.go b/interceptors/headers_test.go index 93ac304..f7db504 100644 --- a/interceptors/headers_test.go +++ b/interceptors/headers_test.go @@ -33,19 +33,19 @@ func TestHeaderInterceptor(t *testing.T) { }, } - for _, c := range cases { - t.Run(c.name, func(t *testing.T) { + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { var header string server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - header = r.Header.Get(c.key) + header = r.Header.Get(tc.key) })) t.Cleanup(server.Close) client := http.Client{ - Transport: interceptor.NewTransportInterceptor( + Transport: interceptor.NewTransport( http.DefaultTransport, - interceptors.HeaderInterceptor(c.key, c.value), + interceptors.AddHeader(tc.key, tc.value), ), Timeout: 15 * time.Second, } @@ -54,13 +54,14 @@ func TestHeaderInterceptor(t *testing.T) { if err != nil { t.Fatalf("client.Get() returned error: %v", err) } + defer resp.Body.Close() - if resp.StatusCode != 200 { + if resp.StatusCode != http.StatusOK { t.Fatalf("unexpected status code: %d", resp.StatusCode) } - if header != c.value { - t.Errorf("Header %q = %q, want %q", c.key, header, c.value) + if header != tc.value { + t.Errorf("Header %q = %q, want %q", tc.key, header, tc.value) } }) } diff --git a/interceptors/logging.go b/interceptors/logging.go index e3a9d54..e869408 100644 --- a/interceptors/logging.go +++ b/interceptors/logging.go @@ -20,7 +20,7 @@ var defaultSensitiveHeaders = []string{ "Set-Cookie", } -// LoggingOptions configures LoggingInterceptor behavior. +// LoggingOptions configures AddRequestLogging behavior. type LoggingOptions struct { // Logger receives structured attributes. // If nil, slog.Default() is used. @@ -59,8 +59,14 @@ type eventData struct { requestID string } -// LoggingInterceptor returns an interceptor that logs request lifecycle events. -func LoggingInterceptor(opts *LoggingOptions) interceptor.InterceptorFunc { +// ErrorTyper can be implemented by error types to provide a stable, +// human-readable classification label for structured logs. +type ErrorTyper interface { + ErrorType() string +} + +// AddRequestLogging returns an interceptor that logs request lifecycle events. +func AddRequestLogging(opts *LoggingOptions) interceptor.Middleware { cfg := buildLoggingConfig(opts) return func(req *http.Request, next interceptor.HandlerFunc) (*http.Response, error) { @@ -192,11 +198,6 @@ func emitLog(req *http.Request, cfg loggingConfig, event eventData) { cfg.logger.LogAttrs(req.Context(), event.level, event.message, attrs...) } -func sanitizeHeaderFieldKey(key string) string { - key = strings.ToLower(key) - return key -} - func buildAttrs(event eventData) []slog.Attr { attrs := make([]slog.Attr, 0, 6) @@ -207,7 +208,7 @@ func buildAttrs(event eventData) []slog.Attr { if len(event.requestHeaders) > 0 { headerAttrs := make([]any, 0, len(event.requestHeaders)) for key, value := range event.requestHeaders { - headerAttrs = append(headerAttrs, slog.String(sanitizeHeaderFieldKey(key), value)) + headerAttrs = append(headerAttrs, slog.String(strings.ToLower(key), value)) } requestAttrs = append(requestAttrs, slog.Group("header", headerAttrs...)) } @@ -288,6 +289,13 @@ func classifyErrorType(err error) string { return "" } + var typedErr ErrorTyper + if errors.As(err, &typedErr) { + if errorType := typedErr.ErrorType(); errorType != "" { + return errorType + } + } + root := err for { unwrapped := errors.Unwrap(root) diff --git a/interceptors/logging_test.go b/interceptors/logging_test.go index b49660d..d979490 100644 --- a/interceptors/logging_test.go +++ b/interceptors/logging_test.go @@ -5,15 +5,15 @@ import ( "context" "encoding/json" "errors" - "fmt" "io" "log/slog" "net/http" "net/http/httptest" + "net/url" + "strconv" "strings" "sync" "testing" - "time" "github.com/fervbmx/interceptor" "github.com/fervbmx/interceptor/interceptors" @@ -88,8 +88,8 @@ func TestLoggingInterceptor_StructuredAttrs(t *testing.T) { })) t.Cleanup(server.Close) - client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, - interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + client := &http.Client{Transport: interceptor.NewTransport(nil, + interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), )} req, err := http.NewRequest(http.MethodGet, server.URL+"/v1/users?page=2", nil) @@ -144,8 +144,8 @@ func TestLoggingInterceptor_StatusLevels(t *testing.T) { })) t.Cleanup(server.Close) - client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, - interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + client := &http.Client{Transport: interceptor.NewTransport(nil, + interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), )} resp, err := client.Get(server.URL) @@ -166,9 +166,9 @@ func TestLoggingInterceptor_StatusLevels(t *testing.T) { func TestLoggingInterceptor_TransportError(t *testing.T) { logger, sink := newCaptureLogger() - transport := interceptor.NewTransportInterceptor(roundTripperFunc(func(req *http.Request) (*http.Response, error) { + transport := interceptor.NewTransport(roundTripperFunc(func(req *http.Request) (*http.Response, error) { return nil, errors.New("dial tcp: connection refused") - }), interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger})) + }), interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger})) client := &http.Client{Transport: transport} _, err := client.Get("http://example.com") @@ -195,8 +195,8 @@ func TestLoggingInterceptor_HTTPErrorStatusSetsErrorType(t *testing.T) { })) t.Cleanup(server.Close) - client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, - interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + client := &http.Client{Transport: interceptor.NewTransport(nil, + interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), )} resp, err := client.Get(server.URL) @@ -217,8 +217,8 @@ func TestLoggingInterceptor_NoErrorTypeOnSuccess(t *testing.T) { })) t.Cleanup(server.Close) - client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, - interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + client := &http.Client{Transport: interceptor.NewTransport(nil, + interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), )} resp, err := client.Get(server.URL) @@ -237,13 +237,12 @@ func TestLoggingInterceptor_Duration(t *testing.T) { logger, sink := newCaptureLogger() server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - time.Sleep(10 * time.Millisecond) w.WriteHeader(http.StatusOK) })) t.Cleanup(server.Close) - client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, - interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + client := &http.Client{Transport: interceptor.NewTransport(nil, + interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), )} resp, err := client.Get(server.URL) @@ -260,9 +259,6 @@ func TestLoggingInterceptor_Duration(t *testing.T) { if duration <= 0 { t.Fatalf("http.client.request.duration = %v, want > 0", duration) } - if duration >= 1 { - t.Fatalf("http.client.request.duration = %v, want < 1 for a 10ms sleep", duration) - } } func TestLoggingInterceptor_SensitiveHeaderRedaction(t *testing.T) { @@ -273,14 +269,17 @@ func TestLoggingInterceptor_SensitiveHeaderRedaction(t *testing.T) { })) t.Cleanup(server.Close) - client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, - interceptors.LoggingInterceptor(&interceptors.LoggingOptions{ + client := &http.Client{Transport: interceptor.NewTransport(nil, + interceptors.AddRequestLogging(&interceptors.LoggingOptions{ Logger: logger, HeadersToLog: []string{"Authorization", "Cookie"}, }), )} - req, _ := http.NewRequest(http.MethodGet, server.URL, nil) + req, err := http.NewRequest(http.MethodGet, server.URL, nil) + if err != nil { + t.Fatalf("http.NewRequest(%q) error: %v", server.URL, err) + } req.Header.Set("Authorization", "Bearer top-secret") req.Header.Set("Cookie", "session=secret") @@ -303,14 +302,17 @@ func TestLoggingInterceptor_CustomHeaders(t *testing.T) { })) t.Cleanup(server.Close) - client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, - interceptors.LoggingInterceptor(&interceptors.LoggingOptions{ + client := &http.Client{Transport: interceptor.NewTransport(nil, + interceptors.AddRequestLogging(&interceptors.LoggingOptions{ Logger: logger, HeadersToLog: []string{"X-Correlation-ID"}, }), )} - req, _ := http.NewRequest(http.MethodGet, server.URL, nil) + req, err := http.NewRequest(http.MethodGet, server.URL, nil) + if err != nil { + t.Fatalf("http.NewRequest(%q) error: %v", server.URL, err) + } req.Header.Set("X-Correlation-ID", "corr-1") resp, err := client.Do(req) @@ -329,8 +331,8 @@ func TestLoggingInterceptor_NilOptions(t *testing.T) { })) t.Cleanup(server.Close) - client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, - interceptors.LoggingInterceptor(nil), + client := &http.Client{Transport: interceptor.NewTransport(nil, + interceptors.AddRequestLogging(nil), )} resp, err := client.Get(server.URL) @@ -352,10 +354,10 @@ func TestLoggingInterceptor_ChainPosition(t *testing.T) { })) t.Cleanup(server.Close) - client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, - interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), - interceptors.HeaderInterceptor("X-Req-Id", "req-1"), - interceptors.BasicAuthInterceptor("user", "pass"), + client := &http.Client{Transport: interceptor.NewTransport(nil, + interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), + interceptors.AddHeader("X-Req-Id", "req-1"), + interceptors.AddBasicAuth("user", "pass"), )} resp, err := client.Get(server.URL) @@ -383,8 +385,8 @@ func TestLoggingInterceptor_Concurrent(t *testing.T) { })) t.Cleanup(server.Close) - client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, - interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + client := &http.Client{Transport: interceptor.NewTransport(nil, + interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), )} const total = 50 @@ -416,7 +418,7 @@ func TestLoggingInterceptor_RequestImmutability(t *testing.T) { } originalReq.Header.Set("X-Original", "keep") - transport := interceptor.NewTransportInterceptor( + transport := interceptor.NewTransport( roundTripperFunc(func(req *http.Request) (*http.Response, error) { if req == originalReq { t.Fatal("downstream received original request pointer; expected clone") @@ -432,7 +434,7 @@ func TestLoggingInterceptor_RequestImmutability(t *testing.T) { } return &http.Response{StatusCode: http.StatusOK, Body: io.NopCloser(strings.NewReader("ok"))}, nil }), - interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), func(req *http.Request, next interceptor.HandlerFunc) (*http.Response, error) { req.Header.Set("X-Mutated", "yes") req.Method = http.MethodPut @@ -468,8 +470,8 @@ func TestLoggingInterceptor_WithJSONHandler(t *testing.T) { var out bytes.Buffer logger := slog.New(slog.NewJSONHandler(&out, nil)) - client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, - interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + client := &http.Client{Transport: interceptor.NewTransport(nil, + interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), )} resp, err := client.Get(server.URL + "/json") @@ -488,7 +490,10 @@ func TestLoggingInterceptor_WithJSONHandler(t *testing.T) { if !ok { t.Fatalf("http group missing: %v", first) } - requestMap := httpMap["request"].(map[string]any) + requestMap, ok := httpMap["request"].(map[string]any) + if !ok { + t.Fatalf("http[request] missing or wrong type, got: %T", httpMap["request"]) + } if requestMap["method"] != "GET" { t.Fatalf("http.request.method = %v, want GET", requestMap["method"]) } @@ -503,8 +508,8 @@ func TestLoggingInterceptor_WithTextHandler(t *testing.T) { var out bytes.Buffer logger := slog.New(slog.NewTextHandler(&out, nil)) - client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, - interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + client := &http.Client{Transport: interceptor.NewTransport(nil, + interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), )} resp, err := client.Get(server.URL + "/text") @@ -545,8 +550,8 @@ func TestLoggingInterceptor_HandlerOptions_ReplaceAttr(t *testing.T) { }, })) - client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, - interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + client := &http.Client{Transport: interceptor.NewTransport(nil, + interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), )} resp, err := client.Get(server.URL) @@ -564,8 +569,14 @@ func TestLoggingInterceptor_HandlerOptions_ReplaceAttr(t *testing.T) { lines := splitLines(out.String()) first := decodeJSONMap(t, lines[0]) - httpMap := first["http"].(map[string]any) - requestMap := httpMap["request"].(map[string]any) + httpMap, ok := first["http"].(map[string]any) + if !ok { + t.Fatalf("http group missing or wrong type: %T", first["http"]) + } + requestMap, ok := httpMap["request"].(map[string]any) + if !ok { + t.Fatalf("http[request] missing or wrong type, got: %T", httpMap["request"]) + } if requestMap["method"] != "OVERRIDDEN" { t.Fatalf("http.request.method = %v, want OVERRIDDEN", requestMap["method"]) } @@ -580,8 +591,8 @@ func TestLoggingInterceptor_HandlerOptions_Level(t *testing.T) { var out bytes.Buffer logger := slog.New(slog.NewJSONHandler(&out, &slog.HandlerOptions{Level: slog.LevelError})) - client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, - interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + client := &http.Client{Transport: interceptor.NewTransport(nil, + interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), )} resp, err := client.Get(server.URL) @@ -605,14 +616,17 @@ func TestLoggingInterceptor_OTelAttributeNames(t *testing.T) { })) t.Cleanup(server.Close) - client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, - interceptors.LoggingInterceptor(&interceptors.LoggingOptions{ + client := &http.Client{Transport: interceptor.NewTransport(nil, + interceptors.AddRequestLogging(&interceptors.LoggingOptions{ Logger: logger, HeadersToLog: []string{"Content-Type"}, }), )} - req, _ := http.NewRequest(http.MethodPost, server.URL+"/otel", strings.NewReader("abc")) + req, err := http.NewRequest(http.MethodPost, server.URL+"/otel", strings.NewReader("abc")) + if err != nil { + t.Fatalf("http.NewRequest(%q) error: %v", server.URL+"/otel", err) + } req.Header.Set("Content-Type", "application/json") req.Header.Set("User-Agent", "otel-test/1.0") @@ -650,8 +664,8 @@ func TestLoggingInterceptor_ServerAddressAndPort(t *testing.T) { })) t.Cleanup(server.Close) - client := &http.Client{Transport: interceptor.NewTransportInterceptor(nil, - interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger}), + client := &http.Client{Transport: interceptor.NewTransport(nil, + interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), )} resp, err := client.Get(server.URL) @@ -666,12 +680,15 @@ func TestLoggingInterceptor_ServerAddressAndPort(t *testing.T) { }) t.Run("explicit https default port", func(t *testing.T) { - transport := interceptor.NewTransportInterceptor(roundTripperFunc(func(req *http.Request) (*http.Response, error) { + transport := interceptor.NewTransport(roundTripperFunc(func(req *http.Request) (*http.Response, error) { return &http.Response{StatusCode: http.StatusOK, Body: io.NopCloser(strings.NewReader("ok"))}, nil - }), interceptors.LoggingInterceptor(&interceptors.LoggingOptions{Logger: logger})) + }), interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger})) client := &http.Client{Transport: transport} - req, _ := http.NewRequest(http.MethodGet, "https://example.com/resource", nil) + req, err := http.NewRequest(http.MethodGet, "https://example.com/resource", nil) + if err != nil { + t.Fatalf("http.NewRequest(%q) error: %v", "https://example.com/resource", err) + } resp, err := client.Do(req) if err != nil { t.Fatalf("client.Do error: %v", err) @@ -763,25 +780,13 @@ func assertGroupPathInt64(t *testing.T, attrs map[string]any, path string, want func mustServerPort(t *testing.T, rawURL string) int { t.Helper() - var hostPort string - if strings.HasPrefix(rawURL, "http://") { - hostPort = strings.TrimPrefix(rawURL, "http://") - } else if strings.HasPrefix(rawURL, "https://") { - hostPort = strings.TrimPrefix(rawURL, "https://") - } else { - t.Fatalf("unsupported URL: %s", rawURL) - } - if idx := strings.Index(hostPort, "/"); idx >= 0 { - hostPort = hostPort[:idx] - } - parts := strings.Split(hostPort, ":") - if len(parts) != 2 { - t.Fatalf("expected host:port in URL: %s", rawURL) - } - var port int - _, err := fmt.Sscanf(parts[1], "%d", &port) + u, err := url.Parse(rawURL) + if err != nil { + t.Fatalf("url.Parse(%q) error: %v", rawURL, err) + } + port, err := strconv.Atoi(u.Port()) if err != nil { - t.Fatalf("failed parsing port from %q: %v", rawURL, err) + t.Fatalf("strconv.Atoi(%q) error: %v", u.Port(), err) } return port } diff --git a/transport.go b/transport.go index 54f9715..cea7bcd 100644 --- a/transport.go +++ b/transport.go @@ -9,57 +9,57 @@ import "net/http" // It takes an HTTP request and returns a response or error. type HandlerFunc func(req *http.Request) (*http.Response, error) -// InterceptorFunc defines an interceptor. It receives the outgoing request and +// Middleware defines an interceptor. It receives the outgoing request and // a next function representing the next processing step in the interceptor // chain. -type InterceptorFunc func(req *http.Request, next HandlerFunc) (*http.Response, error) +type Middleware func(req *http.Request, next HandlerFunc) (*http.Response, error) -// TransportInterceptor implements http.RoundTripper by running a chain of interceptors +// Transport implements http.RoundTripper by running a chain of interceptors // in front of a default transport. -type TransportInterceptor struct { +type Transport struct { defaultTransport http.RoundTripper - interceptors []InterceptorFunc + interceptors []Middleware } -// NewTransportInterceptor creates a new TransportInterceptor with the given default RoundTripper +// NewTransport creates a new Transport with the given default RoundTripper // and interceptors. If defaultTransport is nil, http.DefaultTransport is used. // Interceptors are executed in the order provided. // // // Using the default transport: // client := &http.Client{ -// Transport: interceptor.NewTransportInterceptor(nil, AInterceptor, BInterceptor), +// Transport: interceptor.NewTransport(nil, AInterceptor, BInterceptor), // } // // // Using a custom default transport: // client := &http.Client{ -// Transport: interceptor.NewTransportInterceptor(customTransport, AInterceptor, BInterceptor), +// Transport: interceptor.NewTransport(customTransport, AInterceptor, BInterceptor), // } // // With this configuration, a request flows as: // // AInterceptor → BInterceptor → customTransport -func NewTransportInterceptor(defaultTransport http.RoundTripper, interceptors ...InterceptorFunc) *TransportInterceptor { +func NewTransport(defaultTransport http.RoundTripper, interceptors ...Middleware) *Transport { if defaultTransport == nil { defaultTransport = http.DefaultTransport } - return &TransportInterceptor{ + return &Transport{ defaultTransport: defaultTransport, interceptors: interceptors, } } -// Use appends one or more interceptors to the chain. They are appended after +// Add appends one or more interceptors to the chain. They are appended after // any interceptors already registered. // -// t := interceptor.NewTransportInterceptor(nil, AuthInterceptor).Use(MetricsInterceptor) +// t := interceptor.NewTransport(nil, AuthInterceptor).Add(MetricsInterceptor) // // order: AuthInterceptor → MetricsInterceptor → default transport -func (t *TransportInterceptor) Use(interceptors ...InterceptorFunc) *TransportInterceptor { +func (t *Transport) Add(interceptors ...Middleware) *Transport { t.interceptors = append(t.interceptors, interceptors...) return t } // RoundTrip executes the interceptor chain and then the underlying transport. -func (t *TransportInterceptor) RoundTrip(req *http.Request) (*http.Response, error) { +func (t *Transport) RoundTrip(req *http.Request) (*http.Response, error) { // Build the final handler that delegates to the default transport. final := HandlerFunc(func(r *http.Request) (*http.Response, error) { return t.defaultTransport.RoundTrip(r) @@ -69,13 +69,13 @@ func (t *TransportInterceptor) RoundTrip(req *http.Request) (*http.Response, err // registered is the first to process the request (outermost). handler := final for i := len(t.interceptors) - 1; i >= 0; i-- { - interceptor := t.interceptors[i] + fn := t.interceptors[i] next := handler - handler = func(i InterceptorFunc, n HandlerFunc) HandlerFunc { + handler = func(fn Middleware, n HandlerFunc) HandlerFunc { return func(r *http.Request) (*http.Response, error) { - return i(r, n) + return fn(r, n) } - }(interceptor, next) + }(fn, next) } return handler(req) diff --git a/transport_test.go b/transport_test.go index 3f563e0..f5dbdbb 100644 --- a/transport_test.go +++ b/transport_test.go @@ -9,7 +9,7 @@ import ( "github.com/fervbmx/interceptor" ) -func TestTransportInterceptor(t *testing.T) { +func TestTransport(t *testing.T) { var order []string server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {})) @@ -24,8 +24,8 @@ func TestTransportInterceptor(t *testing.T) { return next(req) } - tp := interceptor.NewTransportInterceptor(nil, aInterceptor) - tp.Use(bInterceptor) + tp := interceptor.NewTransport(nil, aInterceptor) + tp.Add(bInterceptor) client := &http.Client{ Transport: tp, @@ -36,8 +36,9 @@ func TestTransportInterceptor(t *testing.T) { if err != nil { t.Fatalf("client.Get() returned error: %v", err) } + defer resp.Body.Close() - if resp.StatusCode != 200 { + if resp.StatusCode != http.StatusOK { t.Fatalf("unexpected status code: %d", resp.StatusCode) } From a6ee82614fe88728e8489b54c38186d69f237817 Mon Sep 17 00:00:00 2001 From: Fabian Esteban Ruiz Valdes Date: Wed, 11 Mar 2026 14:46:04 -0500 Subject: [PATCH 09/19] feat(logging): improve logging --- interceptors/logging.go | 21 +++++++++++---------- transport.go | 12 +++--------- 2 files changed, 14 insertions(+), 19 deletions(-) diff --git a/interceptors/logging.go b/interceptors/logging.go index e869408..15ce214 100644 --- a/interceptors/logging.go +++ b/interceptors/logging.go @@ -20,18 +20,12 @@ var defaultSensitiveHeaders = []string{ "Set-Cookie", } -// LoggingOptions configures AddRequestLogging behavior. type LoggingOptions struct { - // Logger receives structured attributes. - // If nil, slog.Default() is used. + Logger *slog.Logger - // HeadersToLog is a request header allowlist. - // Empty means no additional headers are logged. HeadersToLog []string - // SensitiveHeaders lists header names to redact as "***". - // Defaults to Authorization, Cookie, and Set-Cookie. SensitiveHeaders []string } @@ -59,13 +53,20 @@ type eventData struct { requestID string } -// ErrorTyper can be implemented by error types to provide a stable, -// human-readable classification label for structured logs. type ErrorTyper interface { ErrorType() string } -// AddRequestLogging returns an interceptor that logs request lifecycle events. +// AddRequestLogging returns an interceptor that logs request lifecycle events +// before and after the next handler runs. It emits a start event, then either a +// completion event or a failure event. If opts is nil, default logging options +// are used. +// +// interceptor.NewTransport(nil, +// interceptors.AddRequestLogging( +// Logging: logging +// ), +// ) func AddRequestLogging(opts *LoggingOptions) interceptor.Middleware { cfg := buildLoggingConfig(opts) diff --git a/transport.go b/transport.go index cea7bcd..ec82ca1 100644 --- a/transport.go +++ b/transport.go @@ -34,10 +34,6 @@ type Transport struct { // client := &http.Client{ // Transport: interceptor.NewTransport(customTransport, AInterceptor, BInterceptor), // } -// -// With this configuration, a request flows as: -// -// AInterceptor → BInterceptor → customTransport func NewTransport(defaultTransport http.RoundTripper, interceptors ...Middleware) *Transport { if defaultTransport == nil { defaultTransport = http.DefaultTransport @@ -52,21 +48,19 @@ func NewTransport(defaultTransport http.RoundTripper, interceptors ...Middleware // any interceptors already registered. // // t := interceptor.NewTransport(nil, AuthInterceptor).Add(MetricsInterceptor) -// // order: AuthInterceptor → MetricsInterceptor → default transport func (t *Transport) Add(interceptors ...Middleware) *Transport { t.interceptors = append(t.interceptors, interceptors...) return t } -// RoundTrip executes the interceptor chain and then the underlying transport. +// RoundTrip executes the interceptor chain. The underlying transport is reached +// only if each interceptor calls next. func (t *Transport) RoundTrip(req *http.Request) (*http.Response, error) { - // Build the final handler that delegates to the default transport. + final := HandlerFunc(func(r *http.Request) (*http.Response, error) { return t.defaultTransport.RoundTrip(r) }) - // Wrap interceptors in reverse order so that the first interceptor - // registered is the first to process the request (outermost). handler := final for i := len(t.interceptors) - 1; i >= 0; i-- { fn := t.interceptors[i] From a9feb2b93f4e9b46fe4efc8bf05077628c9f6222 Mon Sep 17 00:00:00 2001 From: Fabian Esteban Ruiz Valdes Date: Wed, 11 Mar 2026 14:46:30 -0500 Subject: [PATCH 10/19] feat(logging): improve logging --- PRD.md | 442 --------------------------------------------------------- 1 file changed, 442 deletions(-) delete mode 100644 PRD.md diff --git a/PRD.md b/PRD.md deleted file mode 100644 index 797ff47..0000000 --- a/PRD.md +++ /dev/null @@ -1,442 +0,0 @@ -# PRD — `github.com/fervbmx/interceptor` Code Quality Cleanup - -**Status:** Complete -**Author:** Fabian Ruiz -**Audience:** Repository maintainer(s) / contributing engineers -**Scope:** Post-review improvement pass — naming, documentation, testing, and implementation quality - ---- - -## 1. Background - -The `interceptor` library provides a composable HTTP middleware system for Go's `http.RoundTripper`. The library consists of a root package (`interceptor`) that defines the core chain-building infrastructure, and a sub-package (`interceptors`) that ships a set of ready-made implementations for auth, header injection, and structured logging. - -A full code review was conducted on the library. The review found it to be **functionally correct** and architecturally sound. However, several issues were identified across four categories — naming, documentation, testing, and implementation — that need to be addressed before the library can be considered idiomatic Go and ready for wider adoption. - -This document captures those findings as actionable engineering requirements organized into delivery phases. - ---- - -## 2. Goals - -- Bring the public API naming in line with idiomatic Go conventions. -- Ensure all exported symbols are properly documented. -- Eliminate test anti-patterns that hide failures or leak resources. -- Remove unnecessary abstractions and document non-obvious implementation choices. - -## 3. Non-Goals - -- Changing the library's architecture or adding new interceptors. -- Performance optimizations. -- Adding CI/CD pipelines or release automation. -- Any changes to behavior observable at runtime. - ---- - -## 4. Delivery Phases - -The requirements are grouped into four phases. Each phase is designed to be delivered as an independent unit — ideally a single pull request — with a clear rationale for the grouping. - -``` -Phase 1 → Public API + Docs (breaking, bump major version) -Phase 2 → Test Correctness (non-breaking, MUST fixes) -Phase 3 → Test Quality (non-breaking, CONSIDER fixes) -Phase 4 → Implementation Polish (non-breaking, CONSIDER fixes) -``` - -> **Note on breaking changes:** Phase 1 renames exported symbols. This is a semver-breaking change. Phases 2–4 are strictly internal and non-breaking for library consumers. - ---- - -## 5. Requirements - -Requirements are tagged with a severity tier: - -- **[MUST]** — Required for idiomatic Go and API correctness. These block a stable release. -- **[CONSIDER]** — Improvements that meaningfully reduce maintenance burden or test reliability. Strongly recommended. - -Each requirement includes an **Acceptance Criterion** that defines what "done" looks like. - ---- - -### Phase 1 — Public API & Documentation - -**Rationale:** All breaking changes to exported names are batched here so they land in a single semver bump. This phase should be merged before any other phase to avoid downstream churn. - ---- - -#### REQ-N-01 · [MUST] Remove redundant `Interceptor` suffix from `interceptors` sub-package exports - -**Category:** Naming -**Files:** `interceptors/auth.go`, `interceptors/headers.go`, `interceptors/logging.go` - -**Problem:** -The exported functions `BasicAuthInterceptor`, `HeaderInterceptor`, and `LoggingInterceptor` all include the word `Interceptor` as a suffix. Because these symbols live in the `interceptors` package, callers already write `interceptors.BasicAuthInterceptor(...)`. The suffix is redundant noise — it provides no additional information. Package-qualified names should not stutter. - -**Required Change:** - -| Before | After | -|---|---| -| `func BasicAuthInterceptor(...)` | `func BasicAuth(...)` | -| `func HeaderInterceptor(...)` | `func AddHeader(...)` | -| `func LoggingInterceptor(...)` | `func Logging(...)` | - -**Acceptance Criterion:** -All three functions are renamed. No exported identifier in the `interceptors` package repeats the word "interceptor". All callers (including tests) are updated to use the new names. `go vet` and `go build ./...` pass with no errors. - ---- - -#### REQ-N-02 · [MUST] Remove redundant package-name repetition from root `interceptor` package types - -**Category:** Naming -**File:** `transport.go` - -**Problem:** -The root package is named `interceptor`. The types `InterceptorFunc` and `TransportInterceptor`, and the constructor `NewTransportInterceptor`, all contain the word "interceptor" — which is already provided by the package qualifier. Callers write `interceptor.InterceptorFunc` and `interceptor.TransportInterceptor`, making the names stutter. The Go standard library does not repeat the package name in type names (`http.Transport`, `http.Handler`, `http.HandlerFunc` — not `http.HTTPTransport`). `HandlerFunc` is **not** affected by this issue since `Handler` does not repeat the package name. - -**Required Change:** - -| Before | After | -|---|---| -| `type InterceptorFunc func(...)` | `type Middleware func(...)` | -| `type TransportInterceptor struct` | `type Transport struct` | -| `func NewTransportInterceptor(...)` | `func New(...)` or `func NewTransport(...)` | - -> **Note on constructor naming:** If more than one constructor is anticipated in the future, prefer `NewTransport`. If this is the sole constructor for the package's primary type, `New` is idiomatic (see `errors.New`, `ring.New`, `list.New`). - -**Acceptance Criterion:** -Types and constructor are renamed. All references across `transport.go`, `transport_test.go`, and the `interceptors` sub-package are updated. `go build ./...` and `go test ./...` pass. - ---- - -#### REQ-N-03 · [MUST] Rename loop variable `interceptor` in `RoundTrip` to avoid shadowing the package name - -**Category:** Naming -**File:** `transport.go`, `RoundTrip` method - -**Problem:** -Inside the reverse-iteration loop in `RoundTrip`, the code declares: - -```go -interceptor := t.interceptors[i] -``` - -This local variable shadows the imported package name `interceptor` for the remainder of the loop body. Any future developer adding a reference to the `interceptor` package inside that block would silently get the local variable instead, leading to a confusing compile error or incorrect behavior. Additionally, the IIFE parameter `i` shadows the loop counter `i`. - -**Required Change:** -Rename the loop variable to `fn` and the IIFE parameter accordingly: - -```go -for i := len(t.interceptors) - 1; i >= 0; i-- { - fn := t.interceptors[i] - next := handler - handler = func(fn Func, n HandlerFunc) HandlerFunc { - return func(r *http.Request) (*http.Response, error) { - return fn(r, n) - } - }(fn, next) -} -``` - -**Acceptance Criterion:** -No local variable in `transport.go` shadows an imported package name. `go vet ./...` passes. The chain-ordering behavior is unchanged and verified by existing tests. - ---- - -### Phase 2 — Test Correctness - -**Rationale:** These are the MUST-fix test issues. They either hide real failures (swallowed errors, unhandled panics) or leak resources (unclosed response bodies, invalid Go version). They should be fixed before Phase 3 so that the test suite is trustworthy as a baseline going forward. None of these changes are visible to library consumers. - ---- - -#### REQ-T-01 · [MUST] Close response bodies in all tests that make HTTP requests - -**Category:** Testing -**File:** `transport_test.go` - -**Problem:** -`TestTransportInterceptor` calls `client.Get(...)` but never closes `resp.Body`. This leaks the underlying connection back to the `httptest.Server`'s pool and can cause unpredictable behavior in parallel test runs. - -**Required Change:** -Add `defer resp.Body.Close()` immediately after verifying the error: - -```go -resp, err := client.Get(server.URL) -if err != nil { - t.Fatalf("client.Get() returned error: %v", err) -} -defer resp.Body.Close() -``` - -**Acceptance Criterion:** -All test functions that receive an `*http.Response` call `resp.Body.Close()` (via `defer` or explicit call before return). Running `go test -race ./...` produces no data-race warnings related to response body reads. - ---- - -#### REQ-T-02 · [MUST] Replace HTTP status code literals with named constants - -**Category:** Testing -**Files:** `transport_test.go`, `auth_test.go`, `headers_test.go` - -**Problem:** -Multiple test assertions compare `resp.StatusCode` against the integer literal `200`. The `net/http` package exports `http.StatusOK` precisely to avoid magic numbers in code. Using the literal reduces readability and diverges from the style used everywhere else in the codebase. - -**Required Change:** - -```go -// Before: -if resp.StatusCode != 200 { - -// After: -if resp.StatusCode != http.StatusOK { -``` - -**Acceptance Criterion:** -No integer literal HTTP status codes appear in any test file. All status comparisons use `http.Status*` constants. - ---- - -#### REQ-T-03 · [MUST] Handle errors from `http.NewRequest` in all tests - -**Category:** Testing -**File:** `logging_test.go` - -**Problem:** -At least four test cases silently discard the error return from `http.NewRequest` using the blank identifier (`req, _ := ...`). When `http.NewRequest` fails, `req` is `nil`, and the next line that uses `req` will panic with a nil pointer dereference. This results in a cryptic, non-actionable failure message instead of a clear test diagnostic. - -**Affected tests:** -- `TestLoggingInterceptor_SensitiveHeaderRedaction` -- `TestLoggingInterceptor_CustomHeaders` -- `TestLoggingInterceptor_OTelAttributeNames` -- `TestLoggingInterceptor_ServerAddressAndPort` - -**Required Change:** - -```go -// Before: -req, _ := http.NewRequest(http.MethodGet, server.URL, nil) - -// After: -req, err := http.NewRequest(http.MethodGet, server.URL, nil) -if err != nil { - t.Fatalf("http.NewRequest(%q) error: %v", server.URL, err) -} -``` - -**Acceptance Criterion:** -No test file uses `req, _` to discard errors from `http.NewRequest` or any other function that returns `error`. All such errors are checked and reported via `t.Fatalf`. - ---- - -### Phase 3 — Test Quality - -**Rationale:** These are the CONSIDER items scoped to the test layer. They improve consistency, safety, and speed of the test suite without altering any production code. Grouping them together makes for a clean, self-contained PR that is easy to review. - ---- - -#### REQ-T-04 · [CONSIDER] Unify table-driven test loop variable name to `tc` - -**Category:** Testing -**Files:** `auth_test.go`, `headers_test.go` (use `c`), `logging_test.go` (uses `tc`) - -**Problem:** -The two styles are inconsistent across the same test suite. The idiomatic Go convention for table-driven tests is `tc` (short for "test case"). - -**Required Change:** - -```go -// Before (auth_test.go, headers_test.go): -for _, c := range cases { - t.Run(c.name, func(t *testing.T) { ... c.key ... }) -} - -// After: -for _, tc := range cases { - t.Run(tc.name, func(t *testing.T) { ... tc.key ... }) -} -``` - -**Acceptance Criterion:** -All table-driven tests in all files use `tc` as the loop variable name. - ---- - -#### REQ-T-05 · [CONSIDER] Simplify `mustServerPort` using `net/url` - -**Category:** Testing -**File:** `logging_test.go` - -**Problem:** -The `mustServerPort` helper manually strips URL schemes with `strings.HasPrefix` / `strings.TrimPrefix` and then splits on `:` to find the port. This is fragile — it would silently break on URLs with user info or non-standard formatting. The standard library provides `url.Parse` precisely for this purpose. - -**Required Change:** - -```go -func mustServerPort(t *testing.T, rawURL string) int { - t.Helper() - u, err := url.Parse(rawURL) - if err != nil { - t.Fatalf("url.Parse(%q) error: %v", rawURL, err) - } - port, err := strconv.Atoi(u.Port()) - if err != nil { - t.Fatalf("strconv.Atoi(%q) error: %v", u.Port(), err) - } - return port -} -``` - -**Acceptance Criterion:** -`mustServerPort` uses `url.Parse` and `u.Port()` with no manual string manipulation. All existing tests that call `mustServerPort` continue to pass. - ---- - -#### REQ-T-06 · [CONSIDER] Use safe two-value type assertions in JSON-parsing tests - -**Category:** Testing -**File:** `logging_test.go` - -**Problem:** -`TestLoggingInterceptor_WithJSONHandler` and `TestLoggingInterceptor_HandlerOptions_ReplaceAttr` use single-value type assertions on `map[string]any` lookups: - -```go -requestMap := httpMap["request"].(map[string]any) -``` - -If the key is absent or the underlying type does not match, this will **panic** with no test context, making the failure very hard to diagnose. The idiomatic approach is to use the comma-ok form and call `t.Fatalf`. - -**Required Change:** - -```go -requestMap, ok := httpMap["request"].(map[string]any) -if !ok { - t.Fatalf("http[request] missing or wrong type, got: %T", httpMap["request"]) -} -``` - -**Acceptance Criterion:** -No unsafe (single-value) type assertions remain in test files for keys retrieved from `map[string]any`. All assertions use the comma-ok form and call `t.Fatal` on failure. - ---- - -#### REQ-T-07 · [CONSIDER] Remove `time.Sleep` from `TestLoggingInterceptor_Duration` - -**Category:** Testing -**File:** `logging_test.go` - -**Problem:** -The test makes the server sleep for 10ms before responding, then verifies that the logged duration is a float64 less than 1 second. The sleep adds unnecessary latency to the test suite and is sensitive to slow CI environments. The actual requirement — that duration is a positive float64 — does not need a sleep to be verified. - -**Required Change:** -Remove the `time.Sleep` from the handler and tighten the assertion to only check `duration > 0`: - -```go -// Server handler — remove the sleep: -server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - w.WriteHeader(http.StatusOK) -})) - -// Assertion — check only that duration is positive: -if duration <= 0 { - t.Fatalf("http.client.request.duration = %v, want > 0", duration) -} -``` - -**Acceptance Criterion:** -`TestLoggingInterceptor_Duration` contains no `time.Sleep` calls. The test verifies that duration is a positive float64 value. `go test -count=5 ./...` passes consistently. - ---- - -### Phase 4 — Implementation Polish - -**Rationale:** These are internal code quality improvements that do not touch the public API or the tests. They reduce future maintenance cost and improve the long-term readability of `interceptors/logging.go`. Because they are the lowest urgency and most self-contained, they are best left for last so they don't block any other work. - ---- - -#### REQ-I-01 · [CONSIDER] Inline or remove `sanitizeHeaderFieldKey` - -**Category:** Implementation -**File:** `interceptors/logging.go` - -**Problem:** -`sanitizeHeaderFieldKey` is a private function whose entire body is: - -```go -func sanitizeHeaderFieldKey(key string) string { - key = strings.ToLower(key) - return key -} -``` - -It wraps a single call to `strings.ToLower` with no additional logic. The name implies sanitization (validation, filtering) but performs only a case conversion. This is a misleading abstraction that adds indirection without value. - -**Required Change:** -Remove the function and call `strings.ToLower(key)` directly at the call site(s). - -**Acceptance Criterion:** -`sanitizeHeaderFieldKey` no longer exists. All former call sites use `strings.ToLower` directly. `go build ./...` passes. - ---- - -#### REQ-I-02 · [CONSIDER] Add a comment explaining the `reflect`-based error classification in `classifyErrorType` - -**Category:** Implementation -**File:** `interceptors/logging.go` - -**Problem:** -`classifyErrorType` uses `reflect.TypeOf` to derive a string label for the type of an error. This is functional but fragile: type names are implementation details that can change with refactoring, silently altering logged values in production. There is no comment explaining why this approach was chosen over alternatives (e.g., an `ErrorTyper` interface), which makes the decision invisible to future maintainers. - -**Required Change — Option A (minimum):** -Add a comment documenting the tradeoff: - -```go -// classifyErrorType derives a human-readable label for the concrete type of err. -// It uses reflection because error types are not required to self-describe their -// kind. Note: type names are implementation details and may change with refactors; -// callers relying on specific values in logs should define types that implement -// ErrorTyper instead. -``` - -**Required Change — Option B (recommended):** -Expose an `ErrorTyper` interface that error types can implement to opt into stable labels, and fall back to reflect only when the interface is not implemented: - -```go -// ErrorTyper can be implemented by error types to provide a stable, -// human-readable classification label for structured logs. -type ErrorTyper interface { - ErrorType() string -} -``` - -**Acceptance Criterion (Option A):** The function has a godoc comment explaining the reflect usage and its limitations. -**Acceptance Criterion (Option B):** An `ErrorTyper` interface is defined and checked before the reflect fallback. The interface is exported and documented. - ---- - -## 6. Out of Scope - -The following items were considered during the review and **deliberately excluded** from this document: - -- **Architectural changes** — The split between the root `interceptor` package and the `interceptors` sub-package is sound and will not be changed. -- **New interceptor implementations** — Adding new ready-made interceptors (e.g., retry, timeout, metrics) is a feature request, not a cleanup task. -- **API versioning strategy** — The renaming in REQ-N-01 and REQ-N-02 constitutes a breaking change to the public API. How this is communicated to users (semver, deprecation notices, migration guide) is outside the scope of this document. -- **`t.Parallel()`** — Adding parallel test execution is a valid improvement but is a separate concern from the quality issues identified here. - ---- - -## 7. Summary Table - -| Phase | ID | Severity | Category | Title | -|---|---|---|---|---| -| 1 | REQ-N-01 | MUST | Naming | Remove redundant `Interceptor` suffix from `interceptors` exports | -| 1 | REQ-N-02 | MUST | Naming | Remove package-name repetition from root `interceptor` types | -| 1 | REQ-N-03 | MUST | Naming | Rename loop variable `interceptor` to avoid package shadowing | -| 2 | REQ-T-01 | MUST | Testing | Close response bodies in all tests | -| 2 | REQ-T-02 | MUST | Testing | Replace HTTP status literals with `http.Status*` constants | -| 2 | REQ-T-03 | MUST | Testing | Handle errors from `http.NewRequest` in all tests | -| 3 | REQ-T-04 | CONSIDER | Testing | Unify table-driven test loop variable name to `tc` | -| 3 | REQ-T-05 | CONSIDER | Testing | Simplify `mustServerPort` using `net/url` | -| 3 | REQ-T-06 | CONSIDER | Testing | Use safe two-value type assertions in JSON-parsing tests | -| 3 | REQ-T-07 | CONSIDER | Testing | Remove `time.Sleep` from duration test | -| 4 | REQ-I-01 | CONSIDER | Implementation | Inline or remove `sanitizeHeaderFieldKey` | -| 4 | REQ-I-02 | CONSIDER | Implementation | Document or improve `classifyErrorType` reflect usage | From deade7c3f95267088eaac5b3fee9aac9ff5cedfa Mon Sep 17 00:00:00 2001 From: Fabian Esteban Ruiz Valdes Date: Wed, 11 Mar 2026 15:38:01 -0500 Subject: [PATCH 11/19] feat(logging): improve logging --- interceptors/logging.go | 166 ++++++---- interceptors/logging_test.go | 615 ++++++----------------------------- 2 files changed, 199 insertions(+), 582 deletions(-) diff --git a/interceptors/logging.go b/interceptors/logging.go index 15ce214..b584f68 100644 --- a/interceptors/logging.go +++ b/interceptors/logging.go @@ -21,7 +21,6 @@ var defaultSensitiveHeaders = []string{ } type LoggingOptions struct { - Logger *slog.Logger HeadersToLog []string @@ -49,8 +48,7 @@ type eventData struct { requestBodySize *int64 responseBodySize *int64 requestHeaders map[string]string - durationSeconds *float64 - requestID string + duration *float64 } type ErrorTyper interface { @@ -62,11 +60,11 @@ type ErrorTyper interface { // completion event or a failure event. If opts is nil, default logging options // are used. // -// interceptor.NewTransport(nil, -// interceptors.AddRequestLogging( -// Logging: logging -// ), -// ) +// interceptor.NewTransport(nil, +// interceptors.AddRequestLogging( +// Logging: logging +// ), +// ) func AddRequestLogging(opts *LoggingOptions) interceptor.Middleware { cfg := buildLoggingConfig(opts) @@ -131,7 +129,6 @@ func buildStartEvent(req *http.Request, cfg loggingConfig) eventData { serverAddress: req.URL.Hostname(), serverPort: extractServerPort(req.URL), userAgent: req.Header.Get("User-Agent"), - requestID: req.Header.Get("X-Request-ID"), requestHeaders: extractAllowedHeaders(req.Header, cfg.headersToLog, cfg.sensitiveHeaders), } @@ -145,13 +142,13 @@ func buildStartEvent(req *http.Request, cfg loggingConfig) eventData { func buildEndEvent(req *http.Request, resp *http.Response, err error, duration time.Duration) eventData { seconds := duration.Seconds() e := eventData{ - level: getLogLevel(resp, err), - method: req.Method, - urlFull: req.URL.String(), - urlScheme: req.URL.Scheme, - serverAddress: req.URL.Hostname(), - serverPort: extractServerPort(req.URL), - durationSeconds: &seconds, + level: getLogLevel(resp, err), + method: req.Method, + urlFull: req.URL.String(), + urlScheme: req.URL.Scheme, + serverAddress: req.URL.Hostname(), + serverPort: extractServerPort(req.URL), + duration: &seconds, } if req.ContentLength >= 0 { @@ -202,67 +199,120 @@ func emitLog(req *http.Request, cfg loggingConfig, event eventData) { func buildAttrs(event eventData) []slog.Attr { attrs := make([]slog.Attr, 0, 6) - requestAttrs := []any{slog.String("method", event.method)} - if event.requestBodySize != nil { - requestAttrs = append(requestAttrs, slog.Group("body", slog.Int64("size", *event.requestBodySize))) - } - if len(event.requestHeaders) > 0 { - headerAttrs := make([]any, 0, len(event.requestHeaders)) - for key, value := range event.requestHeaders { - headerAttrs = append(headerAttrs, slog.String(strings.ToLower(key), value)) - } - requestAttrs = append(requestAttrs, slog.Group("header", headerAttrs...)) + attrs = append(attrs, buildURLAttrs(event)) + attrs = append(attrs, buildServerAttrs(event)) + attrs = append(attrs, buildHTTPAttrs(event)) + + if event.userAgent != "" { + attrs = append(attrs, + slog.Group("user_agent", + slog.String("original", event.userAgent), + ), + ) } - httpAttrs := []any{slog.Group("request", requestAttrs...)} - if event.statusCode != nil || event.responseBodySize != nil { - responseAttrs := make([]any, 0, 2) - if event.statusCode != nil { - responseAttrs = append(responseAttrs, slog.Int("status_code", *event.statusCode)) - } - if event.responseBodySize != nil { - responseAttrs = append(responseAttrs, slog.Group("body", slog.Int64("size", *event.responseBodySize))) - } - httpAttrs = append(httpAttrs, slog.Group("response", responseAttrs...)) + if event.errorType != "" { + attrs = append(attrs, + slog.Group("error", + slog.String("type", event.errorType), + ), + ) } - urlAttrs := []any{slog.String("full", event.urlFull)} + return attrs +} + +func buildURLAttrs(event eventData) slog.Attr { + attrs := make([]any, 0, 2) + attrs = append(attrs, slog.String("full", event.urlFull)) + if event.urlScheme != "" { - urlAttrs = append(urlAttrs, slog.String("scheme", event.urlScheme)) + attrs = append(attrs, slog.String("scheme", event.urlScheme)) } - attrs = append(attrs, slog.Group("url", urlAttrs...)) - serverAttrs := []any{slog.String("address", event.serverAddress)} + return slog.Group("url", attrs...) +} + +func buildServerAttrs(event eventData) slog.Attr { + attrs := make([]any, 0, 2) + attrs = append(attrs, slog.String("address", event.serverAddress)) + if event.serverPort > 0 { - serverAttrs = append(serverAttrs, slog.Int("port", event.serverPort)) + attrs = append(attrs, slog.Int("port", event.serverPort)) } - attrs = append(attrs, slog.Group("server", serverAttrs...)) - if event.userAgent != "" { - attrs = append(attrs, slog.Group("user_agent", slog.String("original", event.userAgent))) + return slog.Group("server", attrs...) +} + +func buildHTTPAttrs(event eventData) slog.Attr { + attrs := make([]any, 0, 3) + + attrs = append(attrs, buildHTTPRequestAttrs(event)) + attrs = append(attrs, buildHTTPResponseAttrs(event)) + attrs = append(attrs, buildHTTPClientAttrs(event)) + + return slog.Group("http", attrs...) +} + +func buildHTTPRequestAttrs(event eventData) slog.Attr { + attrs := make([]any, 0, 3) + attrs = append(attrs, slog.String("method", event.method)) + attrs = append(attrs, buildHTTPRequestHeaderAttrs(event)) + + if event.requestBodySize != nil { + attrs = append(attrs, + slog.Group("body", + slog.Int64("size", *event.requestBodySize), + ), + ) } - if event.errorType != "" { - attrs = append(attrs, slog.Group("error", slog.String("type", event.errorType))) + + return slog.Group("request", attrs...) +} + +func buildHTTPRequestHeaderAttrs(event eventData) slog.Attr { + if len(event.requestHeaders) == 0 { + return slog.Attr{} } - httpClientRequestAttrs := make([]any, 0, 1) - if event.durationSeconds != nil { - httpClientRequestAttrs = append(httpClientRequestAttrs, slog.Float64("duration", *event.durationSeconds)) + attrs := make([]any, 0, len(event.requestHeaders)) + for k, v := range event.requestHeaders { + attrs = append(attrs, slog.String(strings.ToLower(k), v)) } - if len(httpClientRequestAttrs) > 0 { - httpAttrs = append(httpAttrs, slog.Group("client", slog.Group("request", httpClientRequestAttrs...))) + + return slog.Group("header", attrs...) +} + +func buildHTTPResponseAttrs(event eventData) slog.Attr { + if event.statusCode == nil && event.responseBodySize == nil { + return slog.Attr{} } - attrs = append(attrs, slog.Group("http", httpAttrs...)) - interceptorAttrs := make([]any, 0, 1) - if event.requestID != "" { - interceptorAttrs = append(interceptorAttrs, slog.String("request_id", event.requestID)) + attrs := make([]any, 0, 2) + + if event.statusCode != nil { + attrs = append(attrs, slog.Int("status_code", *event.statusCode)) } - if len(interceptorAttrs) > 0 { - attrs = append(attrs, slog.Group("interceptor", interceptorAttrs...)) + + if event.responseBodySize != nil { + attrs = append(attrs, + slog.Group("body", + slog.Int64("size", *event.responseBodySize), + ), + ) } - return attrs + return slog.Group("response", attrs...) +} + +func buildHTTPClientAttrs(event eventData) slog.Attr { + if event.duration == nil { + return slog.Attr{} + } + + return slog.Group("client", + slog.Group("request", slog.Float64("duration", *event.duration)), + ) } func extractServerPort(u *url.URL) int { diff --git a/interceptors/logging_test.go b/interceptors/logging_test.go index d979490..3d9dd4a 100644 --- a/interceptors/logging_test.go +++ b/interceptors/logging_test.go @@ -1,16 +1,12 @@ package interceptors_test import ( - "bytes" "context" - "encoding/json" "errors" "io" "log/slog" "net/http" "net/http/httptest" - "net/url" - "strconv" "strings" "sync" "testing" @@ -56,6 +52,7 @@ func (h *captureHandler) WithGroup(_ string) slog.Handler { return h } func (h *captureHandler) snapshot() []capturedRecord { h.mu.Lock() defer h.mu.Unlock() + out := make([]capturedRecord, len(h.records)) copy(out, h.records) return out @@ -70,6 +67,7 @@ func resolveAttr(dest map[string]any, a slog.Attr) { dest[a.Key] = group return } + dest[a.Key] = a.Value.Any() } @@ -78,26 +76,30 @@ func newCaptureLogger() (*slog.Logger, *captureHandler) { return slog.New(h), h } -func TestLoggingInterceptor_StructuredAttrs(t *testing.T) { +func TestAddRequestLogging_SuccessWithHeaders(t *testing.T) { logger, sink := newCaptureLogger() server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - w.Header().Set("Content-Type", "application/json") + w.Header().Set("Content-Length", "2") w.WriteHeader(http.StatusOK) - _, _ = w.Write([]byte(`{"ok":true}`)) + _, _ = w.Write([]byte("ok")) })) t.Cleanup(server.Close) client := &http.Client{Transport: interceptor.NewTransport(nil, - interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), + interceptors.AddRequestLogging(&interceptors.LoggingOptions{ + Logger: logger, + HeadersToLog: []string{"Authorization", "X-Correlation-ID"}, + }), )} - req, err := http.NewRequest(http.MethodGet, server.URL+"/v1/users?page=2", nil) + req, err := http.NewRequest(http.MethodPost, server.URL+"/v1/items", strings.NewReader("abc")) if err != nil { t.Fatalf("http.NewRequest error: %v", err) } + req.Header.Set("Authorization", "Bearer secret") + req.Header.Set("X-Correlation-ID", "corr-1") req.Header.Set("User-Agent", "interceptor-tests/1.0") - req.Header.Set("X-Request-ID", "abc-123") resp, err := client.Do(req) if err != nil { @@ -110,32 +112,43 @@ func TestLoggingInterceptor_StructuredAttrs(t *testing.T) { t.Fatalf("len(records) = %d, want 2", len(records)) } - start := records[0].attrs - assertGroupPathString(t, start, "http.request.method", http.MethodGet) - assertGroupPathString(t, start, "url.full", server.URL+"/v1/users?page=2") - assertGroupPathString(t, start, "url.scheme", "http") - assertGroupPathString(t, start, "user_agent.original", "interceptor-tests/1.0") - assertGroupPathString(t, start, "interceptor.request_id", "abc-123") + start := records[0] + if start.msg != "http request started" { + t.Fatalf("start message = %q, want %q", start.msg, "http request started") + } + assertGroupPathString(t, start.attrs, "http.request.method", http.MethodPost) + assertGroupPathString(t, start.attrs, "http.request.header.authorization", "***") + assertGroupPathString(t, start.attrs, "http.request.header.x-correlation-id", "corr-1") + assertGroupPathString(t, start.attrs, "user_agent.original", "interceptor-tests/1.0") + assertGroupPathInt64(t, start.attrs, "http.request.body.size", 3) - finish := records[1].attrs - assertGroupPathInt64(t, finish, "http.response.status_code", int64(http.StatusOK)) - if _, ok := getGroupPath(finish, "http.client.request.duration").(float64); !ok { + finish := records[1] + if finish.level != slog.LevelInfo { + t.Fatalf("finish level = %v, want INFO", finish.level) + } + assertGroupPathInt64(t, finish.attrs, "http.response.status_code", int64(http.StatusOK)) + assertGroupPathInt64(t, finish.attrs, "http.response.body.size", 2) + if _, ok := getGroupPath(finish.attrs, "http.client.request.duration").(float64); !ok { t.Fatal("http.client.request.duration missing") } + if hasGroupPath(finish.attrs, "error.type") { + t.Fatalf("error.type should not exist on success: %+v", finish.attrs) + } } -func TestLoggingInterceptor_StatusLevels(t *testing.T) { - cases := []struct { +func TestAddRequestLogging_StatusLevels(t *testing.T) { + testCases := []struct { name string status int wantLevel slog.Level + wantError string }{ {name: "2xx", status: http.StatusOK, wantLevel: slog.LevelInfo}, - {name: "4xx", status: http.StatusNotFound, wantLevel: slog.LevelWarn}, - {name: "5xx", status: http.StatusBadGateway, wantLevel: slog.LevelError}, + {name: "4xx", status: http.StatusNotFound, wantLevel: slog.LevelWarn, wantError: "404"}, + {name: "5xx", status: http.StatusInternalServerError, wantLevel: slog.LevelError, wantError: "500"}, } - for _, tc := range cases { + for _, tc := range testCases { t.Run(tc.name, func(t *testing.T) { logger, sink := newCaptureLogger() @@ -154,265 +167,66 @@ func TestLoggingInterceptor_StatusLevels(t *testing.T) { } _ = resp.Body.Close() - records := sink.snapshot() - if got := records[len(records)-1].level; got != tc.wantLevel { - t.Fatalf("final level = %v, want %v", got, tc.wantLevel) + finish := sink.snapshot()[1] + if finish.level != tc.wantLevel { + t.Fatalf("finish level = %v, want %v", finish.level, tc.wantLevel) + } + if tc.wantError == "" { + if hasGroupPath(finish.attrs, "error.type") { + t.Fatalf("error.type should not exist: %+v", finish.attrs) + } + } else { + assertGroupPathString(t, finish.attrs, "error.type", tc.wantError) } - assertGroupPathInt64(t, records[len(records)-1].attrs, "http.response.status_code", int64(tc.status)) }) } } -func TestLoggingInterceptor_TransportError(t *testing.T) { - logger, sink := newCaptureLogger() - - transport := interceptor.NewTransport(roundTripperFunc(func(req *http.Request) (*http.Response, error) { - return nil, errors.New("dial tcp: connection refused") - }), interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger})) +type typedErr struct{} - client := &http.Client{Transport: transport} - _, err := client.Get("http://example.com") - if err == nil { - t.Fatal("expected error, got nil") - } +func (typedErr) Error() string { return "typed" } - records := sink.snapshot() - if len(records) != 2 { - t.Fatalf("len(records) = %d, want 2", len(records)) - } - - assertGroupPathString(t, records[1].attrs, "error.type", "errorString") - if records[1].level != slog.LevelError { - t.Fatalf("level = %v, want ERROR", records[1].level) - } -} - -func TestLoggingInterceptor_HTTPErrorStatusSetsErrorType(t *testing.T) { - logger, sink := newCaptureLogger() - - server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - w.WriteHeader(http.StatusInternalServerError) - })) - t.Cleanup(server.Close) - - client := &http.Client{Transport: interceptor.NewTransport(nil, - interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), - )} - - resp, err := client.Get(server.URL) - if err != nil { - t.Fatalf("client.Get error: %v", err) - } - _ = resp.Body.Close() - - records := sink.snapshot() - assertGroupPathString(t, records[1].attrs, "error.type", "500") -} - -func TestLoggingInterceptor_NoErrorTypeOnSuccess(t *testing.T) { - logger, sink := newCaptureLogger() - - server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - w.WriteHeader(http.StatusNoContent) - })) - t.Cleanup(server.Close) - - client := &http.Client{Transport: interceptor.NewTransport(nil, - interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), - )} - - resp, err := client.Get(server.URL) - if err != nil { - t.Fatalf("client.Get error: %v", err) - } - _ = resp.Body.Close() - - records := sink.snapshot() - if hasGroupPath(records[1].attrs, "error.type") { - t.Fatalf("error.type should not exist on successful response: %+v", records[1].attrs) - } -} - -func TestLoggingInterceptor_Duration(t *testing.T) { - logger, sink := newCaptureLogger() - - server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - w.WriteHeader(http.StatusOK) - })) - t.Cleanup(server.Close) - - client := &http.Client{Transport: interceptor.NewTransport(nil, - interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), - )} - - resp, err := client.Get(server.URL) - if err != nil { - t.Fatalf("client.Get error: %v", err) - } - _ = resp.Body.Close() - - records := sink.snapshot() - duration, ok := getGroupPath(records[1].attrs, "http.client.request.duration").(float64) - if !ok { - t.Fatalf("http.client.request.duration has unexpected type: %T", getGroupPath(records[1].attrs, "http.client.request.duration")) - } - if duration <= 0 { - t.Fatalf("http.client.request.duration = %v, want > 0", duration) - } -} +func (typedErr) ErrorType() string { return "custom_error" } -func TestLoggingInterceptor_SensitiveHeaderRedaction(t *testing.T) { - logger, sink := newCaptureLogger() - - server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - w.WriteHeader(http.StatusOK) - })) - t.Cleanup(server.Close) - - client := &http.Client{Transport: interceptor.NewTransport(nil, - interceptors.AddRequestLogging(&interceptors.LoggingOptions{ - Logger: logger, - HeadersToLog: []string{"Authorization", "Cookie"}, - }), - )} - - req, err := http.NewRequest(http.MethodGet, server.URL, nil) - if err != nil { - t.Fatalf("http.NewRequest(%q) error: %v", server.URL, err) - } - req.Header.Set("Authorization", "Bearer top-secret") - req.Header.Set("Cookie", "session=secret") - - resp, err := client.Do(req) - if err != nil { - t.Fatalf("client.Do error: %v", err) - } - _ = resp.Body.Close() - - start := sink.snapshot()[0].attrs - assertGroupPathString(t, start, "http.request.header.authorization", "***") - assertGroupPathString(t, start, "http.request.header.cookie", "***") -} - -func TestLoggingInterceptor_CustomHeaders(t *testing.T) { - logger, sink := newCaptureLogger() - - server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - w.WriteHeader(http.StatusOK) - })) - t.Cleanup(server.Close) - - client := &http.Client{Transport: interceptor.NewTransport(nil, - interceptors.AddRequestLogging(&interceptors.LoggingOptions{ - Logger: logger, - HeadersToLog: []string{"X-Correlation-ID"}, - }), - )} - - req, err := http.NewRequest(http.MethodGet, server.URL, nil) - if err != nil { - t.Fatalf("http.NewRequest(%q) error: %v", server.URL, err) - } - req.Header.Set("X-Correlation-ID", "corr-1") - - resp, err := client.Do(req) - if err != nil { - t.Fatalf("client.Do error: %v", err) - } - _ = resp.Body.Close() - - start := sink.snapshot()[0].attrs - assertGroupPathString(t, start, "http.request.header.x-correlation-id", "corr-1") -} - -func TestLoggingInterceptor_NilOptions(t *testing.T) { - server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - w.WriteHeader(http.StatusOK) - })) - t.Cleanup(server.Close) - - client := &http.Client{Transport: interceptor.NewTransport(nil, - interceptors.AddRequestLogging(nil), - )} - - resp, err := client.Get(server.URL) - if err != nil { - t.Fatalf("client.Get error: %v", err) - } - _ = resp.Body.Close() -} - -func TestLoggingInterceptor_ChainPosition(t *testing.T) { - logger, sink := newCaptureLogger() - - var gotAuth string - var gotHeader string - server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - gotAuth = r.Header.Get("Authorization") - gotHeader = r.Header.Get("X-Req-Id") - w.WriteHeader(http.StatusOK) - })) - t.Cleanup(server.Close) - - client := &http.Client{Transport: interceptor.NewTransport(nil, - interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), - interceptors.AddHeader("X-Req-Id", "req-1"), - interceptors.AddBasicAuth("user", "pass"), - )} - - resp, err := client.Get(server.URL) - if err != nil { - t.Fatalf("client.Get error: %v", err) - } - _ = resp.Body.Close() - - if gotAuth == "" { - t.Fatal("Authorization header missing") - } - if gotHeader != "req-1" { - t.Fatalf("X-Req-Id = %q, want req-1", gotHeader) - } - if len(sink.snapshot()) != 2 { - t.Fatal("expected two logging events") +func TestAddRequestLogging_TransportErrors(t *testing.T) { + testCases := []struct { + name string + err error + wantType string + }{ + {name: "typed error", err: typedErr{}, wantType: "custom_error"}, + {name: "generic error", err: errors.New("dial failed"), wantType: "errorString"}, } -} - -func TestLoggingInterceptor_Concurrent(t *testing.T) { - logger, sink := newCaptureLogger() - - server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - w.WriteHeader(http.StatusOK) - })) - t.Cleanup(server.Close) - client := &http.Client{Transport: interceptor.NewTransport(nil, - interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), - )} + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + logger, sink := newCaptureLogger() + transport := interceptor.NewTransport(roundTripperFunc(func(req *http.Request) (*http.Response, error) { + return nil, tc.err + }), interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger})) - const total = 50 - var wg sync.WaitGroup - for i := 0; i < total; i++ { - wg.Add(1) - go func() { - defer wg.Done() - resp, err := client.Get(server.URL) + client := &http.Client{Transport: transport} + _, err := client.Get("http://example.com") if err == nil { - _ = resp.Body.Close() + t.Fatal("expected error, got nil") } - }() - } - wg.Wait() - records := sink.snapshot() - if len(records) != total*2 { - t.Fatalf("len(records) = %d, want %d", len(records), total*2) + records := sink.snapshot() + if len(records) != 2 { + t.Fatalf("len(records) = %d, want 2", len(records)) + } + if records[1].level != slog.LevelError { + t.Fatalf("level = %v, want ERROR", records[1].level) + } + assertGroupPathString(t, records[1].attrs, "error.type", tc.wantType) + }) } } -func TestLoggingInterceptor_RequestImmutability(t *testing.T) { +func TestAddRequestLogging_RequestCloneIsolation(t *testing.T) { logger, _ := newCaptureLogger() - originalReq, err := http.NewRequest(http.MethodPost, "http://example.com/v1/items", strings.NewReader("immutable-payload")) + originalReq, err := http.NewRequest(http.MethodPost, "http://example.com/v1/items", strings.NewReader("payload")) if err != nil { t.Fatalf("http.NewRequest error: %v", err) } @@ -461,174 +275,18 @@ func TestLoggingInterceptor_RequestImmutability(t *testing.T) { } } -func TestLoggingInterceptor_WithJSONHandler(t *testing.T) { - server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - w.WriteHeader(http.StatusOK) - })) - t.Cleanup(server.Close) - - var out bytes.Buffer - logger := slog.New(slog.NewJSONHandler(&out, nil)) - - client := &http.Client{Transport: interceptor.NewTransport(nil, - interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), - )} - - resp, err := client.Get(server.URL + "/json") - if err != nil { - t.Fatalf("client.Get error: %v", err) - } - _ = resp.Body.Close() - - lines := splitLines(out.String()) - if len(lines) != 2 { - t.Fatalf("expected 2 log lines, got %d", len(lines)) - } - - first := decodeJSONMap(t, lines[0]) - httpMap, ok := first["http"].(map[string]any) - if !ok { - t.Fatalf("http group missing: %v", first) - } - requestMap, ok := httpMap["request"].(map[string]any) - if !ok { - t.Fatalf("http[request] missing or wrong type, got: %T", httpMap["request"]) - } - if requestMap["method"] != "GET" { - t.Fatalf("http.request.method = %v, want GET", requestMap["method"]) - } -} - -func TestLoggingInterceptor_WithTextHandler(t *testing.T) { - server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - w.WriteHeader(http.StatusOK) - })) - t.Cleanup(server.Close) - - var out bytes.Buffer - logger := slog.New(slog.NewTextHandler(&out, nil)) - - client := &http.Client{Transport: interceptor.NewTransport(nil, - interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), - )} - - resp, err := client.Get(server.URL + "/text") - if err != nil { - t.Fatalf("client.Get error: %v", err) - } - _ = resp.Body.Close() - - output := out.String() - if !strings.Contains(output, "http.request.method=GET") { - t.Fatalf("TextHandler output missing grouped dotted key: %s", output) - } - if !strings.Contains(output, "url.full=") { - t.Fatalf("TextHandler output missing url.full: %s", output) - } -} - -func TestLoggingInterceptor_HandlerOptions_ReplaceAttr(t *testing.T) { - server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - w.WriteHeader(http.StatusOK) - })) - t.Cleanup(server.Close) - - var out bytes.Buffer - seenHTTPRequestMethod := false - seenInterceptorDuration := false - - logger := slog.New(slog.NewJSONHandler(&out, &slog.HandlerOptions{ - ReplaceAttr: func(groups []string, a slog.Attr) slog.Attr { - if strings.Join(groups, ".") == "http.request" && a.Key == "method" { - seenHTTPRequestMethod = true - a.Value = slog.StringValue("OVERRIDDEN") - } - if strings.Join(groups, ".") == "http.client.request" && a.Key == "duration" { - seenInterceptorDuration = true - } - return a - }, - })) - - client := &http.Client{Transport: interceptor.NewTransport(nil, - interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), - )} - - resp, err := client.Get(server.URL) - if err != nil { - t.Fatalf("client.Get error: %v", err) - } - _ = resp.Body.Close() - - if !seenHTTPRequestMethod { - t.Fatal("ReplaceAttr did not receive [http request] method") - } - if !seenInterceptorDuration { - t.Fatal("ReplaceAttr did not receive [http client request] duration") - } - - lines := splitLines(out.String()) - first := decodeJSONMap(t, lines[0]) - httpMap, ok := first["http"].(map[string]any) - if !ok { - t.Fatalf("http group missing or wrong type: %T", first["http"]) - } - requestMap, ok := httpMap["request"].(map[string]any) - if !ok { - t.Fatalf("http[request] missing or wrong type, got: %T", httpMap["request"]) - } - if requestMap["method"] != "OVERRIDDEN" { - t.Fatalf("http.request.method = %v, want OVERRIDDEN", requestMap["method"]) - } -} - -func TestLoggingInterceptor_HandlerOptions_Level(t *testing.T) { - server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - w.WriteHeader(http.StatusOK) - })) - t.Cleanup(server.Close) - - var out bytes.Buffer - logger := slog.New(slog.NewJSONHandler(&out, &slog.HandlerOptions{Level: slog.LevelError})) - - client := &http.Client{Transport: interceptor.NewTransport(nil, - interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), - )} - - resp, err := client.Get(server.URL) - if err != nil { - t.Fatalf("client.Get error: %v", err) - } - _ = resp.Body.Close() - - if strings.TrimSpace(out.String()) != "" { - t.Fatalf("expected no logs at error level for successful request, got %q", out.String()) - } -} - -func TestLoggingInterceptor_OTelAttributeNames(t *testing.T) { +func TestAddRequestLogging_HTTPSDefaultPort(t *testing.T) { logger, sink := newCaptureLogger() - server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - w.Header().Set("Content-Length", "3") - w.WriteHeader(http.StatusAccepted) - _, _ = w.Write([]byte("ok!")) - })) - t.Cleanup(server.Close) - - client := &http.Client{Transport: interceptor.NewTransport(nil, - interceptors.AddRequestLogging(&interceptors.LoggingOptions{ - Logger: logger, - HeadersToLog: []string{"Content-Type"}, - }), - )} + transport := interceptor.NewTransport(roundTripperFunc(func(req *http.Request) (*http.Response, error) { + return &http.Response{StatusCode: http.StatusOK, Body: io.NopCloser(strings.NewReader("ok"))}, nil + }), interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger})) - req, err := http.NewRequest(http.MethodPost, server.URL+"/otel", strings.NewReader("abc")) + client := &http.Client{Transport: transport} + req, err := http.NewRequest(http.MethodGet, "https://example.com/resource", nil) if err != nil { - t.Fatalf("http.NewRequest(%q) error: %v", server.URL+"/otel", err) + t.Fatalf("http.NewRequest error: %v", err) } - req.Header.Set("Content-Type", "application/json") - req.Header.Set("User-Agent", "otel-test/1.0") resp, err := client.Do(req) if err != nil { @@ -637,69 +295,8 @@ func TestLoggingInterceptor_OTelAttributeNames(t *testing.T) { _ = resp.Body.Close() start := sink.snapshot()[0].attrs - assertGroupPathString(t, start, "http.request.method", "POST") - assertGroupPathInt64(t, start, "http.request.body.size", 3) - assertGroupPathString(t, start, "http.request.header.content-type", "application/json") - assertGroupPathString(t, start, "url.full", server.URL+"/otel") - assertGroupPathString(t, start, "url.scheme", "http") - assertGroupPathString(t, start, "server.address", "127.0.0.1") - assertGroupPathInt64(t, start, "server.port", int64(mustServerPort(t, server.URL))) - assertGroupPathString(t, start, "user_agent.original", "otel-test/1.0") - - finish := sink.snapshot()[1].attrs - assertGroupPathInt64(t, finish, "http.response.status_code", int64(http.StatusAccepted)) - assertGroupPathInt64(t, finish, "http.response.body.size", 3) - assertGroupPathInt64(t, finish, "http.request.body.size", 3) - if hasGroupPath(finish, "http.target") { - t.Fatalf("http.target must not be emitted: %+v", finish) - } -} - -func TestLoggingInterceptor_ServerAddressAndPort(t *testing.T) { - logger, sink := newCaptureLogger() - - t.Run("implicit http port", func(t *testing.T) { - server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - w.WriteHeader(http.StatusOK) - })) - t.Cleanup(server.Close) - - client := &http.Client{Transport: interceptor.NewTransport(nil, - interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), - )} - - resp, err := client.Get(server.URL) - if err != nil { - t.Fatalf("client.Get error: %v", err) - } - _ = resp.Body.Close() - - records := sink.snapshot() - assertGroupPathString(t, records[len(records)-2].attrs, "server.address", "127.0.0.1") - assertGroupPathInt64(t, records[len(records)-2].attrs, "server.port", int64(mustServerPort(t, server.URL))) - }) - - t.Run("explicit https default port", func(t *testing.T) { - transport := interceptor.NewTransport(roundTripperFunc(func(req *http.Request) (*http.Response, error) { - return &http.Response{StatusCode: http.StatusOK, Body: io.NopCloser(strings.NewReader("ok"))}, nil - }), interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger})) - - client := &http.Client{Transport: transport} - req, err := http.NewRequest(http.MethodGet, "https://example.com/resource", nil) - if err != nil { - t.Fatalf("http.NewRequest(%q) error: %v", "https://example.com/resource", err) - } - resp, err := client.Do(req) - if err != nil { - t.Fatalf("client.Do error: %v", err) - } - _ = resp.Body.Close() - - records := sink.snapshot() - start := records[len(records)-2].attrs - assertGroupPathString(t, start, "server.address", "example.com") - assertGroupPathInt64(t, start, "server.port", 443) - }) + assertGroupPathString(t, start, "server.address", "example.com") + assertGroupPathInt64(t, start, "server.port", 443) } type roundTripperFunc func(req *http.Request) (*http.Response, error) @@ -708,27 +305,6 @@ func (f roundTripperFunc) RoundTrip(req *http.Request) (*http.Response, error) { return f(req) } -func decodeJSONMap(t *testing.T, line string) map[string]any { - t.Helper() - var out map[string]any - if err := json.Unmarshal([]byte(line), &out); err != nil { - t.Fatalf("json.Unmarshal(%q) error: %v", line, err) - } - return out -} - -func splitLines(s string) []string { - parts := strings.Split(strings.TrimSpace(s), "\n") - out := make([]string, 0, len(parts)) - for _, p := range parts { - p = strings.TrimSpace(p) - if p != "" { - out = append(out, p) - } - } - return out -} - func getGroupPath(attrs map[string]any, path string) any { current := any(attrs) for _, segment := range strings.Split(path, ".") { @@ -741,6 +317,7 @@ func getGroupPath(attrs map[string]any, path string) any { return nil } } + return current } @@ -750,6 +327,7 @@ func hasGroupPath(attrs map[string]any, path string) bool { func assertGroupPathString(t *testing.T, attrs map[string]any, path, want string) { t.Helper() + got, ok := getGroupPath(attrs, path).(string) if !ok { t.Fatalf("%s has unexpected type: %T", path, getGroupPath(attrs, path)) @@ -761,6 +339,7 @@ func assertGroupPathString(t *testing.T, attrs map[string]any, path, want string func assertGroupPathInt64(t *testing.T, attrs map[string]any, path string, want int64) { t.Helper() + value := getGroupPath(attrs, path) var got int64 switch v := value.(type) { @@ -773,20 +352,8 @@ func assertGroupPathInt64(t *testing.T, attrs map[string]any, path string, want default: t.Fatalf("%s has unexpected type: %T", path, value) } + if got != want { t.Fatalf("%s = %d, want %d", path, got, want) } } - -func mustServerPort(t *testing.T, rawURL string) int { - t.Helper() - u, err := url.Parse(rawURL) - if err != nil { - t.Fatalf("url.Parse(%q) error: %v", rawURL, err) - } - port, err := strconv.Atoi(u.Port()) - if err != nil { - t.Fatalf("strconv.Atoi(%q) error: %v", u.Port(), err) - } - return port -} From db592bd1f5ffc312648a9f201dc7239a9a36a958 Mon Sep 17 00:00:00 2001 From: Fabian Esteban Ruiz Valdes Date: Wed, 11 Mar 2026 16:08:52 -0500 Subject: [PATCH 12/19] feat(logging): improve logging --- interceptors/logging_test.go | 282 +++++++++++++++++++++-------------- 1 file changed, 170 insertions(+), 112 deletions(-) diff --git a/interceptors/logging_test.go b/interceptors/logging_test.go index 3d9dd4a..7fdc029 100644 --- a/interceptors/logging_test.go +++ b/interceptors/logging_test.go @@ -6,7 +6,6 @@ import ( "io" "log/slog" "net/http" - "net/http/httptest" "strings" "sync" "testing" @@ -79,21 +78,23 @@ func newCaptureLogger() (*slog.Logger, *captureHandler) { func TestAddRequestLogging_SuccessWithHeaders(t *testing.T) { logger, sink := newCaptureLogger() - server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - w.Header().Set("Content-Length", "2") - w.WriteHeader(http.StatusOK) - _, _ = w.Write([]byte("ok")) - })) - t.Cleanup(server.Close) - - client := &http.Client{Transport: interceptor.NewTransport(nil, + transport := interceptor.NewTransport(nil, interceptors.AddRequestLogging(&interceptors.LoggingOptions{ Logger: logger, HeadersToLog: []string{"Authorization", "X-Correlation-ID"}, }), - )} + func(req *http.Request, _ interceptor.HandlerFunc) (*http.Response, error) { + return &http.Response{ + StatusCode: http.StatusOK, + ContentLength: 2, + Body: io.NopCloser(strings.NewReader("ok")), + }, nil + }, + ) + + client := &http.Client{Transport: transport} - req, err := http.NewRequest(http.MethodPost, server.URL+"/v1/items", strings.NewReader("abc")) + req, err := http.NewRequest(http.MethodPost, "https://api.example.com/v1/items", strings.NewReader("abc")) if err != nil { t.Fatalf("http.NewRequest error: %v", err) } @@ -116,22 +117,55 @@ func TestAddRequestLogging_SuccessWithHeaders(t *testing.T) { if start.msg != "http request started" { t.Fatalf("start message = %q, want %q", start.msg, "http request started") } - assertGroupPathString(t, start.attrs, "http.request.method", http.MethodPost) - assertGroupPathString(t, start.attrs, "http.request.header.authorization", "***") - assertGroupPathString(t, start.attrs, "http.request.header.x-correlation-id", "corr-1") - assertGroupPathString(t, start.attrs, "user_agent.original", "interceptor-tests/1.0") - assertGroupPathInt64(t, start.attrs, "http.request.body.size", 3) + httpAttrs := mustMapAttr(t, start.attrs, "http") + requestAttrs := mustMapAttr(t, httpAttrs, "request") + headers := mustMapAttr(t, requestAttrs, "header") + userAgent := mustMapAttr(t, start.attrs, "user_agent") + + if got, ok := requestAttrs["method"].(string); !ok { + t.Fatalf("http.request.method has unexpected type: %T", requestAttrs["method"]) + } else if got != http.MethodPost { + t.Fatalf("http.request.method = %q, want %q", got, http.MethodPost) + } + if got, ok := headers["authorization"].(string); !ok { + t.Fatalf("http.request.header.authorization has unexpected type: %T", headers["authorization"]) + } else if got != "***" { + t.Fatalf("http.request.header.authorization = %q, want %q", got, "***") + } + if got, ok := headers["x-correlation-id"].(string); !ok { + t.Fatalf("http.request.header.x-correlation-id has unexpected type: %T", headers["x-correlation-id"]) + } else if got != "corr-1" { + t.Fatalf("http.request.header.x-correlation-id = %q, want %q", got, "corr-1") + } + if got, ok := userAgent["original"].(string); !ok { + t.Fatalf("user_agent.original has unexpected type: %T", userAgent["original"]) + } else if got != "interceptor-tests/1.0" { + t.Fatalf("user_agent.original = %q, want %q", got, "interceptor-tests/1.0") + } + bodyAttrs := mustMapAttr(t, requestAttrs, "body") + if got := mustInt64Attr(t, bodyAttrs, "size", "http.request.body.size"); got != 3 { + t.Fatalf("http.request.body.size = %d, want %d", got, 3) + } finish := records[1] if finish.level != slog.LevelInfo { t.Fatalf("finish level = %v, want INFO", finish.level) } - assertGroupPathInt64(t, finish.attrs, "http.response.status_code", int64(http.StatusOK)) - assertGroupPathInt64(t, finish.attrs, "http.response.body.size", 2) - if _, ok := getGroupPath(finish.attrs, "http.client.request.duration").(float64); !ok { + httpFinishAttrs := mustMapAttr(t, finish.attrs, "http") + responseAttrs := mustMapAttr(t, httpFinishAttrs, "response") + if got := mustInt64Attr(t, responseAttrs, "status_code", "http.response.status_code"); got != int64(http.StatusOK) { + t.Fatalf("http.response.status_code = %d, want %d", got, int64(http.StatusOK)) + } + responseBodyAttrs := mustMapAttr(t, responseAttrs, "body") + if got := mustInt64Attr(t, responseBodyAttrs, "size", "http.response.body.size"); got != 2 { + t.Fatalf("http.response.body.size = %d, want %d", got, 2) + } + clientAttrs := mustMapAttr(t, httpFinishAttrs, "client") + clientReqAttrs := mustMapAttr(t, clientAttrs, "request") + if _, ok := clientReqAttrs["duration"].(float64); !ok { t.Fatal("http.client.request.duration missing") } - if hasGroupPath(finish.attrs, "error.type") { + if _, ok := finish.attrs["error"]; ok { t.Fatalf("error.type should not exist on success: %+v", finish.attrs) } } @@ -151,17 +185,19 @@ func TestAddRequestLogging_StatusLevels(t *testing.T) { for _, tc := range testCases { t.Run(tc.name, func(t *testing.T) { logger, sink := newCaptureLogger() - - server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { - w.WriteHeader(tc.status) - })) - t.Cleanup(server.Close) - - client := &http.Client{Transport: interceptor.NewTransport(nil, + transport := interceptor.NewTransport(nil, interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), - )} + func(req *http.Request, _ interceptor.HandlerFunc) (*http.Response, error) { + return &http.Response{ + StatusCode: tc.status, + Body: io.NopCloser(strings.NewReader("")), + }, nil + }, + ) + + client := &http.Client{Transport: transport} - resp, err := client.Get(server.URL) + resp, err := client.Get("http://example.com") if err != nil { t.Fatalf("client.Get error: %v", err) } @@ -171,12 +207,20 @@ func TestAddRequestLogging_StatusLevels(t *testing.T) { if finish.level != tc.wantLevel { t.Fatalf("finish level = %v, want %v", finish.level, tc.wantLevel) } + errorAttrs, hasError := finish.attrs["error"].(map[string]any) if tc.wantError == "" { - if hasGroupPath(finish.attrs, "error.type") { + if hasError { t.Fatalf("error.type should not exist: %+v", finish.attrs) } } else { - assertGroupPathString(t, finish.attrs, "error.type", tc.wantError) + if !hasError { + t.Fatal("error.type missing") + } + if got, ok := errorAttrs["type"].(string); !ok { + t.Fatalf("error.type has unexpected type: %T", errorAttrs["type"]) + } else if got != tc.wantError { + t.Fatalf("error.type = %q, want %q", got, tc.wantError) + } } }) } @@ -201,9 +245,12 @@ func TestAddRequestLogging_TransportErrors(t *testing.T) { for _, tc := range testCases { t.Run(tc.name, func(t *testing.T) { logger, sink := newCaptureLogger() - transport := interceptor.NewTransport(roundTripperFunc(func(req *http.Request) (*http.Response, error) { - return nil, tc.err - }), interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger})) + transport := interceptor.NewTransport(nil, + interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), + func(req *http.Request, _ interceptor.HandlerFunc) (*http.Response, error) { + return nil, tc.err + }, + ) client := &http.Client{Transport: transport} _, err := client.Get("http://example.com") @@ -218,7 +265,12 @@ func TestAddRequestLogging_TransportErrors(t *testing.T) { if records[1].level != slog.LevelError { t.Fatalf("level = %v, want ERROR", records[1].level) } - assertGroupPathString(t, records[1].attrs, "error.type", tc.wantType) + errorAttrs := mustMapAttr(t, records[1].attrs, "error") + if got, ok := errorAttrs["type"].(string); !ok { + t.Fatalf("error.type has unexpected type: %T", errorAttrs["type"]) + } else if got != tc.wantType { + t.Fatalf("error.type = %q, want %q", got, tc.wantType) + } }) } } @@ -226,134 +278,140 @@ func TestAddRequestLogging_TransportErrors(t *testing.T) { func TestAddRequestLogging_RequestCloneIsolation(t *testing.T) { logger, _ := newCaptureLogger() - originalReq, err := http.NewRequest(http.MethodPost, "http://example.com/v1/items", strings.NewReader("payload")) + req, err := http.NewRequest(http.MethodPost, "http://example.com/v1/items", strings.NewReader("payload")) if err != nil { t.Fatalf("http.NewRequest error: %v", err) } - originalReq.Header.Set("X-Original", "keep") + req.Header.Set("X-Original", "keep") transport := interceptor.NewTransport( - roundTripperFunc(func(req *http.Request) (*http.Response, error) { - if req == originalReq { + nil, + interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), + func(nextReq *http.Request, next interceptor.HandlerFunc) (*http.Response, error) { + nextReq.Header.Set("X-Mutated", "yes") + nextReq.Method = http.MethodPut + nextReq.URL.Path = "/mutated" + return next(nextReq) + }, + func(nextReq *http.Request, _ interceptor.HandlerFunc) (*http.Response, error) { + if nextReq == req { t.Fatal("downstream received original request pointer; expected clone") } - if req.Header.Get("X-Mutated") != "yes" { - t.Fatalf("X-Mutated header = %q, want yes", req.Header.Get("X-Mutated")) + if nextReq.Header.Get("X-Mutated") != "yes" { + t.Fatalf("X-Mutated header = %q, want yes", nextReq.Header.Get("X-Mutated")) } - if req.Method != http.MethodPut { - t.Fatalf("mutated request method = %q, want %q", req.Method, http.MethodPut) + if nextReq.Method != http.MethodPut { + t.Fatalf("mutated request method = %q, want %q", nextReq.Method, http.MethodPut) } - if req.URL.Path != "/mutated" { - t.Fatalf("mutated request path = %q, want /mutated", req.URL.Path) + if nextReq.URL.Path != "/mutated" { + t.Fatalf("mutated request path = %q, want /mutated", nextReq.URL.Path) } return &http.Response{StatusCode: http.StatusOK, Body: io.NopCloser(strings.NewReader("ok"))}, nil - }), - interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), - func(req *http.Request, next interceptor.HandlerFunc) (*http.Response, error) { - req.Header.Set("X-Mutated", "yes") - req.Method = http.MethodPut - req.URL.Path = "/mutated" - return next(req) }, ) client := &http.Client{Transport: transport} - resp, err := client.Do(originalReq) + resp, err := client.Do(req) if err != nil { t.Fatalf("client.Do error: %v", err) } _ = resp.Body.Close() - if got := originalReq.Header.Get("X-Mutated"); got != "" { + if got := req.Header.Get("X-Mutated"); got != "" { t.Fatalf("original request header X-Mutated = %q, want empty", got) } - if got := originalReq.Method; got != http.MethodPost { + if got := req.Method; got != http.MethodPost { t.Fatalf("original request method = %q, want %q", got, http.MethodPost) } - if got := originalReq.URL.Path; got != "/v1/items" { + if got := req.URL.Path; got != "/v1/items" { t.Fatalf("original request path = %q, want /v1/items", got) } } func TestAddRequestLogging_HTTPSDefaultPort(t *testing.T) { - logger, sink := newCaptureLogger() - - transport := interceptor.NewTransport(roundTripperFunc(func(req *http.Request) (*http.Response, error) { - return &http.Response{StatusCode: http.StatusOK, Body: io.NopCloser(strings.NewReader("ok"))}, nil - }), interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger})) - - client := &http.Client{Transport: transport} - req, err := http.NewRequest(http.MethodGet, "https://example.com/resource", nil) - if err != nil { - t.Fatalf("http.NewRequest error: %v", err) - } - - resp, err := client.Do(req) - if err != nil { - t.Fatalf("client.Do error: %v", err) + testCases := []struct { + name string + url string + wantHost string + wantPort int64 + portLogged bool + }{ + {name: "https default port", url: "https://example.com/resource", wantHost: "example.com", wantPort: 443, portLogged: true}, + {name: "http default port", url: "http://example.com/resource", wantHost: "example.com", wantPort: 80, portLogged: true}, + {name: "explicit port", url: "https://example.com:8443/resource", wantHost: "example.com", wantPort: 8443, portLogged: true}, + {name: "unknown scheme", url: "ftp://example.com/resource", wantHost: "example.com", portLogged: false}, } - _ = resp.Body.Close() - start := sink.snapshot()[0].attrs - assertGroupPathString(t, start, "server.address", "example.com") - assertGroupPathInt64(t, start, "server.port", 443) -} + for _, tc := range testCases { + t.Run(tc.name, func(t *testing.T) { + logger, sink := newCaptureLogger() -type roundTripperFunc func(req *http.Request) (*http.Response, error) + transport := interceptor.NewTransport(nil, + interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), + func(req *http.Request, _ interceptor.HandlerFunc) (*http.Response, error) { + return &http.Response{StatusCode: http.StatusOK, Body: io.NopCloser(strings.NewReader("ok"))}, nil + }, + ) -func (f roundTripperFunc) RoundTrip(req *http.Request) (*http.Response, error) { - return f(req) -} + client := &http.Client{Transport: transport} + req, err := http.NewRequest(http.MethodGet, tc.url, nil) + if err != nil { + t.Fatalf("http.NewRequest error: %v", err) + } -func getGroupPath(attrs map[string]any, path string) any { - current := any(attrs) - for _, segment := range strings.Split(path, ".") { - m, ok := current.(map[string]any) - if !ok { - return nil - } - current, ok = m[segment] - if !ok { - return nil - } - } + resp, err := client.Do(req) + if err != nil { + t.Fatalf("client.Do error: %v", err) + } + _ = resp.Body.Close() - return current -} + start := sink.snapshot()[0].attrs + serverAttrs := mustMapAttr(t, start, "server") + if got, ok := serverAttrs["address"].(string); !ok { + t.Fatalf("server.address has unexpected type: %T", serverAttrs["address"]) + } else if got != tc.wantHost { + t.Fatalf("server.address = %q, want %q", got, tc.wantHost) + } -func hasGroupPath(attrs map[string]any, path string) bool { - return getGroupPath(attrs, path) != nil + portValue, exists := serverAttrs["port"] + if tc.portLogged { + if !exists { + t.Fatal("server.port missing") + } + if got := mustInt64Attr(t, serverAttrs, "port", "server.port"); got != tc.wantPort { + t.Fatalf("server.port = %d, want %d", got, tc.wantPort) + } + } else if exists { + t.Fatalf("server.port should not be logged for %q, got %v", tc.url, portValue) + } + }) + } } -func assertGroupPathString(t *testing.T, attrs map[string]any, path, want string) { +func mustMapAttr(t *testing.T, attrs map[string]any, key string) map[string]any { t.Helper() - got, ok := getGroupPath(attrs, path).(string) + group, ok := attrs[key].(map[string]any) if !ok { - t.Fatalf("%s has unexpected type: %T", path, getGroupPath(attrs, path)) - } - if got != want { - t.Fatalf("%s = %q, want %q", path, got, want) + t.Fatalf("%s has unexpected type: %T", key, attrs[key]) } + + return group } -func assertGroupPathInt64(t *testing.T, attrs map[string]any, path string, want int64) { +func mustInt64Attr(t *testing.T, attrs map[string]any, key string, path string) int64 { t.Helper() - value := getGroupPath(attrs, path) - var got int64 + value := attrs[key] switch v := value.(type) { case int: - got = int64(v) + return int64(v) case int64: - got = v + return v case float64: - got = int64(v) + return int64(v) default: t.Fatalf("%s has unexpected type: %T", path, value) - } - - if got != want { - t.Fatalf("%s = %d, want %d", path, got, want) + return 0 } } From 516d9cd39a01501a8432ef719c140332c6ffde2c Mon Sep 17 00:00:00 2001 From: Fabian Esteban Ruiz Valdes Date: Wed, 11 Mar 2026 16:33:16 -0500 Subject: [PATCH 13/19] feat(logging): improve logging --- interceptors/logging_test.go | 208 ++++++++++------------------------- 1 file changed, 57 insertions(+), 151 deletions(-) diff --git a/interceptors/logging_test.go b/interceptors/logging_test.go index 7fdc029..4ccccd8 100644 --- a/interceptors/logging_test.go +++ b/interceptors/logging_test.go @@ -3,6 +3,7 @@ package interceptors_test import ( "context" "errors" + "fmt" "io" "log/slog" "net/http" @@ -36,7 +37,7 @@ func (h *captureHandler) Handle(_ context.Context, r slog.Record) error { attrs := make(map[string]any) r.Attrs(func(a slog.Attr) bool { - resolveAttr(attrs, a) + resolveAttr(attrs, "", a) return true }) @@ -57,17 +58,20 @@ func (h *captureHandler) snapshot() []capturedRecord { return out } -func resolveAttr(dest map[string]any, a slog.Attr) { +func resolveAttr(dest map[string]any, prefix string, a slog.Attr) { + key := a.Key + if prefix != "" { + key = prefix + "." + key + } + if a.Value.Kind() == slog.KindGroup { - group := make(map[string]any) for _, ga := range a.Value.Group() { - resolveAttr(group, ga) + resolveAttr(dest, key, ga) } - dest[a.Key] = group return } - dest[a.Key] = a.Value.Any() + dest[key] = a.Value.Any() } func newCaptureLogger() (*slog.Logger, *captureHandler) { @@ -75,6 +79,12 @@ func newCaptureLogger() (*slog.Logger, *captureHandler) { return slog.New(h), h } +type typedErr struct{} + +func (typedErr) Error() string { return "typed" } + +func (typedErr) ErrorType() string { return "custom_error" } + func TestAddRequestLogging_SuccessWithHeaders(t *testing.T) { logger, sink := newCaptureLogger() @@ -92,7 +102,9 @@ func TestAddRequestLogging_SuccessWithHeaders(t *testing.T) { }, ) - client := &http.Client{Transport: transport} + client := &http.Client{ + Transport: transport, + } req, err := http.NewRequest(http.MethodPost, "https://api.example.com/v1/items", strings.NewReader("abc")) if err != nil { @@ -117,56 +129,37 @@ func TestAddRequestLogging_SuccessWithHeaders(t *testing.T) { if start.msg != "http request started" { t.Fatalf("start message = %q, want %q", start.msg, "http request started") } - httpAttrs := mustMapAttr(t, start.attrs, "http") - requestAttrs := mustMapAttr(t, httpAttrs, "request") - headers := mustMapAttr(t, requestAttrs, "header") - userAgent := mustMapAttr(t, start.attrs, "user_agent") - - if got, ok := requestAttrs["method"].(string); !ok { - t.Fatalf("http.request.method has unexpected type: %T", requestAttrs["method"]) - } else if got != http.MethodPost { + if got := start.attrs["http.request.method"]; got != http.MethodPost { t.Fatalf("http.request.method = %q, want %q", got, http.MethodPost) } - if got, ok := headers["authorization"].(string); !ok { - t.Fatalf("http.request.header.authorization has unexpected type: %T", headers["authorization"]) - } else if got != "***" { + if got := start.attrs["http.request.header.authorization"]; got != "***" { t.Fatalf("http.request.header.authorization = %q, want %q", got, "***") } - if got, ok := headers["x-correlation-id"].(string); !ok { - t.Fatalf("http.request.header.x-correlation-id has unexpected type: %T", headers["x-correlation-id"]) - } else if got != "corr-1" { + if got := start.attrs["http.request.header.x-correlation-id"]; got != "corr-1" { t.Fatalf("http.request.header.x-correlation-id = %q, want %q", got, "corr-1") } - if got, ok := userAgent["original"].(string); !ok { - t.Fatalf("user_agent.original has unexpected type: %T", userAgent["original"]) - } else if got != "interceptor-tests/1.0" { + if got := start.attrs["user_agent.original"]; got != "interceptor-tests/1.0" { t.Fatalf("user_agent.original = %q, want %q", got, "interceptor-tests/1.0") } - bodyAttrs := mustMapAttr(t, requestAttrs, "body") - if got := mustInt64Attr(t, bodyAttrs, "size", "http.request.body.size"); got != 3 { - t.Fatalf("http.request.body.size = %d, want %d", got, 3) + if got := fmt.Sprint(start.attrs["http.request.body.size"]); got != "3" { + t.Fatalf("http.request.body.size = %v, want %d", got, 3) } - finish := records[1] - if finish.level != slog.LevelInfo { - t.Fatalf("finish level = %v, want INFO", finish.level) + end := records[1] + if end.level != slog.LevelInfo { + t.Fatalf("end level = %v, want INFO", end.level) } - httpFinishAttrs := mustMapAttr(t, finish.attrs, "http") - responseAttrs := mustMapAttr(t, httpFinishAttrs, "response") - if got := mustInt64Attr(t, responseAttrs, "status_code", "http.response.status_code"); got != int64(http.StatusOK) { - t.Fatalf("http.response.status_code = %d, want %d", got, int64(http.StatusOK)) + if got := fmt.Sprint(end.attrs["http.response.status_code"]); got != fmt.Sprint(http.StatusOK) { + t.Fatalf("http.response.status_code = %v, want %d", got, int64(http.StatusOK)) } - responseBodyAttrs := mustMapAttr(t, responseAttrs, "body") - if got := mustInt64Attr(t, responseBodyAttrs, "size", "http.response.body.size"); got != 2 { - t.Fatalf("http.response.body.size = %d, want %d", got, 2) + if got := fmt.Sprint(end.attrs["http.response.body.size"]); got != "2" { + t.Fatalf("http.response.body.size = %v, want %d", got, 2) } - clientAttrs := mustMapAttr(t, httpFinishAttrs, "client") - clientReqAttrs := mustMapAttr(t, clientAttrs, "request") - if _, ok := clientReqAttrs["duration"].(float64); !ok { + if _, ok := end.attrs["http.client.request.duration"]; !ok { t.Fatal("http.client.request.duration missing") } - if _, ok := finish.attrs["error"]; ok { - t.Fatalf("error.type should not exist on success: %+v", finish.attrs) + if _, ok := end.attrs["error.type"]; ok { + t.Fatalf("error.type should not exist on success: %+v", end.attrs) } } @@ -195,7 +188,9 @@ func TestAddRequestLogging_StatusLevels(t *testing.T) { }, ) - client := &http.Client{Transport: transport} + client := &http.Client{ + Transport: transport, + } resp, err := client.Get("http://example.com") if err != nil { @@ -203,22 +198,20 @@ func TestAddRequestLogging_StatusLevels(t *testing.T) { } _ = resp.Body.Close() - finish := sink.snapshot()[1] - if finish.level != tc.wantLevel { - t.Fatalf("finish level = %v, want %v", finish.level, tc.wantLevel) + end := sink.snapshot()[1] + if end.level != tc.wantLevel { + t.Fatalf("end level = %v, want %v", end.level, tc.wantLevel) } - errorAttrs, hasError := finish.attrs["error"].(map[string]any) + _, hasError := end.attrs["error.type"] if tc.wantError == "" { if hasError { - t.Fatalf("error.type should not exist: %+v", finish.attrs) + t.Fatalf("error.type should not exist: %+v", end.attrs) } } else { if !hasError { t.Fatal("error.type missing") } - if got, ok := errorAttrs["type"].(string); !ok { - t.Fatalf("error.type has unexpected type: %T", errorAttrs["type"]) - } else if got != tc.wantError { + if got := end.attrs["error.type"]; got != tc.wantError { t.Fatalf("error.type = %q, want %q", got, tc.wantError) } } @@ -226,12 +219,6 @@ func TestAddRequestLogging_StatusLevels(t *testing.T) { } } -type typedErr struct{} - -func (typedErr) Error() string { return "typed" } - -func (typedErr) ErrorType() string { return "custom_error" } - func TestAddRequestLogging_TransportErrors(t *testing.T) { testCases := []struct { name string @@ -245,14 +232,20 @@ func TestAddRequestLogging_TransportErrors(t *testing.T) { for _, tc := range testCases { t.Run(tc.name, func(t *testing.T) { logger, sink := newCaptureLogger() + transport := interceptor.NewTransport(nil, - interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), + interceptors.AddRequestLogging(&interceptors.LoggingOptions{ + Logger: logger, + }), func(req *http.Request, _ interceptor.HandlerFunc) (*http.Response, error) { return nil, tc.err }, ) - client := &http.Client{Transport: transport} + client := &http.Client{ + Transport: transport, + } + _, err := client.Get("http://example.com") if err == nil { t.Fatal("expected error, got nil") @@ -265,69 +258,13 @@ func TestAddRequestLogging_TransportErrors(t *testing.T) { if records[1].level != slog.LevelError { t.Fatalf("level = %v, want ERROR", records[1].level) } - errorAttrs := mustMapAttr(t, records[1].attrs, "error") - if got, ok := errorAttrs["type"].(string); !ok { - t.Fatalf("error.type has unexpected type: %T", errorAttrs["type"]) - } else if got != tc.wantType { + if got := records[1].attrs["error.type"]; got != tc.wantType { t.Fatalf("error.type = %q, want %q", got, tc.wantType) } }) } } -func TestAddRequestLogging_RequestCloneIsolation(t *testing.T) { - logger, _ := newCaptureLogger() - - req, err := http.NewRequest(http.MethodPost, "http://example.com/v1/items", strings.NewReader("payload")) - if err != nil { - t.Fatalf("http.NewRequest error: %v", err) - } - req.Header.Set("X-Original", "keep") - - transport := interceptor.NewTransport( - nil, - interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), - func(nextReq *http.Request, next interceptor.HandlerFunc) (*http.Response, error) { - nextReq.Header.Set("X-Mutated", "yes") - nextReq.Method = http.MethodPut - nextReq.URL.Path = "/mutated" - return next(nextReq) - }, - func(nextReq *http.Request, _ interceptor.HandlerFunc) (*http.Response, error) { - if nextReq == req { - t.Fatal("downstream received original request pointer; expected clone") - } - if nextReq.Header.Get("X-Mutated") != "yes" { - t.Fatalf("X-Mutated header = %q, want yes", nextReq.Header.Get("X-Mutated")) - } - if nextReq.Method != http.MethodPut { - t.Fatalf("mutated request method = %q, want %q", nextReq.Method, http.MethodPut) - } - if nextReq.URL.Path != "/mutated" { - t.Fatalf("mutated request path = %q, want /mutated", nextReq.URL.Path) - } - return &http.Response{StatusCode: http.StatusOK, Body: io.NopCloser(strings.NewReader("ok"))}, nil - }, - ) - - client := &http.Client{Transport: transport} - resp, err := client.Do(req) - if err != nil { - t.Fatalf("client.Do error: %v", err) - } - _ = resp.Body.Close() - - if got := req.Header.Get("X-Mutated"); got != "" { - t.Fatalf("original request header X-Mutated = %q, want empty", got) - } - if got := req.Method; got != http.MethodPost { - t.Fatalf("original request method = %q, want %q", got, http.MethodPost) - } - if got := req.URL.Path; got != "/v1/items" { - t.Fatalf("original request path = %q, want /v1/items", got) - } -} - func TestAddRequestLogging_HTTPSDefaultPort(t *testing.T) { testCases := []struct { name string @@ -366,20 +303,17 @@ func TestAddRequestLogging_HTTPSDefaultPort(t *testing.T) { _ = resp.Body.Close() start := sink.snapshot()[0].attrs - serverAttrs := mustMapAttr(t, start, "server") - if got, ok := serverAttrs["address"].(string); !ok { - t.Fatalf("server.address has unexpected type: %T", serverAttrs["address"]) - } else if got != tc.wantHost { + if got := start["server.address"]; got != tc.wantHost { t.Fatalf("server.address = %q, want %q", got, tc.wantHost) } - portValue, exists := serverAttrs["port"] + portValue, exists := start["server.port"] if tc.portLogged { if !exists { t.Fatal("server.port missing") } - if got := mustInt64Attr(t, serverAttrs, "port", "server.port"); got != tc.wantPort { - t.Fatalf("server.port = %d, want %d", got, tc.wantPort) + if got := fmt.Sprint(portValue); got != fmt.Sprint(tc.wantPort) { + t.Fatalf("server.port = %v, want %d", got, tc.wantPort) } } else if exists { t.Fatalf("server.port should not be logged for %q, got %v", tc.url, portValue) @@ -387,31 +321,3 @@ func TestAddRequestLogging_HTTPSDefaultPort(t *testing.T) { }) } } - -func mustMapAttr(t *testing.T, attrs map[string]any, key string) map[string]any { - t.Helper() - - group, ok := attrs[key].(map[string]any) - if !ok { - t.Fatalf("%s has unexpected type: %T", key, attrs[key]) - } - - return group -} - -func mustInt64Attr(t *testing.T, attrs map[string]any, key string, path string) int64 { - t.Helper() - - value := attrs[key] - switch v := value.(type) { - case int: - return int64(v) - case int64: - return v - case float64: - return int64(v) - default: - t.Fatalf("%s has unexpected type: %T", path, value) - return 0 - } -} From 73580cdc2bfbc73564ebd1b452047a1facb2e69e Mon Sep 17 00:00:00 2001 From: Fabian Esteban Ruiz Valdes Date: Wed, 11 Mar 2026 16:42:45 -0500 Subject: [PATCH 14/19] feat(logging): improve logging --- README.md | 20 ++++++++++++------ interceptors/logging.go | 40 ++++++++++++++++++++---------------- interceptors/logging_test.go | 8 ++++---- transport.go | 18 ++++++++-------- 4 files changed, 49 insertions(+), 37 deletions(-) diff --git a/README.md b/README.md index 1244d6a..4796e0a 100644 --- a/README.md +++ b/README.md @@ -10,19 +10,30 @@ go get github.com/fervbmx/interceptor ## Usage +Import both packages: + +```go +import ( + "net/http" + + "github.com/fervbmx/interceptor" + "github.com/fervbmx/interceptor/interceptors" +) +``` + ```go // Flow: AddRequestLogging → AddHeader → AddBasicAuth → http.DefaultTransport client := &http.Client{ Transport: interceptor.NewTransport( nil, - interceptors.AddRequestLogging(nil), interceptors.AddHeader("X-API-KEY", "secret"), interceptors.AddBasicAuth("user", "pass"), + interceptors.AddRequestLogging(nil), ), } ``` -Pass `nil` as the first argument to use `http.DefaultTransport`, or provide your own `http.RoundTripper`. +Pass `nil` as the first argument to use `http.DefaultTransport`, or pass a custom `http.RoundTripper` as the base transport. ## Built-in interceptors @@ -32,8 +43,6 @@ Pass `nil` as the first argument to use `http.DefaultTransport`, or provide your | `AddBasicAuth(user, password)` | Sets Basic authentication | | `AddRequestLogging(opts)` | Emits structured `slog` attributes | -`AddRequestLogging` emits request duration as `http.client.request.duration` using seconds as the unit (UCUM `s`). - ## Custom interceptors Write your own `interceptor.Middleware` to hook into the request/response lifecycle. Call `next` to continue the chain, or return early to short-circuit it. @@ -42,7 +51,6 @@ Write your own `interceptor.Middleware` to hook into the request/response lifecy // Log every request and its status code. func Logging(req *http.Request, next interceptor.HandlerFunc) (*http.Response, error) { log.Printf("→ %s %s", req.Method, req.URL) - resp, err := next(req) if err != nil { return nil, err @@ -54,7 +62,7 @@ func Logging(req *http.Request, next interceptor.HandlerFunc) (*http.Response, e client := &http.Client{ Transport: interceptor.NewTransport( http.DefaultTransport, - Logging + Logging, ), } ``` diff --git a/interceptors/logging.go b/interceptors/logging.go index b584f68..9733dc9 100644 --- a/interceptors/logging.go +++ b/interceptors/logging.go @@ -20,14 +20,6 @@ var defaultSensitiveHeaders = []string{ "Set-Cookie", } -type LoggingOptions struct { - Logger *slog.Logger - - HeadersToLog []string - - SensitiveHeaders []string -} - type loggingConfig struct { logger *slog.Logger headersToLog map[string]struct{} @@ -51,6 +43,14 @@ type eventData struct { duration *float64 } +// RequestLoggingOptions configures request logging behavior. +type RequestLoggingOptions struct { + Logger *slog.Logger + HeadersToLog []string + SensitiveHeaders []string +} + +// ErrorTyper is implemented by errors that can expose a stable error type. type ErrorTyper interface { ErrorType() string } @@ -60,12 +60,12 @@ type ErrorTyper interface { // completion event or a failure event. If opts is nil, default logging options // are used. // -// interceptor.NewTransport(nil, -// interceptors.AddRequestLogging( -// Logging: logging -// ), -// ) -func AddRequestLogging(opts *LoggingOptions) interceptor.Middleware { +// interceptor.NewTransport(nil, +// interceptors.AddRequestLogging( +// Logging: logging +// ), +// ) +func AddRequestLogging(opts *RequestLoggingOptions) interceptor.Middleware { cfg := buildLoggingConfig(opts) return func(req *http.Request, next interceptor.HandlerFunc) (*http.Response, error) { @@ -85,7 +85,8 @@ func AddRequestLogging(opts *LoggingOptions) interceptor.Middleware { } } -func buildLoggingConfig(opts *LoggingOptions) loggingConfig { +// buildLoggingConfig merges options with defaults and normalizes header names. +func buildLoggingConfig(opts *RequestLoggingOptions) loggingConfig { cfg := loggingConfig{ logger: slog.Default(), headersToLog: make(map[string]struct{}), @@ -119,6 +120,7 @@ func canonicalHeaderSet(headers []string) map[string]struct{} { return set } +// buildStartEvent assembles attributes for the request-start log entry. func buildStartEvent(req *http.Request, cfg loggingConfig) eventData { e := eventData{ level: slog.LevelInfo, @@ -139,6 +141,7 @@ func buildStartEvent(req *http.Request, cfg loggingConfig) eventData { return e } +// buildEndEvent assembles attributes for completion and failure log entries. func buildEndEvent(req *http.Request, resp *http.Response, err error, duration time.Duration) eventData { seconds := duration.Seconds() e := eventData{ @@ -157,7 +160,7 @@ func buildEndEvent(req *http.Request, resp *http.Response, err error, duration t if err != nil { e.message = "http request failed" - e.errorType = classifyErrorType(err) + e.errorType = getErrorType(err) return e } @@ -289,7 +292,6 @@ func buildHTTPResponseAttrs(event eventData) slog.Attr { } attrs := make([]any, 0, 2) - if event.statusCode != nil { attrs = append(attrs, slog.Int("status_code", *event.statusCode)) } @@ -335,7 +337,8 @@ func extractServerPort(u *url.URL) int { } } -func classifyErrorType(err error) string { +// getErrorType prefers ErrorTyper, then falls back to root error type names. +func getErrorType(err error) string { if err == nil { return "" } @@ -374,6 +377,7 @@ func classifyErrorType(err error) string { return typeName } +// extractAllowedHeaders returns allowlisted headers with sensitive values redacted. func extractAllowedHeaders(headers http.Header, allowlist, sensitive map[string]struct{}) map[string]string { if len(allowlist) == 0 { return nil diff --git a/interceptors/logging_test.go b/interceptors/logging_test.go index 4ccccd8..7aa974e 100644 --- a/interceptors/logging_test.go +++ b/interceptors/logging_test.go @@ -89,7 +89,7 @@ func TestAddRequestLogging_SuccessWithHeaders(t *testing.T) { logger, sink := newCaptureLogger() transport := interceptor.NewTransport(nil, - interceptors.AddRequestLogging(&interceptors.LoggingOptions{ + interceptors.AddRequestLogging(&interceptors.RequestLoggingOptions{ Logger: logger, HeadersToLog: []string{"Authorization", "X-Correlation-ID"}, }), @@ -179,7 +179,7 @@ func TestAddRequestLogging_StatusLevels(t *testing.T) { t.Run(tc.name, func(t *testing.T) { logger, sink := newCaptureLogger() transport := interceptor.NewTransport(nil, - interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), + interceptors.AddRequestLogging(&interceptors.RequestLoggingOptions{Logger: logger}), func(req *http.Request, _ interceptor.HandlerFunc) (*http.Response, error) { return &http.Response{ StatusCode: tc.status, @@ -234,7 +234,7 @@ func TestAddRequestLogging_TransportErrors(t *testing.T) { logger, sink := newCaptureLogger() transport := interceptor.NewTransport(nil, - interceptors.AddRequestLogging(&interceptors.LoggingOptions{ + interceptors.AddRequestLogging(&interceptors.RequestLoggingOptions{ Logger: logger, }), func(req *http.Request, _ interceptor.HandlerFunc) (*http.Response, error) { @@ -284,7 +284,7 @@ func TestAddRequestLogging_HTTPSDefaultPort(t *testing.T) { logger, sink := newCaptureLogger() transport := interceptor.NewTransport(nil, - interceptors.AddRequestLogging(&interceptors.LoggingOptions{Logger: logger}), + interceptors.AddRequestLogging(&interceptors.RequestLoggingOptions{Logger: logger}), func(req *http.Request, _ interceptor.HandlerFunc) (*http.Response, error) { return &http.Response{StatusCode: http.StatusOK, Body: io.NopCloser(strings.NewReader("ok"))}, nil }, diff --git a/transport.go b/transport.go index ec82ca1..74289a9 100644 --- a/transport.go +++ b/transport.go @@ -25,15 +25,15 @@ type Transport struct { // and interceptors. If defaultTransport is nil, http.DefaultTransport is used. // Interceptors are executed in the order provided. // -// // Using the default transport: -// client := &http.Client{ -// Transport: interceptor.NewTransport(nil, AInterceptor, BInterceptor), -// } +// // Using the default transport: +// client := &http.Client{ +// Transport: interceptor.NewTransport(nil, AInterceptor, BInterceptor), +// } // -// // Using a custom default transport: -// client := &http.Client{ -// Transport: interceptor.NewTransport(customTransport, AInterceptor, BInterceptor), -// } +// // Using a custom default transport: +// client := &http.Client{ +// Transport: interceptor.NewTransport(customTransport, AInterceptor, BInterceptor), +// } func NewTransport(defaultTransport http.RoundTripper, interceptors ...Middleware) *Transport { if defaultTransport == nil { defaultTransport = http.DefaultTransport @@ -47,7 +47,7 @@ func NewTransport(defaultTransport http.RoundTripper, interceptors ...Middleware // Add appends one or more interceptors to the chain. They are appended after // any interceptors already registered. // -// t := interceptor.NewTransport(nil, AuthInterceptor).Add(MetricsInterceptor) +// t := interceptor.NewTransport(nil, AuthInterceptor).Add(MetricsInterceptor) func (t *Transport) Add(interceptors ...Middleware) *Transport { t.interceptors = append(t.interceptors, interceptors...) return t From 20778d260e23a0a2a1181603be1e0f8f3b6182d7 Mon Sep 17 00:00:00 2001 From: Fabian Esteban Ruiz Valdes Date: Wed, 11 Mar 2026 17:42:09 -0500 Subject: [PATCH 15/19] feat(logging): improve logging --- interceptors/logging.go | 90 +++++++++++++----------------------- interceptors/logging_test.go | 8 ++-- 2 files changed, 36 insertions(+), 62 deletions(-) diff --git a/interceptors/logging.go b/interceptors/logging.go index 9733dc9..a75f7ec 100644 --- a/interceptors/logging.go +++ b/interceptors/logging.go @@ -1,7 +1,6 @@ package interceptors import ( - "errors" "log/slog" "net/http" "net/textproto" @@ -14,11 +13,12 @@ import ( "github.com/fervbmx/interceptor" ) -var defaultSensitiveHeaders = []string{ +const redacted = "REDACTED" +var defaultSensitiveHeaders = newHeaderSet( "Authorization", "Cookie", "Set-Cookie", -} +) type loggingConfig struct { logger *slog.Logger @@ -50,20 +50,15 @@ type RequestLoggingOptions struct { SensitiveHeaders []string } -// ErrorTyper is implemented by errors that can expose a stable error type. -type ErrorTyper interface { - ErrorType() string -} - // AddRequestLogging returns an interceptor that logs request lifecycle events // before and after the next handler runs. It emits a start event, then either a // completion event or a failure event. If opts is nil, default logging options // are used. // // interceptor.NewTransport(nil, -// interceptors.AddRequestLogging( -// Logging: logging -// ), +// interceptors.AddRequestLogging( +// Logging: logging +// ), // ) func AddRequestLogging(opts *RequestLoggingOptions) interceptor.Middleware { cfg := buildLoggingConfig(opts) @@ -90,7 +85,7 @@ func buildLoggingConfig(opts *RequestLoggingOptions) loggingConfig { cfg := loggingConfig{ logger: slog.Default(), headersToLog: make(map[string]struct{}), - sensitiveHeaders: canonicalHeaderSet(defaultSensitiveHeaders), + sensitiveHeaders: defaultSensitiveHeaders, } if opts == nil { @@ -102,17 +97,17 @@ func buildLoggingConfig(opts *RequestLoggingOptions) loggingConfig { } if len(opts.HeadersToLog) > 0 { - cfg.headersToLog = canonicalHeaderSet(opts.HeadersToLog) + cfg.headersToLog = newHeaderSet(opts.HeadersToLog...) } if len(opts.SensitiveHeaders) > 0 { - cfg.sensitiveHeaders = canonicalHeaderSet(opts.SensitiveHeaders) + cfg.sensitiveHeaders = newHeaderSet(opts.SensitiveHeaders...) } return cfg } -func canonicalHeaderSet(headers []string) map[string]struct{} { +func newHeaderSet(headers ...string) map[string]struct{} { set := make(map[string]struct{}, len(headers)) for _, h := range headers { set[textproto.CanonicalMIMEHeaderKey(h)] = struct{}{} @@ -129,9 +124,9 @@ func buildStartEvent(req *http.Request, cfg loggingConfig) eventData { urlFull: req.URL.String(), urlScheme: req.URL.Scheme, serverAddress: req.URL.Hostname(), - serverPort: extractServerPort(req.URL), + serverPort: getServerPort(req.URL), userAgent: req.Header.Get("User-Agent"), - requestHeaders: extractAllowedHeaders(req.Header, cfg.headersToLog, cfg.sensitiveHeaders), + requestHeaders: getAllowedHeaders(req.Header, cfg.headersToLog, cfg.sensitiveHeaders), } if req.ContentLength >= 0 { @@ -150,7 +145,7 @@ func buildEndEvent(req *http.Request, resp *http.Response, err error, duration t urlFull: req.URL.String(), urlScheme: req.URL.Scheme, serverAddress: req.URL.Hostname(), - serverPort: extractServerPort(req.URL), + serverPort: getServerPort(req.URL), duration: &seconds, } @@ -317,7 +312,8 @@ func buildHTTPClientAttrs(event eventData) slog.Attr { ) } -func extractServerPort(u *url.URL) int { +// getErrorType returns port of the url. +func getServerPort(u *url.URL) int { if u == nil { return 0 } @@ -337,70 +333,50 @@ func extractServerPort(u *url.URL) int { } } -// getErrorType prefers ErrorTyper, then falls back to root error type names. +// getErrorType returns the root error type name. func getErrorType(err error) string { if err == nil { return "" } - var typedErr ErrorTyper - if errors.As(err, &typedErr) { - if errorType := typedErr.ErrorType(); errorType != "" { - return errorType - } - } - - root := err - for { - unwrapped := errors.Unwrap(root) - if unwrapped == nil { - break - } - root = unwrapped - } - - t := reflect.TypeOf(root) - if t == nil { - return "error" - } + t := reflect.TypeOf(err) for t.Kind() == reflect.Pointer { t = t.Elem() } + if name := t.Name(); name != "" { return name } - typeName := t.String() - if idx := strings.LastIndex(typeName, "."); idx >= 0 { - return typeName[idx+1:] - } - return typeName + return t.String() } -// extractAllowedHeaders returns allowlisted headers with sensitive values redacted. -func extractAllowedHeaders(headers http.Header, allowlist, sensitive map[string]struct{}) map[string]string { - if len(allowlist) == 0 { +// getAllowedHeaders returns allowed headers with sensitive values redacted. +func getAllowedHeaders(headers http.Header, allowed, sensitive map[string]struct{}) map[string]string { + if len(allowed) == 0 { return nil } - loggedHeaders := make(map[string]string) - for header := range allowlist { - value := headers.Get(header) - if value == "" { + logged := make(map[string]string, len(allowed)) + + for h := range allowed { + key := textproto.CanonicalMIMEHeaderKey(h) + values, ok := headers[key] + if !ok || len(values) == 0 { continue } - if _, redact := sensitive[textproto.CanonicalMIMEHeaderKey(header)]; redact { - loggedHeaders[header] = "***" + if _, isSensitive := sensitive[key]; isSensitive { + logged[h] = redacted continue } - loggedHeaders[header] = value + logged[h] = values[0] } - if len(loggedHeaders) == 0 { + if len(logged) == 0 { return nil } - return loggedHeaders + return logged } diff --git a/interceptors/logging_test.go b/interceptors/logging_test.go index 7aa974e..fca143b 100644 --- a/interceptors/logging_test.go +++ b/interceptors/logging_test.go @@ -83,8 +83,6 @@ type typedErr struct{} func (typedErr) Error() string { return "typed" } -func (typedErr) ErrorType() string { return "custom_error" } - func TestAddRequestLogging_SuccessWithHeaders(t *testing.T) { logger, sink := newCaptureLogger() @@ -132,8 +130,8 @@ func TestAddRequestLogging_SuccessWithHeaders(t *testing.T) { if got := start.attrs["http.request.method"]; got != http.MethodPost { t.Fatalf("http.request.method = %q, want %q", got, http.MethodPost) } - if got := start.attrs["http.request.header.authorization"]; got != "***" { - t.Fatalf("http.request.header.authorization = %q, want %q", got, "***") + if got := start.attrs["http.request.header.authorization"]; got != "REDACTED" { + t.Fatalf("http.request.header.authorization = %q, want %q", got, "REDACTED") } if got := start.attrs["http.request.header.x-correlation-id"]; got != "corr-1" { t.Fatalf("http.request.header.x-correlation-id = %q, want %q", got, "corr-1") @@ -225,7 +223,7 @@ func TestAddRequestLogging_TransportErrors(t *testing.T) { err error wantType string }{ - {name: "typed error", err: typedErr{}, wantType: "custom_error"}, + {name: "typed error", err: typedErr{}, wantType: "typedErr"}, {name: "generic error", err: errors.New("dial failed"), wantType: "errorString"}, } From 1a2178845af2fee7145ddb8052c386518e79f652 Mon Sep 17 00:00:00 2001 From: Fabian Esteban Ruiz Valdes Date: Wed, 11 Mar 2026 17:43:29 -0500 Subject: [PATCH 16/19] feat(logging): improve logging --- interceptors/logging.go | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/interceptors/logging.go b/interceptors/logging.go index a75f7ec..3d386a4 100644 --- a/interceptors/logging.go +++ b/interceptors/logging.go @@ -20,7 +20,7 @@ var defaultSensitiveHeaders = newHeaderSet( "Set-Cookie", ) -type loggingConfig struct { +type requestLoggingConfig struct { logger *slog.Logger headersToLog map[string]struct{} sensitiveHeaders map[string]struct{} @@ -81,8 +81,8 @@ func AddRequestLogging(opts *RequestLoggingOptions) interceptor.Middleware { } // buildLoggingConfig merges options with defaults and normalizes header names. -func buildLoggingConfig(opts *RequestLoggingOptions) loggingConfig { - cfg := loggingConfig{ +func buildLoggingConfig(opts *RequestLoggingOptions) requestLoggingConfig { + cfg := requestLoggingConfig{ logger: slog.Default(), headersToLog: make(map[string]struct{}), sensitiveHeaders: defaultSensitiveHeaders, @@ -116,7 +116,7 @@ func newHeaderSet(headers ...string) map[string]struct{} { } // buildStartEvent assembles attributes for the request-start log entry. -func buildStartEvent(req *http.Request, cfg loggingConfig) eventData { +func buildStartEvent(req *http.Request, cfg requestLoggingConfig) eventData { e := eventData{ level: slog.LevelInfo, message: "http request started", @@ -189,7 +189,7 @@ func getLogLevel(resp *http.Response, err error) slog.Level { return slog.LevelInfo } -func emitLog(req *http.Request, cfg loggingConfig, event eventData) { +func emitLog(req *http.Request, cfg requestLoggingConfig, event eventData) { attrs := buildAttrs(event) cfg.logger.LogAttrs(req.Context(), event.level, event.message, attrs...) } From 580f6afd26c50ad7f3a44195b4c62acbe1ab8351 Mon Sep 17 00:00:00 2001 From: Fabian Esteban Ruiz Valdes Date: Wed, 11 Mar 2026 17:51:08 -0500 Subject: [PATCH 17/19] feat(logging): improve interfaces --- README.md | 14 +++++++------- interceptors/auth.go | 6 +++--- interceptors/auth_test.go | 4 ++-- interceptors/headers.go | 6 +++--- interceptors/headers_test.go | 2 +- interceptors/logging.go | 27 +++++++++++++++------------ interceptors/logging_test.go | 16 ++++++++-------- transport.go | 20 +++++++++++--------- transport_test.go | 2 +- 9 files changed, 51 insertions(+), 46 deletions(-) diff --git a/README.md b/README.md index 4796e0a..1abd139 100644 --- a/README.md +++ b/README.md @@ -22,13 +22,13 @@ import ( ``` ```go -// Flow: AddRequestLogging → AddHeader → AddBasicAuth → http.DefaultTransport +// Flow: RequestLogging → Header → BasicAuth → http.DefaultTransport client := &http.Client{ Transport: interceptor.NewTransport( nil, - interceptors.AddHeader("X-API-KEY", "secret"), - interceptors.AddBasicAuth("user", "pass"), - interceptors.AddRequestLogging(nil), + interceptors.Header("X-API-KEY", "secret"), + interceptors.BasicAuth("user", "pass"), + interceptors.RequestLogging(nil), ), } ``` @@ -39,9 +39,9 @@ Pass `nil` as the first argument to use `http.DefaultTransport`, or pass a custo | Interceptor | Description | |---|---| -| `AddHeader(key, value)` | Sets a header on every request | -| `AddBasicAuth(user, password)` | Sets Basic authentication | -| `AddRequestLogging(opts)` | Emits structured `slog` attributes | +| `Header(key, value)` | Sets a header on every request | +| `BasicAuth(user, password)` | Sets Basic authentication | +| `RequestLogging(opts)` | Emits structured `slog` attributes | ## Custom interceptors diff --git a/interceptors/auth.go b/interceptors/auth.go index 076eab2..96959d6 100644 --- a/interceptors/auth.go +++ b/interceptors/auth.go @@ -6,13 +6,13 @@ import ( "github.com/fervbmx/interceptor" ) -// AddBasicAuth returns an interceptor that sets Basic authentication on every +// BasicAuth returns an interceptor that sets Basic authentication on every // outgoing request. // // interceptor.NewTransport(nil, -// interceptors.AddBasicAuth("username", "password"), +// interceptors.BasicAuth("username", "password"), // ) -func AddBasicAuth(username, password string) interceptor.Middleware { +func BasicAuth(username, password string) interceptor.Middleware { return func(req *http.Request, next interceptor.HandlerFunc) (*http.Response, error) { clonedReq := req.Clone(req.Context()) clonedReq.SetBasicAuth(username, password) diff --git a/interceptors/auth_test.go b/interceptors/auth_test.go index 3adc882..da62772 100644 --- a/interceptors/auth_test.go +++ b/interceptors/auth_test.go @@ -10,7 +10,7 @@ import ( "github.com/fervbmx/interceptor/interceptors" ) -func TestAddBasicAuth(t *testing.T) { +func TestBasicAuth(t *testing.T) { cases := []struct { name string username string @@ -41,7 +41,7 @@ func TestAddBasicAuth(t *testing.T) { client := http.Client{ Transport: interceptor.NewTransport( http.DefaultTransport, - interceptors.AddBasicAuth(tc.username, tc.password), + interceptors.BasicAuth(tc.username, tc.password), ), Timeout: 15 * time.Second, } diff --git a/interceptors/headers.go b/interceptors/headers.go index 77a8690..66561df 100644 --- a/interceptors/headers.go +++ b/interceptors/headers.go @@ -6,13 +6,13 @@ import ( "github.com/fervbmx/interceptor" ) -// AddHeader returns an interceptor that sets a header on every outgoing +// Header returns an interceptor that sets a header on every outgoing // request. // // interceptor.NewTransport(nil, -// interceptors.AddHeader("User-Agent", "MyApp/1.0"), +// interceptors.Header("User-Agent", "MyApp/1.0"), // ) -func AddHeader(key, value string) interceptor.Middleware { +func Header(key, value string) interceptor.Middleware { return func(req *http.Request, next interceptor.HandlerFunc) (*http.Response, error) { clonedReq := req.Clone(req.Context()) clonedReq.Header.Set(key, value) diff --git a/interceptors/headers_test.go b/interceptors/headers_test.go index f7db504..73f11c2 100644 --- a/interceptors/headers_test.go +++ b/interceptors/headers_test.go @@ -45,7 +45,7 @@ func TestHeaderInterceptor(t *testing.T) { client := http.Client{ Transport: interceptor.NewTransport( http.DefaultTransport, - interceptors.AddHeader(tc.key, tc.value), + interceptors.Header(tc.key, tc.value), ), Timeout: 15 * time.Second, } diff --git a/interceptors/logging.go b/interceptors/logging.go index 3d386a4..b54ea8c 100644 --- a/interceptors/logging.go +++ b/interceptors/logging.go @@ -14,6 +14,7 @@ import ( ) const redacted = "REDACTED" + var defaultSensitiveHeaders = newHeaderSet( "Authorization", "Cookie", @@ -50,17 +51,19 @@ type RequestLoggingOptions struct { SensitiveHeaders []string } -// AddRequestLogging returns an interceptor that logs request lifecycle events +// RequestLogging returns an interceptor that logs request lifecycle events // before and after the next handler runs. It emits a start event, then either a // completion event or a failure event. If opts is nil, default logging options // are used. // // interceptor.NewTransport(nil, -// interceptors.AddRequestLogging( +// +// interceptors.RequestLogging( // Logging: logging // ), +// // ) -func AddRequestLogging(opts *RequestLoggingOptions) interceptor.Middleware { +func RequestLogging(opts *RequestLoggingOptions) interceptor.Middleware { cfg := buildLoggingConfig(opts) return func(req *http.Request, next interceptor.HandlerFunc) (*http.Response, error) { @@ -353,25 +356,25 @@ func getErrorType(err error) string { // getAllowedHeaders returns allowed headers with sensitive values redacted. func getAllowedHeaders(headers http.Header, allowed, sensitive map[string]struct{}) map[string]string { - if len(allowed) == 0 { + if len(headers) == 0 || len(allowed) == 0 { return nil } - logged := make(map[string]string, len(allowed)) + logged := make(map[string]string, len(headers)) - for h := range allowed { - key := textproto.CanonicalMIMEHeaderKey(h) - values, ok := headers[key] - if !ok || len(values) == 0 { + for key, values := range headers { + if _, ok := allowed[key]; !ok { continue } - if _, isSensitive := sensitive[key]; isSensitive { - logged[h] = redacted + if _, ok := sensitive[key]; ok { + logged[key] = redacted continue } - logged[h] = values[0] + if len(values) > 0 { + logged[key] = values[0] + } } if len(logged) == 0 { diff --git a/interceptors/logging_test.go b/interceptors/logging_test.go index fca143b..4820f5a 100644 --- a/interceptors/logging_test.go +++ b/interceptors/logging_test.go @@ -83,11 +83,11 @@ type typedErr struct{} func (typedErr) Error() string { return "typed" } -func TestAddRequestLogging_SuccessWithHeaders(t *testing.T) { +func TestRequestLogging_SuccessWithHeaders(t *testing.T) { logger, sink := newCaptureLogger() transport := interceptor.NewTransport(nil, - interceptors.AddRequestLogging(&interceptors.RequestLoggingOptions{ + interceptors.RequestLogging(&interceptors.RequestLoggingOptions{ Logger: logger, HeadersToLog: []string{"Authorization", "X-Correlation-ID"}, }), @@ -161,7 +161,7 @@ func TestAddRequestLogging_SuccessWithHeaders(t *testing.T) { } } -func TestAddRequestLogging_StatusLevels(t *testing.T) { +func TestRequestLogging_StatusLevels(t *testing.T) { testCases := []struct { name string status int @@ -177,7 +177,7 @@ func TestAddRequestLogging_StatusLevels(t *testing.T) { t.Run(tc.name, func(t *testing.T) { logger, sink := newCaptureLogger() transport := interceptor.NewTransport(nil, - interceptors.AddRequestLogging(&interceptors.RequestLoggingOptions{Logger: logger}), + interceptors.RequestLogging(&interceptors.RequestLoggingOptions{Logger: logger}), func(req *http.Request, _ interceptor.HandlerFunc) (*http.Response, error) { return &http.Response{ StatusCode: tc.status, @@ -217,7 +217,7 @@ func TestAddRequestLogging_StatusLevels(t *testing.T) { } } -func TestAddRequestLogging_TransportErrors(t *testing.T) { +func TestRequestLogging_TransportErrors(t *testing.T) { testCases := []struct { name string err error @@ -232,7 +232,7 @@ func TestAddRequestLogging_TransportErrors(t *testing.T) { logger, sink := newCaptureLogger() transport := interceptor.NewTransport(nil, - interceptors.AddRequestLogging(&interceptors.RequestLoggingOptions{ + interceptors.RequestLogging(&interceptors.RequestLoggingOptions{ Logger: logger, }), func(req *http.Request, _ interceptor.HandlerFunc) (*http.Response, error) { @@ -263,7 +263,7 @@ func TestAddRequestLogging_TransportErrors(t *testing.T) { } } -func TestAddRequestLogging_HTTPSDefaultPort(t *testing.T) { +func TestRequestLogging_HTTPSDefaultPort(t *testing.T) { testCases := []struct { name string url string @@ -282,7 +282,7 @@ func TestAddRequestLogging_HTTPSDefaultPort(t *testing.T) { logger, sink := newCaptureLogger() transport := interceptor.NewTransport(nil, - interceptors.AddRequestLogging(&interceptors.RequestLoggingOptions{Logger: logger}), + interceptors.RequestLogging(&interceptors.RequestLoggingOptions{Logger: logger}), func(req *http.Request, _ interceptor.HandlerFunc) (*http.Response, error) { return &http.Response{StatusCode: http.StatusOK, Body: io.NopCloser(strings.NewReader("ok"))}, nil }, diff --git a/transport.go b/transport.go index 74289a9..041152d 100644 --- a/transport.go +++ b/transport.go @@ -26,14 +26,16 @@ type Transport struct { // Interceptors are executed in the order provided. // // // Using the default transport: -// client := &http.Client{ -// Transport: interceptor.NewTransport(nil, AInterceptor, BInterceptor), -// } +// +// client := &http.Client{ +// Transport: interceptor.NewTransport(nil, AInterceptor, BInterceptor), +// } // // // Using a custom default transport: -// client := &http.Client{ -// Transport: interceptor.NewTransport(customTransport, AInterceptor, BInterceptor), -// } +// +// client := &http.Client{ +// Transport: interceptor.NewTransport(customTransport, AInterceptor, BInterceptor), +// } func NewTransport(defaultTransport http.RoundTripper, interceptors ...Middleware) *Transport { if defaultTransport == nil { defaultTransport = http.DefaultTransport @@ -44,11 +46,11 @@ func NewTransport(defaultTransport http.RoundTripper, interceptors ...Middleware } } -// Add appends one or more interceptors to the chain. They are appended after +// Use appends one or more interceptors to the chain. They are appended after // any interceptors already registered. // -// t := interceptor.NewTransport(nil, AuthInterceptor).Add(MetricsInterceptor) -func (t *Transport) Add(interceptors ...Middleware) *Transport { +// t := interceptor.NewTransport(nil, AuthInterceptor).Use(MetricsInterceptor) +func (t *Transport) Use(interceptors ...Middleware) *Transport { t.interceptors = append(t.interceptors, interceptors...) return t } diff --git a/transport_test.go b/transport_test.go index f5dbdbb..f797284 100644 --- a/transport_test.go +++ b/transport_test.go @@ -25,7 +25,7 @@ func TestTransport(t *testing.T) { } tp := interceptor.NewTransport(nil, aInterceptor) - tp.Add(bInterceptor) + tp.Use(bInterceptor) client := &http.Client{ Transport: tp, From cd558c3238fdbc70ae38fc03217d2447c96d3bf2 Mon Sep 17 00:00:00 2001 From: Fabian Esteban Ruiz Valdes Date: Wed, 11 Mar 2026 17:53:52 -0500 Subject: [PATCH 18/19] feat(logging): improve interfaces --- interceptors/logging.go | 13 ++++++------- 1 file changed, 6 insertions(+), 7 deletions(-) diff --git a/interceptors/logging.go b/interceptors/logging.go index b54ea8c..a94ea7b 100644 --- a/interceptors/logging.go +++ b/interceptors/logging.go @@ -56,13 +56,12 @@ type RequestLoggingOptions struct { // completion event or a failure event. If opts is nil, default logging options // are used. // -// interceptor.NewTransport(nil, -// -// interceptors.RequestLogging( -// Logging: logging -// ), -// -// ) +// interceptor.NewTransport(nil, +// interceptors.RequestLogging(&interceptors.RequestLoggingOptions{ +// HeadersToLog: []string{"User-Agent"}, +// }), +// ) + func RequestLogging(opts *RequestLoggingOptions) interceptor.Middleware { cfg := buildLoggingConfig(opts) From 6319ef3dc45c77b46a83afc7ce5b7f12de8df124 Mon Sep 17 00:00:00 2001 From: Fabian Esteban Ruiz Valdes Date: Wed, 11 Mar 2026 17:58:04 -0500 Subject: [PATCH 19/19] feat(logging): add ci --- .github/workflows/ci.yaml | 25 +++++++++++++++++++++++++ 1 file changed, 25 insertions(+) create mode 100644 .github/workflows/ci.yaml diff --git a/.github/workflows/ci.yaml b/.github/workflows/ci.yaml new file mode 100644 index 0000000..ad07fc4 --- /dev/null +++ b/.github/workflows/ci.yaml @@ -0,0 +1,25 @@ +name: CI + +on: + pull_request: + push: + branches: + - main + +permissions: + contents: read + +jobs: + test: + runs-on: ubuntu-latest + steps: + - name: Checkout + uses: actions/checkout@v4 + + - name: Set up Go + uses: actions/setup-go@v5 + with: + go-version: "1.25" + + - name: Run tests + run: go test ./... \ No newline at end of file