Backend
Last updated on

[Spring Boot] log4j2 설정과 Hibernate SQL·파라미터 로깅


Spring Boot의 기본 로거를 log4j2로 바꾸고, Hibernate가 실행하는 SQL과 바인딩 값을 로그로 확인하도록 설정한 내용을 정리한다.

작성 당시 환경은 다음과 같다. 최신 버전에서 달라진 부분은 글 마지막에 따로 정리했다.

항목 버전
Spring Boot 2.7.x
Hibernate 5.6.x
log4j2 2.17.x (Spring Boot 관리 버전)

Spring Boot의 로깅 구조

Spring Boot 애플리케이션 코드는 보통 SLF4J라는 로깅 API를 통해 로그를 남긴다. SLF4J는 인터페이스일 뿐이고, 실제로 로그를 출력하는 구현체는 따로 있다.

애플리케이션 코드 (log.info(...))
        │
        ▼
     SLF4J (API)
        │
        ▼
 Logback  또는  Log4j2  (구현체)

spring-boot-starter-web 등에 포함된 spring-boot-starter-logging이 기본 구현체로 Logback을 가져온다. log4j2를 쓰려면 Logback을 빼고 log4j2 스타터를 넣어야 한다. 구현체만 바뀌므로 log.info(...) 같은 애플리케이션 코드는 수정할 필요가 없다.

log4j2를 선택하는 이유로는 다음이 자주 꼽힌다.

  • 비동기 로거(Async Logger) — 로그 출력을 별도 스레드에서 처리해, 로그가 많은 환경에서 처리량이 높다.
  • 설정 자동 재적용 — monitorInterval을 지정하면 서버를 재시작하지 않아도 설정 파일 변경을 반영한다.
  • 풍부한 롤링·삭제 정책 — 파일 크기·날짜 기준 분할과 오래된 로그 자동 삭제를 설정만으로 처리한다.

1. 의존성 설정

// 기본 로거(Logback)와 충돌하지 않도록 모든 설정에서 제외
configurations {
    all {
        exclude group: 'org.springframework.boot', module: 'spring-boot-starter-logging'
    }
}

dependencies {
    implementation 'org.springframework.boot:spring-boot-starter-log4j2'
}

exclude를 빼먹으면 클래스패스에 Logback과 log4j2가 함께 올라가, 실행 시 SLF4J가 구현체를 여러 개 발견했다는 경고(Class path contains multiple SLF4J bindings)가 나오거나 의도하지 않은 구현체가 선택된다.

Log4Shell 주의 — 2021년 12월 log4j2에서 원격 코드 실행 취약점(CVE-2021-44228)이 발견됐다. 관련 후속 취약점까지 모두 수정된 버전은 2.17.1 이상이다. 버전을 직접 지정하지 말고 Spring Boot가 관리하는 버전을 쓰되, 아래 명령으로 실제 버전을 확인해 두는 것이 좋다.

./gradlew dependencies --configuration runtimeClasspath | grep log4j-core

2. log4j2.xml 작성

src/main/resources/log4j2.xml에 두면 Spring Boot가 자동으로 읽는다.

<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="warn" monitorInterval="5">
    <Properties>
        <Property name="logFileName">log</Property>
        <Property name="consoleLayout">[%d{yyyy-MM-dd HH:mm:ss}] [%-5p] [%c{1}:%L] - %m%n</Property>
        <Property name="fileLayout">%d [%t] %-5level %c(%M:%L) - %m%n</Property>
    </Properties>

    <Appenders>
        <Console name="console" target="SYSTEM_OUT">
            <PatternLayout pattern="${consoleLayout}" />
        </Console>

        <RollingFile name="file"
                     fileName="logs/${logFileName}.log"
                     filePattern="logs/${logFileName}.%d{yyyy-MM-dd}.%i.log">
            <PatternLayout pattern="${fileLayout}" />
            <Policies>
                <SizeBasedTriggeringPolicy size="20 MB" />
                <TimeBasedTriggeringPolicy interval="1" />
            </Policies>
            <DefaultRolloverStrategy max="5" fileIndex="max">
                <Delete basePath="logs" maxDepth="1">
                    <IfFileName glob="${logFileName}.*.log" />
                    <IfLastModified age="10d" />
                </Delete>
            </DefaultRolloverStrategy>
        </RollingFile>
    </Appenders>

    <!-- TRACE < DEBUG < INFO < WARN < ERROR < FATAL -->
    <Loggers>
        <Logger name="org.springframework" level="INFO" additivity="false">
            <AppenderRef ref="console" />
        </Logger>

        <!-- 실행되는 SQL -->
        <Logger name="org.hibernate.SQL" level="DEBUG" additivity="false">
            <AppenderRef ref="console" />
        </Logger>

        <!-- SQL에 바인딩되는 파라미터 값 -->
        <Logger name="org.hibernate.type.descriptor.sql.BasicBinder" level="TRACE" additivity="false">
            <AppenderRef ref="console" />
        </Logger>

        <!-- 조회 결과에서 읽어온 값 (필요할 때만) -->
        <Logger name="org.hibernate.type.descriptor.sql.BasicExtractor" level="TRACE" additivity="false">
            <AppenderRef ref="console" />
        </Logger>

        <Root level="ERROR">
            <AppenderRef ref="console" />
            <AppenderRef ref="file" />
        </Root>
    </Loggers>
</Configuration>

처음 작성했던 설정에서 바꾼 부분은 다음과 같다.

항목 처음 설정 변경 이유
status debug warn log4j2 자체의 내부 동작 로그가 시작할 때마다 대량으로 출력된다.
filePattern %d{yyyy-MM-dd} %d{yyyy-MM-dd}.%i 하루에 20MB를 넘겨 여러 번 분할되면, 같은 날짜 파일명이 겹쳐 이전 파일을 덮어쓴다. %i로 번호를 붙인다.
Delete basePath /logs logs /logs는 루트 디렉터리 아래의 절대 경로다. 로그는 실행 위치 기준 상대 경로 logs/에 쌓이므로 삭제가 동작하지 않았다.
IfFileName 없음 추가 같은 디렉터리의 다른 파일이 지워지지 않도록 삭제 대상을 로그 파일로 한정한다.

구조 살펴보기

log4j2 설정은 크게 **어디에 어떤 형식으로 쓸지(Appender)**와 **어떤 로그를 쓸지(Logger)**로 나뉜다.

Properties

설정 안에서 반복해 쓸 값을 변수로 정의한다. ${consoleLayout}처럼 참조한다.

Appenders — 출력 대상

Appender 역할
Console 표준 출력(콘솔)에 쓴다.
RollingFile 파일에 쓰고, 조건이 되면 파일을 분할(롤링)한다.

RollingFile의 동작은 세 가지 설정으로 정해진다.

  • Policies — 언제 새 파일로 넘길지. 여기서는 파일이 20MB를 넘거나(SizeBasedTriggeringPolicy), 날짜가 바뀌면(TimeBasedTriggeringPolicy) 분할한다. TimeBasedTriggeringPolicy의 interval="1"은 filePattern 날짜 형식의 가장 작은 단위 기준이다. yyyy-MM-dd이면 하루, yyyy-MM-dd-HH이면 한 시간마다 분할된다.
  • filePattern — 분할된 파일의 이름. 쓰는 중인 파일은 항상 log.log이고, 분할되면 log.2022-10-25.1.log처럼 이름이 바뀌어 보관된다.
  • DefaultRolloverStrategy — 보관 정책. max="5"는 같은 날짜에 번호(%i)를 최대 5개까지 유지한다는 뜻이고, Delete는 10일이 지난 로그 파일을 삭제한다.
logs/
├── log.log                  ← 현재 쓰는 중
├── log.2022-10-25.1.log
├── log.2022-10-25.2.log     ← 같은 날 20MB를 넘겨 한 번 더 분할
└── log.2022-10-24.1.log

PatternLayout — 출력 형식

consoleLayout에 쓴 패턴의 의미는 다음과 같다.

패턴 의미 출력 예
%d{yyyy-MM-dd HH:mm:ss} 시각 2022-10-25 11:02:53
%-5p 로그 레벨 (5칸 왼쪽 정렬) TRACE, INFO
%c{1} 로거 이름의 마지막 한 단계 BasicBinder
%L 소스 코드 줄 번호 64
%m 메시지 binding parameter [1] ...
%n 줄바꿈
%t 스레드 이름 (fileLayout) http-nio-8080-exec-1
%M 메서드 이름 (fileLayout) bind

%L, %M은 호출 위치를 알아내는 비용이 커서 로그가 많은 운영 환경에서는 빼는 경우가 많다.

Loggers — 무엇을 남길지

Logger는 로거 이름(보통 패키지·클래스 이름)별로 레벨과 출력 대상을 지정한다. 이름은 계층 구조라서 org.hibernate에 설정하면 org.hibernate.SQL에도 적용된다. 아무 Logger에도 해당하지 않는 로그는 Root 설정을 따른다.

레벨은 TRACE < DEBUG < INFO < WARN < ERROR < FATAL 순이며, 지정한 레벨 이상만 출력된다. 위 설정에서 Root가 ERROR이므로 따로 지정하지 않은 로거는 에러만 남긴다.

additivity

로그는 기본적으로 자신의 Logger에서 출력된 뒤 부모 Logger(최종적으로 Root)에도 전달된다. 이를 additivity라 한다.

<Logger name="org.hibernate.SQL" level="DEBUG">  <!-- additivity 기본값 true -->
    <AppenderRef ref="console" />
</Logger>

이렇게 두면 SQL 로그가 자기 Logger의 console과 Root의 console, file로 한 번씩 더 전달되어, 콘솔에 같은 로그가 두 번 찍힌다. additivity="false"로 부모에게 전달하지 않도록 해서 중복을 막는다.


3. Hibernate SQL 로깅 설정

# application.properties
spring.jpa.properties.hibernate.format_sql=true
spring.jpa.properties.hibernate.highlight_sql=true
설정 역할
format_sql SQL을 줄바꿈·들여쓰기해서 출력한다.
highlight_sql SQL 키워드에 ANSI 색상을 입혀 출력한다.

로그 레벨은 앞의 log4j2.xml에서 지정했다. 처음에는 application.properties에도 아래 설정을 함께 넣었었다.

logging.level.org.hibernate.SQL=debug
logging.level.org.hibernate.type=trace

Spring Boot는 logging.level.* 값을 log4j2에도 적용하기 때문에 이렇게 하면 같은 설정이 두 곳에 생기고, 어느 쪽이 적용되는지 헷갈린다. 레벨 설정은 log4j2.xml 한 곳에 모으는 편이 관리하기 쉽다.

spring.jpa.show-sql=true로도 SQL을 볼 수 있지만, 이 옵션은 로거가 아니라 System.out으로 직접 출력한다. 레벨 조절이나 파일 저장이 안 되므로 로거 방식(org.hibernate.SQL)을 쓰는 것이 낫다.

로거별 출력 내용

로거 레벨 출력 내용
org.hibernate.SQL DEBUG 실행되는 SQL (? 포함)
org.hibernate.type.descriptor.sql.BasicBinder TRACE ?에 바인딩되는 값
org.hibernate.type.descriptor.sql.BasicExtractor TRACE 조회 결과 컬럼 값

BasicExtractor는 조회한 행의 모든 컬럼 값을 출력하므로 로그 양이 매우 많아진다. 필요할 때만 켠다.


실행 결과

SQL

format_sql로 정렬되고 highlight_sql로 색이 입혀져 출력된다.

format_sql, highlight_sql이 적용된 SQL 로그

바인딩 파라미터

SQL의 ? 순서대로 어떤 타입의 어떤 값이 들어갔는지 출력된다. 실제 값은 as [VARCHAR] - [kim]처럼 타입 뒤에 표시된다.

BasicBinder의 파라미터 바인딩 로그


Spring Boot 3 / Hibernate 6에서 달라진 점

바인딩·조회 값 로거 이름 변경

Hibernate 6에서 타입 시스템이 바뀌면서 BasicBinder, BasicExtractor 로거가 사라졌다. 대신 다음 로거를 사용한다.

용도 Hibernate 5 Hibernate 6
실행 SQL org.hibernate.SQL org.hibernate.SQL (동일)
바인딩 값 org.hibernate.type.descriptor.sql.BasicBinder org.hibernate.orm.jdbc.bind
조회 값 org.hibernate.type.descriptor.sql.BasicExtractor org.hibernate.orm.jdbc.extract
<Logger name="org.hibernate.orm.jdbc.bind" level="TRACE" additivity="false">
    <AppenderRef ref="console" />
</Logger>

Spring Boot 3로 올린 뒤 바인딩 값이 안 보인다면 대부분 이 로거 이름 때문이다.

그 외

  • spring-boot-starter-log4j2와 Logback 제외 방법은 동일하다.
  • format_sql, highlight_sql 설정도 그대로 쓸 수 있다.

참고