At 11:04 the log store starts rejecting writes. At 11:05 the node agents' buffers fill. At 11:06 p99 on three unrelated services sharing those nodes goes from 80 ms to 9 s with CPU at 18%, zero application errors and no deployment. By 11:12 requests are timing out. What failed and which design decision made it possible?
Show the full answer Hide the answer
The trigger
A full log store is an ordinary, recoverable event, and most estates survive one in production without a latency incident. What turned this one into a latency incident is the path between the application and the store, and specifically the delivery mode at the first hop.
Why it propagated into services that logged nothing unusual
Container log delivery has two modes, and the default is direct blocking delivery from the container to the driver. The non-blocking mode is the one that stores messages in an intermediate per-container buffer, with a default max-buffer-size of 1 MB, and it drops new messages when that buffer is full. Docker's own documentation warns that applications are likely to fail in unexpected ways when stdout or stderr blocks.
With blocking delivery, a log line is a synchronous write to a pipe nobody is draining, so the request thread that emitted it stops there. CPU sits at 18% because the threads are blocked, not busy, which is exactly the signature in the timeline. Services that log little still log something per request, so the stall spreads to every service on the node, including the ones with no relationship to the service that filled the store.
Why detection lagged
Every signal the team watched was the wrong one. The log store's dashboard showed rejects, which looked like a storage problem with an obvious owner. The services' error rate stayed at zero, because a blocked write produces latency, never an error. The signal that would have named the cause in a minute was in the node agent: buffer occupancy, dropped-record count, and the age of the oldest unshipped record.
The structural fix against the tempting local fix
The tempting fix is to scale the log store, which removes this trigger and leaves the amplifier in place for the next burst. The structural fix is to decide, in advance, that telemetry is lossy and the request path is not:
- Switch delivery to non-blocking with an explicitly sized buffer, and export the drop counter as a first-class metric with an alert. Choose dropping over blocking wherever the record is telemetry: dropping is a loss you can measure, and blocking is a loss you discover from customers. The cost is honest and visible, which is the point.
- Cap record size in the logging library, so one verbose error cannot consume the buffer for everything else.
- Move anything that must not be lost off stdout entirely. An audit or financial record belongs on an acknowledged path with retries and an error, not in a telemetry pipe.
- Treat any synchronous dependency on the observability path as a product dependency, and rank the outcomes explicitly: degrade telemetry before degrading the request.
When blocking is the right default
For a record that regulation requires you to retain, silently dropping it is worse than failing the request. Then make the write explicit and transactional, with its own error path, so the request fails loudly and quickly instead of hanging. The failure in this incident is not that a write blocked; it is that a blocking write sat on the request path by default and nobody chose it.
Common weak answers
- "Add capacity to the log store." The amplifier is the node's delivery mode. The next retry storm reproduces the incident with a larger bill attached.
- "Shorten the service timeouts." That converts hangs into fast failures and restores nothing.
- "Move logging into a sidecar." Same synchronous write, same blocking default, one more component.