[Spring Boot] 프로젝트 템플릿 만들기(3) - 로깅

실무에서 디버깅을 수행할 때, 로그의 가독성이 디버깅 시간에 큰 영향을 준다는 것을 알게 되었다.

 

자주 접하게 되는 로그는 3종류가 있었다.

 

1. Spring boot 서버의 시스템 로그 (logback 이용)

2. 디버깅 용으로 서버 소스 내에 붙여서 값을 확인하는 용도의 함수 (ex. system.out.println("~~~")

3. DB 로그

 

3 종류의 로깅 설정을 모두 진행해보고, 좀 더 나은 가독성의 로그를 남겨 디버깅이 용이할 수 있도록 설정을 직접 진행해보았다.

 

4. API 호출별 로그 가독성을 높이기 위한 메서드 실행정보 로그

 

추가적으로 API 호출 별로 로그 단락이 구분되어야 파악이 쉬울거라는 판단이 들었고, AOP를 이용하여 각 메서드 실행 시 URL 호출 정보가 남도록 설정을 진행했다.

 

---

Logback

logback은 log4j의 후속버전으로 logging 대표적인 라이브러리이며, Spring-boot-starter 내에 포함되어 있다.

 

implementation 'org.springframework.boot:spring-boot-starter'

 

 

 

starter 내부에 slf4j 도 포함되어 있으므로, 별도의 추가없이 Slf4j 를 사용할 수 있다.

 

 

logback-spring.xml

세부 설정을 위해서 resources 폴더 내부에 logback-spring.xml 파일을 생성한다.

 

<!-- 로그백 설정 프로필을 선택한다 (최상위)-->
<configuration scan="true" scanPeriod="60 seconds">
    <springProfile name="local">
        <property resource="logback/logback-local.properties"/>
    </springProfile>
    <springProfile name="dev">
        <property resource="logback/logback-dev.properties"/>
    </springProfile>
    <springProfile name="prod">
        <property resource="logback/logback-prod.properties"/>
    </springProfile>

    <!--Environment 내의 프로퍼티들을 개별적으로 설정할 수도 있다.-->
    <springProperty scope="context" name="LOG_LEVEL" source="logging.level.root"/>

    <!-- log file path -->
    <property name="LOG_PATH" value="${log.config.path}"/>
    <!-- log file name -->
    <property name="LOG_FILE_NAME" value="${log.config.filename}"/>
    <!-- err log file name -->
    <property name="ERR_LOG_FILE_NAME" value="${log.config.errorfilename}"/>
    <!-- pattern -->
    <property name="LOG_PATTERN" value="%boldMagenta(%-5level) [%boldYellow(%d{yy-MM-dd HH:mm:ss})] [%cyan(%thread)] [%logger{0}:%line] - %msg%n"/>

    <!-- console log -->
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <!-- 위에 PROPERTY로 정의한 LOG_PATTERN 가져다 사용하기 -->
            <pattern>${LOG_PATTERN}</pattern>
        </encoder>
    </appender>

    <!-- File Appender -->
    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">

        <!-- 파일경로 설정 -->
        <file>${LOG_PATH}/${LOG_FILE_NAME}.log</file>

        <!-- 출력패턴 설정-->
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>${LOG_PATTERN}</pattern>
        </encoder>

        <!-- Rolling 정책 -->
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">

            <!-- 로그 파일을 압축 하고싶다면 .log 대신 .zip이나 .gz을 끝에 붙이면 된다 -->
            <fileNamePattern>${LOG_PATH}/${LOG_FILE_NAME}.%d{yyyy-MM-dd}_%i.zip</fileNamePattern>

            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <!-- 파일당 최대 용량 kb, mb, gb -->
                <maxFileSize>10MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>

            <!-- 일자별 로그파일 최대 보관주기(~일), 해당 설정일 이상된 파일은 자동으로 제거-->
            <maxHistory>30</maxHistory>

            <!--10개가 넘어가면 오래된순으로 덮어쓰여진다-->
            <MinIndex>1</MinIndex>
            <MaxIndex>10</MaxIndex>

        </rollingPolicy>
    </appender>

    <!-- 에러의 경우 파일에 로그 처리 -->
    <appender name="ERROR" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>error</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
        <file>${LOG_PATH}/${ERR_LOG_FILE_NAME}.log</file>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>${LOG_PATTERN}</pattern>
        </encoder>
        <!-- Rolling 정책 -->
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- .gz,.zip 등을 넣으면 자동 일자별 로그파일 압축 -->
            <fileNamePattern>${LOG_PATH}/${ERR_LOG_FILE_NAME}.%d{yyyy-MM-dd}_%i.log</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <!-- 파일당 최고 용량 kb, mb, gb -->
                <maxFileSize>10MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
            <!-- 일자별 로그파일 최대 보관주기(~일), 해당 설정일 이상된 파일은 자동으로 제거-->
            <maxHistory>60</maxHistory>
        </rollingPolicy>
    </appender>

    <root level="${LOG_LEVEL}">
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="FILE"/>
        <appender-ref ref="ERROR"/>
    </root>
</configuration>

 

아래 콘솔 log 설정 부분에서 로그 패턴을 지정할 수 있다.

각 단락별 색상 설정이 가능하므로 좀 더 가독성 높은 로그를 출력할 수 있다.

<property name="LOG_PATTERN" value="%boldMagenta(%-5level) [%boldYellow(%d{yy-MM-dd HH:mm:ss})] [%cyan(%thread)] [%logger{0}:%line] - %msg%n"/>

	<!-- console log -->
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <!-- 위에 PROPERTY로 정의한 LOG_PATTERN 가져다 사용하기 -->
            <pattern>${LOG_PATTERN}</pattern>
        </encoder>
    </appender>

 

<root level="${LOG_LEVEL}">
    <appender-ref ref="CONSOLE"/>
    <appender-ref ref="FILE"/>
    <appender-ref ref="ERROR"/>
</root>

구현할 기능 별로 Appender를 구성하고, 각 레벨 별로 Appender를 참조하도록 설정한다.

 

정리하면, Spring Boot  서버에서 생성되는 로그들의 포맷을 지정하고 파일로도 저장할 수 있도록 전체적인 설정을 진행하는 작업이라고 할 수 있다.

 

---

Log.class

에러 로그나, 프론트에서 받은 json을 직접 콘솔을 통해 확인하기 위해서 log.info() 함수를 코드마다 매 번 작성하는 번거로움이 있었다. 따라서, 전역에서 편리하게 메시지를 출력할 수 있도록 함수화를 진행했다.

@Slf4j
public class Log {

    private static final ObjectMapper objectMapper = new ObjectMapper().registerModule(new JavaTimeModule());
    private static final ObjectWriter prettyPrinter = objectMapper.writerWithDefaultPrettyPrinter();

    private static final Logger logger = Logger.getLogger(Log.class.getName());

    private Log() {}

    // 원하는 로그 스타일이 있을 때 마다 추가하여 사용한다.
    public static <T> void objectInfo(T object) {
        try {
            String jsonString = prettyPrinter.writeValueAsString(object);
            log.info("=============================================================");
            log.info("{} as json\n{}", object.getClass().getSimpleName(), jsonString);
            log.info("=============================================================");
        } catch (JsonProcessingException e) {
            log.error("Error converting object to json", e);
        }
    }

    public static void varLog(String key, String value){
        log.info("=============================================================");
        log.info("{} : {}", key, value);
        log.info("=============================================================");
    }

    public static void createBackupLog(File logDir){
        // /home/user/AI_TASK/001.EMI/result/log/
        String pattern = ".*_backup\\.log";

        try{
            File[] files = logDir.listFiles();

            // for문 먼저 돌려서 로그파일, 백업로그 파일 명 가져올 것.
            if (files != null) {
                // 기존 백업파일 삭제
                for (File file : files) {
                    if (file.isFile() && file.getName().matches(pattern)) {
                        if (file.delete()) {
                            log.info("삭제된 파일 : " + file.getAbsolutePath());
                        } else {
                            log.info("삭제 실패한 파일 : " + file.getAbsolutePath());
                        }
                    }
                }
            }

            if (files != null) {
                // 기존 로그파일 백업파일로 변경
                for(File file : files){
                    if(file.exists()){
                        String oldFileName = file.getName();

                        int dotIndex = oldFileName.lastIndexOf('.');
                        String fileNameWithoutExtension = oldFileName.substring(0, dotIndex);
                        String fileExtension = oldFileName.substring(dotIndex);

                        String newFileName = String.format("%s/%s"
                                                    ,logDir.getAbsolutePath()
                                                    ,fileNameWithoutExtension + "_backup" + fileExtension);

                        // 새로운 파일명 생성
                        File newFile = new File(newFileName);

                        if(file.renameTo(newFile)){
                            log.info("변경된 파일명 : " + file.getName());
                        }else {
                            log.info("변경 실패한 파일 : " + file.getAbsolutePath());
                        }
                    } else{
                        log.info("변경할 로그파일이 존재하지 않습니다.");
                    }
                }
            }
        }catch (Exception e){
            e.printStackTrace();
        }
    }
}

 

objectInfo() 출력 결과

클라이언트에게 받아온 Body의 값을 DTO로 매핑했을 때, 각 DTO 클래스의 값을 json으로 파싱하여 바로 출력할 수 있다. 

 

Json 변환을 위해서 아래와 같은 라이브러리가 필요하므로 build.gradle에 추가하면 된다.

// Object Converting to Json
implementation 'com.fasterxml.jackson.datatype:jackson-datatype-jsr310'

 

 

varlog() 출력 결과

Log.varLog("email", request.getEmail());

 

varlog() 함수는 문자열 형식의 객체를 고정 형식에 따라 출력할 수 있도록 설정했다.

 

 

---

LoggingAspect.class

Spring AOP를 사용하여, Controller가 호출될 때마다 실행되어 서버 로그 단에서 단락을 구분할 수 있도록 설정을 진행했다.

@Aspect
@Component
public class LoggingAspect {
    private final Logger logger = LoggerFactory.getLogger(LoggingAspect.class);

    @Before("execution(* com.twin.ai_backend..controller.*.*(..))")
    public void logBeforeControllerMethods(JoinPoint joinPoint) {
        String methodName = joinPoint.getSignature().getName();
        String className = joinPoint.getTarget().getClass().getName();
        String url = ((ServletRequestAttributes) RequestContextHolder.currentRequestAttributes()).getRequest().getRequestURI();

        logger.info("=======================================");
        logger.info("URL accessed: {} | Class: {} | Method: {}", url, className, methodName);
        logger.info("=======================================");
    }
}

 

너무 많은 정보를 담으면 내용이 비대해질 것 같아 어떤 URL 을 호출했고, 대상 함수가 어디인지 정도만 파악할 수 있도록 했다.

 

출력 결과

 

 

---

P6SpyFormatter.class

 

쿼리 로그를 좀더 가독성 있게 출력하기 위해서 p6spy를 사용했다.

 

build.gradle

// p6spy : QueryLog
implementation 'com.github.gavlyukovskiy:p6spy-spring-boot-starter:1.9.0'

 

 

Configuration 클래스를 생성하여 설정 값을 입력했다.

@Configuration
public class P6SpyFormatter implements MessageFormattingStrategy {

    @PostConstruct
    public void setLogMessageFormat() {
        P6SpyOptions.getActiveInstance().setLogMessageFormat(this.getClass().getName());
    }

    @Override
    public String formatMessage(int connectionId, String now, long elapsed, String category, String prepared, String sql, String url) {
        StringBuilder sb = new StringBuilder();
        sb.append(category).append(" ").append(elapsed).append("ms").append("\n");
        sb.append("====================================================================");
        if (StringUtils.hasText(sql)) {
            sb.append(highlight(format(sql))).append("\n");
        }
        sb.append("======================================================================").append("\n");
        return sb.toString();
    }

    private String format(String sql) {
        if (isDDL(sql)) {
            return FormatStyle.DDL.getFormatter().format(sql);
        } else if (isBasic(sql)) {
            return FormatStyle.BASIC.getFormatter().format(sql);
        }
        return sql;
    }

    private String highlight(String sql) {
        return FormatStyle.HIGHLIGHT.getFormatter().format(sql);
    }

    private boolean isDDL(String sql) {
        return sql.startsWith("create") || sql.startsWith("alter") || sql.startsWith("comment");
    }

    private boolean isBasic(String sql) {
        return sql.startsWith("select") || sql.startsWith("insert") || sql.startsWith("update") || sql.startsWith("deleteEmitter");
    }
}

 

sb.append(category).append(" ").append(elapsed).append("ms").append("\n");

각 항목에서 변수가 의미하는 바는 다음과 같다

 

- category : SQL 카테고리 (ex. statement, resultset)

- elapsed : SQL 실행에 걸린 시간

- sql : 실제 실행된 쿼리

 

각 쿼리를 DDL인지, DML인지 구분하여 포맷팅하며, 각 단락별로 HIGHLIGHT를 주어 가독성을 높이도록 설정했다.

 

출력 결과