로그 적용해보기

gnoesnooj·2022년 11월 5일

Java Spring log

로깅 적용기

로깅이란 ?

어떤 소프트웨어나 어플리케이션이 실행이 되면서 발생되는 이벤트들을 추적하여 기록하는 것을 의미한다.

왜 써야할까 ?

여태까지 내가 개발을 하면서 로그를 사용한 경험이 있는지 돌이켜 생각해보면, 상당히 많았다.

우선 단순하게 하나의 메소드를 작성할 때에도, 내가 원하는 값들이 제대로 들어가고 있는지 확인하기 위해 나뿐만 아닌 많은 사람들이 print문을 이용해서 값들을 확인했을 것이다.

또한 개발을 하면서 가끔 의도치 않은 uncheckedException 들이 발생했을 때에도 컴파일러가 알려주는 에러문구들을 확인하면서 고쳐 나갔을 것이다. 이러한 행동들 속에 나는 로그를 사용해왔다.

하지만 개발단계에서 이런 식으로의 로그방식은 적절치 않다고 생각했다.

우선 print 문을 사용하는 것 자체가 웹의 속도를 저하시킨다. print 문을 타고 들어가면 synchronized 로 묶여있어서, 다른 것들이 그 순간 멈추기때문에 속도 저하가 발생한다. (블로킹 발생)

또한 일일이 console에 찍히는 로그를 확인해가면서 에러를 찾는 방식은 비효율적이기 때문이다.

또한 콘솔에 찍는 것 보다 별도로 관리를 한다면, 시간이나 용량등에 맞춰서 로그 분할도 가능하고, 개발 단계에 맞춰서 로그 관리 또한 가능하다.

따라서 로깅을 적용하고, 콘솔이 아닌 로그파일을 따로 생성해줘서 관리해야겠다고 생각하게 되었다.

로깅 방법 선택

log4j 를 알고 있었는데, 명령어를 원하는 곳에서 실행할 수 있고, 이로 인해 사용자가 서버에 접속만 하더라도 공격자가 원격으로 조종할 수 있는 RCE 문제가 발생했다고 알고있어서, Slf4J - logback을 사용해야겠다고 생각했다.

(+) Slf4j 는 파사드 패턴을 활용한 방식이라고 한다. 대부분의 로깅 전략을 보면

SlifJ 를 거치고 있는 것을 볼 수 있다. 이로 인해 로깅 라이브러리를 교체하기에 용이한 장점이 있다고 한다.

(++) 파사드 패턴은 객체지향의 추상화를 생각하면 쉽게 이해할 수 있을 것 같다. API들을 하나의 인터페이스 API를 제공하는 것으로 기능을 묶어서 제공하는데에도 사용이 되고, 외부 라이브러리나 어플리케이션에서 사용할 때 내부의 코드에 의존하지 않도록 도와준다.

로그에 대한 좁았던 시야

try catch 나 Optional<T> 과 같이 예외가 발생할만한 부분에 커스터마이즈한 exception을 throw 해놨다. 따라서 Exception Handler를 통해서 이러한 예외상황들을 처리하게 해줬다. 따라서 exception handler에 우선 log를 적용했다.

하지만 log의 역할에 대해서 생각해보게 되었다.

로깅을 해주는 이유를 대부분 에러를 고치기 위함에 집중하고 있었던 것 같다. 맞는 말이긴 하지만, 에러를 고치는 것 뿐만 아니라 다른 상황에도 유용하게 사용되는 것이 로그라는 것을 알게 되었다.

최근 카카오를 비롯한 데이터센터 화재로 인해 여러 서비스에서 장애가 발생했다. 그 중 하나가 국민 대부분이 사용한다고 과언이 아닌 카카오톡에서의 장애도 포함이 되는데, 카카오 서비스에서 발생한 장애들을 고치는 데에 로그가 사용되었다고 들었다. 모든 서비스에서 Request 당시의 값들을 저장함으로써, 추후 정상적으로 request가 되었지만 그에 대한 response나 서비스 장애로 인해 유실될 때, 그 때 당시의 로그를 이용해서 처리가 가능하다고 한다.

이러한 사례를 접하고 나니, 에러 단에서만 log를 적용하는 것이 아닌, request를 모두 기록해줄 수 있도록 코드를 적용해보는 계기가 되었다.

프로젝트에 적용해보기

우선 로그 파일을 따로 관리하기 위해 RollingFileAppender 를 이용해서 파일로 따로 관리하도록 했다. 의 파일명을 통해서 경로명과 파일네임을 지정해줄 수 있고, 필요하다면 각 로그별로 번호를 매기거나 다른 파일로 관리도 가능하다.

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="30 seconds">
    <property name="LOG_DIR" value="log"></property>

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%d{yyyy-MM-dd HH:mm:ss.SSS}[%-5level] : %msg%n</pattern>
        </encoder>
    </appender>
    <appender name="ROLLING" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <filter class="ch.qos.logback.classic.filter.ThresholdFilter">
            <level>INFO</level>
        </filter>
        <file>${LOG_DIR}/log.txt</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <!-- rollover daily -->
            <fileNamePattern>${LOG_DIR}/log-%d{yyyy-MM-dd}.%i.txt</fileNamePattern>
            <timeBasedFileNamingAndTriggeringPolicy
                    class="ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP">
                <!-- or whenever the file size reaches 100MB -->
                <maxFileSize>100MB</maxFileSize>
            </timeBasedFileNamingAndTriggeringPolicy>
        </rollingPolicy>
        <encoder>
            <!--<pattern>[%-5level] %d{HH:mm:ss.SSS} %logger{36} - %msg%n</pattern>-->
            <pattern>
                {
                "severity": "%level",
                "pid": ${PID:-},
                "thread": "%thread",
                "logger": "%logger",
                "message": "%msg"
                }
            </pattern>
        </encoder>
    </appender>
    <root level="debug">
        <appender-ref ref="STDOUT"/>
        <appender-ref ref="ROLLING"/>
    </root>
</configuration>

이와 같이 로그가 적히게 된다.

그 다음으로는 필터를 이용하여 request들을 기록해주기로 했다.


package com.daily.gaboja.logging;

import lombok.extern.slf4j.Slf4j;
import org.junit.jupiter.api.Order;
import org.springframework.stereotype.Component;
import org.springframework.web.filter.GenericFilterBean;
import org.springframework.web.util.ContentCachingRequestWrapper;
import org.springframework.web.util.ContentCachingResponseWrapper;
import org.springframework.web.util.WebUtils;

import javax.servlet.*;
import javax.servlet.http.HttpServletRequest;
import javax.servlet.http.HttpServletResponse;
import java.io.IOException;
import java.io.UnsupportedEncodingException;
import java.util.Enumeration;
import java.util.HashMap;
import java.util.Map;

@Slf4j
@Component
public class LoggingFilter extends GenericFilterBean {

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        ContentCachingRequestWrapper requestWrapper = new ContentCachingRequestWrapper((HttpServletRequest) request);
        ContentCachingResponseWrapper responseWrapper = new ContentCachingResponseWrapper((HttpServletResponse) response);
        System.out.println("responseWrapper.getContentAsByteArray().toString() = " + responseWrapper.getContentAsByteArray().toString());
        log.info("\n" +
                        "[REQUEST] {} - {} {}\n" +
                        "Request : {}\n",
                ((HttpServletRequest) request).getMethod(),
                ((HttpServletRequest) request).getRequestURI(),
                responseWrapper.getStatus(),
                getRequestBody(requestWrapper));

        chain.doFilter(requestWrapper, responseWrapper);
        responseWrapper.copyBodyToResponse();
    }

    private String getRequestBody(ContentCachingRequestWrapper request) {
        ContentCachingRequestWrapper wrapper = WebUtils.getNativeRequest(request, ContentCachingRequestWrapper.class);
        if (wrapper != null) {
            byte[] buf = wrapper.getContentAsByteArray();
            for(byte b : buf){
                System.out.print("b : " + b);
            }
            if (buf.length > 0) {
                try {
                    return new String(buf, 0, buf.length, wrapper.getCharacterEncoding());
                } catch (UnsupportedEncodingException e) {
                    return " - ";
                }
            }
        }
        return " - ";
    }
}