개발자로서 운영이슈를 해결하기 위해서는 로그메시지가 디버깅을 위해서 꼭 필요하다는건 누구나 알고계실겁니다.

하지만 로깅을 잘 하기 위해서는 많은 고민이 필요합니다.

로그레벨은 어떻게 할지 로그의 내용은 어떤 정보들로 채워넣을지 등등 말이죠.

로그는 많이 남긴다고 좋은게 아니죠.

어떤 분들은 아무런 의미도 없는 정보를 로깅하기도 합니다.

비용적인 측면이 문제되지 않는다면 대량의 로그를 마음껏 남겨도 되겠지만 현실은 그렇지 않죠.

따라서 중요도에 따라서 적당~~히 최소한의 내용만 로깅하는게 좋습니다.

로그 중에서 가장 중요한 로그는 요청과 응답에 대한 것입니다.

API 요청시 어떤 정보를 전달받았는지에 대한 request log과

그 데이터를 기준으로 비즈니스 로직을 태운 뒤에 어떤 응답을 내주었는지

response log 만 있어도 디버깅은 충분히 가능하죠.

물론 요청과 응답 중간에 로직이 복잡하다면 중간중간 추가적인 로그를 심어주는게 많은 도움이 될 수 있습니다.

그래서 이번 포스팅에서는 요청과 응답을 어떻게 로깅하는지에 대해 공유드리고자 합니다.

1. 프로젝트 생성

기본적인 개발환경은 아래와 같습니다.

• IntelliJ IDEA 2021.3.3 (Ultimate Edition)
• SpringBoot 2.7.3
• Java 18 (OpenJDK)

자, 우선 깡통 프로젝트를 만들겠습니다.

자, 깡통 프로젝트가 완성되었습니다. 

2. 라이브러리 추가

이제 개발편의를 위해 lombok과 로깅을 위한 logback 라이브러리를 추가하고, API 개발을 위해 spring-boot-starter-web 라이브러리를 추가하겠습니다.

implementation 'org.springframework.boot:spring-boot-starter-web'
implementation 'org.projectlombok:lombok:1.18.24'
annotationProcessor 'org.projectlombok:lombok:1.18.24'
implementation 'ch.qos.logback:logback-classic:1.2.11'

3. API 작성

그리고 아래와 같이 테스트용 컨트롤러를 하나 작성해줍니다.

package com.keichee.demo.controller;

import lombok.extern.slf4j.Slf4j;
import org.springframework.web.bind.annotation.*;

@Slf4j
@RestController
@RequestMapping("/test")
public class TestController {

    @GetMapping("/log")
    public int requestResponseLog(@RequestParam int code) {
        log.info("requestResponseLog method called with code {}", code);
        return code;
    }
}

여기까지하고 앱을 기동한 뒤 API를 호출하여 로그가 잘 남는지 확인해볼게요.

2022-09-15 17:04:50.580  INFO 92637 --- [           main] com.keichee.demo.DemoLoggingApplication  : No active profile set, falling back to 1 default profile: "default"
2022-09-15 17:04:51.034  INFO 92637 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat initialized with port(s): 8080 (http)
2022-09-15 17:04:51.038  INFO 92637 --- [           main] o.apache.catalina.core.StandardService   : Starting service [Tomcat]
2022-09-15 17:04:51.038  INFO 92637 --- [           main] org.apache.catalina.core.StandardEngine  : Starting Servlet engine: [Apache Tomcat/9.0.65]
2022-09-15 17:04:51.105  INFO 92637 --- [           main] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring embedded WebApplicationContext
2022-09-15 17:04:51.107  INFO 92637 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 495 ms
2022-09-15 17:04:51.306  INFO 92637 --- [           main] o.s.b.w.embedded.tomcat.TomcatWebServer  : Tomcat started on port(s): 8080 (http) with context path ''
2022-09-15 17:04:51.312  INFO 92637 --- [           main] com.keichee.demo.DemoLoggingApplication  : Started DemoLoggingApplication in 0.879 seconds (JVM running for 1.294)
2022-09-15 17:05:56.173  INFO 92637 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2022-09-15 17:05:56.173  INFO 92637 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2022-09-15 17:05:56.174  INFO 92637 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 1 ms
2022-09-15 17:05:56.186  INFO 92637 --- [nio-8080-exec-1] c.k.demo.controller.TestController       : requestResponseLog method called with code 2

제일 마지막줄에 보면 TestController에서 출력한 로그가 보이네요.

비즈니스 로직의 로그는 잘 출력되고 있으니 이제 기본적인 준비가 끝났습니다.

4. Filter 구현

요청과 응답에 대한 로그출력을 위해서 우리는 Filter를 이용할 겁니다. 

spring-web에서는 아래와 같이 여러 종류의 filter를 제공하고 있습니다.

AbstractRequestLoggingFilter
CharacterEncodingFilter
CommonsRequestLoggingFilter
CompositeFilter
CorsFilter
DelegatingFilterProxy
FormContentFilter
ForwardedHeaderFilter
GenericFilterBean
HiddenHttpMethodFilter
HttpPutFormContentFilter
OncePerRequestFilter
RelativeRedirectFilter
RelativeRedirectResponseWrapper
RequestContextFilter
ServletContextRequestLoggingFilter
ServletRequestPathFilter
ShallowEtagHeaderFilter

여기서 request logging과 관련된 filter는 AbstractRequestLoggingFilter, CommonsRequestLoggingFilter, 그리고 ServletContextRequestLoggingFilter 가 있습니다.

우리는 AbstractRequestLoggingFilter를 상속해서 우리만의 필터를 만들어 볼거에요.

com.keichee.demo 패키지 아래에 filter 패키지를 만들고 이 안에 RequestLoggingFilter 라는 클래스를 아래와 같이 만들어주세요

package com.keichee.demo.filter;

import lombok.extern.slf4j.Slf4j;
import org.springframework.web.filter.AbstractRequestLoggingFilter;
import org.springframework.web.util.ContentCachingRequestWrapper;

import javax.servlet.FilterChain;
import javax.servlet.ServletException;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.io.IOException;

@Slf4j
public class RequestLoggingFilter extends AbstractRequestLoggingFilter {

    @Override
    protected void beforeRequest(HttpServletRequest request, String message) {
        logger.info(message);
    }

    @Override
    protected void afterRequest(HttpServletRequest request, String message) {
        logger.info(message);
    }
}

이제 이 필터를 빈으로 등록해줘야 합니다.

com.keichee.demo 패키지 아래에 config 패키지를 만들고 이 안에 RequestLoggingConfig 클래스를 만들겠습니다.

package com.keichee.demo.config;

import com.keichee.demo.filter.RequestLoggingFilter;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;

@Configuration
public class RequestLoggingConfig {

    public static int MAX_PAYLOAD_LENGTH = 1000;

    @Bean
    public RequestLoggingFilter loggingFilter() {
        RequestLoggingFilter filter = new RequestLoggingFilter();
        filter.setIncludeClientInfo(true);
        filter.setIncludeHeaders(false);
        filter.setIncludePayload(true);
        filter.setIncludeQueryString(true);
        filter.setMaxPayloadLength(MAX_PAYLOAD_LENGTH);
        return filter;
    }
}

헤더정보 로깅이 필요할 경우 setIncludeHeaders(true)로 설정해주시면 됩니다.

payload의 max length는 로깅량과 로그를 저장하는 시스템의 용량 등에 따라 적당히 설정해주시면됩니다. 

이제 마지막 한스텝이 남았습니다.

logback-spring.xml 파일을 resources 디렉토리에 추가해줍니다.

<?xml version="1.0" encoding="UTF-8"?>

<configuration>

    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    <include resource="org/springframework/boot/logging/logback/console-appender.xml"/>

    <springProfile name="local">
        <logger name="com.keichee.demo" level="debug" additivity="false">
            <appender-ref ref="CONSOLE"/>
        </logger>

        <root level="error">
            <appender-ref ref="CONSOLE"/>
        </root>
    </springProfile>

</configuration>

지금까지 작성한 파일들을 포함하여 최종적으로 패키지 트리를 보면 아래와 같습니다.

이제 active profile 값에 local 을 주고 앱을 재기동한뒤 필터가 정상적으로 적용되었는지 확인해보겠습니다.

2022-09-16 07:28:54.399 DEBUG 31518 --- [           main] com.keichee.demo.DemoLoggingApplication  : Running with Spring Boot v2.7.3, Spring v5.3.22
2022-09-16 07:28:54.399  INFO 31518 --- [           main] com.keichee.demo.DemoLoggingApplication  : The following 1 profile is active: "local"
2022-09-16 07:28:54.751 DEBUG 31518 --- [           main] c.k.demo.filter.RequestLoggingFilter     : Filter 'loggingFilter' configured for use
2022-09-16 07:28:54.866  INFO 31518 --- [           main] com.keichee.demo.DemoLoggingApplication  : Started DemoLoggingApplication in 0.607 seconds (JVM running for 0.819)

출력되는 로그 중에 Filter 'loggingFilter' configured for use 가 출력된걸로 보아 정상적으로 적용이 된 것으로 확인됩니다.

이제 기존에 만들어 두었던 API를 다시 호출해보겠습니다.

2022-09-16 07:29:18.541  INFO 31518 --- [nio-8080-exec-2] c.k.demo.filter.RequestLoggingFilter     : Before request [GET /test/log?code=2, client=0:0:0:0:0:0:0:1]
2022-09-16 07:29:18.550  INFO 31518 --- [nio-8080-exec-2] c.k.demo.controller.TestController       : requestResponseLog method called with code 2
2022-09-16 07:29:18.560  INFO 31518 --- [nio-8080-exec-2] c.k.demo.filter.RequestLoggingFilter     : After request [GET /test/log?code=2, client=0:0:0:0:0:0:0:1]

요청에 대한 정보 uri와 query parameter 그리고 client에 X-Forwarded-For 값이 출력된 것을 볼 수 있고, 비즈니스 로직 실행이 끝난 뒤 소요시간이 얼마인지 http status 값이 뭔지 출력되는 것을 확인할 수 있습니다.

지금까지 요청에 대한 uri, query parameter와 API를 요청한 클라이언트의 IP 를 출력하고,

응답을 주기까지의 소요시간과 응답 상태값을 로깅하도록 설정을 해보았습니다. 여기까지 잘 따라 오셨나요? 😋

이제 request body 를 입력받아 payload가 잘 출력되는지 보겠습니다.

TestController 에 request body를 받는 API를 하나 추가하겠습니다.

@PostMapping("/request-body-log")
public long requestBodyLog(@RequestBody Employee employee) {
    return employee.getId();
}

Employee 정보를 받아서 id를 그대로 리턴해주는 간단한 API입니다. (어차피 request body 로깅을 위한거니 심플하게 

그리고 domain 패키지 하위에 Employee 클래스를 아래와 같이 생성해주겠습니다.

@Getter
@Setter
@FieldDefaults(level = AccessLevel.PRIVATE)
public class Employee {
    long id;
    String name;
    int age;
}

이제  앱을 기동해서 postman으로 테스트를 해보겠습니다.

로그는 아래와 같이 출력되었습니다.

2022-09-16 07:32:49.190  INFO 31518 --- [nio-8080-exec-5] c.k.demo.filter.RequestLoggingFilter     : Before request [POST /test/request-body-log, client=0:0:0:0:0:0:0:1]
2022-09-16 07:32:49.226  INFO 31518 --- [nio-8080-exec-5] c.k.demo.filter.RequestLoggingFilter     : After request [POST /test/request-body-log, client=0:0:0:0:0:0:0:1, payload={
    "id":1000,
    "name":"케이치",
    "age":20
}]

그런데 로그를 보니 uri 정보와 client 정보가 중복되서 출력이 되고 있고, request body로 넘겨준 데이터가 비즈니스 로직이 모두 실행되고 난 뒤에 출력되는 After request ... 부분에 출력이 되고 있습니다. 뭔가 출력되는 내용이 마음에 들지 않네요. 

다음 포스팅에서는 로그메시지를 바꿔보도록 하겠습니다.

읽어주셔서 감사합니다~ 🙇

도움이 되셨다면 좋아요 꾹 눌러주고 가세요~

[ 다음 포스팅 바로 읽기 ]