#3] 스프링부트 logback 설정 및 로그유틸 설정

프로젝트를 만든 이후, 

추후에 운영하거나 개발할때 로그를 보기편하도록 설정하는 것을 알아보고자 한다.

 

먼저 로그 레벨은

TRACE > DEBUG > INFO > WARN > ERROR > FATAL 의 순이다

 

즉, 현재 로그레벨을 DEBUG로 둔다면, DEBUG에서 FATAL까지의 로그는 모두 다 찍힌다는 뜻이다.

주로 운영환경에서 DEBUG 레벨로 두며,

개발환경에서는 현재 로그를 찍어볼때에 TRACE를 넣는다.

 

로그 레벨을 설정해 두지 않으면 불필요한 로그까지 운영환경에 남게되어, 쓸모없는 용량을 차지하게 된다.

그렇기 때문에 개발할때에 로그를 규칙성 있도록 작성해주는 것이 좋다.

 

보통, CRUD에서 

- R(읽기:select) 의 행위에서는 굳이 로그를 남기지 않고 TRACE로 쌓는다.

- CUD(삽입,수정,삭제)의 행위는 요청값은 DEBUG레벨로 쌓고, 결과 값을 INFO로 쌓는다. 데이터가 변경되는 것이므로 남기는 것이 좋다.

 

그럼 설정에 들어가보자.

application.properties와 같은 레벨인 resources(classpath) 아래에 파일을 만들어 주면된다.

명칭을 "logback-spring.xml" 로 하여 파일을 만들어주면 자동으로 읽어 들이게 된다.

 

필자는 logback-spring.xml 파일을 만들고 아래와 같은 설정을 하였다.

일단 샘플을 하나 보도록 하자.

<?xml version="1.0" encoding="UTF-8"?>
<!DOCTYPE xml>
<configuration>
    <conversionRule conversionWord="ex" converterClass="com.cc.kr.config.ExceptionLogConverter"/>
    <logger name="org.springframework" level="INFO" />
    <logger name="org.springframework.web.servlet.mvc.method.annotation.ExceptionHandlerExceptionResolver" level="ERROR" />
    <logger name="org.springframework.beans.factory" level="WARN" />
    <logger name="org.springframework.jdbc.support" level="WARN" />
    <logger name="org.apache" level="INFO" />
    <logger name="net.sf.ehcache" level="INFO" />
    <logger name="org.apache.ibatis" level="INFO" />
    <logger name="org.aspectj" level="INFO" />
    <logger name="org.mybatis.spring" level="INFO" />
    <logger name="com.zaxxer.hikari" level="INFO" />
    <logger name="org.hibernate" level="INFO" />
    <logger name="javax.management" level="WARN" />
	<logger name="jdk.event.security" level="INFO" />
<!-- 	<logger name="springfox" level="WARN" /> -->
<!-- 	<logger name="io.sentry" level="INFO" /> -->


	<!-- log file path --> 
	<property name="LOG_PATH" value="/Users/shipjh/Documents/log"/> 

	<!-- log file name --> 
	<property name="LOG_FILE_NAME" value="camping-club"/>
	<property name="ERR_LOG_FILE_NAME" value="err_log"/> 
	
	<!-- pattern --> 
	<property name="LOG_PATTERN" value="%-5level %d{HH:mm:ss.SSS} %X{REQSEQ:--} %logger{36} - %msg %ex %n"/>

    <springProfile name="local">
        <logger name="org.springframework.cache" level="TRACE" />
        <logger name="sun.rmi" level="INFO" />
<!--         <logger name="springfox" level="DEBUG" /> -->

        <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
            <encoder>
                <pattern>${LOG_PATTERN}</pattern>
            </encoder>
        </appender>

        <root level="TRACE">
            <appender-ref ref="STDOUT" />
        </root>
    </springProfile>

    <springProfile name="!local">
        <appender name="FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
            <file>${LOG_PATH}/${LOG_FILE_NAME}.log</file>
            <append>true</append>

            <encoder>
                <pattern>${LOG_PATTERN}</pattern>
            </encoder>

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

        </appender>
        
        <appender name="ERR" 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}/${ERR_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}/${ERR_LOG_FILE_NAME}.%d{yyyy-MM-dd}.log</fileNamePattern>
			</rollingPolicy>
        </appender>
        

        <root level="TRACE">
            <appender-ref ref="FILE" />
            <appender-ref ref="ERR" />
        </root>
        
    </springProfile>
    
</configuration>

제일 윗줄의 <configuration> 태그안에 설정하여 주면된다.

별도로 <configuration scan="true" scanPeriod="30 seconds"> 이러한 옵션을 준다면, 30초마다 해당 logback-spring.xml 파일을 읽어들여 변경점이 있으면 새롭게 갱신한다.

운영을 하다가 보면, 갑자기 로그레벨을 낮추거나 높일때 별도 톰캣을 재시작하지 않고 변경하면 적용이 된다.

 

 

<conversionRule conversionWord="ex" converterClass="com.cc.kr.config.ExceptionLogConverter"/>

은, 하나의 에러가 발생하면 로그내에 수십줄의 로그가 찍히게 될 것이다.

그렇게 되면 불필요하게 용량을 차지하는 것이니,

에러 발생시에 로그를 줄여주는 클래스를 직접 구현하였다.

아래의 설명하도록 하겠다.

 

 

<logger> 태그는 해당 클래스의 로그의 레벨을 잡아주는 것이다.

별도 스프링의 내장되어있는 클래스나 불필요한 레벨이 로그에 남는것을 방지한다.

필요시 로그레벨을 조정하면 된다.

어떠한것인지 경험하기 위해서는 모두 주석하고 난 후 실행해보고, 다시 주석을 푼다음 실행해보면 콘솔에 찍히는 것으로 체감할 수 있으니 해보길 바란다.

 

 

<property> 태그는

해당 logback-spring.xml 파일 내에서 사용할 변수를 지정하는 것으로 보면 된다.

name을 지정하여 그대로 사용하면 된다.

 

 

<springProfile> 태그는

앞서 쓴 #2번 글의 스프링의 application.properties 뒤에 붙는 환경에 따라 

로그를 분리할 수 있다.

필자는 local 환경에서는 콘솔에 찍을 것이며,

그 외의 환경(개발,운영)에서는 파일로 남겨 기록 할 예정이다.

 

 

<appender> 태그는

log의 형태나 로그 메시지가 어디에 출력될지를 설정할 수 있는 태그이다.

앞서 말했듯 로컬 환경에서는 IDE의 콘솔에 찍을 것이다.

- ch.qos.logback.core.ConsoleAppender 는 콘솔에 찍도록 해준다.

- ch.qos.logback.core.FileAppender 는 파일에 로그를 찍어준다.

- ch.qos.logback.core.rolling.RollingFileAppender 는 여러개의 파일을 순회(롤링)하면서 파일을 찍어준다. FileAppender를 상속한 형태이다.

 

그 외에도 DB, SMTP 등등의 로그를 찍는 방식도 있다.

https://logback.qos.ch/manual/appenders.html 에 더 많은 내용이 있다.

 

 

 

<encoder> 태그는

출력 형태를 설정할 수 있다.

위에서 설정한 property태그의 ${LOG_PATTEN} 을 읽어와 해당 패턴을 출력하여 준다.

 

패턴은

%-5level : 로그 레벨, -5는 출력의 고정폭 값(5글자)
%msg : - 로그 메시지 (=%message)
${PID:-} : 프로세스 아이디
%d : 로그 기록시간
%p : 로깅 레벨
%F : 로깅이 발생한 프로그램 파일명
%M : 로깅일 발생한 메소드의 명
%l : 로깅이 발생한 호출지의 정보
%L : 로깅이 발생한 호출지의 라인 수
%thread : 현재 Thread 명
%t : 로깅이 발생한 Thread 명
%c : 로깅이 발생한 카테고리
%C : 로깅이 발생한 클래스 명
%m : 로그 메시지
%n : 줄바꿈(new line)
%% : %를 출력
%r : 애플리케이션 시작 이후부터 로깅이 발생한 시점까지의 시간(ms)

%Logger{length} : Logger name을 축약할 수 있다. {length}는 최대 자리 수, ex)logger{35}

 

이렇게 있으니 필요한 것을 선정하여 쓰는게 좋다.

필자의 경우 별도로 %X{REQSEQ:--} 라는 것을 설정하였는데, 이것은 추후 필터에 설정하여

각 요청건 마다 시작과 끝까지 같은 랜덤값을 지정하여 줘서 

하나의 요청건을 로그에서 쉽게 찾기 위하여 설정하였다.

추후 설명하도록 하겠다.

 

 

 

<rollingPolicy> 태그는 

class 부분은 

- ch.qos.logback.core.rolling.TimeBasedRollingPolicy 은 일자별로 적용
- ch.qos.logback.core.rolling.SizeAndTimeBasedFNATP 은 일자와 크기별로 적용

로 설정할 수 있다.

 

 

<fileNamePattern> 태그는

파일의 이름의 패턴을 정해주는 것이다.

위에 property 의 설정한것과 날짜를 더해서 파일을 생성하도록 하였다.

다음날이 되면 기존에 있는 파일에 날짜가 더해지고 현재에는 날짜없이 파일이 생성될 것이다.

 

 

<Filter> 태그는

별도로 로그 레벨을 설정할 때 사용된다.

 

대체로 위와 같은 태그들을 사용하였으며,

구성은 

local 의 환경일 경우, 콘솔에만 로그를 찍게해두었고,

local의 환경이 아닐 경우(개발,운영), 파일로 생성되도록 하였다.

또한 local 환경이 아닐 경우에는 error 로그를 따로 파일로 저장하도록 설정까지 추가하였다.

 

이대로 실행을 해보자.

 

먼저 로컬에서 실행하였다.

로그의 패턴이 위에서 설정한 것 처럼 잘 나왔다.

필자는 DB까지 연동한 API를 호출한 것이다. 다음 파트에서 DB연결을 할 것이니 로그패턴만 봐주면 된다.

 

8eA0y라는 것은 아까 말한  %X{REQSEQ:--} 의 값이다.

또한, 요청한 URL 인 GET /user 라는 항목이 찍히는 것도 같이 필터에서 설정하여 주었다.

로그에서 보듯 com.cc.kr.filter.LogginfFilter 라는 곳에서 설정했다.

 

소스는 아래와 같다.

package com.cc.kr.filter;

import java.io.IOException;

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

import org.apache.commons.lang3.RandomStringUtils;
import org.slf4j.MDC;
import org.springframework.http.HttpStatus;
import org.springframework.stereotype.Component;
import org.springframework.web.filter.OncePerRequestFilter;

import com.cc.kr.domain.Constant;

import lombok.extern.slf4j.Slf4j;

/**
 * @since 2021-08-26
 * @category 필터 요청과 응답에 대한 로그를 남기는 필터
 * @author shipjh
 *
 */

@Slf4j
@Component
public class LoggingFilter extends OncePerRequestFilter {

	@Override
	protected void doFilterInternal(final HttpServletRequest request, final HttpServletResponse response,
			final FilterChain filterChain) throws ServletException, IOException {
		MDC.put(Constant.MDCProperty.REQSEQ, RandomStringUtils.randomAlphanumeric(5));

		final HttpServletRequest req = (HttpServletRequest) request;
		final String method = req.getMethod();
		final String uri = req.getRequestURI();

		if (log.isTraceEnabled()) {
			log.trace("path, {} {}", method, uri);
		}

		filterChain.doFilter(request, response);

		final HttpServletResponse res = (HttpServletResponse) response;
		final int status = res.getStatus();

		switch (HttpStatus.resolve(status).series()) {
		case INFORMATIONAL:
		case SUCCESSFUL:
		case REDIRECTION:
			if (log.isInfoEnabled()) {
				log.info("status: {}, path: {} {}", status, method, uri);
			}
			break;
		case CLIENT_ERROR:
			if (log.isWarnEnabled()) {
				log.warn("status: {}, path: {} {}", status, method, uri);
			}
			break;
		case SERVER_ERROR:
			if (log.isErrorEnabled()) {
				log.error("status: {}, path: {} {}", status, method, uri);
			}
			break;
		}
		MDC.clear();
	}

}

위와 같이 설정하면 필터단에서 요청과 응답 url을 찍어주며, 

MDC.put 하여 넣은 REQSEQ값은 랜덤한 5자리로 설정하여 주었다.

그렇게 하면 로그는 거의 설정이 완료된 것이다.

추후에는 사용자의 ID 까지 넣어서 특정 로그를 찾을때 더 편리하도록 설정 할 것이다.

 

같은 url 을 3번 호출하였다.

특정 REQSEQ 값은 각각 한번의 호출당 같은 번호이며 각각 호출에따라 랜덤으로 변하고 있는 것을 보인다.

이렇게 하였을때, z9Xvv라는 호출만 찾아보고자 한다면

이렇게 찾을 수 있다.

추후에 에러발생시, sentry라는 것을 통하여 REQSEQ와 함께 넣어 보낼 것이다.

로그에서 찾을때 해당 REQSEQ만 찾는다면 하나의 요청 시작부터 끝까지의 로그를 손쉽게 찾을 수 있다.

 

 

 

그다음으로, 아까 에러로그에 관한 것을 설명하고자 한다.

<conversionRule conversionWord="ex" converterClass="com.cc.kr.config.ExceptionLogConverter"/>

package com.cc.kr.config;

import java.util.stream.Stream;

import org.apache.commons.lang3.StringUtils;

import ch.qos.logback.classic.pattern.ThrowableProxyConverter;
import ch.qos.logback.classic.spi.IThrowableProxy;

public class ExceptionLogConverter extends ThrowableProxyConverter {
    @Override
    protected String throwableProxyToString(IThrowableProxy tp) {
        return this.extractException(tp);
    }

    private String extractException(IThrowableProxy tp) {
        StringBuffer sb = new StringBuffer();
        sb.append(tp.getClassName());
        sb.append(" : ");
        sb.append(tp.getMessage());
        Stream.of(tp.getStackTraceElementProxyArray())
                .forEach(v -> {
                    if (StringUtils.indexOf(v.getSTEAsString(), "com.cc.kr") > 0) {
                        sb.append("\n");
                        sb.append(v.getSTEAsString());
                    }
                });
        return sb.toString();
    }
}

 

을 설정하여 주었다.

 

위와 같은 설정을 해주면 에러로그를 최소한으로 줄일 수 있다.

 

차이를 보도록 하겠다.

먼저 설정하지 않은 에러로그이다. 테스트로 0을 0으로 나눴다.

예상되는 에러는 java.lang.ArithmeticException이 발생하고 내용으로는 / by zero 에러를 발생 할 것으로 추측한다.

 

엄청나게 길게 찍혔다.

 

설정을 준 다음 에러를 발생시켜 보겠다.

상당히 간단해 졌다.

 

또한 에러발생지점과 필요한 로그만 쏙 들어가있다. 

이렇게 하여, 로그를 남긴다면 추후에 디스크용량을 아낄 수 있다.

 

 

 

 

별도로, 로그유틸을 하나 더 소개하고자 한다.

위와 같이 LogUtil.toJSONString(object); 하면 모든 타입의 오브젝트를 json 형태로 변경하여 로그를 출력하여 준다.

테스트를 위하여 받은 request값과, map, list, 객체(Test object) 를 다 넣고 돌려 보도록 하겠다.

localhost:port/test?longValue=777 을 호출하여 보겠다.

 

 

예쁘게 잘찍힌다.

추후에 요청값, 응답값을 찍을때 사용하기에 좋다.

 

소스는 아래와 같다.

package com.cc.kr.util;

import java.util.Objects;

import org.apache.commons.lang3.StringUtils;
import org.springframework.beans.factory.annotation.Autowired;
import org.springframework.stereotype.Component;

import com.fasterxml.jackson.core.JsonProcessingException;
import com.fasterxml.jackson.databind.ObjectMapper;

import lombok.extern.slf4j.Slf4j;

/**
 * @since 2021-08-26
 * @category 유틸 
 * 객체를 JsonString 화 하여, 로그를 보기 쉽도록 변경해주는 유틸
 * @author shipjh
 */
@Slf4j
@Component
public class LogUtil {
	
	private static ObjectMapper objectMapper;

	@Autowired
	public void setObjectMapper(final ObjectMapper objectMapper) {
		LogUtil.objectMapper = objectMapper.copy();
	}
	
	public static String exception(final Throwable e) {
		return StringUtils.normalizeSpace(e.toString());
	}

	public static String toJSONString(final Object object) {
		if (Objects.isNull(object)) {
			return null;
		}
		try {
			return StringUtils.normalizeSpace(objectMapper.writeValueAsString(object));
		} catch (final JsonProcessingException e) {
			e.printStackTrace();
			if (log.isErrorEnabled()) {
				log.error("toJSONString, {}", StringUtils.normalizeSpace(e.toString()));
			}
		}
		return null;
	}
}