로그만 보고 @SpringBootApplication을 따라가보자

@SpringBootApplication을 사용하나 어플리케이션이 어떻게 돌아가는지 알지 못하는 개발 어린이 박세환입니다.

오늘은 @SpringBootApplication 실행시 어떤 로그들을 남기는지 순서대로 따라가면서 Spring Boot Application의 동작 과정을 이해해보는 시간을 가져보겠습니다.

준비물

1. Spring boot Initializr로 기본 Spring Boot 프로젝트 생성

2. 실행

이게.. 끝? 뭔가 이상합니다. logback.xml을 설정해 log level을 Trace로 수정합니다.

3. logback.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="30 seconds">

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <layout class="ch.qos.logback.classic.PatternLayout">
            <Pattern>%d{HH:mm:ss.SSS} [%thread] %-5level %logger{36} - %msg%n</Pattern>
        </layout>
    </appender>

    <root level = "trace"> <!-- 로그를 따라가 보기 위해 trace 레벨로 설정 -->
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

시작. logback 구성

시작하자마자 logback.xml이 아닌 logback-test.xml과 logback.groovy를 탐색하고 찾지 못하니 후순위로 logback.xml을 찾는것을 볼 수 있습니다.

logback.xml-> logback-test.xml로 한 번 바꿔보겠습니다.

바로 찾아서 logback을 구성하는 것을 로그를 통해 확인하실 수 있습니다. 하지만 바로 아래 문구가 제 의문을 자극합니다.

This appender no longer admits a layout as a sub-component, set an encoder instead.

appender에서는 더이상 Layout에 대해 sub-component로 인정하지 않으니 encoder로 바꾸라는 로그입니다. 하라는대로 수정합니다.

PropertySourcesPropertyResolver 설정값 탐색

어플리케이션 재실행시 맨 처음 나왔던 로그들이 보이지 않는것을 볼 수 있습니다.
하지만 또다른 로그들이 다시 반겨주는걸 볼 수 있습니다. 로그를 확인해 보겠습니다.

PropertySourcesPropertyResolver에서는 다음 값들을 확인 중이었습니다.

PropertySourcesPropertyResolver가 찾는 Key List

• logging.register-shutdown-hook
• context.listener.classes
• spring.beaninfo.ignore
• spring.banner.image.location
• spring.banner.location
• spring.profiles.active
• spring.profiles.default

Key List를 찾는 PropertySource 목록

• configurationProperties
• systemProperties
• systemEnvironment
• random

그렇다면 과연 PropertySourcesPropertyResolver는 무엇을 하는 클래스일까요?

• PropertySourcesPropertyResolver Definition
• Github PropertySourcesPropertyResolver.java code

로직 중 logger.isTraceEnabled() 가 눈에 띕니다. 우리는 log level을 trace로 적용했기에 다음과 같은 로그가 추가로 남은 것으로 확인되어집니다.

Application 실행 시작

위의 PropertySourcesPropertyResolver가 열심히 설정값을 찾는 도중에 어플리케이션이 뜨고 실행환경, PID, 사용하고 있는 Spring Boot 및 Spring 버전을 확인할 수 있습니다.

모든 설정값을 확인하는 것이 끝나면 Application이 source를 로딩하기 시작합니다.

Application 설정 파일 탐색

로딩 이후 어플리케이션은 애타게 설정 파일을 찾습니다. 대표적으로는 yml, yaml, properties 가 있으며 아래의 우선순위로 해당 파일이 있는지 검사합니다.

확인 순서 (번호 - 우선순위)

• 1. 확장자
  • 1. application.properties
  • 2. application.xml
  • 3. application.yml
  • 4. application.yaml
• 2. 경로
  • 1. ./config
  • 2. ./
  • 3. /config
• 3. 종류
  • 1. file
  • 2. classpath

다음 순서로 application 설정값을 필요할때마다 찾는 것을 확인하실 수 있습니다.
application 설정값을 찾다보면 어느새 난잡한 부분에 와계실 겁니다.

Component Scan

profile 설정이 없음을 확인하고 default로 설정을 진행하여 source를 로딩합니다.
로딩과 동시에 ClassPathBeanDefinitionScanner가 component scanning을 진행하며
@Component 어노테이션이 붙은 대상들을 @Bean으로 생성하기 시작합니다.

internalConfigurationAnnotationProcessor Bean 생성

세부 로그를 하나하나 천천히 보다보면 해당 부분은 Bean 생성과 밀접한 연관이 있는 부분이라는 것을 알 수 있습니다.
해당 부분의 키워드는 'Bean, Configuration이며 한 번씩 로그 창에서 키워드 검색을 통해 확인해보시면 더 직관적으로 알 수 있습니다.

마지막 로그를 보시면 다음과 같습니다.

Finished creating instance of bean 'org.springframework.context.annotation.internalConfigurationAnnotationProcessor'

이를 통해 어플리케이션에서는 internalConfigurationAnnotationProcessor에서 정의한 Bean들을 가장 먼저 생성한다는 것을 알 수 있습니다.

다음 로그를 보시면 internalConfigurationAnnotationProcessor에서 정의한 Bean 생성이 마무리되면 enableautoconfiguration을 시작하는것을 알 수 있습니다.

Report

모든 구성이 마무리되면 Spring Boot Application은 Report를 작성해 개발자에게 어떤 내용이 구성이 됐고 어떤 부분이 구성 실패됐는지 공유해줍니다.

Application 실행 (JVM Run)

모든게 마무리되면 다음과 같이 JVM에서 실행되는 것을 알 수 있습니다.

결론

로그만 봐서는 @SpringBootApplication에 대해 깊이 알 수 없음을 깨달았습니다.

무슨 소린지 모르겠는 내용들의 연속이었지만 대략적인 실행 순서는 알 수 있었습니다.

• 1. logback 구성
• 2. 설정값 탐색
• 3. application 시작
• 4. component scan
• 5. Autoconfiguration 등록
• 6. 구성 결과 Report 공유
• 7. Application 실행 (JVM Run)

다음에는 구체적으로 Application 동작 과정에 대해 알아보는 시간을 가져보겠습니다.

감사합니다.