스프링 로깅 기능 구현하기 (인터셉터, ThreadLocal 사용)

프로젝트 진행 중 로깅을 하고 로그를 저장할 방법이 필요했습니다. Spring의 인터셉터를 이용하여 로깅을 구현하였고 ThreadLocal을 통해서 트랜젝션 아이디를 기록했습니다.

 

 

먼저 인터셉터입니다.

@Slf4j
public class RequestInterceptor implements HandlerInterceptor {

    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) throws Exception {

        String uuid = UUID.randomUUID().toString(); // (1)
        String requestURI = request.getMethod() + " " + request.getRequestURL();

        log.info("Request [{}][{}]", uuid, requestURI); // (2)
        LogUtility.set(uuid, requestURI); // (3)

        return true;
    }

    @Override
    public void afterCompletion(HttpServletRequest request, HttpServletResponse response, Object handler, Exception ex) throws Exception {

        log.info("Response {} [{}][{}]", response.getStatus(), LogUtility.getUUID(), handler); // (4)
        LogUtility.remove(); // (5)
    }
}

• (1): 요청 트랜젝션 아이디를 얻습니다.
• (2): 핸들러로 가기 전에 logging을 수행합니다.
• (3): 다른 곳에서 트랜젝션 아이디와 request URI를 사용하기 위해서 LogUtility 내부 ThreadLocal에 값을 설정합니다.
• (4): view 처리까지 끝내고 logging을 수행합니다.
• (5): 톰캣은 스레드를 재사용하기 때문에 ThreadLocal에 저장한 데이터를 지워주어야 데이터가 공유되지 않습니다. 물론 현재 로직에서 꼭 필요한 코드는 아닙니다.

이제 인터셉터를 등록해줍니다.

@Configuration
public class WebConfig implements WebMvcConfigurer {

    @Override
    public void addInterceptors(InterceptorRegistry registry) {

        registry.addInterceptor(new RequestInterceptor())
                .order(1) // (1)
                .addPathPatterns("/**") // (2)
                .excludePathPatterns("/error"); // (3)
    }
}

• (1): 우선순위입니다.
• (2): 모든 경로에서 인터셉터를 수행합니다.
• (3): "/error"로 오는 요청에 대해서는 인터셉터를 수행하지 않습니다.

인터셉터에서 쓰인 LogUtility는 다음과 같습니다.

package com.hoppy.app.common.tool;

import lombok.AllArgsConstructor;
import lombok.Getter;

public class LogUtility {

    @Getter
    @AllArgsConstructor
    public static class LogInfo {
        private String uuid;
        private String requestURI;
    }

    private static final ThreadLocal<LogInfo> REQUEST_INFO = new ThreadLocal<>(); // (1) 
    
    public static void set(String uuid, String requestURI) {
        REQUEST_INFO.set(new LogInfo(uuid, requestURI));
    }
    
    public static String getUUID() {
        return REQUEST_INFO.get().getUuid();
    }
    
    public static String getRequestURI() {
        return REQUEST_INFO.get().getRequestURI();
    }
    
    public static void remove() {
        REQUEST_INFO.remove();
    }
}

• (1): 각 스레드는 ThreadLocal을 통해 전역에서 LogInfo를 참조할 수 있습니다. 

하나의 스레드가 여러 개의 ThreadLocal을 가질 수 있으니 이를 명심하고 사용해야 합니다. 

 

이제 로그를 저장해야하는데, 저는 간단하게 application.properties 설정을 통해서 로그 파일의 저장과 삭제 주기를 설정해주었습니다.

# logging
logging.file.name=logs/test.log // (1)
logging.logback.rollingpolicy.max-history=7 // (2)
logging.logback.rollingpolicy.max-file-size=100MB // (3)
logging.logback.rollingpolicy.file-name-pattern=${LOG_FILE}.%d{yyyy-MM-dd}-%i.log // (4)

• (1): 로그 파일이 저장될 위치입니다.
• (2): 7번 째 이후 로깅 파일은 순차적으로 삭제됩니다.
• (3): 각 로그 파일은 최대 100MB의 크기를 가집니다.
• (4): 로그 파일을 보관할 때 사용되는 파일 이름 패턴입니다.

로깅 결과입니다. 동시에 여러 요청을 보냈지만 트렌젝션 아이디가 공유되지 않고 잘 동작합니다.

2022-09-13 00:56:02.650  INFO 22568 --- [nio-8888-exec-6] c.h.a.c.interceptor.RequestInterceptor   : Request [6bc52f2e-d6d6-4bda-b13e-8ec1382de42a][GET http://localhost:8888/health]
2022-09-13 00:56:02.651  INFO 22568 --- [nio-8888-exec-6] c.h.a.c.interceptor.RequestInterceptor   : Response 200 [6bc52f2e-d6d6-4bda-b13e-8ec1382de42a][com.hoppy.app.common.controller.HealthController#checkHealth()]
2022-09-13 00:56:02.800  INFO 22568 --- [nio-8888-exec-7] c.h.a.c.interceptor.RequestInterceptor   : Request [2f580b8b-7837-49a4-8486-0f4a704b03eb][GET http://localhost:8888/health]
2022-09-13 00:56:02.804  INFO 22568 --- [nio-8888-exec-7] c.h.a.c.interceptor.RequestInterceptor   : Response 200 [2f580b8b-7837-49a4-8486-0f4a704b03eb][com.hoppy.app.common.controller.HealthController#checkHealth()]
2022-09-13 00:56:02.944  INFO 22568 --- [nio-8888-exec-8] c.h.a.c.interceptor.RequestInterceptor   : Request [bb98e3dd-6bf2-4257-97da-529908ad5e37][GET http://localhost:8888/health]
2022-09-13 00:56:02.946  INFO 22568 --- [nio-8888-exec-8] c.h.a.c.interceptor.RequestInterceptor   : Response 200 [bb98e3dd-6bf2-4257-97da-529908ad5e37][com.hoppy.app.common.controller.HealthController#checkHealth()]

아래는 현재 프로젝트에서 실제로 로깅된 모습입니다.

2022-09-12 12:55:22.263  INFO 1 --- [http-nio-8080-exec-6] c.h.a.c.interceptor.RequestInterceptor   : Request [dad560d6-1a84-494b-b1d5-0e0b85c5e36c][GET http://hoppy.kro.kr/health]
2022-09-12 12:55:22.265  INFO 1 --- [http-nio-8080-exec-6] c.h.a.c.interceptor.RequestInterceptor   : Response 200 [dad560d6-1a84-494b-b1d5-0e0b85c5e36c][com.hoppy.app.common.controller.HealthController#checkHealth()]

필요한 로그만 기록해둬서 문제가 발생했을 때 조금 더 빨리 대처할 수 있었습니다. 추후 더 자세한 로그를 남기기 위해 리펙토링을 수행해보겠습니다.