feat(coderd/tracing): correlate request logs and spans by client_session_id (#27671)

## What

Adds `client_session_id` correlation to coderd's HTTP request handling,
per the
[Connection log collection and correlation
RFC](https://www.notion.so/coderhq/Connection-log-collection-and-correlation-36ed579be5928025a56cd11fe58661fb).

Clients attach a per-session correlation ID to every API request via W3C
baggage using the `client_session_id` key. This change makes coderd's
tracing
middleware read that baggage member and:

- add `client_session_id` to the **per-request log context** so all logs
for a
request (and the handlers it calls) can be correlated by a single ID,
and
- set `client_session_id` as a **span attribute** when tracing is
enabled.

Per RFC requirement 6.1, the value is added to the log context **even
when
tracing is disabled** (the middleware previously returned early when no
tracer
provider was configured, so baggage was never read). The
`client_session_id` is
validated as a 32-character hexadecimal string (a 16-byte value, per RFC
requirement 1) to guard against logging arbitrary client-controlled
baggage
values.

## Scope

This is `DEVEX-659` and is intentionally limited to the coderd tracing
middleware. It is the first piece of a stack: the web terminal client
change
(`DEVEX-663`) that generates and sends the `client_session_id` will be
stacked on top
of this PR. No client currently sends `client_session_id` baggage, so
this change is
a no-op until the client work lands.

## Testing

- `coderd/tracing`: new unit tests cover `validSessionID`, baggage
extraction
  (`sessionIDFromHeaders`), and the middleware end to end, asserting
`client_session_id` lands on the log context with tracing enabled
**and** disabled,
  is exposed as a span attribute when tracing is enabled, and that
  absent/malformed baggage is ignored.
- Existing `Test_Middleware` route-matching behavior is unchanged.

<details>
<summary>Design notes / decision log</summary>

- **Where the value is read:** the existing `tracing.Middleware` runs
high in
the coderd middleware stack (`coderd/coderd.go`), before request-id and
request-logger middleware, and already matches the `/api`, `/api/**`,
app
proxy, and external-auth routes. Reading baggage here means the
`client_session_id`
is on the context before the request logger and handlers run, so it
flows
into all downstream `slog` calls that use the request context. This
mirrors
  the existing `request_id` pattern in `httpmw.AttachRequestID`
  (`slog.With(ctx, ...)` + span attribute).
- **Works when tracing is off:** the middleware now gates only on the
route
matcher, extracts baggage and adds `client_session_id` to the log
context for all
matched routes, and only then branches on whether a tracer is
configured.
When a tracer is present, `client_session_id` is additionally set as a
span
  attribute.
- **Explicit baggage propagator:** extraction uses
`propagation.Baggage{}`
directly rather than the global text map propagator, so it does not
depend
on the global propagator being configured (also makes it deterministic
in
  tests).
- **Validation:** only a 32-char hex string is accepted (lower or upper
case).
Malformed values are dropped rather than logged, preventing
log/attribute
  pollution from arbitrary client-supplied baggage.
- **Out of scope for this PR (tracked elsewhere):** client
generation/sending
of `client_session_id` (`DEVEX-663`, web terminal), the equivalent
agent-side
middleware (RFC 6.2), `connection_logs.client_session_id` (RFC 12), and
additional
  connection state-change logging (RFC 7-13).

</details>

---

_Opened by Coder Agents on behalf of @aqandrew._
This commit is contained in:
Andrew Aquino
2026-08-18 17:28:36 -07:00
committed by GitHub
parent 821d91fabd
commit 71e95a3611
3 changed files with 449 additions and 4 deletions
+81 -4
View File
@@ -2,20 +2,31 @@ package tracing
import (
"context"
"encoding/hex"
"fmt"
"net/http"
"net/url"
"github.com/go-chi/chi/v5"
"go.opentelemetry.io/otel"
"go.opentelemetry.io/otel/attribute"
"go.opentelemetry.io/otel/baggage"
"go.opentelemetry.io/otel/propagation"
semconv "go.opentelemetry.io/otel/semconv/v1.14.0"
"go.opentelemetry.io/otel/semconv/v1.14.0/httpconv"
"go.opentelemetry.io/otel/semconv/v1.14.0/netconv"
"go.opentelemetry.io/otel/trace"
"go.opentelemetry.io/otel/trace/noop"
"cdr.dev/slog/v3"
"github.com/coder/coder/v2/coderd/httpmw/patternmatcher"
)
// SessionIDBaggageKey is the W3C baggage key clients use to propagate the
// per-session correlation ID described in the connection-log RFC. The value is
// a 16-byte identifier encoded as a 32-character hexadecimal string.
const SessionIDBaggageKey = "client_session_id"
// Middleware adds tracing to http routes.
func Middleware(tracerProvider trace.TracerProvider) func(http.Handler) http.Handler {
// We only want to create spans on the following route patterns, however
@@ -29,18 +40,26 @@ func Middleware(tracerProvider trace.TracerProvider) func(http.Handler) http.Han
"/external-auth/*/callback",
}.MustCompile()
var tracer trace.Tracer
if tracerProvider != nil {
tracer = tracerProvider.Tracer(TracerName)
if tracerProvider == nil {
tracerProvider = noop.NewTracerProvider()
}
tracer := tracerProvider.Tracer(TracerName)
return func(next http.Handler) http.Handler {
return http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) {
if tracer == nil || !re.MatchString(r.URL.Path) {
if !re.MatchString(r.URL.Path) {
next.ServeHTTP(rw, r)
return
}
// Read the client_session_id from the request and add it to the log
// context. This is done even when tracing is disabled so that logs can
// always be correlated by client_session_id.
sessionID := sessionIDFromRequest(r)
if sessionID != "" {
r = r.WithContext(slog.With(r.Context(), slog.F("client_session_id", sessionID)))
}
// Start span with default span name. Span name will be updated to
// "method route" format once request finishes. The initial name
// excludes the query string because span names are exported to
@@ -49,6 +68,10 @@ func Middleware(tracerProvider trace.TracerProvider) func(http.Handler) http.Han
r, span := StartHTTPSpan(tracer, rw, r, fmt.Sprintf("%s %s", r.Method, r.URL.Path))
defer span.End()
if sessionID != "" {
span.SetAttributes(attribute.String("client_session_id", sessionID))
}
sw, ok := rw.(*StatusWriter)
if !ok {
panic(fmt.Sprintf("ResponseWriter not a *tracing.StatusWriter; got %T", rw))
@@ -62,6 +85,60 @@ func Middleware(tracerProvider trace.TracerProvider) func(http.Handler) http.Han
}
}
// sessionIDFromRequest extracts and validates the client_session_id from the
// request. It prefers the W3C baggage member and falls back to the
// client_session_id query parameter. The query parameter fallback exists
// because browser WebSocket clients (such as the web terminal PTY) cannot set
// arbitrary baggage headers. It returns an empty string when neither source
// provides a valid value.
func sessionIDFromRequest(r *http.Request) string {
if id := sessionIDFromHeaders(r.Header); id != "" {
return id
}
return sessionIDFromQueryString(r.URL.Query())
}
// sessionIDFromHeaders extracts and validates the client_session_id baggage member
// from the request headers. It returns an empty string when the member is
// absent or malformed. Extraction uses an explicit baggage propagator so it
// does not depend on the globally configured text map propagator.
func sessionIDFromHeaders(h http.Header) string {
ctx := propagation.Baggage{}.Extract(context.Background(), propagation.HeaderCarrier(h))
id := baggage.FromContext(ctx).Member(SessionIDBaggageKey).Value()
if !validSessionID(id) {
return ""
}
return id
}
// sessionIDFromQueryString extracts and validates the client_session_id query
// parameter. It returns an empty string when the parameter is absent or
// malformed. It mirrors sessionIDFromHeaders for the query-parameter fallback
// used by browser WebSocket clients (such as the web terminal PTY) that cannot
// set arbitrary baggage headers.
func sessionIDFromQueryString(q url.Values) string {
id := q.Get(SessionIDBaggageKey)
if !validSessionID(id) {
return ""
}
return id
}
// validSessionID reports whether s is a 32-character lowercase hexadecimal
// string (a 16-byte value), the encoding the RFC mandates for the session ID.
// Only lowercase is accepted so that case-sensitive searches correlate
// reliably. Validating also guards against logging arbitrary client-controlled
// baggage values.
func validSessionID(s string) bool {
b, err := hex.DecodeString(s)
if err != nil || len(b) != 16 {
return false
}
// hex.DecodeString also accepts upper-case, so require the canonical
// lowercase encoding.
return hex.EncodeToString(b) == s
}
// StartHTTPSpan starts a span, propagating inbound trace context and writing
// X-Trace-ID/X-Span-ID response headers. The caller must end the span.
func StartHTTPSpan(tracer trace.Tracer, rw http.ResponseWriter, r *http.Request, name string) (*http.Request, trace.Span) {
+90
View File
@@ -0,0 +1,90 @@
package tracing
import (
"net/http"
"net/url"
"testing"
"github.com/stretchr/testify/require"
)
func TestValidSessionID(t *testing.T) {
t.Parallel()
cases := []struct {
name string
id string
valid bool
}{
{"LowerHex", "0123456789abcdef0123456789abcdef", true},
{"UpperHex", "0123456789ABCDEF0123456789ABCDEF", false},
{"MixedCase", "0123456789abcdef0123456789ABCDEF", false},
{"Empty", "", false},
{"TooShort", "0123456789abcdef0123456789abcde", false},
{"TooLong", "0123456789abcdef0123456789abcdef0", false},
{"NonHex", "0123456789abcdef0123456789abcdeg", false},
{"Uuid", "0123456789ab-cdef-0123456789abcde", false},
}
for _, c := range cases {
t.Run(c.name, func(t *testing.T) {
t.Parallel()
require.Equal(t, c.valid, validSessionID(c.id))
})
}
}
func TestSessionIDFromHeaders(t *testing.T) {
t.Parallel()
const validID = "0123456789abcdef0123456789abcdef"
cases := []struct {
name string
baggage string
want string
}{
{"Valid", SessionIDBaggageKey + "=" + validID, validID},
{"WithOtherMembers", "foo=bar," + SessionIDBaggageKey + "=" + validID + ",baz=qux", validID},
{"Missing", "foo=bar", ""},
{"NoHeader", "", ""},
{"Malformed", SessionIDBaggageKey + "=not-a-hex-value", ""},
}
for _, c := range cases {
t.Run(c.name, func(t *testing.T) {
t.Parallel()
h := http.Header{}
if c.baggage != "" {
h.Set("baggage", c.baggage)
}
require.Equal(t, c.want, sessionIDFromHeaders(h))
})
}
}
func TestSessionIDFromQueryString(t *testing.T) {
t.Parallel()
const validID = "0123456789abcdef0123456789abcdef"
cases := []struct {
name string
query url.Values
want string
}{
{"Valid", url.Values{SessionIDBaggageKey: {validID}}, validID},
{"Missing", url.Values{"foo": {"bar"}}, ""},
{"Empty", url.Values{}, ""},
{"Malformed", url.Values{SessionIDBaggageKey: {"not-a-hex-value"}}, ""},
{"Uppercase", url.Values{SessionIDBaggageKey: {"0123456789ABCDEF0123456789ABCDEF"}}, ""},
}
for _, c := range cases {
t.Run(c.name, func(t *testing.T) {
t.Parallel()
require.Equal(t, c.want, sessionIDFromQueryString(c.query))
})
}
}
+278
View File
@@ -11,11 +11,13 @@ import (
"github.com/go-chi/chi/v5"
"github.com/stretchr/testify/require"
"go.opentelemetry.io/otel/attribute"
sdktrace "go.opentelemetry.io/otel/sdk/trace"
"go.opentelemetry.io/otel/sdk/trace/tracetest"
"go.opentelemetry.io/otel/trace"
"go.opentelemetry.io/otel/trace/noop"
"cdr.dev/slog/v3"
"github.com/coder/coder/v2/coderd/tracing"
"github.com/coder/coder/v2/testutil"
)
@@ -28,6 +30,10 @@ type fakeTracer struct {
noop.TracerProvider
noopTracer
startCalled atomic.Int64
// span, when set, is returned from Start so tests can assert on the
// attributes the middleware records. When nil, Start returns
// tracing.NoopSpan.
span *recordingSpan
}
var (
@@ -43,9 +49,281 @@ func (f *fakeTracer) Tracer(_ string, _ ...trace.TracerOption) trace.Tracer {
// Start implements trace.Tracer.
func (f *fakeTracer) Start(ctx context.Context, _ string, _ ...trace.SpanStartOption) (context.Context, trace.Span) {
f.startCalled.Add(1)
if f.span != nil {
return ctx, f.span
}
return ctx, tracing.NoopSpan
}
// recordingSpan wraps a noop span and records the attributes set on it so
// tests can assert on span attributes.
type recordingSpan struct {
trace.Span
attrs []attribute.KeyValue
}
func (s *recordingSpan) SetAttributes(kv ...attribute.KeyValue) {
s.attrs = append(s.attrs, kv...)
}
func (s *recordingSpan) attributes() []attribute.KeyValue {
return s.attrs
}
const testSessionID = "0123456789abcdef0123456789abcdef"
func Test_Middleware_SessionID(t *testing.T) {
t.Parallel()
// requestFields serves a request through the middleware and returns the
// fields logged by a downstream handler using the request context.
requestFields := func(t *testing.T, tp trace.TracerProvider, path, header string) []slog.Field {
t.Helper()
sink := testutil.NewFakeSink(t)
logger := sink.Logger()
handler := http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) {
// Logging with the request context surfaces any fields the
// middleware added via slog.With.
logger.Info(r.Context(), "downstream handler invoked")
rw.WriteHeader(http.StatusNoContent)
})
rw := &tracing.StatusWriter{ResponseWriter: httptest.NewRecorder()}
r := httptest.NewRequest(http.MethodGet, path, nil)
if header != "" {
r.Header.Set("baggage", header)
}
ctx := context.WithValue(context.Background(), chi.RouteCtxKey, chi.NewRouteContext())
r = r.WithContext(ctx)
tracing.Middleware(tp)(handler).ServeHTTP(rw, r)
entries := sink.Entries(func(e slog.SinkEntry) bool {
return e.Message == "downstream handler invoked"
})
require.Len(t, entries, 1)
return entries[0].Fields
}
fieldValue := func(fields []slog.Field, name string) (any, bool) {
for _, f := range fields {
if f.Name == name {
return f.Value, true
}
}
return nil, false
}
hasAttrKey := func(attrs []attribute.KeyValue, key string) bool {
for _, a := range attrs {
if string(a.Key) == key {
return true
}
}
return false
}
t.Run("TracingEnabled", func(t *testing.T) {
t.Parallel()
tp := &fakeTracer{span: &recordingSpan{Span: tracing.NoopSpan}}
fields := requestFields(t, tp, "/api/v2/workspaces", tracing.SessionIDBaggageKey+"="+testSessionID)
val, ok := fieldValue(fields, "client_session_id")
require.True(t, ok, "client_session_id should be on the log context")
require.Equal(t, testSessionID, val)
require.Contains(t, tp.span.attributes(), attribute.String("client_session_id", testSessionID))
})
t.Run("TracingEnabledNoBaggage", func(t *testing.T) {
t.Parallel()
// With tracing on but no baggage, the session ID is empty and the
// middleware must not set an empty client_session_id span attribute or log
// field.
tp := &fakeTracer{span: &recordingSpan{Span: tracing.NoopSpan}}
fields := requestFields(t, tp, "/api/v2/workspaces", "")
_, ok := fieldValue(fields, "client_session_id")
require.False(t, ok, "client_session_id should be absent when no baggage is sent")
require.False(t, hasAttrKey(tp.span.attributes(), "client_session_id"),
"no client_session_id attribute should be set when no baggage is sent")
})
t.Run("TracingDisabled", func(t *testing.T) {
t.Parallel()
// A nil tracer provider disables span creation, but the client_session_id
// must still land on the log context.
fields := requestFields(t, nil, "/api/v2/workspaces", tracing.SessionIDBaggageKey+"="+testSessionID)
val, ok := fieldValue(fields, "client_session_id")
require.True(t, ok, "client_session_id should be on the log context even when tracing is disabled")
require.Equal(t, testSessionID, val)
})
t.Run("NoBaggage", func(t *testing.T) {
t.Parallel()
fields := requestFields(t, nil, "/api/v2/workspaces", "")
_, ok := fieldValue(fields, "client_session_id")
require.False(t, ok, "client_session_id should be absent when no baggage is sent")
})
t.Run("MalformedSessionID", func(t *testing.T) {
t.Parallel()
tp := &fakeTracer{span: &recordingSpan{Span: tracing.NoopSpan}}
fields := requestFields(t, tp, "/api/v2/workspaces", tracing.SessionIDBaggageKey+"=not-a-valid-session-id")
_, ok := fieldValue(fields, "client_session_id")
require.False(t, ok, "malformed client_session_id should be ignored")
require.False(t, hasAttrKey(tp.span.attributes(), "client_session_id"),
"no client_session_id attribute should be set for a malformed session ID")
})
t.Run("QueryParameter", func(t *testing.T) {
t.Parallel()
// Browser WebSocket clients (such as the web terminal PTY) cannot set
// baggage headers, so the middleware falls back to the
// client_session_id query parameter.
tp := &fakeTracer{span: &recordingSpan{Span: tracing.NoopSpan}}
fields := requestFields(t, tp, "/api/v2/workspaces?"+tracing.SessionIDBaggageKey+"="+testSessionID, "")
val, ok := fieldValue(fields, "client_session_id")
require.True(t, ok, "client_session_id from the query parameter should be on the log context")
require.Equal(t, testSessionID, val)
require.Contains(t, tp.span.attributes(), attribute.String("client_session_id", testSessionID))
})
t.Run("BaggageTakesPrecedence", func(t *testing.T) {
t.Parallel()
// When both baggage and the query parameter are present, baggage wins.
const querySessionID = "fedcba9876543210fedcba9876543210"
tp := &fakeTracer{span: &recordingSpan{Span: tracing.NoopSpan}}
fields := requestFields(t, tp,
"/api/v2/workspaces?"+tracing.SessionIDBaggageKey+"="+querySessionID,
tracing.SessionIDBaggageKey+"="+testSessionID)
val, ok := fieldValue(fields, "client_session_id")
require.True(t, ok, "client_session_id should be on the log context")
require.Equal(t, testSessionID, val, "baggage should take precedence over the query parameter")
require.Contains(t, tp.span.attributes(), attribute.String("client_session_id", testSessionID))
})
t.Run("MalformedQuerySessionID", func(t *testing.T) {
t.Parallel()
tp := &fakeTracer{span: &recordingSpan{Span: tracing.NoopSpan}}
fields := requestFields(t, tp, "/api/v2/workspaces?"+tracing.SessionIDBaggageKey+"=not-a-valid-session-id", "")
_, ok := fieldValue(fields, "client_session_id")
require.False(t, ok, "malformed client_session_id query parameter should be ignored")
require.False(t, hasAttrKey(tp.span.attributes(), "client_session_id"),
"no client_session_id attribute should be set for a malformed query session ID")
})
t.Run("NonMatchingRoute", func(t *testing.T) {
t.Parallel()
// The middleware only runs on matched API/app routes. Static and
// asset routes must not extract client_session_id, even from well-formed
// baggage or a well-formed query parameter, so client-controlled
// values are never logged for every request.
tp := &fakeTracer{span: &recordingSpan{Span: tracing.NoopSpan}}
fields := requestFields(t, tp, "/index.html?"+tracing.SessionIDBaggageKey+"="+testSessionID, tracing.SessionIDBaggageKey+"="+testSessionID)
_, ok := fieldValue(fields, "client_session_id")
require.False(t, ok, "client_session_id must not be logged on a non-matching route")
require.False(t, hasAttrKey(tp.span.attributes(), "client_session_id"),
"no client_session_id attribute should be set on a non-matching route")
})
// FieldNamesMatchBaggageKey pins the baggage key, the log field name, and
// the span attribute name to the same value. slog field names must be
// snake_case string literals, so the log field and span attribute cannot
// reference SessionIDBaggageKey directly; this test guards against the
// three drifting apart and silently breaking log/trace correlation.
t.Run("FieldNamesMatchBaggageKey", func(t *testing.T) {
t.Parallel()
require.Equal(t, "client_session_id", tracing.SessionIDBaggageKey)
tp := &fakeTracer{span: &recordingSpan{Span: tracing.NoopSpan}}
fields := requestFields(t, tp, "/api/v2/workspaces", tracing.SessionIDBaggageKey+"="+testSessionID)
_, ok := fieldValue(fields, tracing.SessionIDBaggageKey)
require.True(t, ok, "log field name must match the baggage key")
require.Contains(t, tp.span.attributes(),
attribute.String(tracing.SessionIDBaggageKey, testSessionID),
"span attribute name must match the baggage key")
})
// QuerySessionIDNotInSpanName guards the interaction between the
// query-parameter fallback and span naming. A client_session_id supplied
// via the query string (as the web terminal PTY does) must surface as the
// client_session_id span attribute but must never leak into an exported
// span name, which is emitted to tracing backends at span start.
t.Run("QuerySessionIDNotInSpanName", func(t *testing.T) {
t.Parallel()
startNames := &startNameRecorder{}
recorder := tracetest.NewSpanRecorder()
provider := sdktrace.NewTracerProvider(
sdktrace.WithSpanProcessor(startNames),
sdktrace.WithSpanProcessor(recorder),
)
rw := &tracing.StatusWriter{ResponseWriter: httptest.NewRecorder()}
r := httptest.NewRequest(http.MethodGet,
"/api/v2/workspaceagents/abc/pty?"+tracing.SessionIDBaggageKey+"="+testSessionID, nil)
ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitLong)
defer cancel()
ctx = context.WithValue(ctx, chi.RouteCtxKey, chi.NewRouteContext())
r = r.WithContext(ctx)
tracing.Middleware(provider)(http.HandlerFunc(func(rw http.ResponseWriter, r *http.Request) {
rw.WriteHeader(http.StatusOK)
})).ServeHTTP(rw, r)
require.NoError(t, provider.ForceFlush(ctx))
// Neither the span-start name nor the exported span name may contain
// the session ID, since the initial name is built from the path only.
require.NotEmpty(t, startNames.names)
for _, name := range startNames.names {
require.NotContains(t, name, testSessionID,
"span start name must not carry the query session ID")
}
spans := recorder.Ended()
require.NotEmpty(t, spans)
for _, span := range spans {
require.NotContains(t, span.Name(), testSessionID,
"exported span name must not carry the query session ID")
}
// The ID must still be recorded as the dedicated span attribute.
var found bool
for _, span := range spans {
for _, attr := range span.Attributes() {
if string(attr.Key) == tracing.SessionIDBaggageKey {
require.Equal(t, testSessionID, attr.Value.AsString())
found = true
}
}
}
require.True(t, found,
"client_session_id from the query parameter must be recorded as a span attribute")
})
}
// startNameRecorder captures span names as they are at span start, before
// EndHTTPSpan renames them, because span names are exported to tracing
// backends at span start.