logback에서 stdout 로그 출력 시 특정 Thread가 lock을 무기한 보유하는 이슈

운영중인 개발 환경 서버에서 504 Gateway Time-out이 발생하고 일정 시간이 지나도 회복되지 않는 문제가 발생했습니다.

해당 어플리케이션의 경우 지속적으로 헬스체크를 진행하고 실패시 트래픽을 받지 않도록 구성해두었는데도 문제가 있는 장비는 제거되지 않고 계속 트래픽을 받고 있었습니다.

트래픽을 받는 특정 장비 내부에서 curl을 이용해 헬스체크 path에 대해 요청을 보내보았으나 아래와 같이 정상적으로 200 응답이 내려오는 것을 확인할 수 있었습니다.

❯ curl http://localhost/actuator/health
{"status":"UP","components":{"ping":{"status":"UP"}}}

명확한 원인 파악을 위해 아래와 같이 스레드 덤프를 따서 확인해보았습니다.

java.lang.Thread.State: RUNNABLE
at java.io.FileOutputStream.writeBytes(Native Method)
at java.io.FileOutputStream.write(FileOutputStream.java:326)
at java.io.BufferedOutputStream.write(BufferedOutputStream.java:122)
- locked <0x00000000c023a8e0> (a java.io.BufferedOutputStream)
at java.io.PrintStream.write(PrintStream.java:480)
- locked <0x00000000c023a8c0> (a java.io.PrintStream)
at java.io.FilterOutputStream.write(FilterOutputStream.java:97)
at ch.qos.logback.core.joran.spi.ConsoleTarget$1.write(ConsoleTarget.java:37)
at ch.qos.logback.core.OutputStreamAppender.writeBytes(OutputStreamAppender.java:199)
at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:231)
at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:102)
at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:270)
at ch.qos.logback.classic.Logger.callAppenders(Logger.java:257)
at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:421)
at ch.qos.logback.classic.Logger.filterAndLog_1(Logger.java:398)
at ch.qos.logback.classic.Logger.info(Logger.java:583)
at 문제가 발생한 패키지(문제가 발생한 클래스.kt:107)

해당 스레드 덤프의 내용을 보면 특정 스레드 하나가 RUNNABLE 상태임에도 불구하고 at java.io.PrintStream.write(PrintStream.java:480)에서 locked로 lock이 발생한 것을 확인할 수 있습니다.

원인

대부분의 로그는 파일로 별도로 떨구게 구성해두었는데, 개발 환경이다보니 어플리케이션 내부에 아래와 같이 stdout 로그를 찍는 부분이 logback 설정에 포함되어 있었고 이 부분에서 문제가 발생한 것으로 보입니다.

<?xml version="1.0" encoding="UTF-8"?>
<appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
    <encoder>
        <charset>utf8</charset>
        <pattern>%d{MM-dd HH:mm:ss} [%thread] %.-5level %logger{36} - %msg%n</pattern>
    </encoder>
</appender>

stdout으로 로그를 출력하더라도 기존에 잘 동작하고 특별한 설정의 변경이 없던 어플리케이션에서 갑자기 왜 위와 같은 문제가 발생한 것인지는 명확히 파악하지 못했습니다. 트래픽, 로깅의 양도 늘어나지 않았고 별다른 설정의 변경이 없는 상태에서 왜 Lock이 잡혀 어플리케이션이 행이 걸리는지는 의문입니다.

일단 근본적인 원인은 Lock을 무기한으로 보유하고 있는 RUNNABLE 스레드로 보입니다. 아래와 같이 유사한 현상을 겪은 케이스를 logback 이슈에서 찾을 수 있었습니다.

https://jira.qos.ch/browse/LOGBACK-1406?attachmentViewMode=list

https://jira.qos.ch/browse/LOGBACK-1422?attachmentViewMode=list

해결

근본적인 원인은 확인하지 못했으나, stdout으로 로그를 찍는 부분이 어플리케이션에 영향을 주지 않도록 아래 부분을 변경했습니다.

ConsoleAppender → AsyncAppender로 변경
neverBlock 설정 추가

<appender name="STDOUT-ASYNC" class="ch.qos.logback.classic.AsyncAppender">
    <neverBlock>true</neverBlock>
    <appender-ref ref="STDOUT"/>
</appender>

AsyncAppender만 사용해도 문제가 없을 것으로 생각했는데 AsyncAppender만을 적용해도 스레드가 무기한으로 Lock을 보유하는 문제는 동일하게 발생했습니다.

설정을 조금 잘못 넣어서 그런것일지도 모르겠으나, neverBlock 설정을 추가한 시점부터 의도한 대로 Lock이 걸려도 어플리케이션이 멈추지 않고 정상적으로 동작했습니다.

위와 같이 설정하는 경우 Lock이 걸린 시점부터는 stdout 로그가 정상적으로 출력되지 않습니다.

2021년 May 1일 작성

서버 개발자입니다.

logback에서 stdout 로그 출력 시 특정 Thread가 lock을 무기한 보유하는 이슈

원인

해결

Table of contents