IL-0179 MUSINSA · 2026-10-01 (published)kubernetesobservability
MUSINSA's common platform team maintains a standard logging library that writes JSON logs and fills trace_id and span_id from OpenTelemetry's Span.current(), so logs and distributed traces share IDs across services. When log output went through Logback's AsyncAppender, the worker thread could not see the request thread's ThreadLocal context and the IDs came out empty. The company-wide standard guide treated that as an observability problem and banned AsyncAppender, so many services went back to synchronous logging on the assumption that logging is rarely a performance bottleneck.
In a container, stdout passes through a kernel pipe buffer of about 64 KB to containerd, a log file and fluent-bit. Logback's OutputStreamAppender lets one thread write at a time under a lock, and with the default immediateFlush=true every log call flushes the 8 KB Java buffer with a write() system call. When fluent-bit and the runtime could not keep up with about 100 times the usual volume, the pipe filled, write() blocked, other threads queued on the lock, and request threads that held HikariCP connections could not return them. New requests then failed when the 30-second connection acquisition timeout expired, in bursts.
The platform team kept asynchronous output and fixed the trace IDs with TraceAwareAsyncAppender, about 30 lines that extend AsyncAppender and, in append(), read the span context on the calling thread and wrap the event in a TraceStampedEvent carrying trace_id and span_id before it is queued. With neverBlock=true, events that do not fit in the queue are dropped instead of blocking the request thread. In load tests on one instance, a few hundred lines per second lost nothing; about 1,500 lines per second dropped about 33%; 15,000 lines per second for 20 minutes dropped about 65%, and all of about 3.13 million printed lines had a trace_id. With log volume fixed at 15,000 lines per second, p95 stayed at 29 ms whether requests logged 300 times at 50 requests per second or 10 times at 1,500 requests per second.
The on-call engineer for a high-traffic service was alerted that requests were failing in large batches every 30 seconds.
The database connection pool was exhausted. In the load-test data gathered for the root cause analysis, failures bunched up exactly every 30 seconds, matching the default connection acquisition timeout, and thread dumps showed dozens of threads stopped at the stdout write.
The cause was several steps away from the alert. The service was running with DEBUG logging in production when traffic surged; each query produced dozens of log lines and log volume rose to about 100 times normal. Working back from the failed requests to the connection pool, then to the blocked threads, finally led to the full stdout buffer.
Symptom ? High error rateIntermittent timeoutsConnection pool exhaustion
Root cause ? Configuration change
The on-call engineer was alerted that requests were failing in large batches every 30 seconds.
–
Removing AsyncAppender to keep trace IDs also removed the protection that kept request threads away from stdout back-pressure. A company-wide standard applies the same side effect to dozens of services, so check what a standard rests on and what working behaviour it takes away.
ThreadLocal context does not cross into an asynchronous worker, but capturing it on the calling thread before handing the event off keeps both the IDs and the asynchronous output. Under extreme load, dropping log lines is preferable to stopping request handling.
same root cause · shared Container runtime, Telemetry agent
same root cause · shared Telemetry agent