Monitoring & Observability · lesson 4 of 5
Intermediate
2Advanced
2Also part of Monitoring & Observability
3Also part of: Microservices
OpenTelemetry Buffers Spans — a SIGKILL Can Lose Them
OpenTelemetry's BatchSpanProcessor holds finished spans in memory and exports them on a timer. A process killed before that timer fires loses every span it created — proven with a real trace, a real SIGKILL, and force_flush().
By SkillByExample · Updated
Ending a span in OpenTelemetry doesn’t send it anywhere. It hands the span to a background queue — and a process killed before that queue empties loses every span in it, silently.
A collector that just prints what it gets
.scratch/otel-collector.yml runs a real OpenTelemetry Collector with the plainest
pipeline possible: receive OTLP over HTTP and gRPC, print everything to its own logs.
receivers:
otlp:
protocols:
grpc:
endpoint: 0.0.0.0:4317
http:
endpoint: 0.0.0.0:4318
exporters:
debug:
verbosity: detailed
service:
pipelines:
traces:
receivers: [otlp]
exporters: [debug]
$ docker logs otel-collector | tail -3
2026-09-14T08:54:32.842Z info otlpreceiver@v0.160.0/otlp.go:175 msg="Starting HTTP server" endpoint="[::]:4318"
2026-09-14T08:54:32.842Z info service@v0.160.0/service.go:284 msg="Everything is ready. Begin running and processing data."
An app that creates one trace, two spans
.scratch/otel_app.py uses the real Python OpenTelemetry SDK — no mocking — to start a
parent span and a child span, then prints the trace ID it generated:
provider = TracerProvider(resource=Resource.create({"service.name": "order-service"}))
processor = BatchSpanProcessor(
OTLPSpanExporter(endpoint="http://otel-collector:4318/v1/traces"),
schedule_delay_millis=30000, # only export automatically every 30s
)
provider.add_span_processor(processor)
tracer = trace.get_tracer("order-service")
with tracer.start_as_current_span("process_order") as parent:
parent.set_attribute("order.id", "ORD-4471")
with tracer.start_as_current_span("charge_payment") as child:
child.set_attribute("payment.amount_usd", 42.50)
print(f"trace_id={format(parent.get_span_context().trace_id, '032x')}")
schedule_delay_millis=30000 is set deliberately high here so the background worker’s
own timer can’t rescue the next experiment by accident.
The bug: SIGKILL before the batch ever flushes
Run the container, capture its trace ID from stdout, then kill it immediately — before its own 30-second timer, before any graceful shutdown:
$ docker run -d --name otel-app-nokill-test --network monitoring-net otel-app-demo
$ docker logs otel-app-nokill-test
trace_id=6762d2e6629cc00b58bc16a18c8c2ef2
sleeping so the process can be killed before it exits on its own
$ docker kill -s SIGKILL otel-app-nokill-test
Search the collector’s logs for that exact trace ID:
$ docker logs otel-collector | grep -c 6762d2e6629cc00b58bc16a18c8c2ef2
0
Zero. The script printed a real trace ID for a trace that genuinely existed in the
process’s memory — it just never left. SIGKILL doesn’t run atexit handlers, doesn’t run
finally blocks, doesn’t give the batch processor’s worker thread a chance to wake up
early. Whatever was still queued when the kill landed is gone.
The fix: force_flush() before anything risky
Same app, same kill, with one addition — provider.force_flush() called right after the
spans are created, before the process does anything else:
provider.force_flush()
print("force_flush() completed")
$ docker run -d --name otel-app-flush-test --network monitoring-net -e FORCE_FLUSH=1 otel-app-demo
$ docker logs otel-app-flush-test
trace_id=f21f2f1a254d1945734cf512e9601dfe
force_flush() completed
sleeping so the process can be killed before it exits on its own
$ docker kill -s SIGKILL otel-app-flush-test
$ docker logs otel-collector | grep -c f21f2f1a254d1945734cf512e9601dfe
2
Two matches — one per span — because force_flush() blocked until the export to the
collector actually completed, before the sleep even started. The SIGKILL that followed
had nothing left to lose.
What the collector actually received
The debug exporter prints every field, which is enough to read the trace back without
any separate UI:
$ docker logs otel-collector | grep -A 25 f21f2f1a254d1945734cf512e9601dfe
Resource attributes:
-> service.name: Str(order-service)
Span #0
Trace ID : f21f2f1a254d1945734cf512e9601dfe
Parent ID : aad20c7051d83a20
ID : ba98897d5fc2e905
Name : charge_payment
Start time : 2026-09-14 08:56:32.322905165 +0000 UTC
End time : 2026-09-14 08:56:32.353097591 +0000 UTC
Attributes:
-> payment.amount_usd: Double(42.5)
Span #1
Trace ID : f21f2f1a254d1945734cf512e9601dfe
Parent ID :
ID : aad20c7051d83a20
Name : process_order
Start time : 2026-09-14 08:56:32.272643406 +0000 UTC
End time : 2026-09-14 08:56:32.353145888 +0000 UTC
Attributes:
-> order.id: Str(ORD-4471)
charge_payment’s Parent ID (aad20c7051d83a20) is exactly process_order’s own ID.
That single matching field is the whole parent/child relationship — a trace viewer just
walks these links to draw the call tree. process_order’s Parent ID is blank because
it’s the root of this trace.
Practice
-
Set
schedule_delay_millisback down to its SDK default (remove the argument entirely) and repeat the no-flush kill test, but wait 6 seconds between starting the container and killing it instead of killing immediately. Confirm the trace now arrives even withoutforce_flush().Solution
$ docker run -d --name otel-app-default-test --network monitoring-net otel-app-default-demo $ docker logs otel-app-default-test trace_id=53e303f3ee4211146520a9b92ea6a995 sleeping so the process can be killed before it exits on its own $ sleep 6 && docker kill -s SIGKILL otel-app-default-test $ docker logs otel-collector | grep -c 53e303f3ee4211146520a9b92ea6a995 2With the default 5-second schedule delay, the worker thread’s own periodic export fires and completes well before the 6-second kill — proving the bug in this lesson is about the race between the kill and the next flush, not about
force_flush()being the only way spans ever leave. -
Add a third, sibling span called
send_confirmation_emailinside the sameprocess_orderblock (not nested insidecharge_payment), and confirm in the collector’s debug output that itsParent IDmatchesprocess_order’sIDwhilecharge_payment’s does too — two children, one parent.Solution
$ docker logs otel-collector | grep -E "Trace ID|Parent ID|^ ID |Name" Parent ID : fe8c61d59b4c1396 ID : 269061a31e1f5b38 Name : charge_payment Parent ID : fe8c61d59b4c1396 ID : 50ea749b8a915773 Name : send_confirmation_email Parent ID : ID : fe8c61d59b4c1396 Name : process_orderBoth children show the identical
Parent ID(fe8c61d59b4c1396,process_order’s ownID) but differentIDvalues for themselves — confirming siblings share a parent without needing to share anything else. -
Change the OTLP exporter’s endpoint to a wrong port (
http://otel-collector:4319/v1/traces) and run the app withFORCE_FLUSH=1. Check whatforce_flush()returns and what the app’s own stdout shows, since — unlike the SIGKILL case — this time the process is still alive to report the failure.Solution
$ docker run -d --name otel-app-badport-test --network monitoring-net \ -e FORCE_FLUSH=1 -e OTEL_ENDPOINT="http://otel-collector:4319/v1/traces" otel-app-demo $ docker logs otel-app-badport-test trace_id=0c5ed47fdb184d630207e4402fa969a6 Transient error HTTPConnectionPool(host='otel-collector', port=4319): Max retries exceeded with url: /v1/traces (Caused by NewConnectionError("HTTPConnection(host='otel-collector', port=4319): Failed to establish a new connection: [Errno 111] Connection refused")) encountered while exporting span batch, retrying in 1.17s. Transient error HTTPConnectionPool(host='otel-collector', port=4319): Max retries exceeded with url: /v1/traces (Caused by NewConnectionError(...)) encountered while exporting span batch, retrying in 1.99s. Transient error HTTPConnectionPool(host='otel-collector', port=4319): Max retries exceeded with url: /v1/traces (Caused by NewConnectionError(...)) encountered while exporting span batch, retrying in 4.52s. force_flush() completed sleeping so the process can be killed before it exits on its own Failed to export span batch due to timeout, max retries or shutdown. $ docker logs otel-collector | grep -c 0c5ed47fdb184d630207e4402fa969a6 0force_flush()still returns — it has its own timeout — but only after the exporter has burned through several real retries with exponential backoff (1.17s, 1.99s, 4.52s) against a port nothing is listening on, then given up with"Failed to export span batch due to timeout, max retries or shutdown."docker logs otel-collectorshows nothing for that trace ID: the same silent-on-the-receiving-end outcome as the alerting lesson’s misconfigured Alertmanager port, except here the failure is at least visible — loudly — in the app’s own logs, because nothing killed the process before it could report it. -
Set
child.set_status(trace.StatusCode.ERROR, "card declined")on thecharge_paymentspan before it ends, instead of leaving it unset, and confirm the collector’s debug output shows a differentStatus codeline for that span.Solution
$ docker logs otel-collector | grep -A 8 a90bcebd6024cdce718d862fa600c775 Name : charge_payment Status code : Error Status message : card declined ... Name : process_order Status code : Unset Status message :The parent
process_orderspan’s own status is unaffected — span status doesn’t propagate upward automatically; a real error-tracking dashboard built on this data has to explicitly check descendant spans if it wants to flag a trace as failed based on a failure several levels down.