Application Context Refresh 전에 로깅 설정하기

 

개발 중 Application Context가 Refresh 되기전 비정상 종료하면 내가 설정한 로그 파일이 적용되지 않는 이슈를 발견했고, 이 이슈를 해결한 과정을 공유한다.

 

배경

기존 프로젝트에 새로운 Profile을 추가하는 과정에 Java 프로그램이 제대로 실행되지 않는 이슈 발생했다.원인은 Zookeeper 설정 누락으로 새로운 Profile에 대한 Zookeeper endpoint를 제대로 지정하지 않아 실패했다.

 

원인은 간단하지만, 로그가 내가 설정한데로 동작하지 않아 로그를 찾는데 오랜 시간이 걸렸다...

그럼 왜 로그 설정이 내가 원하는데로 되지 않았을까?

 

로그 설정이 적용되지 않은 이유

두괄식으로 이유만 먼저 말하면 application.yaml의 logging.config에 설정한 값은 Application Context Refresh 과정중 LoggingApplicationListener에 의해 설정되는데, 해당 설정이 적용되기 전에 프로그램이 비정상 종료해 로그가 설정한 것과 다르게 동작했다.

 

좀 더 구첵인 이유는 SpringApplication의 run 메소드를 보면 알 수 있다.

 

실제로 Application Context Refresh 전에 Environment 구성이 준비를 먼저 진행한다.

 

Environment를 세팅하는 작업은 내부적으로 Spring Event를 통해 처리됩니다. Flow를 그리면 아래와 같다.

 

 

1. EventPublishingRunListener에서 SimpleApplicationEventMulticaster를 이용해 ApplicationEnvironmentPreparedEvent 발행.

2. 여러 Event Listeners들이 Event 수신 후 처리

 

ApplicationEnvironmentPreparedEvent를 처리하는 Listeners 들은 많지만, 이번 이슈와 관련된 리스너는 EnvironmentProcessorApplicationListener과 LoggingApplicationListener 이다. 그리고 처리 순서는 EnvironmentPostProcessorApplicationListener가 먼저 실행된다.

 

ApplicationEnvironmentProcessorApplicationListener는 Application Context가 refresh 되기 전에 Environment를 구성한다. 만약 Zookeeper를 연동해 공통 설정 파일의 저장소로 사용하고 있다면, 이 과정에서 Zookeeper와 Environment를 연동하는 작업이 진행된다.

 

LoggingApplicationListener는 Environment에 logging.config 설정이 되어 있다면 해당 설정을 이용해 LoggingSystem을 세팅한다. (쉽게 말하면 application.yaml 파일에 logging.config 값에 있는 로그 설정 파일을 이용해 로그 관련 세팅을 진행한다.)

 

Zookeeper 연동 이슈 관련 로그가 내가 의도한 로그 시스템에 남지 않은 이유는 LoggingApplicationListener가 실행되기 전에 프로그램이 종료됐기 때문이다.

 

해결책 및 시행착오..

시행착오 1

처음 생각난 아이디어는 Listener의 순서를 변경하는 것이였다. 실제로 순서를 변경할 수 있도록 메서드 접근 제어자도 Public으로 열려있다.

ref - https://github.com/spring-projects/spring-boot/issues/2543

ApplicationListeners between ConfigFileApplicationListener and LoggingApplicationListener · Issue #2543 · spring-projects/spri

 

EnvironmentPostProcessorApplicationListener가 LoggingApplicationListener보다 나중에 실행되면 이슈가 해결될까 싶었다.

하지만.. LoggingApplicationListener를 보면 알 수 있듯이 Environment에서 로그 설정 값을 가져온다. 즉, 위 방법은 사용할 수 없다.

 

시행착오 2

그 다음 생각난 아이디어는 Listener들을 비동기로 처리하면 EnvironmentPostProcessorApplicationListener가 수행되다 실패해도 로그가 남지 않을까 싶었다. (1번과 동일한 이유로 애초에 불가능한 해결책이다.)

 

그리고.. Application Context가 Refresh 되기전에 발행되는 Event들을 처리하는 EventPublishingRunListener는 커스터마이징이 불가능하다.

 

--- TMI

 

AbstractApplicationContext의 applicationEventMulticasters는 커스터마이징해 리스너들이 비동기로 처리하게 할 수 있다.

 

protected void initApplicationEventMulticaster() {
        ConfigurableListableBeanFactory beanFactory = this.getBeanFactory();
        if (beanFactory.containsLocalBean("applicationEventMulticaster")) {
            this.applicationEventMulticaster = (ApplicationEventMulticaster)beanFactory.getBean("applicationEventMulticaster", ApplicationEventMulticaster.class);
            if (this.logger.isTraceEnabled()) {
                this.logger.trace("Using ApplicationEventMulticaster [" + this.applicationEventMulticaster + "]");
            }
        } else {
            this.applicationEventMulticaster = new SimpleApplicationEventMulticaster(beanFactory);
            beanFactory.registerSingleton("applicationEventMulticaster", this.applicationEventMulticaster);
            if (this.logger.isTraceEnabled()) {
                this.logger.trace("No 'applicationEventMulticaster' bean, using [" + this.applicationEventMulticaster.getClass().getSimpleName() + "]");
            }
        }
}

 

위 코드를 보면 알 수 있듯이 applicationEventMulticaster를 내가 직접 등록해주면 된다.

 

@Configuration
public class AsyncSpringEventConfig {
	@Bean
	public ApplicationEventMulticaster applicationEventMulticaster() {
		SimpleApplicationEventMulticaster eventMulticaster = new SimpleApplicationEventMulticaster();
		SimpleAsyncTaskExecutor taskExecutor = new SimpleAsyncTaskExecutor("SimpleAsync-Task");
		eventMulticaster.setTaskExecutor(taskExecutor);
		return eventMulticaster;
	}
}

 

해결책

java CLI를 이용해 jar를 실행할때 로그파일을 넘기면 해당 설정이 SpringApplication이 실행되기 전에 로그 설정이 적용된다.

java -Dlog4j.configurationFile={logConfigfile} -jar api.jar

 

(위 처럼 세팅하면 LoggingApplicationListener가 실행되기 전까지 인자로 넘긴 로그 세팅이 사용되다. LoggingApplicationListener가 수행되면 logging.config에 있는 설정 파일로 덮어씌어진다.)