feat: Add Structured Logging (#9)

Author: bartventer

.golangci.yaml

@@ -25,6 +25,7 @@ linters:
     - gosec
     - govet
     - ineffassign
+    - iface
     - loggercheck
     - makezero
     - mirror
@@ -178,6 +179,14 @@ linters:
     rowserrcheck:
       packages:
         - github.com/jmoiron/sqlx
+    sloglint:
+      static-msg: true
+      attr-only: true
+      args-on-sep-lines: true
+      no-global: all
+      context: all
+      msg-style: capitalized
+      key-naming-case: snake
     staticcheck:
       checks:
         - -ST1003

context.go

@@ -0,0 +1,33 @@
+// Copyright (c) 2025 Bart Venter <bartventer@proton.me>
+//
+// Licensed under the Apache License, Version 2.0 (the "License");
+// you may not use this file except in compliance with the License.
+// You may obtain a copy of the License at
+//
+//   http://www.apache.org/licenses/LICENSE-2.0
+//
+// Unless required by applicable law or agreed to in writing, software
+// distributed under the License is distributed on an "AS IS" BASIS,
+// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+// See the License for the specific language governing permissions and
+// limitations under the License.
+
+package httpcache
+
+import (
+	"context"
+
+	"github.com/bartventer/httpcache/internal"
+)
+
+// ContextWithTraceID adds a trace ID to the context, which can be used for
+// logging or tracing purposes. The trace ID can be retrieved later using
+// [TraceIDFromContext].
+func ContextWithTraceID(ctx context.Context, traceID string) context.Context {
+	return context.WithValue(ctx, internal.TraceIDKey, traceID)
+}
+
+// TraceIDFromContext retrieves the trace ID from the context, if it exists.
+func TraceIDFromContext(ctx context.Context) (string, bool) {
+	return internal.TraceIDFromContext(ctx)
+}

docs/log.schema.md

@@ -0,0 +1,83 @@
+# Log Schema for HTTP Cache
+
+This document describes the structured log schema, in JSON format, used by the HTTP cache service. The schema is designed to provide detailed, machine-readable logs for cache operations, including hits, misses, stale responses, revalidations, bypasses, and errors.
+
+| Field     | Type   | Description                                                       |
+| --------- | ------ | ----------------------------------------------------------------- |
+| timestamp | string | ISO8601 timestamp of the log entry                                |
+| level     | string | Log level: `DEBUG`, `INFO`, `WARN`, `ERROR`                       |
+| service   | string | Always `httpcache`                                                |
+| event     | string | Event type: `HIT`, `MISS`, etc.                                   |
+| msg       | string | Human-readable summary                                            |
+| trace_id  | string | Trace/correlation ID (if provided)                                |
+| error     | string | Error message (only for error logs)                               |
+| request   | object | HTTP request context (see [below](#request-object))               |
+| cache     | object | Cache context (see [below](#cache-object))                        |
+| misc      | object | Additional context (optional, see [below](#misc-object-optional)) |
+
+## `request` object
+| Field  | Type   | Description      |
+| ------ | ------ | ---------------- |
+| method | string | HTTP method      |
+| url    | string | Full request URL |
+| host   | string | Host header      |
+
+## `cache` object
+| Field   | Type   | Description         |
+| ------- | ------ | ------------------- |
+| status  | string | HIT, MISS, STALE... |
+| url_key | string | Cache key           |
+
+## `misc` object (optional)
+| Field       | Type   | Description                                                    |
+| ----------- | ------ | -------------------------------------------------------------- |
+| cc_request  | object | Cache-Control request directives (if present)                  |
+| cc_response | object | Cache-Control response directives (if present)                 |
+| stored      | object | Cached response details (if present)                           |
+| freshness   | object | Freshness details (if present, see [below](#freshness-object)) |
+| ref         | object | Reference details (if present)                                 |
+
+## `freshness` object (optional)
+| Field     | Type    | Description                                           |
+| --------- | ------- | ----------------------------------------------------- |
+| is_stale  | boolean | Whether the response is stale                         |
+| age       | object  | Age of the cached response (see [below](#age-object)) |
+| timestamp | string  | Timestamp of the age calculation (ISO8601)            |
+
+## `age` object (optional)
+| Field     | Type   | Description                                |
+| --------- | ------ | ------------------------------------------ |
+| value     | number | Age in seconds                             |
+| timestamp | string | Timestamp of the age calculation (ISO8601) |
+
+
+### Example
+```json
+{
+  "timestamp": "2025-07-01T14:20:00.000Z",
+  "level": "INFO",
+  "service": "httpcache",
+  "event": "HIT",
+  "msg": "Cache hit; served from cache.",
+  "trace_id": "abc123def456",
+  "request": {
+    "method": "GET",
+    "url": "https://api.example.com/data",
+    "host": "api.example.com"
+  },
+  "cache": {
+    "status": "HIT",
+    "url_key": "https://api.example.com/data"
+  },
+  "misc": {
+    "cc_request": {"max-age":"60"},
+    "cc_response": {"max-age":"120", "stale-while-revalidate":"30"},
+    "freshness": {
+      "is_stale":false,
+      "age": {
+        "value":298741541,
+        "timestamp":"2025-07-01T14:35:19.298742743Z"
+      },
+    }
+}
+```

internal/entry.go

@@ -22,6 +22,7 @@ import (
 	"fmt"
 	"io"
 	"iter"
+	"log/slog"
 	"net/http"
 	"net/http/httputil"
 	"os"
@@ -36,6 +37,18 @@ type Response struct {
 	ReceivedAt  time.Time      // time when the response was received, used for determining cache freshness
 }
 
+var _ slog.LogValuer = (*Response)(nil)
+
+func (r Response) LogValue() slog.Value {
+	return slog.GroupValue(
+		slog.String("id", r.ID),
+		slog.Time("requested_at", r.RequestedAt),
+		slog.Time("received_at", r.ReceivedAt),
+		slog.String("status", r.Data.Status),
+		slog.Int("status_code", r.Data.StatusCode),
+	)
+}
+
 // DateHeader returns the parsed value of the "Date" header from the response.
 //
 // NOTE: It assumes a valid "Date" header has been set by [FixDateHeader].
@@ -65,7 +78,7 @@ func (r *Response) ExpiresHeader() (t time.Time, found bool, valid bool) {
 	}
 	expires, err := parseHTTPDateCompat(expiresStr)
 	if err != nil || expires.IsZero() {
-		return time.Time{}, false, false
+		return
 	}
 	return expires, true, true
 }
@@ -138,6 +151,17 @@ type ResponseRef struct {
 	ReceivedAt   time.Time         `json:"received_at,omitzero"` // when the response was generated.
 }
 
+var _ slog.LogValuer = (*ResponseRef)(nil)
+
+func (r ResponseRef) LogValue() slog.Value {
+	return slog.GroupValue(
+		slog.String("response_id", r.ResponseID),
+		slog.String("vary", r.Vary),
+		slog.Any("vary_resolved", r.VaryResolved),
+		slog.Time("received_at", r.ReceivedAt),
+	)
+}
+
 type ResponseRefs []*ResponseRef
 
 func (he ResponseRefs) ResponseIDs() iter.Seq[string] {

internal/freshness.go

@@ -15,6 +15,8 @@
 package internal
 
 import (
+	"cmp"
+	"log/slog"
 	"net/http"
 	"strconv"
 	"time"
@@ -25,12 +27,31 @@ type Age struct {
 	Timestamp time.Time     // Time when the age was calculated
 }
 
+var _ slog.LogValuer = (*Age)(nil)
+
+func (a Age) LogValue() slog.Value {
+	return slog.GroupValue(
+		slog.Duration("value", a.Value),
+		slog.Time("timestamp", a.Timestamp),
+	)
+}
+
 type Freshness struct {
 	IsStale    bool          // Whether the response is stale
 	Age        *Age          // Current age (seconds) of the response (RFC9111 §4.2.3)
 	UsefulLife time.Duration // Freshness lifetime (seconds) of the response (RFC9111 §4.2.1)
 }
 
+var _ slog.LogValuer = (*Freshness)(nil)
+
+func (f Freshness) LogValue() slog.Value {
+	return slog.GroupValue(
+		slog.Bool("is_stale", f.IsStale),
+		slog.Any("age", cmp.Or(f.Age, &Age{Value: 0, Timestamp: time.Time{}})),
+		slog.Duration("useful_life", f.UsefulLife),
+	)
+}
+
 // heuristicFreshness calculates freshness lifetime using heuristics (10% of (date - last-modified)),
 // per RFC9111 §4.2.2.
 func heuristicFreshness(h http.Header, date time.Time) time.Duration {

internal/header.go

@@ -15,6 +15,7 @@
 package internal
 
 import (
+	"log/slog"
 	"net/http"
 )
 
@@ -41,6 +42,15 @@ func (s CacheStatus) ApplyTo(header http.Header) {
 	}
 }
 
+var _ slog.LogValuer = (*CacheStatus)(nil)
+
+func (s CacheStatus) LogValue() slog.Value {
+	return slog.GroupValue(
+		slog.String("value", s.Value),
+		slog.Bool("from_cache", s.Legacy == FromCache),
+	)
+}
+
 const (
 	FromCache    = "1"
 	NotFromCache = ""

internal/helpers.go

@@ -153,8 +153,8 @@ func validOptionalPort(port string) bool {
 	return true
 }
 
-func IsUnsafeMethod(req *http.Request) bool {
-	switch req.Method {
+func IsUnsafeMethod(method string) bool {
+	switch method {
 	case http.MethodPost, http.MethodPut, http.MethodDelete, http.MethodPatch:
 		return true
 	default: