Skip to main content
Monitoring & Observability · lesson 4 of 5
Monitoring & Observability advanced Lesson 4 of 5

Also 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

monitoring opentelemetry tracing observability

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

  1. Set schedule_delay_millis back 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 without force_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
    2

    With 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.

  2. Add a third, sibling span called send_confirmation_email inside the same process_order block (not nested inside charge_payment), and confirm in the collector’s debug output that its Parent ID matches process_order’s ID while charge_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_order

    Both children show the identical Parent ID (fe8c61d59b4c1396, process_order’s own ID) but different ID values for themselves — confirming siblings share a parent without needing to share anything else.

  3. Change the OTLP exporter’s endpoint to a wrong port (http://otel-collector:4319/v1/traces) and run the app with FORCE_FLUSH=1. Check what force_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
    0

    force_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-collector shows 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.

  4. Set child.set_status(trace.StatusCode.ERROR, "card declined") on the charge_payment span before it ends, instead of leaving it unset, and confirm the collector’s debug output shows a different Status code line 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_order span’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.

Frequently Asked Questions

Does creating a span with the OpenTelemetry SDK send it anywhere immediately?
No. Ending a span only marks it finished and hands it to the configured SpanProcessor — with the default BatchSpanProcessor, that means it sits in an in-memory queue until the processor's background worker thread wakes up on its own schedule (5 seconds by default) or until something explicitly flushes it. The span exists, and even has a real trace ID, well before it has actually left the process.
Why did the collector never receive a trace even though the Python script printed its trace_id and exited without any error?
Because the script was killed with SIGKILL while it was still inside its BatchSpanProcessor's 30-second export window and before anything forced an export. A SIGKILL gives a process no chance to run cleanup code — no atexit handler, no signal handler, nothing — so whatever spans were still queued in memory simply vanish with the process. A normal exit or a caught SIGTERM can still flush in time; a SIGKILL never can.
What does provider.force_flush() actually do?
It blocks the calling thread until every span currently queued in the processor has been handed to the exporter and the export call has returned (or a timeout is hit) — a synchronous, on-demand version of what the batch worker does periodically. Calling it before a risky shutdown path, or inside a signal handler for SIGTERM, is what makes trace delivery survive a deliberate or orchestrator-driven process stop.
What is the parent/child relationship between spans made of?
Every span in the same trace shares one Trace ID, and a child span's Parent ID field holds the exact Span ID of whatever span was active when it started — that's the entire mechanism. There's no separate tree structure stored anywhere; a trace viewer reconstructs the call tree purely by matching each span's Parent ID back to another span's ID within the same Trace ID.
Do I need Jaeger or another trace backend to see OpenTelemetry data?
Not to see that data was received — the Collector's own debug exporter prints every field of every span (trace ID, span ID, parent ID, name, timestamps, attributes) straight to its logs, which is enough to confirm delivery and inspect a span's contents without standing up a separate UI. A backend like Jaeger adds a searchable, visual trace timeline on top of the same data; it isn't what makes the data arrive.