In February our delivery slot service stopped answering for fifty minutes. Checkout calls it to offer customers a delivery time, and without it nobody could complete an order. CPU was idle, memory was flat, and every process was alive. Every request thread was waiting on the same thing, a write to standard output.
The service is one of the last we run on plain Docker, on four EC2 hosts, with the awslogs logging driver sending container output straight to CloudWatch Logs. That afternoon CloudWatch Logs in our region was degraded, and calls to put log events were slow and often failing.
Docker's logging drivers have a delivery mode, and the default is blocking. The daemon reads what the container writes and hands it to the driver directly, and when the driver cannot keep up, the daemon stops reading. The pipe between the container and the daemon holds sixty four kilobytes, and once it is full a write to stdout simply does not return. Our service logs a line for every request. Each request thread did its work, tried to log the result, and stopped there, holding its connection and its worker slot. The health check logs a line too, so the load balancer took all four hosts out of service, and every container we restarted hung again within a minute.
Docker documents the alternative, non-blocking mode, which puts messages in a ring buffer inside the daemon and drops them when the buffer is full. It was a two line change to daemon.json that we had never made.
The four hosts now run non-blocking mode with an eight megabyte buffer. We would rather lose log lines than orders, and we said so in the runbook so nobody switches it back to save a few lines. The service is moving to the cluster, where containers write to local files and an agent ships them, so a slow log backend becomes lag on the agent instead of a stall in the application. The health check no longer logs. And twice a year in staging we block the route to CloudWatch with a firewall rule and watch what stops, which found two more services set up the same way.
We thought of logging as something the service did on the side. In blocking mode it was a synchronous dependency of every request, and the one we monitored least.
– Sergey Shinder
Top comments (1)
The fix I would add next is an alert for dropped logs, because non-blocking mode trades a visible outage for a quiet blind spot. An 8 MB buffer also fills fast if the service logs a line per request, so its size should follow log rate and how long an outage might last, not a round number. The cluster move helps, but it moves the same risk to disk, so the agent lag and disk use need the same attention as the buffer did. If the agent falls behind and the disk fills, the service can stall again in a different form.