{"id":"IL-0179","org":"MUSINSA","date":"2026-10-01","docs":[],"title":{"en":"With DEBUG logging and synchronous log output, a high-traffic service filled the 64 KB stdout pipe, so request threads blocked in write() while holding database connections and HikariCP ran dry, failing requests in 30-second bursts","ko":"DEBUG 로그가 쏟아지자 동기 로깅을 하던 요청 스레드들이 가득 찬 stdout 파이프에서 멈춘 채 DB 커넥션을 쥐고 있어, HikariCP 커넥션 풀이 고갈되고 요청이 30초 주기로 한꺼번에 실패했다."},"domain":["kubernetes","observability"],"impact":{"scope":"Requests to one high-traffic service failed in bursts while the connection pool was exhausted","users":"unknown","region":"unknown"},"review":{"written_by":"session","reviewed_at":null,"reviewed_by":null},"lessons":{"en":"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.\n\nThreadLocal 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.","ko":"AsyncAppender 를 떼어 내면서 trace_id 누락은 막았지만, 요청 스레드를 로그 출력 대기에서 지켜 주던 기능도 함께 사라졌다. 여러 서비스에 한꺼번에 적용하는 표준일수록 해결하려는 문제뿐 아니라 기존에 동작하던 무엇이 바뀌는지도 확인해야 한다. 표준의 결론이 어떤 제약을 전제로 하는지 먼저 봐야 하며, 이번에는 trace 값을 읽는 시점을 바꾸자 그 제약이 풀렸다. 비동기 로깅에서는 ThreadLocal 값이 스레드 경계를 넘지 않는다는 점을 먼저 확인해야 한다. AsyncAppender 로도 지속적인 과부하는 막을 수 없으므로 로그량 자체를 적정하게 관리해야 한다."},"related":[],"sources":[{"url":"https://techblog.musinsa.com/%EB%A1%9C%EA%B7%B8%EA%B0%80-%EC%84%9C%EB%B9%84%EC%8A%A4%EB%A5%BC-%EC%A3%BD%EC%98%80%EB%8B%A4-4013e35a463b","kind":"blog","license":"unknown","archived":null}],"summary":{"en":"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.\n\nIn 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.\n\nThe 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.","ko":"무신사는 사내 모든 서비스가 같은 형식으로 로그를 남기도록 표준 로깅 라이브러리를 운영한다. 이 라이브러리는 로그를 JSON 으로 남기고 trace_id 와 span_id 를 OpenTelemetry 의 Span.current() 에서 읽어 채운다. 그런데 로그 출력을 AsyncAppender 로 바꾸면 trace_id 와 span_id 가 빈 값으로 남았다. 이 값은 요청 스레드의 ThreadLocal 에 있어서 별도 워커 스레드에서는 읽을 수 없기 때문이다. 전사 표준 가이드는 이 누락을 관측성 문제로 보고 AsyncAppender 를 금지했고, 여러 서비스가 동기 로깅으로 돌아갔다. 이 가이드는 로깅이 성능 병목이 되는 일은 드물다고 가정했다.\n\n컨테이너 환경에서 로그는 앱에서 약 64KB 의 stdout 파이프 버퍼를 지나 containerd 와 로그 파일을 거쳐 fluent-bit 으로 간다. 동기 로깅에서는 요청 스레드가 stdout 에 직접 쓴다. Logback 의 OutputStreamAppender 는 락 하나로 한 번에 한 스레드만 쓰게 하고, 기본값 immediateFlush=true 때문에 로그마다 write() 시스템 콜을 부른다. 수집 쪽이 로그 발생 속도를 따라가지 못하면 파이프 버퍼가 가득 차고 write() 가 하염없이 기다린다. 한 스레드가 멈추면 같은 락을 기다리는 다른 스레드도 모두 멈춘다.\n\n트래픽이 많은 서비스에서 DEBUG 로그가 켜진 채 트래픽이 몰리자 로그량이 약 100배로 늘었고 stdout 파이프 버퍼가 가득 찼다. 요청 스레드들은 DB 커넥션을 쥔 채 write 에서 멈췄고, HikariCP 풀이 바닥났다. 새 요청은 기본 30초인 커넥션 획득 타임아웃에 걸려 한꺼번에 실패했다.\n\n팀은 AsyncAppender 를 상속한 TraceAwareAsyncAppender 를 30줄 남짓한 코드로 만들었다. 큐에 넣기 전, 아직 요청 스레드에서 trace_id 와 span_id 를 읽어 이벤트에 담아 워커로 넘긴다. neverBlock=true 로 설정해 큐가 차면 로그를 버리고, 요청 스레드는 기다리지 않는다. 부하테스트에서 초당 약 1,500줄일 때 약 33% 를, 초당 1만 5천 줄을 20분 유지했을 때 약 65% 를 버렸지만, 출력된 약 313만 줄에서 trace_id 결측은 0% 였다. 초당 로그량을 1만 5천 줄로 고정하고 요청당 log.info 호출을 300번과 10번으로 바꿔 측정해도 p95 는 29ms 로 유지됐다."},"trigger":{"en":"DEBUG level logging was on in production when traffic surged, raising log volume to about 100 times normal while the service logged synchronously.","ko":"트래픽이 많은 서비스의 운영 환경에서 DEBUG 레벨 로깅이 켜진 채 트래픽이 몰렸다. 쿼리 한 건마다 로그가 수십 줄씩 나오면서 로그량이 평소의 약 100배로 늘었다."},"severity":"unknown","symptoms":["high-error-rate","intermittent-timeouts","connection-pool-exhausted"],"timeline":{"detected_after":null,"resolved_after":null},"date_kind":"published","detection":{"en":"The on-call engineer was alerted that requests were failing in large batches every 30 seconds.","ko":"당직자가 처음 받은 알림은 요청이 30초마다 무더기로 실패한다는 내용이었다. 이후 부하테스트의 근본 원인 분석 데이터에서 30초 주기의 커넥션 풀 고갈과, stdout write 에서 멈춘 스레드들이 담긴 스레드 덤프를 확인했다."},"components":["logging-library","container-runtime","telemetry-agent","database"],"root_cause":"config-change","remediation":[],"action_items":[{"text":{"en":"Replace synchronous logging with TraceAwareAsyncAppender, which captures trace_id and span_id on the calling thread and drops logs instead of blocking when the queue is full (neverBlock=true)","ko":"AsyncAppender 를 상속해 큐에 넣기 전 요청 스레드에서 trace_id 와 span_id 를 캡처하는 TraceAwareAsyncAppender 를 만들고, neverBlock=true 로 큐가 차면 로그를 버리게 해 비동기 로깅과 trace_id 보존을 함께 유지했다."}},{"text":{"en":"Keep the amount of log output at a sustainable level, since an asynchronous queue still fills under sustained overload","ko":"지속적인 부하에 대응하도록 출력하는 로그량 자체를 적정 수준으로 관리한다."}}],"contributing":["assumption-unverified","blast-radius-too-wide"],"recurrence_of":null,"symptoms_text":{"en":"The on-call engineer for a high-traffic service was alerted that requests were failing in large batches every 30 seconds.\n\nThe 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.\n\nThe 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.","ko":"트래픽이 많은 한 서비스에서 요청이 30초마다 무더기로 실패했다. 당직자가 처음 받은 알림도 이 증상이었다.\n\n커넥션 풀은 고갈돼 있었다. 풀 고갈 때문에 생긴 실패는 정확히 30초 주기로 몰렸고, 이 주기는 커넥션 획득 타임아웃의 기본값과 같았다.\n\n스레드 덤프를 보니 수십 개의 스레드가 stdout write 지점에서 멈춰 있었다. 로그를 쓰지 못한 요청 스레드들이 기다리는 사이 서비스 전체가 멈췄다.\n\n요청 실패와 로그 쓰기 사이에 여러 단계가 끼어 있어서, 처음 보이는 증상만으로는 원인을 알기 어려웠다. 마지막 증상에서부터 단계를 거슬러 올라가야 중간의 stdout 버퍼 포화를 찾을 수 있었다."},"updated_at":"2026-11-10T00:00:37.522825Z","url":"https://benchlet.com/incidentlib/app/cases/IL-0179","org_slug":"musinsa"}