[Spring] Custom Filter로 로그 파밍하기 (CloudWatch X Logback)

 

들어가기 전에

모든 요청과 응답 로그를 Logback 설정을 통해 CloudWatch에 적재하기로 했다. 이미 CloudWatchLogsClient를 활용해서 로그를 적재하는 코드가 있었기 때문에 굳이 구현 방법을 변경할 필요는 없었지만, Logback 설정을 통해 적재했을 때 어떤 장점과 단점이 있는지 그리고 우리가 구현하고자 하는 방향과 어느 것이 더 맞는지 확인해 보기로 했다.

 

시작하기에 앞서 이번 글은 CloudWatch 적재에 초점을 둔 만큼 Loback 설정에서 다양한 방법으로 로그를 적재하는 방법은 다루지 않는다. console로 출력하거나 file로 저장하는 등의 방법을 설정하기 위해서는 아래와 같이 appender를 사용하면 된다.

 

// 출처 : https://docs.spring.io/spring-cloud-sleuth/docs/current/reference/htmlsingle/logback-spring.xml
<configuration>
    <script/>
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    <springProperty scope="context" name="springAppName" source="spring.application.name"/>
    
    <property name="LOG_FILE" value="${BUILD_FOLDER:-build}/${springAppName}"/>
    
    <property name="CONSOLE_LOG_PATTERN" value="%clr(%d{yyyy-MM-dd HH:mm:ss.SSS}){faint} %clr(${LOG_LEVEL_PATTERN:-%5p}) %clr(${PID:- }){magenta} %clr(---){faint} %clr([%15.15t]){faint} %clr(%-40.40logger{39}){cyan} %clr(:){faint} %m%n${LOG_EXCEPTION_CONVERSION_WORD:-%wEx}"/>
    
    <appender name="console" class="ch.qos.logback.core.ConsoleAppender">
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
        	<level>DEBUG</level>
        </filter>
        <encoder>
            <pattern>${CONSOLE_LOG_PATTERN}</pattern>
            <charset>utf8</charset>
        </encoder>
    </appender>
    
    <!--  Appender to log to file  -->
    <appender name="flatfile" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${LOG_FILE}</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOG_FILE}.%d{yyyy-MM-dd}.gz</fileNamePattern>
            <maxHistory>7</maxHistory>
        </rollingPolicy>
        <encoder>
            <pattern>${CONSOLE_LOG_PATTERN}</pattern>
            <charset>utf8</charset>
        </encoder>
    </appender>
    
    <root level="INFO">
    <appender-ref ref="console"/>
    </root>
</configuration>

 

 

Customized Filter 구현

1) 미리 알아둬야 할 것들

먼저 모든 요청과 응답에 대한 정보를 수집하기 위해 Customized Filter를 구현할 것이다. 이때 Filter, Interceptor 그리고 AOP 중 어떤 것을 커스터마이즈하여 사용하느냐 선택할 수 있었는데 Filter로 구현하는 이유는 어떤 특정한 메서드나 특정 시점에 로직을 추가하여 조작하는 것이 필요한 게 아니었기 때문이다. 모든 요청에 대해 인증 Filter를 거친 후에 정보를 수집해 로그를 남기고 싶었던 목표와 일치하게 사용할 수 있었다. 더군다나 Spring이 이 작업을 편하게 할 수 있도록 관련 클래스를 제공해 주기도 했다. 

 

 

[Filter를 구현할 때 유의해야 할 점]

HTTP 프로토콜에서 요청 본문은 바이트 스트림을 사용해 전송한다. Stream의 특성 상 요청 본문을 단 한 번만 읽을 수 있다는 것을 알 수 있다.

On a high level, HttpServletRequest is designed for a one-time read, meaning that the input stream can typically 
ONLY be read once. This is due to the nature of HTTP protocol, where the request body is a stream of bytes that can only be read once. Once the stream is read, it cannot be reset to the start.

출처 : https://codippa.com/read-httpservletrequest-multiple-times-in-spring/

 

 

요청 본문을 읽기 위해 사용하는 HttpServeltRequest 인터페이스를 살펴보면 두 가지 주요 메서드인 getInputStream()과 getReader()를 제공한다.

Spring Boot uses the Servlet API, with the Dispatcher Servlet acting as the main entry point. The HttpServletRequest interface provides two primary methods to read the request body: getInputStream and getReader. These methods rely on the same InputStream, so once the stream is read, it cannot be read again. To solve this, we can cache the request content for multiple reads.

출처 : https://bootcamptoprod.com/read-request-body-multiple-times/

 

• getInputStream() : 바이트 기반 스트림으로 요청 본문을 ServletInputStream을 사용해 바이너리 데이터로 가져온다.
• getReader() : 문자 기반 스트림으로 요청 본문을 BufferedReader를 사용해 문자 데이터로 가져온다. 

 

두 메서드는 동일한 InputStream에 의존하기 때문에, 한 번 읽고 나면 다시 읽을 수 없다. 문제는 우리가 요청과 응답의 정보를 수집해 로그를 적재하기 위해 스트림을 읽어버리면 정작 실제로 데이터를 처리해야 하는 상황에 처리할 수 없다는 것이다. 예를 들면, 응답 본문이 담긴 스트림을 읽어버려 클라이언트에게 데이터를 전달할 수 없는 경우를 말한다.

 

 

그렇다면 어떻게 데이터를 여러 번 읽게 할 수 있을까?

다행히도 Spring이 여러 번 읽을 수 있게 캐싱 기능을 지닌 클래스들을 제공한다. 각각 요청과 응답 본문을 캐시할 수 있는 클래스들이다.

• ContentCachingRequestWrapper
• ContentCachingResponseWrapper

1️⃣ ContentCachingRequestWrapper

요청 본문을 읽을 때 캐싱하여 여러 번 읽을 수 있게 하는 역할을 한다. HttpServletRequestWrapper 추상 클래스를 상속받으며 HttpServletRequest 인터페이스를 구현한다. 

 

🏷️ 주요 메서드

// 캐시된 요청 본문을 바이트 배열로 반환한다. 
public byte[] getContentAsByteArray() {
    return this.cachedContent.toByteArray();
}

 

 

2️⃣ ContentCachingResponseWrapper

응답 본문을 읽을 때 캐싱하여 여러 번 읽을 수 있도록 하고 응답 데이터를 클라이언트에게 전송하는 역할을 한다. HttpServletResponseWrapper 추상 클래스를 상속받으며 HttpServletResponse 인터페이스를 구현한다. 

 

🏷️ 주요 메서드

// 캐시된 응답 본문을 바이트 배열로 반환한다. 
public byte[] getContentAsByteArray() {
    return this.content.toByteArray();
}

 

// 캐시된 응답 본문을 클라이언트에게 전송한다. 
// 만약 이 메소드가 실행되지 않으면 클라이언트에서는 응답 값을 받을 수 없게 된다.
public void copyBodyToResponse() throws IOException {
    this.copyBodyToResponse(true);
}

protected void copyBodyToResponse(boolean complete) throws IOException {
    if (this.content.size() > 0) {
        HttpServletResponse rawResponse = (HttpServletResponse)this.getResponse();
        if ((complete || this.contentLength != null) && !rawResponse.isCommitted()) {
            if (rawResponse.getHeader("Transfer-Encoding") == null) {
                rawResponse.setContentLength(complete ? this.content.size() : this.contentLength);
            }

            this.contentLength = null;
        }

        this.content.writeTo(rawResponse.getOutputStream());
        this.content.reset();
        if (complete) {
            super.flushBuffer();
        }
    }

}

 

 

2) 구현 코드

이제 위에서 배운 내용들을 활용해서 코드를 구현해 보자.

 

아래 커스텀 필터에서는 OncePerRequestFilter를 상속받아 doFilterInternal() 메서드를 구현한다. Spring은 해당 Filter가 요청 당 한 번만 실행되도록 보장해 주기 때문에 하나의 요청에 대해 요청과 응답 각 하나씩 로그가 적재되도록 할 수 있다.

 

CachingFilter.class

@Component
@WebFilter(filterName = "CachingFilter", urlPatterns = "/*") // Servlet Filter 선언
public class CachingFilter extends OncePerRequestFilter {
	
	private final static Logger log = LoggerFactory.getLogger(CachingFilter.class);
	
}

 

 

doFilterInternal() - overriding

@Override
protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain)
        throws ServletException, IOException {
    // 요청마다 고유 값 할당하여 로그 판별
    MDC.put("traceId", UUID.randomUUID().toString());
    if (isAsyncDispatch(request)) {
        filterChain.doFilter(request, response);
    } else {
        doFilterWrapped(new ContentCachingRequestWrapper(request), new ContentCachingResponseWrapper(response), filterChain);
    }
    MDC.clear();
}

• org.slf4j.MDC.put() 
  • MDC(Mapped Diagnostic Context)는 로그 메시지를 작성할 때 사용할 수 있는 정보들을 담는 맵 구조를 제공한다. 
  • 특정 스레드에서 설정한 정보를 로그 메시지와 함께 활용할 수 있기에 하나의 HTTP 요청에 대한 요청 및 응답 값을 판별하는 값으로 사용할 수 있게 된다.
• org.slf4j.MDC.clear()
  • 작업이 끝난 후 초기화한다.
• isAsyncDispatch()
  • 현재 요청이 비동기적으로 처리된 요청인지 확인하는 역할을 한다.
  • 비동기인 경우
    • 요청이 효율적으로 처리될 수 있도록 불필요한 캐싱 작업이 이루어지지 않도록 한다.
  • 비동기가 아닌 경우
    • doFilterWrapped() 메서드를 호출하여 해당 로그를 처리하는 작업을 수행한다. 
    • 이때 각 요청과 응답을 Wrapper 클래스로 생성하여 전달한다.

 

doFilterWrapped()

요청이 처리된 후 요청과 응답을 로깅하고, 최종적으로 응답 본문을 클라이언트에게 전달한다.

private void doFilterWrapped(ContentCachingRequestWrapper request, ContentCachingResponseWrapper response, FilterChain filterChain)
throws IOException, ServletException{
    try {
        filterChain.doFilter(request, response); // 요청 필터를 다음 필터로 전달
        logRequest(request); // 요청이 처리된 후 요청 내용을 로그로 기록
    } finally {
        logResponse(response); // 응답이 처리된 후 응답 내용을 로그로 기록
        response.copyBodyToResponse(); // 캐시된 응답 본문을 실제 응답으로 복사하여 클라이언트에게 최종 전달
    }
}

 

 

logRequest(), logResponse() - 로그 출력

/**
 * 요청 정보 로그 출력
 * @param request
 */
private void logRequest(ContentCachingRequestWrapper request) {
    // Logging 데이터 추출
    String method = request.getMethod();
    String requestURI = request.getRequestURI();
    String queryString = request.getQueryString();
    String clientIp = IpUtils.getClientIp(request);
    String body = new String(request.getContentAsByteArray());
    
    log.info("[REQUEST] {} uri = [{}], QueryString = [{}], ip = [{}], body = [{}] ", method, requestURI, queryString, clientIp, body);
}

/**
 * 응답 정보 로그 출력
 * @param response
 */
private void logResponse(ContentCachingResponseWrapper response) {
    log.info("[RESPONSE] body = [{}]", new String(response.getContentAsByteArray()));
}

 

 

AWS CloudWatch 설정

1) 사용자 설정

AWS > IAM > 사용자 추가를 통해 사용자를 생성해야 한다. 

 

1️⃣ 사용자 이름을 설정하고 자동 생성된 암호를 사용하도록 한다.

 

 

2️⃣ 권한 정책은 CloudWatchFullAccessV2를 선택한다.

 

 

3️⃣ 생성된 사용자를 클릭해 액세스 키를 만든다. 여기에서 만들어진 Access key Id와 Secret Access Key 정보를 통해 CloudWatch에 접근할 수 있으니 저장해 놓자.

 

 

 

 

2) 로그 그룹 생성 

CloudWatch > 로그 그룹을 통해 이름과 보존 기간을 설정하여 로그 그룹을 생성한다.

 

 

3) 민감 데이터 보호 설정 (선택 사항)

DB에는 암호화해서 넣어야 하는 데이터 혹은 암호화 데이터를 복호화 한 경우의 정보들을 모두 마스킹 처리하기 위해 데이터 보호 로그 그룹 정책을 설정했다.

 

1️⃣ CloudWatch > 로그그룹 중 데이터 보호 정책을 설정할 로그 그룹을 선택하여 정책을 생성한다.

 

 

2️⃣ AWS에서 제공하는 식별자 외에 사용자 지정 데이터 식별자를 구성할 수 있다. 이름과 정규식을 설정한다.

 

위의 식별자를 정의한 후에 데이터 보호를 활성화하면 로그 메시지에서 아래와 같이 마스킹 처리가 된 것을 확인할 수 있다.

-- 설정 전
"password":"password1234!"

-- 설정 후
**************************

 

 

🏷️ 참고. 일시적으로 마스킹을 해제한 데이터를 확인하고 싶다면 하위 기능을 사용하면 된다.

 

 

Logback 설정

1) 의존성 추가

CloudWatch로 로그를 전송하기 위한 Appender를 사용하기 위해 의존성을 추가해 준다.

// https://mvnrepository.com/artifact/ca.pjer/logback-awslogs-appender
implementation 'ca.pjer:logback-awslogs-appender:1.6.0'

 

 

2) logback-spring.xml 설정

필요한 값들을 설정한다.

 

1️⃣ logback-spring.xml

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    <appender name="CLOUDWATCH_LOGS" class="ca.pjer.logback.AwsLogsAppender">
      <layout>
          <pattern>[%X{traceId}] %-5level - %msg%n</pattern>
      </layout>
      <springProfile name="local, dev">
          <logGroupName>${LOG_GROUP_PREFIX}/dev</logGroupName>
      </springProfile>
      <springProfile name="prod">
          <logGroupName>${LOG_GROUP_PREFIX}/prod</logGroupName>
      </springProfile>
      <logRegion>ap-northeast-2</logRegion>
      <maxBatchLogEvents>50</maxBatchLogEvents>
      <maxFlushTimeMillis>30000</maxFlushTimeMillis>
      <maxBlockTimeMillis>5000</maxBlockTimeMillis>
      <retentionTimeDays>0</retentionTimeDays>

      <!-- AWS credentials -->
      <accessKeyId>${AWS_ACCESS_ID}</accessKeyId>
      <secretAccessKey>${AWS_SECRET_KEY}</secretAccessKey>
    </appender>
    
    <logger name="com.bubaum.ipss.has.filter.CachingFilter" level="INFO" additivity="false">
        <appender-ref ref="CLOUDWATCH_LOGS"/>
    </logger>
</configuration>

• appender
  • name : 원하는 이름으로 설정한다.
• layout
  • pattern : 원하는 로그 출력 형식을 설정한다.
• springProfile
  • local, dev 환경과 prod 환경에서 사용하는 로그 그룹이 달라 해당 태그를 사용해 설정해줬다.
  • 이번 설정의 경우 다른 옵션은 모두 동일하였고 만약 if 문을 통한 분기문을 사용하기 위해서는 의존성을 추가해줘야 하기 때문에 간단하게 처리하기 위해 사용했다.
• logRegion : 해당 AWS Region을 설정한다.
• maxBatchLogEvents : 플러시되기 전에 최대 몇 개의 로그 이벤트를 배치할 수 있는지를 정의한다. 기본 값은 50이다.
• maxFlushTimeMillis : 배치 크기가 충족되지 않더라도 플러시할 때까지 기다리는 최대 시간을 설정한다. 기본 값은 30000이다.
• maxBlockTimeMillis : 로그를 전송하기 위해 얼마나 오랫동안 기다릴지를 정의한다. 기본 값은 5000이다.
• retentionTimeDays : 로그 그룹의 보존 값으로 기본 값은 0이다.
• accessKeyId : AWS IAM 사용자의 액세스 키 아이디이다.
• secretAceessKey : AWS IAM 사용자의 시크릿 액세스 키이다.
• logger
  • name : 설정을 적용할 클래스를 설정한다.
  • level : 로그 레벨을 설정한다.
• appender-ref : 어떤 appender를 참조할 것인지 설정한다.

 

2️⃣ 환경변수 설정

IAM 사용자 정보와 로그 그룹 prefix 값을 애플리케이션 환경변수로 설정한다.

 

 

최종 결과

첫 요청과 응답이 발생하면 몇 초 이내로 아래와 같은 로그가 뜨는 것을 확인할 수 있다. 그 이후에 CloudWatch에 적재된 로그를 확인하자.

 

 

애플리케이션이 구동될 때마다 새로운 로그 스트림이 생성되며 내부에 로그가 적재되는데 간혹 빈 로그 스트림이 생기기도 한다.

 

 

정리

Logback 설정을 통해 모든 요청 및 응답 로그를 CloudWatch에 적재하는 작업을 마치고 간략하게 장점과 단점을 정리해 봤다. 여담이지만 이번 프로젝트에서는 해당 내용을 토대로 다시 CloudWatchLogsClient를 활용하기로 했다. 로그와 관련해서 세부적인 설정이 필요하지 않았고 어떤 것을 로깅할 것이냐가 명확하게 정해졌었기 때문에 로그스트림을 지정해 한꺼번에 요청과 응답 로그를 확인하는 게 좋겠다는 판단이 섰기 때문이다. 이렇게 프로젝트 상황에 따라 Logback 설정의 장점을 활용할 수 있을 때 사용하면 좋을 것 같다. 

 

 

[장점]

• 각종 상황에 따라 혹은 로그 레벨에 따라 콘솔 출력 및 파일 저장 등으로 작업해야 할 때 세세한 설정을 할 수 있다. 그외에도 로그 패턴을 커스터마이즈하거나 profile에 따른 값도 설정할 수 있다.
• 하나의 파일 안에서 설정 값들을 관리하기 용이하다.

 

[단점]

• 특정 로그 스트림으로 로그를 적재할 수 없어 전체 로그 관리가 용이하지 않다. (간혹 생기는 빈 스트림도 거슬린다.)
• CloudWatchLogsClient를 사용할 때와 비교해 적재되는 속도가 느리다.

 

 

참고

• logback-awslogs-appender
• Spring - Log Incoming Request
• Spring Boot 2 Request and Response Logging
• Spring Logging (1) : HTTP Request/Respone 로그 남기기
• [Java] MDC를 사용한 로그(Log)추적하기