Spring Boot LogBack 적용하기

스프링부트로 개발을 하다가 프론트쪽에서 어떠한 문제가 발생해서 해당 문제를 해결하기 위해 서버쪽에서 어떤 요청이 들어왔는지 확인해야했는데 직접 Break Point를 찍어서 확인하다보니 너무 불편했습니다. 그래서 요청이 들어왔을 때 직접 Break Point를 찍으면서 확인하는게 아닌 일괄적으로 Console에 남기고 싶어졌습니다. System.out.println으로 할 수도 있겠지만 따로 레벨(디버그, 에러)을 정할 수 도 없고 나중에 로그를 파일로 남기려고 할 때 추가적인 작업이 들어가기 때문에 Logging 프레임워크를 사용하기로 했습니다. 스프링부트에서 기본적으로 지원하는 Logging 프레임워크는 Logfj, Logback가 있습니다.

Logfj vs LogBack

LogBack 같은경우는 Logfj를 만들었던 개발자가 따로 제작한 프레임워크이며 Logfj의 컨셉을 토대로 만들었습니다. Logfj의 성능을 더 개선시키고 Slf4j도 지원하도록 개발하였고 고급 필터링 옵션 등등 몇 가지 향상된 기능을 포함하고 있습니다. 이렇기 때문에 LogBack를 선택하게 되었습니다.

LogBack Architecture

LogBack logback-core, logback-classic 그리고 logback-access 3개의 모듈로 나눠집니다. Core Module은 나머지 두 모듈의 기반을 다지고 Classic 모듈은 이러한 Core 모듈을 확장시킵니다. 또한 Classic 모듈은 Log4j의 상당히 개선된 버전이라고 보시면 됩니다. 또한 이 모듈은 slf4j api를 기본적으로 구현하고 있기 때문에 다른 Logging Framework로 마이그레이션 하기 쉽습니다. 마지막 모듈인 logback-access 모듈은 서블릿 컨테이너와 통합되어 Http Access 로그 기능을 제공합니다.

Logger, Appenders And Layouts

LogBack은 Logger, Appender 그리고 Layout 클래스 기반으로 되어있습니다. 이 세가지에 대해서 한번 알아보도록 하겠습니다. Logger 클래스는 classic 모듈에 포함되어있습니다 반면에 Appender나 Layout 같은 경우는 core 모듈에 위치하고 있습니다. 이러한 이유로 Core 모듈에는 Logger 클래스가 존재하지 않기 때문에 Logger 개념이 존재하지 않습니다.

Logger Effective Level

Logging Api가 System.out.println 보다 더 좋은 이유는 특정 로그를 비활성화 시키고 다른 로그문은 제약 없이 출력할 수 있다는 점 입니다. 이러한 기능은 Logger Efftive Level 덕에 가능합니다. Logger Level은 Trace, Debug, Info, Warn, Error 이렇게 존재합니다. 또한 Logger는 네이밍에 따른 부모 자식 관계를 맺을 수 있습니다. 예를들어 xxx라는 네임이 있다면 xxx는 xxx.yyy의 부모가 됩니다, xxx.yyy는 xxx의 자식이 되는거구요 이렇게 .을 통해서 계층구조를 만들 수 있습니다. 이러한 부모 자식 관계는 Effective Level 설정할 때 유용하게 사용할 수 있습니다. Efftive Level은 아래와 같습니다.

만약 부모 Level이 Trace라면 자식 Level도 Default로 Trace로 설정이 됩니다. 부모 Level이 Debug라면 자식 Level도 Debug로 설정됩니다.

Appenders and Layouts

Logback은 로깅 요청을 여러곳에 보내 출력할 수 도있습니다. Logback에서 출력 대상을 Appender라고 부릅니다. 현재는 Console, File, Socket Server, Mysql, PostgreSQL 및 기타 데이터베이스 이러한 여러개의 Appender를 로거에 부착할 수 있습니다. Layout 같은 경우는 출력 포맷을 Customize할 때 사용하게 됩니다. 예를들어 Pattern이 “%-4relative [%thread] %-5level %logger{32} - %msg%n” 이렇게 되어있으면

176  [main] DEBUG manual.architecture.HelloWorld2 - Hello world.

위와 같이 표시됩니다. 자세한 내용은 https://logback.qos.ch/manual/layouts.html 와 https://logback.qos.ch/manual/appenders.html에서 확인하실 수 있습니다.

Logback Configuration

Logback 설정을 위해 Logback 설정 관련 구성을 코드로 작성하거나 XML 혹은 Groovy를 통해 설정 할 수 있습니다. 참고로 log4j.properties 파일을 logback.xml로 변환시킬 수 있습니다. Logback은 ServiceLoader를 통해 Custom Configurator를 찾습니다. 만약 찾았다면 DefaultJoranConfigurator보다 우선시 합니다. Custom Configurator는 Configurator를 구현해야합니다. 만약 Custom Configurator를 찾지 못하면 DefaultJoranConfigurator가 인스턴스화되고 실행됩니다. logback.configurationFile이 설정된 경우 DefaultJoranConfigurator는 위에서 언급한 시스템 속성에 지정된 파일을 찾으려고 시작합니다. 만약 이전 과정에서 실패했다면 DefaultJoranConfigurator는 ClassPath에서 logback-test.xml 구성파일을 찾습니다. 아무 파일도 찾을 수 없다면 logback.xml 파일을 ClassPath에서 찾으려고 시도합니다. 두 과정 모두 실패했을 경우에는 DefaultJoranConfigurator는 더이상 처리하지 않고 return 합니다. 그리고 BasicConfigurator로 자동 설정됩니다. 설정 방법은 https://logback.qos.ch/manual/configuration.html를 참고해주세요.

Spring Boot LogBack Configuration

이제는 Spring Boot에서 LogBack Configuration을 설정하는 방법에 대해 알아보도록 하겠습니다. 간단하게 logback-spring.xml을 생성해주고 해당 파일에 Log에 대한 설정을 해주면 됩니다. 또는 application.properties에 logging.config = classpath:configuration.xml 이런식으로 설정해줘서 내가 원하는 네이밍의 configuration을 생성해 줄 수 있습니다.

<configuration scan="true" scanPeriod="60 seconds">
    <property name="LOG_PATH" value="log"/>
    <property name="LOG_FILE_NAME" value="errorLog"/>
    <property name="LOG_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [traceId=%X{traceId}] [%thread] [%logger{40}] - %msg%n"/>

    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <Pattern>${LOG_PATTERN}</Pattern>
        </encoder>
    </appender>

    <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">

        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>ERROR</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>

        <file>${LOG_PATH}/${LOG_FILE_NAME}.log</file>

        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>${LOG_PATTERN}</pattern>
        </encoder>

        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOG_PATH}/%d{yyyy-MM, aux}/${LOG_FILE_NAME}.%d{yyyy-MM-dd}.log</fileNamePattern>
            <totalSizeCap>20GB</totalSizeCap>
        </rollingPolicy>

    </appender>

    <root level="INFO">
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="FILE"/>
    </root>
</configuration>

resource 폴더 안에 해당 xml 파일을 생성해주도록 합시다. 이제 xml 파일을 하나하나 살펴보도록 하겠습니다.

<configuration scan="true" scanPeriod="60 seconds">

scan을 true로 설정하고 scanPeriod를 60 seconds로 설정 해주었습니다. scan true는 configuration이 바뀌었는지 체크하는걸 허용하고 자동으로 재구성하게 됩니다. scanPeriod로 scan을 반복할 시간을 설정해 줄 수 있습니다. milliseconds, seconds, minutes or hours. 이렇게 설정이 가능한데 밀리초, 초, 분, 시 이렇게 설정할 수 있습니다.

<property name="LOG_PATH" value="log"/>
<property name="LOG_FILE_NAME" value="errorLog"/>
<property name="LOG_PATTERN" value="%d{yyyy-MM-dd HH:mm:ss.SSS} %-5level [traceId=%X{traceId}] [%thread] [%logger{40}] - %msg%n"/>

property 같은 경우에는 변수를 선언할 때 사용하게 됩니다. 주로 반복적으로 쓰이는 것들로 구성되어있습니다. 여기서 LOG_PATH 는 Log가 저장될 경로 입니다. /를 같이 입력해주면 최상위 경로에 생성이 되고 /를 입력하지 않으면 프로젝트 경로에 생성이 됩니다. LOG_PATEERN을 보시면 맨 앞 %d 부분은 로그가 생성된 날짜 및 시간을 나타냅니다. %-5level은 Log의 Level을 나타냅니다. %X로 표시한 부분은 traceId가 적혀있는데 MDC라고 해서 Mapped Diagnostic Context라고 있는데 이것은 복잡한 분산 응용프로그램에서 디버깅하기 위해 만들어진 것으로 일반적인 멀티쓰레드 환경을 고려해서 나온것입니다. 여러 요청들은 다중 쓰레드에서 처리가 되기 때문에 이러한 요청이 섞이게 되면 식별하기가 어려워지는데 이러한 문제점을 해결하기 위해 나온것이 MDC입니다. Thread Local에 Key-Value 형태로 저장해서 사용하게 됩니다. 그래서 한 요청에 대한 로그을 판단하기 위해 나중에 설정하게 될 UID 값인 traceId를 넣어주었습니다. %thread는 쓰레드의 이름을 나타냅니다. %logger는 Logger의 이름을 나타내고 괄호안에 숫자는 Logger의 이름의 최대길이를 나타냅니다. 만약 해당 길이보다 더 크다면 자동으로 단축해서 출력됩니다. %msg는 Logger의 메세지를 나타내고 %n은 줄바꿈을 나타냅니다.

 <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
     <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
          <Pattern>${LOG_PATTERN}</Pattern>
     </encoder>
 </appender>

appender같은 경우는 출력 대상을 나타냅니다. 여기서 설정한 ConsoleAppender는 Console에 출력시켜주게 됩니다. encoder 같은 경우는 이벤트를 바이트 배열로 변환하고 해당 바이트 배열을 OutputStream으로 쓰는 역할을 합니다. 어떻게 출력될 것인지 위에 선언해 두었던 LOG_PATTERN을 사용해서 pattern을 지정해 줍니다.

<appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">

      <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>ERROR</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
      </filter>

      <file>${LOG_PATH}/${LOG_FILE_NAME}.log</file>

      <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <pattern>${LOG_PATTERN}</pattern>
      </encoder>

      <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOG_PATH}/%d{yyyy-MM, aux}/${LOG_FILE_NAME}.%d{yyyy-MM-dd}.log</fileNamePattern>
            <totalSizeCap>20GB</totalSizeCap>
      </rollingPolicy>
</appender>

해당 appender는 log를 파일로 저장하기 위해 RollingFileAppender를 사용하고 있습니다. 여기서 filter는 해당 appender가 동작할 조건을 나타냅니다. 로그의 레벨이 Error일 때만 동작하게 할 것이기 때문에 LevelFilter를 사용하였습니다. 다음은 file인데요 file 태그는 로그의 파일이름을 나타냅니다. 그래서 위에서 선언했던 LOG_PATH와 LOG_FILE_NAME을 통해서 지정해 줍니다. encoder는 ConsoleAppender와 마찬가지로 설정해 줍니다. rollingPolicy는 Rollover가 발생할 때 RollingFileAppender의 동작을 지시하는 구성 요소입니다. 시간을 기준으로 롤오버 정책을 정의하기 위해 TimeBasedRollingPolicy를 사용하였습니다. fileNamePattern 프로퍼티는 롤오버된 로그 파일의 이름을 정의합니다. totalSizeCap 프로퍼티는 모든 로그파일의 총 크기를 제어해서 가장 오래된 로그 파일은 한도를 초과하게 되면 비동기식으로 삭제됩니다.

<root level="INFO">
        <appender-ref ref="CONSOLE"/>
        <appender-ref ref="FILE"/>
</root>

root는 전역적인 로그 설정을 할 때 사용됩니다. level은 info로 설정해 주었고 CONSOLE, FILE appender를 추가해주었습니다. 만약 지역적으로 설정해 줄 때는 logger을 통해서 설정해 줄 수 있습니다.

Request Response 로그 작성하기

Request Response 관련해서 로그를 작성하기 위해 Filter에서 처리해 줄지 Controller에서 Aspect를 통해 처리해 줄지 고민하다가 요청은 웹레이어 쪽에서 들어와서 컨트롤러로 넘겨주기 때문에 웹레이어 부분에서 에러가 발생하면 컨트롤러까지 가지 않기 때문에 요청에 대한 로그를 남기는 요구사항을 처리하기 위해서는 Filter에서 처리해주는게 좋다고 생각이들어서 Logging용 Filter를 생성해 주었습니다. 코드는 아래와 같습니다.

@Slf4j
public class LoggingFilter extends OncePerRequestFilter {
    @Override
    protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {
        MDC.put("traceId", UUID.randomUUID().toString());
        doFilterWrapped(request, response, filterChain);
        MDC.clear();
    }

    public void doFilterWrapped(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws IOException, ServletException {
        HttpServletRequest requestWrapper = getWrappedRequest(request);
        ContentCachingResponseWrapper responseWrapper = new ContentCachingResponseWrapper(response);
        try {
            logRequest(requestWrapper);
            doFilter(requestWrapper, responseWrapper, filterChain);
        } finally {
            logResponse(responseWrapper);
            responseWrapper.copyBodyToResponse();
        }
    }

    public void logRequest(HttpServletRequest request) throws IOException {
        String queryString = request.getQueryString();
        String prefix = "Request";
        log.info("Request : {} uri=[{}] content-type=[{}]",
                request.getMethod(),
                queryString == null ? request.getRequestURI() : request.getRequestURI() + queryString,
                request.getContentType()
        );
        if(request.getContentType() == null)
            return;
        if(request instanceof ReReadableRequestWrapper){
            logPayload(prefix,request.getInputStream());
        } else{
            logPayload(prefix, request.getParameterMap());
        }

    }

    public void logResponse(ContentCachingResponseWrapper response) throws IOException {
        logPayload("Response", response.getContentInputStream());
    }

    private void logPayload(String prefix, InputStream inputStream) throws IOException {
        byte[] content = StreamUtils.copyToByteArray(inputStream);
        if (content.length > 0) {
            String contentString = new String(content);
            log.info("{} Payload: {}", prefix, contentString);
        }
    }

    public HttpServletRequest getWrappedRequest(HttpServletRequest request) throws IOException {
        if(!needParameterPayload(request.getContentType()) && request.getContentType() != null)
            return new ReReadableRequestWrapper(request);
        else
            return request;
    }

    private boolean needParameterPayload(String contentType) {
        return (contentType.equalsIgnoreCase(MediaType.APPLICATION_FORM_URLENCODED_VALUE) ||
                contentType.startsWith(MediaType.MULTIPART_FORM_DATA_VALUE));
    }

    private void logPayload(String prefix, Map<String,String[]> parameter) throws IOException {
        log.info("{} Payload: {}", prefix, getParameterString(parameter));
    }

    private String getParameterString(Map<String,String[]> parameter){
        return parameter.entrySet().stream()
                .map(e -> "["+e.getKey() + " : " + String.join(", ",e.getValue())+"]")
                .collect(Collectors.joining(", "));
    }

}

OncePerRequestFilter같은 경우는 한 요청당 한번만 실행하도록 동작하는 Filter입니다. 로그를 찍을 것 이기때문에 여러번 실행되면 의미없는 로그가 찍히기 때문에 그걸 방지하고자 OncePerRequestFilter를 사용하게 되었습니다. 코드가 상당히 긴대요 위에서 부터 한번 분석해 보겠습니다.

protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws ServletException, IOException {
        MDC.put("traceId", UUID.randomUUID().toString());
        doFilterWrapped(request, response, filterChain);
        MDC.clear();
    }

doFilterInternal로직을 보면 먼저 MDC에 로그 식별자로 쓰일 Key traceId 그리고 Value가 UUID인 한 쌍을 넣어줍니다. 그다음 doFilterWrapped 메서드를 호출하는데 해당 메서드는 아래에서 설명하겠습니다. 그리고 MDC를 비워줍니다.

public void doFilterWrapped(HttpServletRequest request, HttpServletResponse response, FilterChain filterChain) throws IOException, ServletException {
        HttpServletRequest requestWrapper = getWrappedRequest(request);
        ContentCachingResponseWrapper responseWrapper = new ContentCachingResponseWrapper(response);
        try {
            logRequest(requestWrapper);
            doFilter(requestWrapper, responseWrapper, filterChain);
        } finally {
            logResponse(responseWrapper);
            responseWrapper.copyBodyToResponse();
        }
    }

public HttpServletRequest getWrappedRequest(HttpServletRequest request) throws IOException {
        if(!needParameterPayload(request.getContentType()) && request.getContentType() != null)
            return new ReReadableRequestWrapper(request);
        else
            return request;
}

private boolean needParameterPayload(String contentType) {
        return (contentType.equalsIgnoreCase(MediaType.APPLICATION_FORM_URLENCODED_VALUE) ||
                contentType.startsWith(MediaType.MULTIPART_FORM_DATA_VALUE));
}

doFilterWrapped 메서드입니다. 먼저 왜 Request를 따로 Wrapping하는지 부터 설명하겠습니다. Tomcat의 Request에 inputStream을 통해 클라이언트에서 getWrappedRequest 메서드를 호출해서 만약에 요청의 ContentType이 form-data 거나 form-urlencoded인 경우에는 getParameter를 통해 Content에 대한 값을 가져올거라 InputStream으로 Content를 가져오지 않아도 되기 때문에 따로 ReReadableRequestWrapper로 감싸주지 않아도 됩니다. 또한 ContentType null인 경우 Payload에 대한 로그를 작성하지 않을 것 이기 때문에 ContentType이 null인 경우에도 감싸주지 않습니다. 그다음 먼저 Request에 대한 로그를 작성하는 logRequest 메서드를 실행 시키고 그 다음 필터를 동작시킵니다. 그래서 모든 요청이 처리되고 finally에서 Response에 대한 로그를 작성하는 logResponse 메서드를 호출해 줍니다. 그 다음 responseWrapper.copyBodyToResponse()를 호출해 주는데 이걸 설명하기 위해 잠시 ContentCachingResponseWrapper가 어떤방식으로 Caching하는지 알아보도록 하겠습니다.

private final FastByteArrayOutputStream content = new FastByteArrayOutputStream(1024);
@Override
	public ServletOutputStream getOutputStream() throws IOException {
		if (this.outputStream == null) {
			this.outputStream = new ResponseServletOutputStream(getResponse().getOutputStream());
		}
		return this.outputStream;
	}

private class ResponseServletOutputStream extends ServletOutputStream {

		private final ServletOutputStream os;

		public ResponseServletOutputStream(ServletOutputStream os) {
			this.os = os;
		}

		@Override
		public void write(int b) throws IOException {
			content.write(b);
		}

		@Override
		public void write(byte[] b, int off, int len) throws IOException {
			content.write(b, off, len);
		}

		@Override
		public boolean isReady() {
			return this.os.isReady();
		}

		@Override
		public void setWriteListener(WriteListener writeListener) {
			this.os.setWriteListener(writeListener);
		}
	}

위 코드는 ContentCachingResponseWrapper의 일부 코드인데요 getOutputStream을 오버로드해서 outputStream을 ResponseServletOutputStream으로 wrapping해서 반환해 주는데요 ResponseServletOutputStream는 write할 때 FastByteArrayOutputStream인 content에 write를 해주게 됩니다. FastByteArrayOutputStream의 write 메서드를 보면 아래와 같습니다.

@Override
	public void write(int datum) throws IOException {
		if (this.closed) {
			throw new IOException("Stream closed");
		}
		else {
			if (this.buffers.peekLast() == null || this.buffers.getLast().length == this.index) {
				addBuffer(1);
			}
			// store the byte
			this.buffers.getLast()[this.index++] = (byte) datum;
		}
	}

	@Override
	public void write(byte[] data, int offset, int length) throws IOException {
		if (offset < 0 || offset + length > data.length || length < 0) {
			throw new IndexOutOfBoundsException();
		}
		else if (this.closed) {
			throw new IOException("Stream closed");
		}
		else {
			if (this.buffers.peekLast() == null || this.buffers.getLast().length == this.index) {
				addBuffer(length);
			}
			if (this.index + length > this.buffers.getLast().length) {
				int pos = offset;
				do {
					if (this.index == this.buffers.getLast().length) {
						addBuffer(length);
					}
					int copyLength = this.buffers.getLast().length - this.index;
					if (length < copyLength) {
						copyLength = length;
					}
					System.arraycopy(data, pos, this.buffers.getLast(), this.index, copyLength);
					pos += copyLength;
					this.index += copyLength;
					length -= copyLength;
				}
				while (length > 0);
			}
			else {
				// copy in the sub-array
				System.arraycopy(data, offset, this.buffers.getLast(), this.index, length);
				this.index += length;
			}
		}
	}

addBuffer를 통해 buffers에 byte를 저장해줍니다. 이 buffer는 getInputStream에서 사용이 되는데요

public InputStream getInputStream() {
		return new FastByteArrayInputStream(this);
}

public FastByteArrayInputStream(FastByteArrayOutputStream fastByteArrayOutputStream) {
			this.fastByteArrayOutputStream = fastByteArrayOutputStream;
			this.buffersIterator = fastByteArrayOutputStream.buffers.iterator();
			if (this.buffersIterator.hasNext()) {
				this.currentBuffer = this.buffersIterator.next();
				if (this.currentBuffer == fastByteArrayOutputStream.buffers.getLast()) {
					this.currentBufferLength = fastByteArrayOutputStream.index;
				}
				else {
					this.currentBufferLength = (this.currentBuffer != null ? this.currentBuffer.length : 0);
				}
			}
		}

FastByteArrayInputStream을 생성할 때 FastByteArrayInputStream의 buffersIterator에 FastByteArrayOutputStream의 buffers의 iterator를 설정해주게 됩니다. 그래서 결과적으로 ContentCachingResponseWrapper의 InputStream을 read할 때 buffers의 iterator를 기반으로 읽기 때문에 캐시가 유지될 수 있습니다. 하지만 ContentCachingResponseWrapper의 getContentInputStream 메서드를 통해서만 캐싱된 결과를 가져올 수 있기 때문에 http로 보낼때에는 ContentCachingResponseWrapper의 getContentInputStream으로 받아와서 하는게 아닌 HttpServletResponse의 getInputStream 통해 Response를 생성하기 때문에 copyBodyToResponse 메서드를 통해 HttpServletResponse에 캐시 값을 다시 써주는 작업을 해줘야 정상적으로 Response를 생성할 수 있습니다. 다음으로 ReReadableRequestWrapper에 대해서 한번 살펴 보겠습니다.

public class ReReadableRequestWrapper extends HttpServletRequestWrapper {
    private final byte[] rawData;

    public ReReadableRequestWrapper(HttpServletRequest request) throws IOException {
        super(request);
        InputStream inputStream = request.getInputStream();
        this.rawData = StreamUtils.copyToByteArray(inputStream);
    }

    @Override
    public ServletInputStream getInputStream() {
        final ByteArrayInputStream byteArrayInputStream = new ByteArrayInputStream(this.rawData);
        return new ServletInputStream() {
            @Override
            public boolean isFinished() {
                return byteArrayInputStream.available() == 0;
            }

            @Override
            public boolean isReady() {
                return true;
            }

            @Override
            public void setReadListener(ReadListener listener) {
                throw new UnsupportedOperationException();
            }

            public int read() {
                return byteArrayInputStream.read();
            }
        };
    }

}

단순하게 content를 캐싱할 것이기 때문에 getInputStream 부분만 Override 해주었습니다. 일단 생성할 때 request에 있는 inputStream을 이용해서 content를 따로 byteArray로 변환시켜서 캐싱해줍니다. 그다음 getInputStream 메서드에서 매번 ServletInputStream을 생성해주고 아까 캐싱했던 content를 기반으로 ByteArrayInputStream도 생성해줍니다. 이렇게 해주게되면 매번 값을 읽더라도 캐싱된 결과를 계속 읽을 수 있게 됩니다. 다음은 logRequest와 logPayload 메서드입니다.

public void logRequest(HttpServletRequest request) throws IOException {
        String queryString = request.getQueryString();
        String prefix = "Request";
        log.info("Request : {} uri=[{}] content-type=[{}]",
                request.getMethod(),
                queryString == null ? request.getRequestURI() : request.getRequestURI() + queryString,
                request.getContentType()
        );
        if(request.getContentType() == null)
            return;
        if(request instanceof ReReadableRequestWrapper){
            logPayload(prefix,request.getInputStream());
        } else{
            logPayload(prefix, request.getParameterMap());
        }

    }

private void logPayload(String prefix, InputStream inputStream) throws IOException {
        byte[] content = StreamUtils.copyToByteArray(inputStream);
        if (content.length > 0) {
            String contentString = new String(content);
            log.info("{} Payload: {}", prefix, contentString);
        }
    }

private void logPayload(String prefix, Map<String,String[]> parameter) throws IOException {
        log.info("{} Payload: {}", prefix, getParameterString(parameter));
    }

private String getParameterString(Map<String,String[]> parameter){
        return parameter.entrySet().stream()
                .map(e -> "["+e.getKey() + " : " + String.join(", ",e.getValue())+"]")
                .collect(Collectors.joining(", "));
    }

logRequest 메서드를 보면 먼저 uri, contentType, http method, queryString을 포함하는 로그를 작성해줍니다. 그 다음에는 contentType이 null인지 체크해줍니다 만약 null이라면 Get 요청이거나 content가 없는경우기 때문에 payLoad에 대한 로그를 작성할 필요가 없어서 ealry return 시켜줍니다. 그 다음에 requset 객체가 ReReadableRequestWrapper인 경우에는 inputStream에 대해 payLoad 로그를 작성하고 그렇지 않은 경우는 parmeterMap에 대한 payLoad 로그를 작성해줍니다. 마지막으로 logResponse 메서드에 대해 이야기 하겠습니다.

public void logResponse(ContentCachingResponseWrapper response) throws IOException {
        logPayload("Response", response.getContentInputStream());
    }

Response는 항상 inputStream에 대한 payload 로그를 작성하기 때문에 위와같이 작성해주었습니다.

마무리

이렇게 Filter를 통해 Logging 처리를 해주었는데요 ContentType을 고려해서 작성했어야 했기 때문에 많이 어려웠던 것 같습니다. 사실 서블릿에서 발생하는 에러는 직접 핸들링 하기엔 쉽지않고 발생할 여지가 많이 없기 때문에 Filter로 처리하는 것보다 어쩌면 Aspect를 통해 더 세밀하고 간단하게 Logging 처리를 하는게 좋지 않았나 싶습니다. 그래도 많은것을 배울수 있어서 정말 좋았습니다.

참고자료

https://logback.qos.ch/manual/index.html

https://meetup.nhncloud.com/posts/44

https://prohannah.tistory.com/182