Skip to content

feat(sidecar): OpenTelemetry spans + structured audit log + Jaeger compose - #41

Open
VibhorGautam wants to merge 9 commits into
c2siorg:mainfrom
VibhorGautam:feat/telemetry-observability
Open

feat(sidecar): OpenTelemetry spans + structured audit log + Jaeger compose#41
VibhorGautam wants to merge 9 commits into
c2siorg:mainfrom
VibhorGautam:feat/telemetry-observability

Conversation

@VibhorGautam

@VibhorGautam VibhorGautam commented Apr 14, 2026

Copy link
Copy Markdown
Contributor

Summary

fills the Phase 2 telemetry scaffolding in sidecar/internal/telemetry/. adds async, non-blocking OpenTelemetry spans across the 4 pipeline stages and a structured JSON audit log, without touching the Stage interface or any stage-level code. an opt-in docker compose --profile observability up -d brings up a local OTel collector and a Jaeger instance so spans are inspectable at http://localhost:16686

closes the scaffolding otel.go and audit.go left behind in phase02. schema declared in the audit.go doc block is preserved exactly: hook_type, decision, score, signals, provenance, session_id, policy_version, trace_id

What changed

  • sidecar/internal/telemetry/otel.go - tracer provider wired to OTLP HTTP, ParentBased sampler, graceful Shutdown(ctx). empty endpoint installs a noop provider so dev and prod code paths stay identical
  • sidecar/internal/telemetry/audit.go - async audit writer. buffered channel, 1 drain goroutine, atomic drop counter. Emit never blocks the caller
  • sidecar/internal/pipeline/pipeline.go - root span per run, child span per stage. duration, signals-added, hard_block, decision and score land on the spans. 1 audit line emitted after the run
  • sidecar/cmd/sidecar/main.go - reads the new telemetry: block from sidecar.yaml, opens the audit file (or stdout), flushes both on SIGTERM
  • docker-compose.yml - opt-in observability profile adds the OTel collector and Jaeger. sidecar service unaffected unless the profile is enabled
  • config/otel-collector.yaml - receives OTLP HTTP on :4318 and forwards to Jaeger on :4317
  • docs/observability.md - privacy rules, sampling guidance, what the audit writer deliberately never records (raw payload, canonical text)

new tests:

  • sidecar/internal/telemetry/audit_test.go - JSON shape, drop accounting under backpressure, concurrent Emit, emit-after-close no-op
  • sidecar/internal/telemetry/otel_test.go - noop fallback, exporter init with a dead endpoint does not panic, scheme stripping
  • sidecar/internal/pipeline/pipeline_telemetry_test.go - full span tree, OPA input/output attributes, audit trace correlation, strict short-circuit and OPA error fallback
  • sidecar/internal/transport/drain_test.go - graceful drain waits for the serve loop and closes stalled connections
  • sidecar/internal/pipeline/bench_test.go - 3 benchmark configurations

0 existing tests changed. all 4 CI jobs are green, including ubuntu and windows integration

Design notes

non-invasive integration. the Stage interface is untouched. Pipeline.Run wraps stage.Run with a child span and reads rc.Signals before and after the call to compute signals.added. stages stay pure; only the pipeline dispatcher knows about spans

fail-open on the observability path. neither the OTel exporter nor the audit writer can block enforcement. audit is a buffered channel with a background drain goroutine; when the queue is full, entries are dropped and the drop counter increments. if the OTel collector is down the exporter buffers internally and drops silently. telemetry failures must not take down the PDP

privacy. the audit writer never records rc.Payload or rc.CanonicalText. only decision metadata and named signals reach the sink. span attributes are the same controlled set. same idea as the LLM-05 prompt-leakage guidance, adapted to the PDP path

compatibility. old pipeline.New(cfg, stages) still works and keeps the existing threshold fallback behaviour. new pipeline.NewWithOptions takes a Tracer and AuditSink plus a PolicyVersion string stamped onto every audit entry

parent context. Pipeline.Run(rc) stays unchanged and kicks off a fresh root span. Pipeline.RunContext(ctx, rc) is a new entry point that takes a caller-supplied context so the ParentBased sampler honours any upstream sampling decision and spans link into an existing trace. the transport listener does not yet propagate context because the SDK frame does not carry traceparent, but when it does the listener can swap to RunContext without any pipeline-level change

OTel version. pinned to go.opentelemetry.io/otel v1.40.0 and semconv v1.26.0 (aligned with the version OPA already pulls in). tested on go 1.25.6

Benchmarks

go test -run '^$' -bench '^BenchmarkPipeline_' -benchmem -benchtime=2s -count=5 -cpu=1 ./internal/pipeline on Apple M4:

BenchmarkPipeline_NoTelemetry          7508 ns/op   1776 B/op   29 allocs/op
BenchmarkPipeline_WithAudit            8617 ns/op   2202 B/op   30 allocs/op
BenchmarkPipeline_WithTracerAndAudit  12716 ns/op   5824 B/op   45 allocs/op

audit adds about 1.11 µs per run. real span recording plus audit adds about 5.21 µs over the no-telemetry path, with tracing itself adding about 4.10 µs over audit-only. this measures in-process span recording and audit queueing, not OTLP network or collector cost

Audit line sample

{"ts":"2026-04-13T09:35:12.521Z","trace_id":"6e8a...","span_id":"9f1...","hook_type":"on_prompt","decision":"block","score":0.9,"signals":["jailbreak_pattern"],"provenance":"user","session_id":"sess-42","policy_version":"v1","blocked_at":"scan","duration_ms":1.7}

How to run locally

# start everything
docker compose --profile observability up -d

# point the sidecar at the collector
cat >> config/sidecar.yaml <<'YAML'
telemetry:
  otel_endpoint: http://otel-collector:4318
  sample_ratio: 1.0
  service_name: acf-sidecar
  insecure: true
YAML

# open the UI
open http://localhost:16686

trace hierarchy should look like:

pipeline.Run (1.7 ms)
├── stage.validate    (0.1 ms)
├── stage.normalise   (0.4 ms)
├── stage.scan        (0.8 ms)  signals.added=1, hard_block=false
├── stage.aggregate   (0.3 ms)
└── opa.evaluate      (0.2 ms)  opa.output.decision=block

Scope decisions and non-goals

  • no metrics added. spans + audit cover the current PDP observability scope
  • signals are a span attribute, not span events. event cardinality on a busy sidecar would explode. signals stay in a stable controlled vocabulary
  • no SDK frame changes. the SDK frame does not carry a traceparent yet; happy to open a follow-up issue if useful
  • no kernel or SDK code touched. pure sidecar addition
  • no test infra or CI changes. new tests run under the existing go test ./...
  • Stage interface unchanged, on purpose, so the 4 existing stages stay frozen

@VibhorGautam

Copy link
Copy Markdown
Contributor Author

quick follow-up while poking at the phase 02 docs for context on the otel span naming in this pr

one thing worth flagging for phase 3: docs/pipeline.md signal table lists hmac_invalid: 1.0 # always hard block, but sidecar/internal/pipeline/aggregate.go computes score = maxSignalWeight * provenanceWeight in AggregateStage.Run and always returns hardBlock=false. so if phase 3's opa path emits hmac_invalid for a memory-provenance payload (trust weight 0.6), the score ends up 1.0 × 0.6 = 0.6, which is sanitise under the default 0.85 block threshold, not block. since memory is exactly where hmac_invalid is supposed to be strict (tampered stored state), either it needs a validate-style hardBlock return before aggregate runs, or the "always hard block" note should say it's provenance-weighted like every other signal

not blocking for this otel pr, just flagging since i was in those files already. happy to split it out as a separate issue if useful

@VibhorGautam
VibhorGautam force-pushed the feat/telemetry-observability branch 2 times, most recently from 30eb48a to f894580 Compare June 2, 2026 10:57
@VibhorGautam
VibhorGautam force-pushed the feat/telemetry-observability branch from f894580 to b211849 Compare June 19, 2026 17:04
…mpose

Fills the Phase 2 telemetry scaffolding in sidecar/internal/telemetry/.
Adds async, non-blocking OpenTelemetry spans across the four pipeline
stages and a structured JSON audit log. Stage interface is untouched,
no stage-level code changes.

- otel.go: OTLP HTTP tracer with ParentBased sampler, scheme-tolerant
  endpoint, noop fallback on empty endpoint or exporter init failure
- audit.go: async writer with buffered channel, single drain goroutine,
  atomic drop counter, idempotent Close
- pipeline.go: root span per run, child span per stage, one audit entry
  per run. Run() kept for backward compat; RunContext() is the new entry
  point that honours caller-supplied context
- main.go: reads telemetry block from sidecar.yaml, opens the audit sink
  (file or stdout), flushes tracer and sink on SIGTERM with a deadline
- docker-compose.yml: opt-in 'observability' profile adds OTel collector
  and Jaeger all-in-one
- config/otel-collector.yaml: receives OTLP HTTP on :4318, forwards to
  jaeger:4317 with batching + memory_limiter
- docs/observability.md: span layout, audit schema, privacy rules,
  tuning guidance, failure modes

Tests (go test ./... -race green):
- audit_test.go: JSON shape, drop accounting under backpressure,
  concurrent Emit, emit-after-close no-op
- otel_test.go: noop fallback, dead endpoint does not panic,
  scheme stripping, ratio clamp
- bench_test.go: three benchmark configurations

Benchmarks on Apple M4 show ~450 ns overhead per run with both span
emission and audit enabled. Under real Aho-Corasick scan workloads the
relative cost drops below 5%.

Signed-off-by: VibhorGautam <vibhorgautam907@gmail.com>
Addresses two shutdown-path races flagged during review:

1. asyncJSONSink.Emit could panic with 'send on closed channel' when a
   producer raced Close. The unsynchronised closed.Load() check let Emit
   proceed into the channel send while Close was mid-close. Replaces the
   atomic flag with an RWMutex; Emit holds the read lock around the send,
   Close takes the write lock around the close. Adds a concurrent
   Emit/Close regression test (50 trials, 8 producers each).

2. main shut tracing down before in-flight IPC handlers returned, so
   late-finishing spans and audit entries were silently lost. Listener
   now tracks handlers via a WaitGroup and exposes Drain(ctx). main calls
   Stop then Drain (5s deadline) before flushing the tracer and closing
   the audit sink.

Signed-off-by: VibhorGautam <vibhorgautam907@gmail.com>
Codex re-review flagged a late-accept race: Serve.handlers.Add(1) fires
after Accept returns, but Drain started handlers.Wait() without first
verifying the accept loop had exited. A connection already queued by
the kernel when Stop ran could land as a new Add after Wait returned,
leaving a handler running while telemetry was torn down.

Fix: Listener.serveDone channel closed when Serve returns. Drain waits
on serveDone before calling handlers.Wait(). Regression test confirms
Drain blocks until Serve exits rather than returning on an empty wait
group.

Signed-off-by: VibhorGautam <vibhorgautam907@gmail.com>
…eout

Codex caught two remaining shutdown gaps after the serveDone change:

1. Stop only closed the listening socket, leaving accepted connections
   alive. A stalled client could pin a handler inside DecodeRequest's
   blocking ReadFull forever, defeating graceful drain.
2. main treated the 5s drain deadline as advisory: if Drain returned
   ctx.DeadlineExceeded main logged and proceeded to shutdownTracer +
   audit.Close, producing truncated traces and racing the audit channel
   close against any handler that was still running.

Fix:
- Listener tracks accepted connections via a mutex-protected map.
- Stop closes every tracked conn after closing the listening socket,
  unblocking handleConn's pending reads and writes.
- Serve refuses new connections observed after stopCh fires so we do
  not leak a conn registered between Accept and the loop exit.
- main hard-fails via log.Fatalf when Drain misses its deadline,
  skipping tracer/audit shutdown rather than flushing partial state.
- New TestStopClosesConns asserts a stalled client unblocks cleanly
  under Stop + Drain.

Signed-off-by: VibhorGautam <vibhorgautam907@gmail.com>
Codex re-review flagged audit.Close as the last unbounded shutdown
step: the drain goroutine finishes only after all pending writes to
the underlying io.Writer complete, and a backpressured stdout or
stalled filesystem could hang Close indefinitely even after ln.Drain
succeeded.

Run audit.Close in a helper goroutine and race it against a 2s
context. On timeout the process continues to exit; the worker dies
with the process and the last few entries may be lost, which is the
correct tradeoff against wedging on SIGTERM.

Signed-off-by: VibhorGautam <vibhorgautam907@gmail.com>
The drain goroutine inside asyncJSONSink.Close may still be mid-write
when the 2s deadline fires. Closing the underlying file in that branch
truncates or corrupts the final JSONL record. Move closeAuditFile into
the success branch; on timeout the fd is left to process exit, which
is the correct tradeoff against shipping a corrupt audit tail.

Signed-off-by: VibhorGautam <vibhorgautam907@gmail.com>
A bad or unwritable audit_path used to kill the sidecar at startup via log.Fatalf, which breaks the fail-open behaviour the tracer already follows. Fall back to a noop sink and log a warning instead, so an audit problem can never stop enforcement.

Also fix the observability doc: audit defaults to stdout rather than noop, and document the opa.evaluate span and its attributes.
@VibhorGautam
VibhorGautam force-pushed the feat/telemetry-observability branch from b211849 to 3b9fce5 Compare August 14, 2026 11:22
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant