8. 로그 파일 만들기, 인터셉터 구현하기

코드 확인을 위해, 관련 PR 링크를 첨부한다.

#5 로깅 구현 및 로깅을 위한 인터셉터 구현하기 by include42 · Pull Request #10 · include42/spring-books-diary

Resolved: #5 실수로 Develop 브랜치에 커밋해 버려서, Revert 후 기능 브랜치에 다시 작성하였습니다. 이를 merge하는 방향으로 가고자 합니다.

github.com

간만에 돌아온 포스팅. 오늘은 다음의 목표를 이루기 위해 어떤 작업을 했는지 적어보려고 한다.

서버에 들어온 요청/응답, 예외 발생 등에 대해 로그를 남긴다.
남긴 로그를 콘솔에서 확인한다.
로그를 파일로 남겨, 추후 배포 중 오류가 발생한 경우 확인할 수 있도록 한다.

1. 로깅이란 무엇인가?

로깅(logging)은, 프로그램이 동작하면서 발생하는 다양한 정보를 저장하는 기록, 로그(log)를 생성하도록 시스템을 작성하는 활동이다.

이러한 로그는 재현하기 힘든 버그나, 성능에 대한 통계 등에 대해 유용한 정보를 제공할 수 있다.

따라서 로깅을 통해 로그를 남기게 되면, 예기치 못한 문제가 발생할 때 적절한 대응을 할 수 있고,

최적화나 기능 추가 등이 필요할 때에도 안정성에 큰 도움을 받을 수 있다.

나 역시 알고리즘 문제를 풀 때, printf()를 통해 로그를 남겨 프로그램의 흐름을 파악하고,

디버깅 과정에서 어느 부분의 값이 이상한지 로그를 통해 직관적으로 파악하는 경우가 많았다.

그러나 운영중인 스프링 서버에서 System.out.println()로 로그를 남긴다면,

어플리케이션의 속도도 크게 느려지고 관리자가 실시간으로 확인하지 않으면 조치를 취하기도 어려울 것이다.

이를 해결하기 위해, 로그 라이브러리가 제공된다.

2. 로그 라이브러리

java.util.logging

우리가 제일 편하게 쓸 수 있는 로그 라이브러리는 자바에 포함되는 java.util.logging 이다.

java.util.logging은 Log의 수준을 다양하게 나눠 로그를 발생시키는 기능을 포함한다.

수준의 목록은 다음과 같다.

SEVERE (highest value)
WARNING
INFO
CONFIG
FINE
FINER
FINEST (lowest value)

더 관심이 있다면, 오라클 문서의 java.util.logging.level을 참고하기를 바란다.

하지만 java.util.logging은 다양한 기능이 지원되지 않고, 불편한 점이 있어 지금은 잘 쓰지 않는 것으로 알고 있다.

Log4j

Log4j는 다양하고 효율적인 로그 출력을 돕는 오픈소스 라이브러리이다.

1.1버전 공식 페이지(2015년 이후 지원하지 않는 버전)

2버전 공식 페이지

공식 페이지에서 언급하는 Log4j의 장점은 다음과 같다.

속도에 최적화되어 있음
다양한 API와 함께 사용할 수 있음
멀티스레드 환경에서 사용할 수 있음
다양한 수준의 로그를 정의하여 사용할 수 있음
로그 빌더 API를 제공함
다양한 방식으로 출력 결과를 외부로 보낼 수 있음

Log4j는 java.util.logging.level과는 다른 자체적인 로그 레벨을 지원한다.

각 계층의 우선 순위에 대해서는 해당 링크 참고.

나 역시 이 레벨 기준을 따르고 있는데, 보통 이 5가지를 사용한다.

ERROR : 프로그램을 실행할 수 있는 정도의 에러 이벤트에 대한 로그
WARN : 잠재적으로 유해한 상황에 대한 로그
INFO : 큰 단위 수준에서 응용 프로그램의 진행 상황을 강조하는 정보성 로그
DEBUG : 디버깅할 때 유용하도록 세분화된 정보 이벤트를 남기는 로그
TRACE : DEBUG보다 더 상세한 내용을 추적하기 위해, log4j 1.2.12에서 추가된 로그 레벨

이외에도 잘 사용되지는 않는 추가 레벨이 존재한다.

FATAL : 프로그램이 중단될 정도의 매우 심각한 오류 이벤트 로그
OFF : 가장 높은 우선순위를 가지며, 로깅을 해제함

Logback

Logback은 앞서 설명한 log4j의 후속 프로젝트이다.

왜 log4j를 Logback으로 전환하는지, 공식 문서에서 설명하는 바는 다음과 같다.

Logback은 log4j와 동일한 개발자에 의해 설립되었으며, 그렇기 때문에 개념적으로 매우 유사하다

Logback으로 전환할 이유는 다음과 같다.

더 빠른 구현 : 약 10배 정도 빠를 뿐 아니라, 메모리 공간도 적게 차지
테스트를 위한 광범위한 지원
SLF4J와 함께 이용할 수 있도록 지원
광범위한 문서 지원
오래된 로그 아카이브 자동 제거, 자동 압축 등의 기능 제공
필터링 기능 제공

간단하게만 정리해도 써야 할 이유가 분명해 보인다.

그래서 이번 프로젝트에서는, Logback을 사용하기로 했다.

3. 로그 사용하기와 SLF4J

Logback은 스프링부트 스타터에 기본적으로 포함되어 있다.

그러므로 별도의 gradle 설정이 필요하지는 않다.

로그를 남기기 위해, 우리는 SLF4J를 사용할 것이다.

SLF4J는 로깅 Facade로, 다양한 로깅 프레임 워크 (예 : java.util.logging, logback, log4j)에 대한 추상화를 수행한다.

최종 사용하는 SLF4J를 통해 로그를 남기면 되고, 이 경우 원하는 로깅 프레임워크에 연결하여 로그 기능을 수행한다.

SLF4J 사용을 통해, 우리는 추후 로깅 라이브러리를 교체하더라도 설정 파일 외의 코드를 건드리지 않아도 된다.

그리고 더 편안한 점!!

SLF4J 클래스를 만드는 등의 반복 작업을 줄여주기 위해,

Lombok이 SLF4J 어노테이션을 제공한다!!

사용은 다음과 같이 하면 된다.

@Slf4j(topic = "ERROR_FILE_LOGGER")
@RestControllerAdvice
public class GlobalExceptionHandler {
    /**
     * javax.validation.Valid or @Validated 으로 binding error 발생시 발생한다.
     * HttpMessageConverter 에서 등록한 HttpMessageConverter binding 못할경우 발생
     * 주로 @RequestBody, @RequestPart 어노테이션에서 발생
     */
    @ExceptionHandler(MethodArgumentNotValidException.class)
    protected ResponseEntity<ErrorResponse> handleMethodArgumentNotValidException(MethodArgumentNotValidException e) {
        log.error("handleMethodArgumentNotValidException", e);
        final ErrorResponse response = ErrorResponse.of(ErrorCode.INVALID_INPUT_VALUE, e.getBindingResult());
        return new ResponseEntity<>(response, HttpStatus.BAD_REQUEST);
    }
}

위 코드는 에러 핸들링을 위한 GlobalExceptionHandler이다.

해당 클래스에 @Slf4j 어노테이션을 달면, 해당 클래스 내에서 log라는 인스턴스를 사용할 수 있다.

어노테이션을 자세히 보면 topic이라는 옵션이 붙어 있다.

topic은 로그 생성 시 부여되는 카테고리로, 추후 보여주겠지만 로그 분류 등을 위해 사용한다.

4. 로그 설정파일 만들기

로그에 대한 설정을 파일로 만들어서 정리할 수 있다.

Logback의 경우, logback-spring.xml이라는 파일을 만들어 resource 디렉토리에 넣으면 된다.

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

    <property name="home" value="logs"/>

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

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

    <logger name="ERROR_FILE_LOGGER" level="ERROR" additivity="true">
        <appender-ref ref="ERROR_FILE_APPENDER"/>
    </logger>

    <logger name="DEFAULT_FILE_LOGGER" level="DEBUG" additivity="true">
        <appender-ref ref="DEFAULT_FILE_APPENDER"/>
    </logger>
</configuration>

이 파일을 보면, 일단 맨 하단에 다음과 같은 옵션을 두었다.

ERROR_FILE_LOGGER : level이 ERROR인 해당 topic의 로그가 있다면, ERROR_FILE_APPENDER로 연결한다.
additivity=true이므로 콘솔 화면에도 로그를 출력한다.
예외 발생 시 이 로그를 발생시킨다.
DEFAULT_FILE_LOGGER : level이 debug인 해당 topic의 로그가 있다면, DEFAULT_FILE_APPENDER로 연결한다.
additivity=true이므로 콘솔 화면에도 로그를 출력한다.
디버그를 위해 로그가 필요할 시 이 옵션으로 로그를 발생시킨다.

또한 각각의 어펜더에서는 RollingFileAppender를 사용한다.

RollingFileAppender는 FileAppender를 상속한 옵션으로, 로그 파일이 특정 크기에 도달하면 백업한다.

최대 용량은 15mb, 최대 보관 일수는 30일로 설정해놓았으며

로그의 패턴은 우리에게 익숙한 스프링부트의 기본 설정 로그 패턴을 쓴다.

5. 로그 적용하기

나는 로그를 두 곳에 적용하였다.

GlobalExceptionHandler : 예외 발생 시 연결되어 응답을 보내는 ControllerAdvice이다. 여기서 예외에 대한 로그를 남긴다.
LogInterceptor : 컨트롤러가 요청/응답을 남길 시 로그를 남기기 위해 만든 인터셉터이다.

Interceptor와 ControllerAdvice(ExceptionHandler)에 대해서는 이 링크를 참조하기를 바란다.

ExceptionHandler에 대해서는 추후 포스팅할 예정이고,

Interceptor만 간단히 설명하면, 아래 이미지의 DispatcherServlet이 실행된 뒤 시점에서 실행되는 로직이라고 생각하면 된다.

이제 코드를 통해 확인해 보자.

먼저, LogInterceptor이다.

package com.booksdiary.controller.common;

import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Component;
import org.springframework.web.servlet.AsyncHandlerInterceptor;

import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;

@Slf4j(topic = "DEFAULT_FILE_LOGGER")
@Component
public class LogInterceptor implements AsyncHandlerInterceptor {
    @Override
    public boolean preHandle(HttpServletRequest request, HttpServletResponse response, Object handler) {
        log.info("url : {}", request.getRequestURL());
        log.info("request : {} response : {}", request.getMethod(), request.getRequestURL());

        return true;
    }
}

@slf4j를 통해, DEFAULT_FILE_LOGGER topic의 로그를 설정한다.

이후 AsyncHandlerInterceptor에 추상화되어있는 preHandle 메서드를 구현한다.

이때 request와 response에 대해, 그리고 어떤 URL로 요청이 들어오는지에 대해 로그를 발생시킨다.

해당 로그의 결과는 다음과 같다.

2021-02-27 16:59:33.679  INFO 14423 --- [http-nio-8080-exec-2] DEFAULT_FILE_LOGGER                      : url : http://localhost:8080/api/books
2021-02-27 16:59:33.680  INFO 14423 --- [http-nio-8080-exec-2] DEFAULT_FILE_LOGGER                      : request : POST response : http://localhost:8080/api/books

이제 GlobalExceptionHandler를 보자.

코드는 중간을 생략하고, 대표적인 메서드만 포함하였다.

전체 코드가 보고 싶다면 상단의 github 링크 참조.

package com.booksdiary.global.error;

import com.booksdiary.global.error.exception.BusinessException;
import com.booksdiary.global.error.exception.EntityNotFoundException;
import com.booksdiary.global.error.exception.InvalidValueException;
import lombok.extern.slf4j.Slf4j;
import org.springframework.http.HttpStatus;
import org.springframework.http.ResponseEntity;
import org.springframework.validation.BindException;
import org.springframework.web.HttpRequestMethodNotSupportedException;
import org.springframework.web.bind.MethodArgumentNotValidException;
import org.springframework.web.bind.annotation.ExceptionHandler;
import org.springframework.web.bind.annotation.RestControllerAdvice;
import org.springframework.web.method.annotation.MethodArgumentTypeMismatchException;

import java.nio.file.AccessDeniedException;

/**
 * GlobalExceptionHandler는 다양한 예외에 대한 핸들링 작업을 수행한다.
 * Exception을 상속받은 모든 클래스에 대해 대응하며, ErrorResponse를 ResponseEntity에 담아 반환한다.
 * <p>
 * ref https://cheese10yun.github.io/spring-guide-exception/
 */
@Slf4j(topic = "ERROR_FILE_LOGGER")
@RestControllerAdvice
public class GlobalExceptionHandler {
    /**
     * javax.validation.Valid or @Validated 으로 binding error 발생시 발생한다.
     * HttpMessageConverter 에서 등록한 HttpMessageConverter binding 못할경우 발생
     * 주로 @RequestBody, @RequestPart 어노테이션에서 발생
     */
    @ExceptionHandler(MethodArgumentNotValidException.class)
    protected ResponseEntity<ErrorResponse> handleMethodArgumentNotValidException(MethodArgumentNotValidException e) {
        log.error("handleMethodArgumentNotValidException", e);
        final ErrorResponse response = ErrorResponse.of(ErrorCode.INVALID_INPUT_VALUE, e.getBindingResult());
        return new ResponseEntity<>(response, HttpStatus.BAD_REQUEST);
    }
    (중간 생략...)

    @ExceptionHandler(Exception.class)
    protected ResponseEntity<ErrorResponse> handleException(Exception e) {
        log.error("Exception", e);
        final ErrorResponse response = ErrorResponse.of(ErrorCode.INTERNAL_SERVER_ERROR);
        return new ResponseEntity<>(response, HttpStatus.INTERNAL_SERVER_ERROR);
    }
}

발생한 예외에 대해, 어떤 예외인지를 로그로 남기고, 해당 예외 클래스를 포함한다.

이 경우, 예외에 대한 stack trace까지 함께 기록된다.

실제 로그의 모습은 다음과 같다.

2021-02-27 16:59:33.699 ERROR 14423 --- [http-nio-8080-exec-2] ERROR_FILE_LOGGER                        : Exception

org.springframework.web.HttpMediaTypeNotSupportedException: Content type 'multipart/form-data;boundary=--------------------------044323815056547462515939;charset=UTF-8' not supported
	at org.springframework.web.servlet.mvc.method.annotation.AbstractMessageConverterMethodArgumentResolver.readWithMessageConverters(AbstractMessageConverterMethodArgumentResolver.java:225)
	at org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor.readWithMessageConverters(RequestResponseBodyMethodProcessor.java:158)
	at org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor.resolveArgument(RequestResponseBodyMethodProcessor.java:131)
	at org.springframework.web.method.support.HandlerMethodArgumentResolverComposite.resolveArgument(HandlerMethodArgumentResolverComposite.java:121)
	at org.springframework.web.method.support.InvocableHandlerMethod.getMethodArgumentValues(InvocableHandlerMethod.java:170)
	at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:137)
	at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:106)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:894)
	at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:808)
	at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1061)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:961)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
	at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:909)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:652)
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:733)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:53)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.web.filter.RequestContextFilter.doFilterInternal(RequestContextFilter.java:100)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.web.filter.FormContentFilter.doFilterInternal(FormContentFilter.java:93)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:201)
	at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:119)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:202)
	at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:97)
	at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:542)
	at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:143)
	at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:92)
	at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:78)
	at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:343)
	at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:374)
	at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:65)
	at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:888)
	at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1597)
	at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
	at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
	at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.base/java.lang.Thread.run(Thread.java:830)

DTO를 만드는 과정에서 LocalDateTime 포맷 오류가 났는데,

이에 대해 (별도로 핸들링하지 않았으므로) Exception으로 표시해 주고, 스택트레이스를 보여준다.

이 로그들은, 앞서 설정한 값에 의해 파일로도 저장된다.

6. 결론

오늘은 로그에 대해 간단히 알아보고, 실제 프로젝트에서 로그를 만들고 저장해보았다.

이미 다 읽으셨겠지만...간단히 내용을 요약하면 다음과 같다.

Log를 통해, 우리는 디버그, 운영 등에 있어 큰 도움을 받는다.
Logback 사용을 권한다. 스프링에서는 기본으로 포함되어 있다.
@Slf4j 어노테이션을 통해 로그를 편하게 찍을 수 있다.
logback-spring.xml로 로그 옵션을 관리하고 파일로 로그를 남길 수 있다.
인터셉터, 예외 핸들러 등에 로그를 찍으면 유용하며, 그 외에도 다양한 활용이 가능하다.

글이 산만해서 도움이 될런지 모르겠다만,

이 글을 읽으신 분들이 추후 로그 작업 시 편하게 하시기를 바란다.

이번 글은 공부하면서 작성한 글이라 중간중간 확실치 않은 내용이 있을 수 있다.

잘못된 내용이 있다면 지적 부탁드립니다.

'프로그래밍 > 프로젝트' 카테고리의 다른 글

9. Log4jdbc로 DB 로그 저장하기 (0)	2021.04.01
7. 도메인과 조회 로직 다시 만들기 (0)	2021.02.26
6. 프로젝트 요구사항 정리와 ERD (0)	2021.02.18
5. Request DTO의 Validation / 예외 테스트와 ParameterizedTest (0)	2021.02.09
4. TDD 개발 : Read/delete 기능 만들어보기 (0)	2021.02.05

긴 이별을 위한 짧은 편지

8. 로그 파일 만들기, 인터셉터 구현하기

1. 로깅이란 무엇인가?

2. 로그 라이브러리

java.util.logging

Log4j

Logback

3. 로그 사용하기와 SLF4J

4. 로그 설정파일 만들기

5. 로그 적용하기

6. 결론

'프로그래밍 > 프로젝트' 카테고리의 다른 글

댓글

티스토리툴바

8. 로그 파일 만들기, 인터셉터 구현하기

1. 로깅이란 무엇인가?

2. 로그 라이브러리

java.util.logging

Log4j

Logback

3. 로그 사용하기와 SLF4J

4. 로그 설정파일 만들기

5. 로그 적용하기

6. 결론

'프로그래밍 > 프로젝트' 카테고리의 다른 글

관련글

댓글

티스토리툴바