Logging 관리

🥋 팀에서 논의해 봐야 될 사항

❓어떤 로그를 남길 것인가

• 예를 들면..?
• API 통신에 대한 로그
• DB 쿼리 로그
• ERROR 단계의 로그만 파일로 저장하겠다.

💾 롤링 정책

• 로그 파일의 보관 주기

• 각 파일의 최고 용량

📁 로그백 설정 방식

1. 하나의 파일에서 Profile 별로 관리

<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
    <include resource="logback/properties.xml" />

    <springProfile name="local">
        ...
    </springProfile>

    <springProfile name="dev">
        ...
    </springProfile>
</configuration>

2. Profile 파일 별로 관리

🐶 현재 선택한 방법

📁 하나의 파일에서 Profile 관리 (로그백 설정 방식)

• 선택 이유
• 하나의 파일에서 Profile 관리 이유
Profile 별로 관리를 한다. 라는 것은 장단점이 있다고 생각했습니다.
• 장점 : 각각의 환경마다 설정값들을 달리 할 수 있다. (파일의 크기 제한 등)
• 단점 : 경우에 따라서 설정 구문이 중복 될 수 있다.
그런데 이처럼 설정값들을 달리 하기에는 경험치가 부족하지 않을까 싶었습니다. 결국 단점에서 나오는 구문 중복만 야기되지 않을까 싶어서 한 파일에서 관리 되도록 했습니다.
• appender 분리 이유
아래의 폴더 트리를 보면 알 수 있듯이 각각의 appender로 분리해서 관리 되도록 했습니다. appender가 많지 않다면 하나의 파일에서 다 작성하는 것이 좋겠죠.
하지만 로그 레벨마다 파일을 분리해서 관리를 한다면, 레벨에 따라서 로그를 추적하기 쉽지 않을까 싶어 분리를 하게 되었고, 이에 따라 appender 수가 늘어나게 되서 파일을 분리하게 되었습니다.

• 폴더 트리

resources
	⌙ logback-spring.xml
	⌙ logback[folder]
		⌙ console-appender.xml
		⌙ db-file-appender.xml
		⌙ error-file-appender.xml
		⌙ properties.xml

• logback-spring.xml
• include 태그를 이용해서 분리된 파일 활용
• springProfile : Profile 별로 각각 로그 설정

<?xml version="1.0" encoding="UTF-8" ?>
<configuration>
    <include resource="logback/properties.xml" />

		<!-- Profile 별로 관리 -->
    <springProfile name="local">
        <include resource="logback/console-appender.xml" />
        <include resource="logback/db-file-appender.xml" />
        <include resource="logback/error-file-appender.xml" />

        <root level="INFO">
            <appender-ref ref="CONSOLE" />
            <appender-ref ref="DB_FILE" />
            <appender-ref ref="ERROR_FILE" />
        </root>
    </springProfile>

    <springProfile name="dev">
        ...


</configuration>

• logback 폴더에 있는 appender들… 중에 하나 예시
• 각각 비동기 설정도 추가 완료
• included 태그를 이용해서 메인 logback 파일에서 사용 되도록 설정

<included>
    <appender name="WARN_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${ROOT_PATH}/${SUB_PATH_WARN}/warn-${LOG_DATE}.log</file>

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

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

        <rollingPolicy class="ch.qos.logback.core.rolling.TimeBasedRollingPolicy">
            <fileNamePattern>${LOG_BACKUP_PATH}/${SUB_PATH_WARN}/warn-%d{yyyy-MM-dd}.zip</fileNamePattern>
            <maxHistory>${MAX_HISTORY}</maxHistory>
            <totalSizeCap>${TOTAL_SIZE_CAP}</totalSizeCap>
        </rollingPolicy>
    </appender>

    <appender name="ASYNC_WARN_FILE" class="ch.qos.logback.classic.AsyncAppender">
        <appender-ref ref="WARN_FILE"/>
        <queueSize>1024</queueSize>
        <discardingThreshold>0</discardingThreshold>
        <includeCallerData>false</includeCallerData>
        <neverBlock>false</neverBlock>
    </appender>
</included>

🪬 logback vs logback-spring

• 스프링 부트의 경우 logback-spring.xml을 이용한다.
logback.xml을 사용하게 되면 스프링 부트 설정 전에 로그백 설정이 먼저 되서 로그 제어가 어려워짐

또는 property의 logging.config = classpath:logback-${spring.profile.active}.xml을 통해 각 프로파일별로 logback 설정 파일을 관리한다. 덧붙여 application.yml의 설정만으로도 logger, 로그 레벨 설정이 가능하다.

🔍 logback 구성 요소

🧶 appender

📺 ConsoleAppender

• 콘솔 로깅

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

💾 RollingFileAppender

• 파일로 저장하는 파일 로깅

<appender name="FILE-ERROR" class="ch.qos.logback.core.rolling.RollingFileAppender">
    <file>./log/error/error-${BY_DATE}.log</file>
    <filter class = "ch.qos.logback.classic.filter.LevelFilter">
        <level>ERROR</level>
        <onMatch>ACCEPT</onMatch>
        <onMismatch>DENY</onMismatch>
    </filter>
    <encoder>
        <pattern>${LOG_PATTERN}</pattern>
    </encoder>
		<!--
			SizeAndTimeBasedRollingPolicy : 각각의 로그 파일에 대한 크기를 제한 하는 부분 추가
			- fileNamePattern 에서 %i, %d 필수 포함 되어야 함!
		-->
    <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
				<!-- 파일명 패턴 지정 → %i, %d가 필수 포함 되어야 됨! -->
        <fileNamePattern> ./backup/error/error-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
				<!-- 각 파일명의 최대 용량 [SizeAndTimeBasedRollingPolicy 에서만 있는 필드] -->
        <maxFileSize>100MB</maxFileSize>
				<!-- 보관 기간(일단위 / 월단위) -->
        <maxHistory>30</maxHistory>
				<!-- 저장소의 최대 크기 (maxHistory → totalSizeCap 순서로 적용) -->
        <totalSizeCap>3GB</totalSizeCap>
    </rollingPolicy>
</appender>

🪬 AsyncAppender

• 비동기 로깅
• 비동기로 로그를 기록합니다.
• 큐에 있는 쓰기 대기상태의 로그 메시지를 꺼내오는 Event dispatcher 역할
→ 실제 로그를 남기는 appender 참조 필요(사용 예제를 보면 기존의 appender를 참조)
• worker thread 생성
→ 얘가 큐에서 메시지를 꺼내서 dispatcher appender에게 넘겨줌
→ dispatcher 가 로그 쓰기 비동기 처리
• 발생한 로그를 BlockingQueue에 보관
• 서버가 멈추거나 재배포될 때는 maxFlushTime 만큼 큐에 남아있던걸 처리하고 끝남
→ 0으로 설정하게 되면 모두 처리

• 장점
• Application 입장에서는 로그 발생 시, File IO 작업이 사라지므로 빨라짐

• 단점
• 비동기식이기 때문에 성공 ≠ 로그 기록 성공 → 다양한 이유로 로그의 손실 발생
• 큐 메모리 관리 등의 관리 대상이 늘어남

• 사용 예제

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

<appendername="ASYNC_CONSOLE_APPENDER"class="ch.qos.logback.classic.AsyncAppender">
		<!- 실제로 로그 처리할 Appender 참조 ->
    <appender-ref ref="CONSOLE_APPENDER"/>
		<!- BlockingQueue 사이즈 (default: 256) ->
    <queueSize>1024</queueSize>
		<!- 큐 크기가 지정한 %가 남았을 때, Log Drop! → 0은 No Drop!! ->
    <discardingThreshold>0</discardingThreshold>
		<!- 로그 호출한 곳 정보 표시 여부 ->
    <includeCallerData>false</includeCallerData>
		<!- 큐가 다 차면, False : 기다림, True : 메시지 넣는 것을 기다리지 않고 다 버림 ->
    <neverBlock>false</neverBlock>
</appender>

🔧 logger

• additivity
: 상위 로거로부터의 상속 여부
• True(기본값) : 모든 상위 로거들의 설정값을 상속받아서 현재 로거에 설정된 값을 덮어쓰기
• False : 상속 X

• 사용 예제

<configuration>

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

	<logger name="org.hibernate.SQL" level="DEBUG" additivity="false">
      <appender-ref ref="CONSOLE"/>
  </logger>

	<!-- prepared statement 문 형태의 질의문에 들어가는 파라미터를 보기 위한 설정 
				- devug 레벨이면 파라미터 로그 나오지 않음
				- 로그 형태
	-->
  <logger name="org.hibernate.type.descriptor.sql.BasicBinder" level="TRACE" additivity="false">
      <appender-ref ref="CONSOLE"/>
  </logger>

	<!-- SELECT문의 질의 결과를 로그로 출력
				- 로그 형태
	-->
  <logger name="org.hibernate.type.descriptor.sql.BasicExtractor" level="TRACE" additivity="false">
      <appender-ref ref="CONSOLE"/>
  </logger>

	<!-- DB 연결 정보 출력 -->
  <logger name="org.zaxxer.hikari" level="DEBUG">
      <appender-ref ref="CONSOLE"/>
  </logger>

	<!-- Root 로거의 속성으로는 오직 단 하나의 level만 허용 -->
	<root level="OFF">
    <appender-ref ref="CONSOLE" />
  </root>

</configuration>

🖼 layout

• 간단하게 사용되는 키워드 정리

%logger : 패키지 포함 클래스 정보
%logger{0} : 패키지를 제외한 클래스 이름만 출력
%logger{최대-자리수} : Logger name 축약
%d : 로그 기록시간 출력
%i : 롤링 순번을 자동적으로 지정 … 0, 1 , …
%m : 로그 메시지
%msg : - 로그 메시지
%n : 줄 바꿈 (new line)
%thread : 스레드명
%-5level : 로그 레벨(5글자로 고정: 4글자면 1글자는 공백으로 채움)
%-4relative : 초 아래 단위 시간(밀리초)
%C : 로깅이 발생한 클래스명
%M : 로깅이 발생한 메소드명 출력
%L : 로깅이 발생한 호출지 라인

• 사용 예제

<property name="LOG_PATTERN" value="[%d{yyyy-MM-dd HH:mm:ss}:%-4relative] %green([%thread]) %highlight(%-5level) %cyan(%logger{15}) %C.%M.%L :%msg%n"/>
<property name="FILE_LOG_PATTERN" value="[%d{yyyy-MM-dd HH:mm:ss}:%-4relative] [%thread] %-5level %logger{15} %C.%M.%L :%msg%n"/>

🌐 API 로그 남기기

🫠 첫 번째 방법

• LogServletWrappingFilter
HttpServlet은 단 한번만 읽을 수 있도록 톰캣에서 만들어 두었기 때문에, 다시 읽을 수 있도록!! ContentCaching 으로 Wrapping 이 필요합니다.

✨  wrappingResponse.copyBodyToResponse() 이 메서드를 통해서 body 값을 copy해서 캐시로 저장하기 때문에, 다시 읽을 수 있습니다.

@Component
public class LogServletWrappingFilter extends OncePerRequestFilter {

	@Override
	protected void doFilterInternal(
		HttpServletRequest request,
		HttpServletResponse response,
		FilterChain filterChain) throws ServletException, IOException
	{
		ContentCachingRequestWrapper wrappingRequest = new ContentCachingRequestWrapper(request);
		ContentCachingResponseWrapper wrappingResponse = new ContentCachingResponseWrapper(response);

		filterChain.doFilter(wrappingRequest, wrappingResponse);

		// 이 부분을 하지 않으면 client가 응답을 받지 못한다.
		wrappingResponse.copyBodyToResponse();
	}
}

• LogInterceptor

@RequiredArgsConstructor
@Component
public class LogInterceptor implements HandlerInterceptor {

	private static final Logger logger = LoggerFactory.getLogger(LogInterceptor.class);
	private final ObjectMapper objectMapper;

	@Override
	public boolean preHandle(
		HttpServletRequest request,
		HttpServletResponse response,
		Object handler) throws Exception
	{
		String[] content = handler.toString().split("\\.");
		logger.warn("{} invoked", content[content.length - 1]);
		return true;
	}

	@Override
	public void afterCompletion(
		HttpServletRequest request,
		HttpServletResponse response,
		Object handler,
		Exception ex) throws Exception
	{
		ContentCachingRequestWrapper cachingRequest = (ContentCachingRequestWrapper) request;
		ContentCachingResponseWrapper cachingResponse = (ContentCachingResponseWrapper) response;

		String params = request.getParameterMap().entrySet().stream()
			.map(entry -> String.format("{\"%s\":\"%s\"", entry.getKey(), Arrays.toString(entry.getValue())))
			.collect(Collectors.joining(","));

		logger.warn("Params: {}", params);
		logger.warn("RequestBody: {} / ResponseBody: {}",
			objectMapper.readTree(cachingRequest.getContentAsByteArray()),
			objectMapper.readTree(cachingResponse.getContentAsByteArray())
		);
	}
}

• preHandle
: 어느 Controller 에서 어떤 메서드를 호출하는지 기록하고 있습니다.
• afterCompletion
: 받은 파라미터, RequestBody, ResponseBody 를 각각 기록했습니다.

하지만…?

🧑🏻‍💻 두 번째 방법 (피드백 후)

public class JwtAuthenticationFilter extends OncePerRequestFilter {

	@Override
	protected void doFilterInternal(HttpServletRequest request, HttpServletResponse response,
		FilterChain filterChain) throws ServletException, IOException {

		logRequest(request);

		... 기존 로직
	}

	private void logRequest(HttpServletRequest request) {
		log.info(String.format(
			"[%s] %s %s",
			request.getMethod(),
			request.getRequestURI().toLowerCase(),
			request.getQueryString() == null ? "" : request.getQueryString())
		);
	}
}

• 어떤 불순한 의도로 공격을 할 수도 있기 때문에, QueryString도 함께 남기고 있습니다.

🔖 참고 사이트

로그 전략을 통해 메시지를 남기자

웹이나 앱 어플리케이션을 개발하다 보면 어플리케이션의 상태를 확인하기 위해 로그를 남긴다. 그럼 로그는 왜 남길까? 보통 로그는 개발의 원활함을 위해, 에러 등을 확인하고 해결하기 위해, 보안의 의미로, 또는 마케팅 전략을 위해 남기기도 한다. 이런 장점들을 살려보기 위해 로그를 적용했던 이야기를 해 보려 한다. 이번 우아한 테크코스에서 진행하는 웹 프로젝트에 로거를 적용해 보았다.

https://tecoble.techcourse.co.kr/post/2020-07-30-use-logger/

'Spring/Logback' 카테고리의 글 목록

배운것을 기록해 나가는 초보개발자의 소소한 블로그입니다 :)

https://ckddn9496.tistory.com/category/Spring/Logback

Logback으로 로그 관리하기

안녕하세요~ 이번 포스팅에서는 Logback의 구조와 사용 방법에 대해서 정리해보려고 합니다.모든 내용을 다 다룰 수는 없지만, 기본적인 구조를 인지하고 있으면 나머지는 필요할 때마다 찾아보면서 적용할 수 있습니다.특히 Logback은 공식 문서가 꼼꼼하게 되어있는 편이어서, 없는 것 빼고 다 있다는 느낌이 들기도 합니다.

https://wbluke.tistory.com/51

📌 읽어봐야 될 글

Log4j2 vs Logback

Log4j2 및 Logback의 Async Logging 성능 테스트 비교

이 글은 Pick-Git 기술 블로그 에 업로드한 글입니다. Java 및 Spring 진영에서 사용할 수 있는 Logging Framework는 Log4j와 Logback 및 Log4j2 등 다양합니다. Pick-Git을 개발하면서 팀원들과 어떤 Logging Framework를 선택해야할지 고믾이 많았습니다. Logging Framework 종류별 특징을 학습하는 것에서 그치지 않고, 직접 Logging Framework들의 비동기 로깅(Async Logging) 성능을 테스트해보고 결과를 비교했습니다.

https://xlffm3.github.io/spring%20&%20spring%20boot/async-logger-performance/

로그 시각화 (Kibana 등)

📊 로그 시각화는 왜 중요할까?

로깅을 통해 개발자는 개발 과정 혹은 개발 후에 발생할 수 있는 예상치 못한 애플리케이션의 문제를 진단할 수 있고, 다양한 정보를 수집할 수 있다. 단순히 로그를 확인한다는 것은 추상적인 행위로 보인다. 기록을 남기는 것이 아닌 구체적으로 어떤 정보를 어떻게 확인하고 관리하는지가 로깅의 핵심이라고 생각한다. 로그는 시간의 경과에 따라 수집된 데이터의 한 종류로 볼 수 있다.

https://tecoble.techcourse.co.kr/post/2021-09-01-log-visualization/