logback < 1.2.0 에서 로그가 Rolling 안되는 이슈

노력을 즐겼던 사람·2023년 5월 5일

시작하기 전

운영 중인 서버에서 emphemeral volume 이 가득 찼다는 인프라 알림이 발생했다. emphemeral volume은 disk 저장소이며, 임시 저장소로서 pod가 종료되면 모든 데이터가 유실된다.

이러한 특성 때문에 emphemeral volume에는 애플리케이션 로그가 저장되었다. 로그 파일들은 로그 플랫폼 서버로 전송한 후에 제거되기 때문에 emphemeral volume이 가득차는 일은 없어야 했지만 알림이 발생했다. 이 문제를 해결한 경험을 공유한다.

애플리케이션 로그 정책

SpringBoot 서버를 운영하고 있었기 때문에 logback으로 정책을 관리하고 있었다. 정책은 아래와 같다.


<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">

			...
  			...
  
            <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">

              	...
              	...
              
                <maxFileSize>1GB</maxFileSize>
                <maxHistory>4</maxHistory>
                <totalSizeCap>4GB</totalSizeCap>
            </rollingPolicy>
</appender>

appender 는 RollingFileAppender 를 사용했고, rollingPolicy는 SizeAndTimeBasedRollingPolicy이다.
보다시피 로그 파일을 어떠한 조건에 의해서 Rolling 하며 저장하는 Appender이며, 조건은 다음과 같다.

파일의 최대 크기는 1GB이다.
파일은 최대 4개까지 보관한다.

이런 조건으로 Rolling 한다면 최대 4GB의 emphemeral volume을 점유하게 된다.

적용되지 않는 RollingPolicy

정책 상 최대 4GB의 로그만 저장될 수 있으나 실제로 pod에 접속해서 확인해보니 더 많은 크기의 로그 파일이 저장되어 있었다. emphemeral storage가 8GB로 설정이 되어 있었는데 90%인 7.2GB까지 점유하도록 로그 파일이 계속해서 저장되고 있었다.

적용이 안되는 이유

구글링을 해보니 원인은 파일 삭제를 담당하는 TimeBasedArchiveRemover 클래스의 capTotalSize 메서드에 변수가 int로 정의되어 있어서 발생하는 버그였다. 버그가 발생하는 부분의 코드를 보자

public class TimeBasedArchiveRemover extends ContextAwareBase implements ArchiveRemover {

 	private long totalSizeCap = CoreConstants.UNBOUNDED_TOTAL_SIZE_CAP; // long type

	
    void capTotalSize(Date now) {
        int totalSize = 0;     // int type
        int totalRemoved = 0;
        for (int offset = 0; offset < maxHistory; offset++) {
            Date date = rc.getEndOfNextNthPeriod(now, -offset);
            File[] matchingFileArray = getFilesInPeriod(date);
            descendingSortByLastModified(matchingFileArray);
            for (File f : matchingFileArray) {
                long size = f.length();
                if (totalSize + size > totalSizeCap) { // always false 
                    addInfo("Deleting [" + f + "]" + " of size " + new FileSize(size));
                    totalRemoved += size;
                    f.delete();
                }
                totalSize += size; // <<<<< overflow!!
            }
        }
        addInfo("Removed  " + new FileSize(totalRemoved) + " of files");
	}
    

}

위의 코드는 RollingPolicy에 맞게 로그 파일을 지우는 작업을 수행한다. 작업을 수행하기 위해서 의해서 저장된 파일들을 읽어와서 조건 검사 후 제거하는 코드가 있다. 그 과정에서 제거된 전체 용량을 측정하고 로깅하기 위해서 int totalSize 변수를 선언해두었는데 여기서 오버플로우가 발생한다.

int 타입은 2^31 이므로 byte로 변환하면 2GB에 불과하다. 반면에 우리 서버의 설정에 의하면 저장될 수 있는 최대 로그 용량은 4GB에 달하기 때문에 당연히 오버플로우가 발생하고 조건식이 항상 실패하는 버그이다.

테스트 코드가 없었나 싶어서 찾아봤더니 시간에 대한 RollingPolicy 테스트는 꼼꼼하게 작성되어 있었으나 사이즈에 대한 테스트는 거의 찾아볼 수 없었다.