14:32 UTC. PagerDuty fires on 5xx rate for
/checkout/complete. The on-call engineer opens the trace dashboard to find the slow dependency. It's green. No red spans, no latency bump, nothing flagged in the service map. The load balancer says the checkout service is failing. Tracing says everything is fine.
the scramble
First theory: a bad deploy. The deploy log shows nothing shipped in the last six hours. Second theory: the payment gateway is slow again, it's happened before. The gateway's own status page is green and our circuit breaker metrics show zero trips. Third theory, the one everyone wants to believe: it's a blip, give it two minutes and watch it clear.
It doesn't clear. 5xx count on /checkout/complete goes from a baseline of about two per minute to 1,900 over nine minutes. A marketing push notification had gone out to 400,000 users twelve minutes earlier, and checkout traffic was running at roughly 6x normal. Nobody in the incident channel is arguing it's noise anymore. The trace dashboard, the thing built specifically to answer "where is this slow," is still just sitting there green.
the hunt
With tracing giving nothing to go on, the hunt moves to raw signals. Application logs (not spans, actual log lines) show a climbing count of a specific exception on the checkout path.
checkout service logs, grepped for the error
asyncpg.exceptions.TooManyConnectionsError: too many connections for role "checkout_svc"
(occurred 340 times in the last 6 minutes)
A connection pool exhaustion. Someone runs a query directly against Postgres to see what's actually holding connections open.
pg\_stat\_activity, filtered to the checkout role
SELECT pid, state, now() - query_start AS duration, query
FROM pg_stat_activity
WHERE usename = 'checkout_svc' AND state != 'idle'
ORDER BY duration DESC LIMIT 5;
pid | state | duration | query
18422 | idle in transaction | 00:00:05 | SELECT ... FOR UPDATE
18390 | idle in transaction | 00:00:05 | SELECT ... FOR UPDATE
18401 | idle in transaction | 00:00:04 | SELECT ... FOR UPDATE
Dozens of connections sitting idle in transaction for four to five seconds each. The checkout handler wraps a row lock on the order table in the same transaction as a call to a third-party inventory and fraud-check API, a call that normally returns in 80ms and, under the spike's downstream load, was taking four to six seconds. Every slow inventory call held a database connection open and idle for the full duration. With a pool of 20 connections per pod across 14 pods, it didn't take many of these stacking up at once to starve everything else on the checkout path.
That explains the outage. It still doesn't explain why tracing showed nothing for nine minutes of a real, 1,900-error spike. That question gets parked for the retro, because the immediate fix (move the external call outside the transaction, add a hard timeout) stops the bleeding and the team moves on to writing the postmortem.
the find
During the retro, someone pulls the raw request count from the load balancer access logs for the 14:32 to 14:55 window and compares it against the span count ingested by Tempo for the checkout service over the same window.
94,612 Requests logged by the load balancer for the checkout service during the window
11,480 Spans actually ingested by Tempo for the same service, same window
Roughly 88% of the traffic that hit checkout during the outage has no trace at all. The gap starts almost exactly ninety seconds into the spike, right around when the queue behind the OpenTelemetry BatchSpanProcessor would have filled on its default settings.
tracing.py (before)
from opentelemetry.sdk.trace.export import BatchSpanProcessor
processor = BatchSpanProcessor(
otlp_exporter,
max_queue_size=2048,
max_export_batch_size=512,
schedule_delay_millis=5000,
)
At 6x traffic, span creation outran what the exporter could drain to the collector. The collector sat behind the same OTLP endpoint that was itself catching some of the spike's traffic, so it was draining slower right when it needed to drain faster. Once the queue hit 2048, the processor started refusing new spans outright. It logs a warning the first time this happens, at the Python logging module's WARNING level. It does not log it again for every subsequent drop, because the service's log pipeline runs a dedup filter on repeated identical lines to cut noise. The one warning that would have told anyone tracing had gone blind fired once, got suppressed as a duplicate, and the drops kept happening silently for the rest of the incident.
the fix
Two separate problems needed two separate fixes. The application bug: the inventory check moved outside the database transaction, with its own timeout, so a slow third-party call can no longer hold a connection hostage.
checkout.py
async def complete_order(order_id: str) -> OrderResult:
inventory_result = await asyncio.wait_for(
check_inventory_and_fraud(order_id), timeout=1.5
)
async with db.transaction():
order = await lock_order_for_update(order_id)
apply_inventory_result(order, inventory_result)
await order.save()
return OrderResult(order)
The observability gap needed a fix that didn't depend on anyone noticing a suppressed warning line. Instead of trusting the SDK's internal counters, the team wired an alert directly off the signal that actually caught this: the gap between load balancer request count and ingested span count for the same service and window.
alert rule (Prometheus-style)
- alert: TraceCoverageGap
expr: |
(sum(rate(alb_requests_total{service="checkout"}[5m]))
- sum(rate(otel_spans_ingested_total{service="checkout"}[5m]))) / sum(rate(alb_requests_total{service="checkout"}[5m])) > 0.15 for: 2m annotations: summary: "Checkout requests are outrunning ingested trace coverage"
The queue itself got widened too, max_queue_size raised to 8192 and schedule_delay_millis dropped to 2000 so the exporter drains more often under burst, but the team treated that as a buffer, not a fix. A bigger queue just moves the point where it fills. The log dedup filter was also changed to let repeated WARNING-level lines from the tracing SDK through after the third occurrence instead of suppressing indefinitely.
the aftermath
- A trace pipeline degrades under exactly the kind of load spike it exists to help diagnose, because span volume scales with request volume, and the exporter's throughput doesn't automatically scale with either.
- A monitoring tool failing silent and green is more dangerous than one failing loud, because it actively points the hunt in the wrong direction instead of just leaving a blank.
- Log dedup filters tuned to cut noise can suppress the exact one-time warning that would have shortened an incident, if that warning only fires once per condition instead of once per occurrence.
- The most reliable way to catch a tracing pipeline lying isn't inside the tracing pipeline. It's comparing it against a source that doesn't share its failure mode, like raw load balancer request counts.
The checkout fix was the kind of bug that's obvious once found, a slow call sitting inside a transaction it never needed to be in. The nine minutes it took to find it without any tracing to lean on is the part that changed how the team treats observability itself: not as a tool that's either working or broken, but as a system with its own capacity limits that can fail exactly when the traffic that needs it shows up.
Top comments (0)