Coffee journaling on ATProto (alpha)
alpha.arabica.social
coffee
feat: correlation ID for log correlating
authored by
Patrick Dewey
and committed by
tangled.org
75e29b74
ba0181d2
+76
-6
+10
cmd/server/main.go
+10
cmd/server/main.go
···
5
5
"context"
6
6
"flag"
7
7
"fmt"
8
+
"log/slog"
8
9
"net/http"
9
10
"os"
10
11
"os/signal"
···
62
63
Out: os.Stdout,
63
64
TimeFormat: time.RFC3339,
64
65
})
66
+
}
67
+
68
+
// Configure slog default handler to match zerolog format.
69
+
// Third-party libraries (e.g. indigo OAuth) use slog, so without this
70
+
// their output bypasses zerolog and breaks structured log parsing.
71
+
if os.Getenv("LOG_FORMAT") == "json" {
72
+
slog.SetDefault(slog.New(slog.NewJSONHandler(os.Stdout, nil)))
73
+
} else {
74
+
slog.SetDefault(slog.New(slog.NewTextHandler(os.Stdout, nil)))
65
75
}
66
76
67
77
log.Info().Msg("Starting Arabica Coffee Tracker")
+10
-4
internal/middleware/logging.go
+10
-4
internal/middleware/logging.go
···
58
58
// Calculate duration
59
59
duration := time.Since(start)
60
60
61
+
// Use the context logger (enriched with trace_id by RequestIDMiddleware)
62
+
ctxLogger := zerolog.Ctx(r.Context())
63
+
if ctxLogger.GetLevel() == zerolog.Disabled {
64
+
ctxLogger = &logger
65
+
}
66
+
61
67
// Select log level based on status code
62
68
var logEvent *zerolog.Event
63
69
if rw.statusCode >= 500 {
64
-
logEvent = logger.Error()
70
+
logEvent = ctxLogger.Error()
65
71
} else if rw.statusCode >= 400 {
66
-
logEvent = logger.Warn()
72
+
logEvent = ctxLogger.Warn()
67
73
} else {
68
-
logEvent = logger.Info()
74
+
logEvent = ctxLogger.Info()
69
75
}
70
76
71
77
// Add core fields
···
96
102
logEvent.Str("user_did", did)
97
103
}
98
104
99
-
if logger.GetLevel() == zerolog.DebugLevel {
105
+
if ctxLogger.GetLevel() == zerolog.DebugLevel {
100
106
// Log all request headers for debugging malicious traffic (debug mode only)
101
107
headers := make(map[string]string)
102
108
for name, values := range r.Header {
+51
internal/middleware/request_id.go
+51
internal/middleware/request_id.go
···
1
+
package middleware
2
+
3
+
import (
4
+
"crypto/rand"
5
+
"encoding/hex"
6
+
"net/http"
7
+
8
+
"github.com/rs/zerolog"
9
+
"go.opentelemetry.io/otel/trace"
10
+
)
11
+
12
+
// RequestIDMiddleware extracts the OTel trace ID from the current span (set by
13
+
// otelhttp) and injects it into the zerolog logger on the request context. If
14
+
// no active trace exists, it generates a random 8-byte hex ID as a fallback.
15
+
//
16
+
// Every downstream handler that uses zerolog.Ctx(r.Context()) will
17
+
// automatically include the trace_id field in its log output, making it easy
18
+
// to correlate all log lines from a single request.
19
+
//
20
+
// The trace ID is also set as the X-Trace-ID response header so that it can be
21
+
// correlated with client-side error reports.
22
+
func RequestIDMiddleware(logger zerolog.Logger) func(http.Handler) http.Handler {
23
+
return func(next http.Handler) http.Handler {
24
+
return http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
25
+
traceID := extractTraceID(r)
26
+
27
+
// Create a sub-logger with trace_id and inject into context
28
+
subLogger := logger.With().Str("trace_id", traceID).Logger()
29
+
ctx := subLogger.WithContext(r.Context())
30
+
31
+
// Set response header for client-side correlation
32
+
w.Header().Set("X-Trace-ID", traceID)
33
+
34
+
next.ServeHTTP(w, r.WithContext(ctx))
35
+
})
36
+
}
37
+
}
38
+
39
+
// extractTraceID returns the OTel trace ID if an active span exists,
40
+
// otherwise generates a random fallback ID.
41
+
func extractTraceID(r *http.Request) string {
42
+
sc := trace.SpanFromContext(r.Context()).SpanContext()
43
+
if sc.HasTraceID() {
44
+
return sc.TraceID().String()
45
+
}
46
+
47
+
// Fallback: generate a random ID (e.g. for requests filtered out of tracing)
48
+
var buf [8]byte
49
+
_, _ = rand.Read(buf[:])
50
+
return hex.EncodeToString(buf[:])
51
+
}
+5
-2
internal/routing/routing.go
+5
-2
internal/routing/routing.go
···
192
192
// 5. Apply logging middleware
193
193
handler = middleware.LoggingMiddleware(cfg.Logger)(handler)
194
194
195
-
// 6. Enrich trace spans with client page context (runs inside otelhttp span)
195
+
// 6. Inject trace_id into zerolog context (runs after otelhttp creates the span)
196
+
handler = middleware.RequestIDMiddleware(cfg.Logger)(handler)
197
+
198
+
// 7. Enrich trace spans with client page context (runs inside otelhttp span)
196
199
handler = pageContextMiddleware(handler)
197
200
198
-
// 7. Apply OpenTelemetry HTTP instrumentation (outermost - wraps everything)
201
+
// 8. Apply OpenTelemetry HTTP instrumentation (outermost - wraps everything)
199
202
handler = otelhttp.NewHandler(handler, "arabica",
200
203
otelhttp.WithFilter(func(r *http.Request) bool {
201
204
return !strings.HasPrefix(r.URL.Path, "/static/") && r.URL.Path != "/favicon.ico"