[SpringBoot] http request logging

http request logging이라고 표현하는게 옳은것인지는 잘 모르겠지만 아무튼, API 인터페이스 서버를 개발하면서 요청시스템코드/요청자 아이디/응답시간/요청URI 와 같은 것들만을 간단하게 로깅해야하는일이 생겼다.

과거 다른 프로젝트에서 해둔 게 있었는데 전자정부 기반(이라고 해봤자 사실 스프링이랑 차이가 없음)이라, 조금 손보고 해서 SpringBoot 2.7.8 버전에 맞게 수정했다.

 

이것만 해서는 되지 않고, 기존에는 직접 해당 interceptor 에서 log파일까지 생성해서 append 하는 방식이었는데, 나는 이걸 logback에서 로깅하는 방식으로 수정해보았다. 로컬 개발환경에서는 잘 돌아가지만, 개발서버에서는 DispatcherServlet도 같이 로깅되는 문제가 있기는 하다. 이거에 대해 수정하는 건 좀 나중으로 미루고, 일단은 까먹기 전에 기록을 먼저 하는 걸로 하자.

 

1. LoggingInterceptor.java

package com.test.common.config;
 
import java.text.SimpleDateFormat;
import java.util.Calendar;
 
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
 
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.stereotype.Component;
import org.springframework.util.StringUtils;
import org.springframework.web.servlet.HandlerInterceptor;
import org.springframework.web.servlet.ModelAndView;
 
@Component
public class LoggerInterceptor implements HandlerInterceptor {
    private static final Logger logger = LoggerFactory.getLogger(LoggerInterceptor.class);
    
    @Override
    public boolean preHandle(HttpServletRequest req, HttpServletResponse res , Object handler) throws Exception {
        System.out.println("=== LoggerInterceptor ===");
        String contextPath = req.getContextPath();
        String requestUrl = req.getRequestURI().substring(contextPath.length());
        
        // 응답시간 체크를 위한 선언
        long startTime = System.currentTimeMillis();
        req.setAttribute("__start__time",  startTime);
        req.setAttribute("__call__time", getTodayStr("yyyyMMddHHmmss"));
        
        
        return true;
    }
    
    /** 
     * 로그 예시 
     * SYSTEM_CODE,yyyyMMddHHmmss,/test/api.do,00,9999,CALL_SYS_CD,CALL_USER,0:0:0:0:0:0:1
     */
    @Override
    public void postHandle(HttpServletRequest req , HttpServletResponse res , Object handler , ModelAndView modelAndView) throws Exception {
        long startTime = (long)req.getAttribute("__start__time");
        long endTime = System.currentTimeMillis();
        long resTime = endTime - startTime;         // 응답시간 계산
        
        // 호출일시
        String callTime = (String)req.getAttribute("__call__time");
        
        // 호출 URI
        String contextPath = req.getContextPath();
        String requestUrl = req.getRequestURI().substring(contextPath.length());
        
        // 호출 시스템 및 사용자 , api 통신시 http header에 세팅해야 함
        String callSysCd = req.getHeader("callSysCd");
        String callUser = req.getHeader("callUser");
        
        StringBuffer logSb = new StringBuffer();
        logSb.append("SYSTEM_CODE");
        logSb.append("," + callTime);
        logSb.append("," + requestUrl);
        logSb.append("," + "00");
        logSb.append("," + resTime);
        logSb.append("," + callSysCd);
        logSb.append("," + callUser);
        logSb.append("," + getClientIP(req));
        
        logger.info(logSb.toString());
    }
    
    
    /**
     * IP 가져오기
     */
    private static String getClientIP(HttpServletRequest req) {
        String ip = req.getHeader("X-Forwarded-For");
        
        if ( ip == null ) 
            ip = req.getHeader("Proxy-Client-IP");
        
        if ( ip == null ) 
            ip = req.getHeader("WL-Proxy-Client-IP");
        
        if ( ip == null ) 
            ip = req.getHeader("HTTP_CLIENT_IP");
        
        if ( ip == null ) 
            ip = req.getHeader("HTTP_X_FORWARDED_FOR");
        
        if ( ip == null ) 
            ip = req.getRemoteAddr();
        
        return ip;
    }
    
    // 오늘 날짜 String 리턴 
    private static String getTodayStr ( String pattern ) {
        if ( StringUtils.isEmpty( pattern ) ) {
            pattern = "yyyyMMdd";
        }
        
        SimpleDateFormat simpleDate = new SimpleDateFormat ( pattern );
        Calendar c1 = Calendar.getInstance();
        String strToday = simpleDate.format(c1.getTime());
        
        return strToday;
    }
}
 

 

엄청 길어보이지만 사실 별거 아닌 소스이다. 

URL HttpServletRequest가 올 때 preHandle이 먼저 가로채서 적당한 데이터들을 가공해서 넣어준 후, URL에 매핑된 controller 가 실행된 후, postHandle이 가로채서 preHandle에 넣어준 데이터들을 빼내어 로그형태를 가공한다.

 

간단히 정리하자면 다음과 같다

(Client) Http URL 요청(Httprequest) -> (서버) Interface의 preHandle -> (서버) URL 매핑된 controller 로직 수행 -> (서버) client 응답 전 Interface의 postHandle -> (Client) Http URL 응답(HttpResponse)

 

그럼 이걸 어떻게 logback에서 설정했냐, 하면 다음과 같다.

 

2.WebConfig.java

package com.test.common.config;
 
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.context.annotation.Configuration;
import org.springframework.web.servlet.config.annotation.InterceptorRegistry;
import org.springframework.web.servlet.config.annotation.WebMvcConfigurer;
 
@Configuration
public class WebConfig implements WebMvcConfigurer {
    
    @Autowired
    HeaderInterceptor headerIntercepter;
    
    @Autowired
    LoggerInterceptor loggerInterceptor;
    
    @Override
    public void addInterceptors(InterceptorRegistry registry) {
        System.out.println("===== ===== WebMvcConfig ===== =====");
        // Header에 저장된 시스템 코드를 체크하기 위해 headerInterceptor를 add 해준다
        registry.addInterceptor(headerIntercepter).addPathPatterns("/test/**");
        // HttpRequest Logging을 위해 loggerInterceptor를 add 해준다.
        registry.addInterceptor(loggerInterceptor).addPathPatterns("/**");
    }
}

logback을 설정하기 전, WebMvcConfig를 만들고 여기서 interceptor를 정의해주어야 한다.

23번째 줄이 LoggerInterceptor를 정의해주는 부분이다.

 

3. logback-spring.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="60 seconds">
    <property name="LOG_NAME" value="SampleProject" />
    <property name="LOG_HOME" value="/sw/apiServer/logs" />
    <property name="LOGBACK_HOME" value="/sw/apiServer/logs/old" />
    <property name="InterceptorLogPattern" value ="%msg %n" />
    
    <!--  개발툴 콘솔창 설정 -->
    <appender name ="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <Pattern>%d{yyyy-MM-dd HH:mm:ss.SSS} [%thread] %-5level [%logger{0}:%line] - %msg %n</Pattern>
        </encoder>
    </appender>
    
    <!-- LoggerInterceptor 로그 파일 -->
    <appender name="INTERCEPTOR" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <Append>true</Append>
        <file>${LOG_HOME}/insLog/${LOG_NAME}.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOGBACK_HOME}/insLog/${LOG_NAME}-%d{yyyy-MM-dd}.log</fileNamePattern>
            <cleanHistoryOnStart>true</cleanHistoryOnStart>
            <maxHistory>365</maxHistory>
        </rollingPolicy>
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>DEBUG</level>
        </filter>
        <encoder>
            <Pattern>${InterceptorLogPattern}</Pattern>
        </encoder>
    </appender>
    
    <root leve="WARN">
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="INTERCEPTOR"/>
    </root>
    
    <!-- 로그 대상 패키지 지정 -->
    <logger name="com.test.common" level="DEBUG" additivity="false">
        <appender-ref ref="CONSOLE" /> <!-- 개발 콘솔 -->
    </logger>
    <logger name="com.test.common.config" level="DEBUG" additivity="false">
        <appender-ref ref="INTERCEPTOR" /> <!-- 인터셉터 로그 -->
    </logger>
</configuration>

 

logback 설정은 나중에 좀 더 자세히 알아보고,

nterceptor가 위치한 패키지의 경로를 41번 라인에서 지정해주고,

42번에서 지정한 appender-ref를 통해 위의 16번 라인의 appender 설정을 수행하게 된다.

 

가장 중요한 건, 41번 라인의 logger name 부분으로 여기에서는 로그를 찍을 대상 패키지를 지정해야한다.

 

이렇게 저장하면 큰 문제는 발생하지 않는데, 로컬에서는 내가 의도한대로 로그가 잘 남기는 하지만, 개발서버에서는 DispatcherServlet 로그가 잔존해서 남는 문제가 발생하고 있다. 문제까지는 아니긴 한데, 이게 왜 같은 패키지가 로컬/개발서버에서 각기 다르게 뜨는지는 조금 더 연구가 필요한 상황.

 

아무튼 이거 나중에 로그 파일 분리하는 방향으로 많이 활용될 것 같아 작성해보았다.

 

 

*** interceptor.log에 spring dispatcher servlet 로그 등이 남는 것들에 대해 수정하여 덧붙인다.

interceptor 로그에 위와 같이 작성할 경우, 스프링 프레임워크의 로그들도 남고 있었는데 오만가지 잡다한 설정을 수정해봐도 안되길래 혹시나, 싶은 마음으로 실행 스크립트를 살펴보니 --debug 옵션을 주고 있었다.

이걸 빼니까 위 설정만으로 해결이 완료됨ㅋㅋㅋㅋ

 

log 파일을 java interceptor 에서 직접 작성해야하나 아주 고민이 많았는데 다행히 잘 먹었다. ㅋㅋㅋ