Spring Boot - Logging, 20분 정리

결론적으로 말하고 싶은건 프로젝트 시작시 Logback 부터 설정하자. 개발의 시작은 Logger 설정부터 아니겠는가?

스프링 부트의 로깅 잔혹사

태초에 스프링은 JCL(Jakarta Commons Logging)을 사용해서 로깅(Logging)을 구현했습니다. 그리고 현재의 스프링 부트의 로그 구현체로 사용된 것 중에서 대표적인 것이 Log4j와 Logback이다. JCL을 사용하면 기본적인 인터페이스인 Log와 Log 객체 생성을 담당하는 LogFactory만 구현하면 얼마든지 다른 로깅 구현체로 교체할 수 있습니다. 마음만 먹으면 본인이 직접 만들수도 있습니다.

스프링 부트에서 로깅 구현체를 선택하는 방법은 백기선님 슬라이드에 매우 자세히 소개하고 있고, 자세한 사항은 JCL의 Configuration를 참고하면 됩니다. 단순하게 말하자면 JCL이 구현체를 선택하는 시점이 런타임이라 클래스 로더에 의존적입니다(요즘에 클래스 로더에 뭔가 하는 일이 거의 없긴 하지만 JDK 9에서 변화가 많아졌으니 Nicolai Parlog의 기사를 참고해서 필요하다면 더 찾아보길 권장).

JCL의 문제를 한마디로 퉁치면 "가비지 컬렉션"이 제대로 작동하지 않는 치명적인 문제가 발생합니다. 문제 해결을 위해서 클래스 로더 대신에 컴파일 시점에 구현체를 선택하도록 변경됩니다. 이 때 도입되는 것이 SLF4J입니다.

SLF4J에서는 Bridging, API, Binding 모듈을 제공하여 컴파일 시점에 로깅 구현체를 결정합니다. 스프링 부트에선 Logback이 기본으로 선택되어 있으니 JCL의 긴 여정의 끝에는 Logback이 있는 것입니다.

.. If we could turn back the clock and start Spring now as a new project it would use a different logging dependency. Logging Dependencies in Spring 중..

Logback 사용법

일단 로깅이 뭔지 구경부터 하고 시작해보죠. LogService를 하나 만들어서, /log URL에 GET 메소드에 연결하겠습니다.

//LogService.java
@Service
public class LogService {
    private final Logger logger = LoggerFactory.getLogger(this.getClass().getSimpleName());

    public void log() {
        logger.trace("Trace");
        logger.debug("Debug");
        logger.info("Info");
        logger.warn("Warn");
        logger.error("Error");
    }
}

로그를 확인하는게 목적이라 @RestController를 사용해서 GET 메소드에 필요한 메서드를 연결하겠습니다.

@RestController
@SpringBootApplication
public class LogApplication {

    @Autowired
    private LogService logService;

    public static void main(String[] args) {
        SpringApplication.run(LogApplication.class, args);
    }

    @GetMapping("/log")
    public String getLogger() {
        logService.log();
        return "console log";
    }
}

curl localhost:8080/log로 GET 메소드를 호출하면 콘솔창 아래와 같은 형태로 로그가 출력됩니다. 아래 내용을 통해서 유추할 수 있는 것은 로그 수준은 INFO(trace > debug > info > warn > error) 레벨이며, 별다른 설정을 하지 않아도 로그를 사용할 수 있습니다.

2019-03-15 11:23:54.800  INFO 10216 --- [nio-8080-exec-1] LogService                               : Info
2019-03-15 11:23:54.800 ERROR 10216 --- [nio-8080-exec-1] LogService                               : Error
2019-03-15 11:23:54.800  WARN 10216 --- [nio-8080-exec-1] LogService                               : Warn

logback-spring.xml

내가 로그를 사용하는 대부분의 이유는 두 가지로 요약되는데, 1) 에러나 장애가 발생할 때 해당 내용을 재현하기 위한 기초 자료로 사용하기 위함이며 2) 사용자 로그의 경우 분석 데이터로 활용하기 위해서 입니다. 따라서 콘솔에서 출력되는 로그는 로그 수준을 높이거나 낮추는데 그 목적이 있고, 에러나 장애 혹은 로그 분석을 위해선 로그를 파일에 저장하는데 그 목적이 있습니다.

콘솔 로그의 수준을 변경하는 방법은 application.yml에서 로깅 수준을 설정하는 방법이 있습니다. 개발 환경에서 콘솔에서 출력되는 내용을 조절하는 방법으로 적당합니다. 하지만 실제 제품에서 사용하기엔 한계가 있고 세부적인 설정이 불편하기 때문에 개인적으론 logback-spring.xml을 별도로 만들어서 로그를 관리합니다.

개발시 콘솔에 출력되는 로깅 수준을 간단하게 관리하고자 한다면 아래와 같이 간단한 설정을 통해서 손쉽게 변경할 수 있습니다. 물론 파일에 저장하거나 콘솔에 출력 문자의 양식을 변경하는 것도 가능합니다.

// application.yml
logging:
  level:
    org.springframework: INFO
    org.springframework.web: DEBUG

logback-spring.xml은 appender와 logger로 나눌 수 있습니다. appender는 콘솔, 파일, DB 등 로그를 출력하는 방법을 지정할 수 있으며, logger는 출력할 곳을 설정합니다. 아래 예제는 매우 단순한 형태로 실제 업무에선 FILE 뿐만 아니라 SocketAppender나 LogStash 등도 함께 설정해서 사용할 수 있습니다.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <property name="LOGS_ABSOLUTE_PATH" value="./logs" />

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

    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOGS_ABSOLUTE_PATH}/logback.log</file>
        <encoder>
            <pattern>[%d{yyyy-MM-dd HH:mm:ss}:%-3relative][%thread] %-5level %logger{35} - %msg%n</pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOGS_ABSOLUTE_PATH}/logback.%d{yyyy-MM-dd}.%i.log.gz</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <maxFileSize>5MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
    </appender>

    <root level="INFO">
        <appender-ref ref="STDOUT" />
    </root>

    <logger name="org.springframework.web" level="DEBUG">
        <appender-ref ref="STDOUT" />
        <appender-ref ref="FILE" />
    </logger>
</configuration>

해당 로그를 설정하면 아래와 같은 결과를 콘솔과 파일을 통해서 확인할 수 있습니다.

// 콘솔에 출력되는 내용
14:04:17.480 [http-nio-8080-exec-1] INFO  LogService - Info
14:04:17.480 [http-nio-8080-exec-1] WARN  LogService - Warn
14:04:17.480 [http-nio-8080-exec-1] ERROR LogService - Error

// 파일에 출력되는 내용
[2019-03-15 15:36:59:14554][http-nio-8080-exec-1] DEBUG o.s.w.s.m.m.a.RequestMappingHandlerMapping - Mapped to public java.lang.String com.sangkon.log.LogApplication.getLogger()
[2019-03-15 15:36:59:14571][http-nio-8080-exec-1] DEBUG o.s.w.s.m.m.a.RequestResponseBodyMethodProcessor - Using 'text/plain', given [*/*] and supported [text/plain, */*, text/plain, */*, application/json, application/*+json, application/json, application/*+json]
[2019-03-15 15:36:59:14572][http-nio-8080-exec-1] DEBUG o.s.w.s.m.m.a.RequestResponseBodyMethodProcessor - Writing ["console log"]
[2019-03-15 15:36:59:14579][http-nio-8080-exec-1] DEBUG o.s.web.servlet.DispatcherServlet - Completed 200 OK

배포환경에 맞게 로그를 설정하고 싶다면 (Spring Boot)Logging과 Profile 전략를 참고해서 자신의 배포환경에 맞게 수정해서 사용하세요.