Add a local structured recorder to the existing documentation retrieval service. Run concurrent HTTP requests and follow each execution through admission, search, read and controlled failure spans. The recorded identical requests complete with different execution IDs and the same content request hash. No model is called and no answer is generated.
When you need this. Use this pattern when interleaved requests make it difficult to identify which operation failed. A trace is a group of operational spans for one execution; a span records an operation and its parent. Neither proves that a retrieved passage answers the question.
Give each execution its own context
The HTTP handler creates a random execution ID and returns it in X-Execution-Trace-ID. The existing request_id is a hash of request content and corpus identity. Repeating identical content should preserve that hash while receiving a new execution ID.
The recorded first pair has equal content request IDs: true. Its execution IDs differ: true. These are actual concurrent loopback requests, not simulated trace entries.
ContextVar stores the current execution and parent span. asyncio.to_thread propagates that context into the retrieval worker. The worker constructs its own SQLite tools; it does not share a connection created in the HTTP task. finally resets the context even when an operation fails. Order means span start order, not elapsed time.
Construct a small log instead of filtering a large one
The recorder accepts only an allowlisted operation name. Every span contains execution ID, span ID, parent span ID, order, name and operational status. Questions, source paragraphs, credentials and exception messages never enter those fields. API responses still contain the normal retrieved source text; the redaction contract applies to the structured log.
Unknown span name. The named test refuses an unrecognized name instead of accepting arbitrary log labels. Interleaved contexts. Concurrent tasks and worker threads must retain their own execution and parent IDs; the isolation test checks both relationships and context reset.
The root span includes request admission. Before each core-admitted search/read invocation, the wrapper records an admission span followed by that operation. After the controller returns a limited result, the wrapper adds an admission span with denied status; no denied tool call is executed. Strict body/schema failures occur before execution tracing. This instrumentation does not replace the action-budget checks.
Retain bounded diagnostics without breaking retrieval
The recorder retains at most 32 traces with 32 spans each. Fixed ASCII fields bound each serialized span; the raw record includes the measured retained byte count and conservative maximum. The local /traces endpoint exposes records and loss counters without authentication; use it only within this demonstration boundary.
Active eviction. A new execution can evict the oldest retained trace even while its worker is running. Later spans for that trace are dropped and counted; retrieval continues. Span capacity. A full trace drops additional spans rather than failing an otherwise valid request. This is diagnostic retention, not a durable audit history. The tests reproduce both loss paths.
Controlled tool failure. The trusted factory raises an exception containing a sensitive sentinel. The real HTTP run returns 503; its failed search/root spans and error event omit the exception text. A successful error-recording event does not turn the failed request into a successful retrieval.
Execute the tracing feature
Download the trace rag requests lab. It includes the original Python-summary corpus, unchanged retrieval core, HTTP body contract, pinned dependencies and executable tests. Create a virtual environment and install requirements.lock before running the driver.
python3 -m venv .venv
source .venv/bin/activate
python -m pip install -r requirements.lock"""Bounded local structured spans; deliberately no question or passage fields."""
from contextvars import ContextVar
from contextlib import contextmanager
from collections import OrderedDict
import threading
import uuid
current_trace=ContextVar('current_trace',default=None)
current_span=ContextVar('current_span',default=None)
class Recorder:
def __init__(self,max_traces=32,max_spans=32):
if any(type(x) is not int or not 1<=x<=1024 for x in (max_traces,max_spans)):raise ValueError('invalid_recorder_limit')
self.max_traces=max_traces;self.max_spans=max_spans;self._traces=OrderedDict();self._lock=threading.RLock();self.dropped_traces=0;self.dropped_spans=0
@contextmanager
def request(self):
trace_id=uuid.uuid4().hex
with self._lock:
self._traces[trace_id]=[]
while len(self._traces)>self.max_traces:
self._traces.popitem(last=False);self.dropped_traces+=1
token=current_trace.set(trace_id);parent=current_span.set(None)
try:
with self.span('request'):yield trace_id
finally:current_span.reset(parent);current_trace.reset(token)
@contextmanager
def span(self,name):
if name not in {'request','admission','search','read','error'}:raise ValueError('invalid_span_name')
trace_id=current_trace.get()
if trace_id is None:raise RuntimeError('missing_request_context')
with self._lock:
rows=self._traces.get(trace_id)
if rows is None or len(rows)>=self.max_spans:
self.dropped_spans+=1;rows=None
row={'trace_id':trace_id,'span_id':uuid.uuid4().hex,'parent_span_id':current_span.get(),'order':len(rows)+1 if rows is not None else 0,'name':name,'status':'running'}
if rows is not None:rows.append(row)
token=current_span.set(row['span_id'])
try:yield row
except BaseException:
with self._lock:row['status']='error'
raise
else:
with self._lock:
if row['status']=='running':row['status']='ok'
finally:current_span.reset(token)
def snapshot(self):
with self._lock:return {key:[dict(row) for row in rows] for key,rows in self._traces.items()}
def mark_response(self,code):
with self._lock:
rows=self._traces.get(current_trace.get())
if rows:rows[0]['status']='error' if code>=500 else 'ok'
def stats(self):
import json
with self._lock:return {'retained_traces':len(self._traces),'dropped_traces':self.dropped_traces,'dropped_spans':self.dropped_spans,'serialized_utf8_bytes':len(json.dumps(self.snapshot(),separators=(',',':')).encode()),'max_traces':self.max_traces,'max_spans_per_trace':self.max_spans,'maximum_span_utf8_bytes':320,'maximum_retained_utf8_bytes':self.max_traces*(self.max_spans*320+40)+2}python run.py --output scratch-result.json
python -m unittest discover -v{
"execution_mode": "actual-loopback-local-structured-tracing",
"cases": [
{
"http_status": 200,
"execution_trace_id": "4f5fb5c9ce9848c48f5e67785be64634",
"content_request_id": "c4b35bcad796671fdb9ebd92411172aa68574ee99fecbd854bcef13db24dc067",
"status": "completed"
},
{
"http_status": 200,
"execution_trace_id": "2dbfe5bcfb6d44a7963e9ec275c0155b",
"content_request_id": "c4b35bcad796671fdb9ebd92411172aa68574ee99fecbd854bcef13db24dc067",
"status": "completed"
},
{
"http_status": 200,
"execution_trace_id": "78e51bc5eb2548a98ea1f5d361f66973",
"status": "limited"
}
],
"failure_http_status": 503,
"retained_traces": 3
}The driver starts temporary loopback Uvicorn processes, performs real HTTPX requests and reaps each child. Trusted fixture factories control failure injection; public requests cannot choose a delay or bypass a guard. This is a local structured recorder, not an OpenTelemetry SDK or hosted tracing service.
Inspect the complete saved result
{
"execution_mode": "actual-loopback-local-structured-tracing",
"model_called": false,
"cases": [
{
"http_status": 200,
"execution_trace_id": "4f5fb5c9ce9848c48f5e67785be64634",
"content_request_id": "c4b35bcad796671fdb9ebd92411172aa68574ee99fecbd854bcef13db24dc067",
"status": "completed"
},
{
"http_status": 200,
"execution_trace_id": "2dbfe5bcfb6d44a7963e9ec275c0155b",
"content_request_id": "c4b35bcad796671fdb9ebd92411172aa68574ee99fecbd854bcef13db24dc067",
"status": "completed"
},
{
"http_status": 200,
"execution_trace_id": "78e51bc5eb2548a98ea1f5d361f66973",
"status": "limited"
}
],
"invalid_request_http_status": 422,
"record": {
"traces": {
"4f5fb5c9ce9848c48f5e67785be64634": [
{
"trace_id": "4f5fb5c9ce9848c48f5e67785be64634",
"span_id": "0bad9bf5996f4ce887f935d069dba333",
"parent_span_id": null,
"order": 1,
"name": "request",
"status": "ok"
},
{
"trace_id": "4f5fb5c9ce9848c48f5e67785be64634",
"span_id": "b784599e314f48fe9ca3f06b29466a03",
"parent_span_id": "0bad9bf5996f4ce887f935d069dba333",
"order": 2,
"name": "admission",
"status": "ok"
},
{
"trace_id": "4f5fb5c9ce9848c48f5e67785be64634",
"span_id": "1a04dc8fb1924941b871d5a0fc05ce17",
"parent_span_id": "0bad9bf5996f4ce887f935d069dba333",
"order": 3,
"name": "admission",
"status": "ok"
},
{
"trace_id": "4f5fb5c9ce9848c48f5e67785be64634",
"span_id": "9b709f89e4834374b6348936dfb0e85e",
"parent_span_id": "0bad9bf5996f4ce887f935d069dba333",
"order": 4,
"name": "search",
"status": "ok"
},
{
"trace_id": "4f5fb5c9ce9848c48f5e67785be64634",
"span_id": "49916e00d29c43d385bacd0ac05b168a",
"parent_span_id": "0bad9bf5996f4ce887f935d069dba333",
"order": 5,
"name": "admission",
"status": "ok"
},
{
"trace_id": "4f5fb5c9ce9848c48f5e67785be64634",
"span_id": "a3911be498d7448cbd1916f805f6884d",
"parent_span_id": "0bad9bf5996f4ce887f935d069dba333",
"order": 6,
"name": "read",
"status": "ok"
},
{
"trace_id": "4f5fb5c9ce9848c48f5e67785be64634",
"span_id": "63c0c719b3864b5b94faf53e98ac805d",
"parent_span_id": "0bad9bf5996f4ce887f935d069dba333",
"order": 7,
"name": "admission",
"status": "ok"
},
{
"trace_id": "4f5fb5c9ce9848c48f5e67785be64634",
"span_id": "c533068f63cd42318c163cd9564d2a1e",
"parent_span_id": "0bad9bf5996f4ce887f935d069dba333",
"order": 8,
"name": "search",
"status": "ok"
},
{
"trace_id": "4f5fb5c9ce9848c48f5e67785be64634",
"span_id": "271483d6b6b14806b2aec359c78d7999",
"parent_span_id": "0bad9bf5996f4ce887f935d069dba333",
"order": 9,
"name": "admission",
"status": "ok"
},
{
"trace_id": "4f5fb5c9ce9848c48f5e67785be64634",
"span_id": "e504f408c31a4fd386320c184ea6700e",
"parent_span_id": "0bad9bf5996f4ce887f935d069dba333",
"order": 10,
"name": "read",
"status": "ok"
}
],
"2dbfe5bcfb6d44a7963e9ec275c0155b": [
{
"trace_id": "2dbfe5bcfb6d44a7963e9ec275c0155b",
"span_id": "20f0b64805f84239a397614e5788e919",
"parent_span_id": null,
"order": 1,
"name": "request",
"status": "ok"
},
{
"trace_id": "2dbfe5bcfb6d44a7963e9ec275c0155b",
"span_id": "2933b2de32fc40f89b67f4ada53edb70",
"parent_span_id": "20f0b64805f84239a397614e5788e919",
"order": 2,
"name": "admission",
"status": "ok"
},
{
"trace_id": "2dbfe5bcfb6d44a7963e9ec275c0155b",
"span_id": "bf0c8b10bbea493c9b3b0127ab1aebc1",
"parent_span_id": "20f0b64805f84239a397614e5788e919",
"order": 3,
"name": "admission",
"status": "ok"
},
{
"trace_id": "2dbfe5bcfb6d44a7963e9ec275c0155b",
"span_id": "6b0b53435a634ec0ae9bf70c0647cfec",
"parent_span_id": "20f0b64805f84239a397614e5788e919",
"order": 4,
"name": "search",
"status": "ok"
},
{
"trace_id": "2dbfe5bcfb6d44a7963e9ec275c0155b",
"span_id": "604ae916963e4ce6bb3d178e34ba4f25",
"parent_span_id": "20f0b64805f84239a397614e5788e919",
"order": 5,
"name": "admission",
"status": "ok"
},
{
"trace_id": "2dbfe5bcfb6d44a7963e9ec275c0155b",
"span_id": "29f4728235a1426a9b563ff386eeeab8",
"parent_span_id": "20f0b64805f84239a397614e5788e919",
"order": 6,
"name": "read",
"status": "ok"
},
{
"trace_id": "2dbfe5bcfb6d44a7963e9ec275c0155b",
"span_id": "23d757cc46034e2792e13fd456ca832e",
"parent_span_id": "20f0b64805f84239a397614e5788e919",
"order": 7,
"name": "admission",
"status": "ok"
},
{
"trace_id": "2dbfe5bcfb6d44a7963e9ec275c0155b",
"span_id": "6afe8d25d8b1414da0e3c099f00c746f",
"parent_span_id": "20f0b64805f84239a397614e5788e919",
"order": 8,
"name": "search",
"status": "ok"
},
{
"trace_id": "2dbfe5bcfb6d44a7963e9ec275c0155b",
"span_id": "e1ea78bc89d04839beb28b58bb872363",
"parent_span_id": "20f0b64805f84239a397614e5788e919",
"order": 9,
"name": "admission",
"status": "ok"
},
{
"trace_id": "2dbfe5bcfb6d44a7963e9ec275c0155b",
"span_id": "03c431330cb54ce0b5cee8eea6043efd",
"parent_span_id": "20f0b64805f84239a397614e5788e919",
"order": 10,
"name": "read",
"status": "ok"
}
],
"78e51bc5eb2548a98ea1f5d361f66973": [
{
"trace_id": "78e51bc5eb2548a98ea1f5d361f66973",
"span_id": "741865934705499896a854a1394a7107",
"parent_span_id": null,
"order": 1,
"name": "request",
"status": "ok"
},
{
"trace_id": "78e51bc5eb2548a98ea1f5d361f66973",
"span_id": "2cff3668f7bf471c9bb4d06255e953cc",
"parent_span_id": "741865934705499896a854a1394a7107",
"order": 2,
"name": "admission",
"status": "ok"
},
{
"trace_id": "78e51bc5eb2548a98ea1f5d361f66973",
"span_id": "f9f82fbde3ed458c881e71be33b81af7",
"parent_span_id": "741865934705499896a854a1394a7107",
"order": 3,
"name": "admission",
"status": "denied"
}
]
},
"retention": {
"retained_traces": 3,
"dropped_traces": 0,
"dropped_spans": 0,
"serialized_utf8_bytes": 4314,
"max_traces": 32,
"max_spans_per_trace": 32,
"maximum_span_utf8_bytes": 320,
"maximum_retained_utf8_bytes": 328962
}
},
"controlled_tool_failure": {
"http_status": 503,
"status": "failed",
"execution_trace_id": "ba105bcda75f4a4eb640e8202b66046c",
"record": {
"traces": {
"ba105bcda75f4a4eb640e8202b66046c": [
{
"trace_id": "ba105bcda75f4a4eb640e8202b66046c",
"span_id": "0af7315b7b734726979a70051114c32b",
"parent_span_id": null,
"order": 1,
"name": "request",
"status": "error"
},
{
"trace_id": "ba105bcda75f4a4eb640e8202b66046c",
"span_id": "b2c8ccb37d6e48d0bfbf3b2ad28fa111",
"parent_span_id": "0af7315b7b734726979a70051114c32b",
"order": 2,
"name": "admission",
"status": "ok"
},
{
"trace_id": "ba105bcda75f4a4eb640e8202b66046c",
"span_id": "b409bd41db7f40408e8d4e75b3767498",
"parent_span_id": "0af7315b7b734726979a70051114c32b",
"order": 3,
"name": "admission",
"status": "ok"
},
{
"trace_id": "ba105bcda75f4a4eb640e8202b66046c",
"span_id": "17a4199ae59b4575a97c1a500061e69b",
"parent_span_id": "0af7315b7b734726979a70051114c32b",
"order": 4,
"name": "search",
"status": "error"
},
{
"trace_id": "ba105bcda75f4a4eb640e8202b66046c",
"span_id": "2e0b6542fc634a95a443680c5ad9fbe3",
"parent_span_id": "0af7315b7b734726979a70051114c32b",
"order": 5,
"name": "error",
"status": "ok"
}
]
},
"retention": {
"retained_traces": 1,
"dropped_traces": 0,
"dropped_spans": 0,
"serialized_utf8_bytes": 945,
"max_traces": 32,
"max_spans_per_trace": 32,
"maximum_span_utf8_bytes": 320,
"maximum_retained_utf8_bytes": 328962
}
}
},
"lifecycle": {
"command": [
"python3",
"serve.py",
"--fd",
"<inherited-loopback-socket>",
"--app",
"app:app"
],
"startup_observed": true,
"shutdown_exit_status": -15,
"stdout": "",
"stderr": "INFO: Started server process [37393]\nINFO: Waiting for application startup.\nINFO: Application startup complete.\nINFO: Shutting down\nINFO: Waiting for application shutdown.\nINFO: Application shutdown complete.\nINFO: Finished server process [37393]\n",
"shutdown_complete_observed": true,
"server_process_reaped": true
},
"fault_lifecycle": {
"command": [
"python3",
"serve.py",
"--fd",
"<inherited-loopback-socket>",
"--app",
"fault_fixture:app"
],
"startup_observed": true,
"shutdown_exit_status": -15,
"stdout": "",
"stderr": "INFO: Started server process [37394]\nINFO: Waiting for application startup.\nINFO: Application startup complete.\nINFO: Shutting down\nINFO: Waiting for application shutdown.\nINFO: Application shutdown complete.\nINFO: Finished server process [37394]\n",
"shutdown_complete_observed": true,
"server_process_reaped": true
},
"scope": "Local bounded recorder; schema/body rejections occur before trace creation. Tool admission spans record actual core-admitted invocation, not denied actions. No raw questions or source text in spans; response content is not the trace log."
}Inspect a failure without overstating the result
Compare the first two execution IDs and content hashes. Follow one search/read pair to its parent request. Then inspect the controlled failure: identify its failed operation without finding the sensitive exception sentinel in the log. Run the active-eviction test and explain why the missing spans are counted rather than interpreted as showing that no work occurred.
The recorder provides bounded operational diagnostics without persistence, authentication, cross-process correlation or answer-quality checks.
Read the explanation
Execution identity, content identity and semantic correctness are different contracts.
What’s next
Continue with Limit Concurrent RAG Requests.
References
The official contextvars documentation explains context-local state and token reset. The asyncio thread documentation describes context propagation to a worker thread. The bounded record schema and loss behavior are this lab’s tested application policy.