21.11.22 TIL

오늘의 삽질

SQL 로그 파일만들기

스케줄러가 잘 동작했는지 검증할 수 있는 로그 파일을 만들기 위해서 발생한 SQL을 파일로 저장하려고 한다.

logback-spring.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <include resource="org/springframework/boot/logging/logback/base.xml"/>
    <property name="home" value="logs"/>

    <appender name="SCHEDULER_FILE_APPENDER" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${home}/scheduler-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxFileSize>10MB</maxFileSize>
            <maxHistory>30</maxHistory>
        </rollingPolicy>
        <encoder>
            <charset>utf8</charset>
            <pattern>${FILE_LOG_PATTERN}</pattern>
        </encoder>
    </appender>

    <logger name="SCHEDULER_FILE_LOGGER" level="INFO" additivity="true">
        <appender-ref ref="SCHEDULER_FILE_APPENDER"/>
    </logger>

    <logger name="org.hibernate.SQL" level="DEBUG" additivity="false">
        <appender-ref ref="SCHEDULER_FILE_APPENDER"/>
    </logger>
</configuration>

위의 설정을 간단하게 설명하자면
hibernate가 기본적으로 제공하는 로깅 'org.hibernate.SQL' 중에서 DEBUG 이상의 로그들은 SCHEDULER_FILE_APPENDER에 의해서 파일로 써지도록 하는 것이다. (TRACE-DEBUG-INFO-WARN-ERROR)
hibernate.SQL은 기본적으로 DEBUG인데, application.properties에서 레벨을 변경할 수도 있다.

SCHEDULER_FILE_APPENDER에는 사용할 파일의 경로나 로테이션, 제한을 설정할 수 있다.
maxFileSize는 단일 로그 파일의 사이즈 제한이다.
maxHistory는 저장할 파일의 개 수 이다.

SCHEDULER_FILE_LOGGER라는 로거도 추가해놓았는데,

<logger name="SCHEDULER_FILE_LOGGER" level="INFO" additivity="true">
    <appender-ref ref="SCHEDULER_FILE_APPENDER"/>
</logger>

이 로거는 자바 코드에서 발생하는 로그들을 파일에 쓰기 위해서 생성했다.

@Component
@Slf4j(topic = "SCHEDULER_FILE_LOGGER")
@RequiredArgsConstructor
public class SchedulerRunner {

예를들어 SchedulerRunner 클래스에서 위와 같이 해당 로거를 topic으로 지정해두면
이 클래스에서 발생하는 Slf4j 로그들 중에서 level "INFO" 이상의 로그들은 SCHEDULER_FILE_APPENDER에 의해 파일에 써지는 것이다.
ex) log.info("scheduler start")

설정이 끝나고 실행하면 아래와 같이 SQL과 SchedulerRunner 클래스의 INFO 로그가 파일에 저장된다.

scheduler-2021-11-22.0.log

2021-11-22 19:02:00.006  INFO 87485 --- [scheduling-1] SCHEDULER_FILE_LOGGER                    : Habit count for delete: 0
2021-11-22 19:02:59.997 DEBUG 87485 --- [scheduling-1] org.hibernate.SQL                        : 
    select
        habit0_.id as id2_2_0_,
        user1_.id as id1_13_1_,
        habit0_.created_at as created_3_2_0_,
        habit0_.accomplish_counter as accompli4_2_0_,
        habit0_.category as category5_2_0_,
        habit0_.description as descript6_2_0_,
        habit0_.duration_end as duration7_2_0_,
        habit0_.duration_start as duration8_2_0_,
        habit0_.is_accomplish_in_session as is_accom9_2_0_,
        habit0_.n_per_day as n_per_d10_2_0_,
        habit0_.next_practice_day as next_pr11_2_0_,
        habit0_.practice_days as practic12_2_0_,
        habit0_.session_duration as session13_2_0_,
        habit0_.title as title14_2_0_,
        habit0_.user_id as user_id16_2_0_,
        habit0_.whole_days as whole_d15_2_0_,
        habit0_1_.goal_count_in_session as goal_cou1_3_0_,
        habit0_1_.today_counter as today_co2_3_0_,
        habit0_2_.current_duration as current_1_4_0_,
        habit0_2_.goal_duration_time as goal_dur2_4_0_,
        habit0_.dtype as dtype1_2_0_,
        user1_.created_at as created_2_13_1_,
        user1_.disabled as disabled3_13_1_,
        user1_.email as email4_13_1_,
        user1_.monster_id as monster_9_13_1_,
        user1_.monster_code as monster_5_13_1_,
        user1_.provider_type as provider6_13_1_,
        user1_.social_id as social_i7_13_1_,
        user1_.username as username8_13_1_ 
    from
        habit habit0_ 
    left outer join
        habit_with_counter habit0_1_ 
            on habit0_.id=habit0_1_.id 
    left outer join
        habit_with_timer habit0_2_ 
            on habit0_.id=habit0_2_.id 
    inner join
        user user1_ 
            on habit0_.user_id=user1_.id 
    where
        (
            habit0_.practice_days like ?
        ) 
        and habit0_.is_accomplish_in_session=?
2021-11-22 19:02:59.999 DEBUG 87485 --- [scheduling-1] org.hibernate.SQL                        : 
    update
        habit 
    set
        is_accomplish_in_session=0