로그를 남기자 - logback(4)

# 관련 소스는 여기에서 확인하실 수 있습니다.

# 2023-06-18 업데이트

현재 포스팅까지 구현된 코드에서 잘못된 점을 발견하여 수정 중에 있습니다. 수정사항은 다음 포스팅에서 다루어질 예정입니다.

# 2023-06-23 업데이트

2023-06-18 발견된 문제점을 수정하여 포스팅 완료, Github 소스 업데이트 완료 했습니다

지난 포스팅에서 예고했던 대로 구현 코드를 공유하고 설명하고자 한다.

1. CustomTimeBasedFileNamingAndTriggeringPolicy 클래스

이 클래스는 DefaultTimeBasedFileNamingAndTriggeringPolicy 클래스를 상속받아 메서드를 오버라이딩한 클래스이다.

@NoAutoStart
public class CustomTimeBasedFileNamingAndTriggeringPolicy<E> extends DefaultTimeBasedFileNamingAndTriggeringPolicy<E> {

	private final int LOG_CREATION_CYCLE = 5;

	@Override
	public boolean isTriggeringEvent(File activeFile, E event) {
		long time = this.getCurrentTime();
		if (time >= this.nextCheck) {
			Date dateOfElapsedPeriod = this.dateInCurrentPeriod;
			this.addInfo("Elapsed period: " + dateOfElapsedPeriod);

			this.setDateInCurrentPeriod(this.nextCheck);

			this.elapsedPeriodsFileName = this.getCurrentPeriodsFileNameWithoutCompressionSuffix();

			this.setDateInCurrentPeriod(time);
			this.computeNextCheck();
			return true;
		} else {
			return false;
		}
	}

	@Override
	protected void computeNextCheck() {
		this.nextCheck = this.rc.getEndOfNextNthPeriod(this.dateInCurrentPeriod, LOG_CREATION_CYCLE).getTime();
	}
}

이 클래스에서는 롤링 시간을 체크하고 이벤트를 발생시키는 isTriggeringEvent 메서드와 다음 롤링 시간을 계산하는 computeNextCheck 메서드를 오버라이딩하여 구현한다. 오버라이딩한 각 메서드를 설명하자면 아래와 같다.

isTriggeringEvent 메서드

DefaultTimeBasedFileNamingAndTriggeringPolicy 클래스의 메서드로 로그 이벤트가 발생할 때마다 RollingFileAppender 클래스에서 해당 메서드를 호출하는 것을 볼 수 있다.

public class RollingFileAppender<E> extends FileAppender<E> {

...
...
...

	/**
	* This method differentiates RollingFileAppender from its super class.
	*/
	@Override
	protected void subAppend(E event) {
		// The roll-over check must precede actual writing. This is the
		// only correct behavior for time driven triggers.

		// We need to synchronize on triggeringPolicy so that only one rollover
		// occurs at a time
		synchronized (triggeringPolicy) {
			if (triggeringPolicy.isTriggeringEvent(currentlyActiveFile, event)) {
				rollover();
			}
		}

		super.subAppend(event);
	}

...
...
...

이 메서드가 호출되면 애플리케이션 실행 시 logback이 초기 설정을 하면서 저장한 파일 롤링 시간 this.nextCheck를 통해 파일 롤링 여부를 결정하고, 롤링 파일 이름 패턴을 통해 파일 이름을 결정하고, 동시에 롤링 시 다음 파일 롤링 시간을 계산하는 computeNextCheck 메서드를 호출하게 된다.

오버라이딩하기 전의 원래 코드는 다음과 같다.

public boolean isTriggeringEvent(File activeFile, final E event) {
	long time = getCurrentTime();
	if (time >= nextCheck) {
		Date dateOfElapsedPeriod = dateInCurrentPeriod;
		addInfo("Elapsed period: " + dateOfElapsedPeriod);
		elapsedPeriodsFileName = tbrp.fileNamePatternWithoutCompSuffix.convert(dateOfElapsedPeriod);
		setDateInCurrentPeriod(time);
		computeNextCheck();
		return true;
	} else {
		return false;
	}
}

오버라이딩하기 전의 코드와 비교해서 다른점은 롤링 파일의 이름을 결정하는 메서드는 접근 제어자가 protected로 선언되어 있어 오버라이딩하여 호출할 수 없기 때문에 동일한 역할을 하도록 dateInCurrentPeriod 값을 원하는 값으로 설정한 뒤에 getCurrentPeriodsFileNameWithoutCompressionSuffix 메서드를 호출하였다.

computeNextCheck 메서드

isTriggeringEvent 메서드에서 호출하며, 다음 롤링 시간을 계산한다.

protected void computeNextCheck() {
	nextCheck = rc.getNextTriggeringDate(dateInCurrentPeriod).getTime();
}

본래의 소스 코드는 위와 같고 오버라이딩한 소스 코드와 다른 점은 실제 다음 롤링 시간을 계산하는 RollingCalendar 클래스의 getEndOfNextNthPeriod 메서드를 직접 호출하도록 변경하여, 인자 값으로 롤링 사이클에 대한 값을 지정할 수 있도록 했다는 것이다.

logback-spring.xml

요구사항에 맞추어 logback Custom을 마쳤다면, 이제 이 설정을 사용하도록 해주어야 한다. 기본적인 logback 설정은 생략하도록 하겠다.

<appender name="CUSTOM_APPENDER" class="ch.qos.logback.core.rolling.RollingFileAppender">
	<file>${LOG_PATH}/${LOG_FILE_NAME}.log</file>
	<rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
		<fileNamePattern>${LOG_PATH}/${LOG_FILE_NAME}.%d{yyyy-MM-dd-HH-mm}.log</fileNamePattern>
		<timeBasedFileNamingAndTriggeringPolicy class="com.huning.logback.CustomTimeBasedFileNamingAndTriggeringPolicy"/>
		<maxHistory>30</maxHistory>
	</rollingPolicy>
	<encoder>
		<pattern>${LOG_PATTERN}</pattern>
	</encoder>
</appender>

<logger name="com.huning.logback.LogbackScheduler" level="DEBUG" additivity="false">
	<appender-ref ref="CUSTOM_APPENDER"/>
	<appender-ref ref="CONSOLE"/>
</logger>

먼저 appender 이름을 정하고, rollingPolicy는 TimeBasedRollingPolicy를 사용하도록 한다. 그리고, timeBasedFileNamingAndTriggeringPolicy에는 우리가 만든 CustomTimeBasedFileNamingAndTriggeringPolicy을 넣어주도록 하자.

이후에 logger에 해당 appender가 사용될 경로를 지정하여 사용하도록 설정해 준다.

끝!!!!! 이 아니다.

logback은 다들 아시겠지만,(나는 몰랐다) 로그 이벤트가 발생하지 않으면 동작을 하지 않는다. 이렇게 되면 우리의 요구사항 중에서 사용자의 동작이 없을 때 빈 로그 파일이라도 남겨야 한다는 요구사항을 만족시키지 못하는 것이다. 이 문제를 해결하기 위해 스프링에서 제공하는 Scheduler를 이용하여 1분마다 빈 로그 이벤트를 발생시키도록 해주었다.

LogBackScheduler 클래스

@Slf4j
@Component
@EnableScheduling
public class LogbackScheduler {

	private static int index = 1;

  @Scheduled(cron = "1 * * * * *")
  public void checkRollingLogFile() {
    LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory();
    Appender<ILoggingEvent> appender = loggerContext.getLogger("com.huning.logback.LogbackScheduler").getAppender("CUSTOM_APPENDER");

    try {
      appender.doAppend(new LoggingEvent());
    } catch (Exception e) {
      new RuntimeException("로그 이벤트 발생 실패");
    }
  }

	@Scheduled(fixedRate = 10000) // 10초마다 실행
	public void writeLog() {
		LocalDateTime now = LocalDateTime.now();
		DateTimeFormatter formatter = DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss");
		String nowDateTime = now.format(formatter);
		log.info("{}번째 로그입니다. 현재 시간은 {}입니다.", index, nowDateTime);
		index++;
	}
}

checkRollingLogFile 메서드에서 custom appender 객체를 가져와 1분마다 빈 로그 이벤트를 발생시켜서 사용자의 동작으로 인한 로그 이벤트가 발생하지 않아도 logback에서 파일을 롤링시킬 수 있도록 하였다.

아래의 writeLog 메서드는 10초마다 log가 기록되도록 하는 테스트용 메서드이다.

마무리

이렇게 해서 logback을 요구사항에 맞추어 Custom 해보는 시간을 가졌다. 이 시간을 통해서 다시금 자바의 위대함에 대해서 알게 되었고, 기초가 중요하다는 사실을 또 한 번 깨닫게 되는 시간이었다.

#소스코드

logback 관련 포스팅에 소개된 소스코드는 아래의 링크에 있습니다.
https://github.com/hun-ing/custom-logback/tree/main/logback

비상 비상 !!!

이제까지 잘 되는줄 알았던 logback이 여러번의 테스트를 거치면서 이상한점을 발견했다...
무엇이 잘못 되었고, 어떻게 해결했는지의 과정을 다음 포스팅에서 다루어 보겠다.