Skip to content

로깅 전략

Jump to bottom
서민정 edited this page Oct 1, 2021 · 4 revisions

1. 출력 장치와 로그 종류 구분하기

출력 장치

  • 콘솔 (기존에 스프링 애플리케이션 실행시킬 때와 동일하게 콘솔창에 로그 출력)
  • 파일 (로그를 파일로 만들어서 보관)

로그 종류

  • info 레벨 message
  • warn 레벨 message
  • error 레벨 message
  • 요청 & 응답 http message
  • DB 액세스 query message

로컬환경과 테스트를 실행할 때는 로그의 종류에 상관없이 모두 콘솔에서 보도록 했다.

개발 서버와 배포 서버에서는 로그의 종류에 따라 다른 로그 파일에 기록되도록 했다.

2. logback xml 종류

resources 디렉토리에 logback 관련된 xml 파일들이 있다:

xml 파일 설명
logback-spring 우리 애플리케이션에서 발생하는 로그를 다루는 설정
logback-access 애플리케이션에 들어오고 나가는 응답 / 요청 관련 로그를 다루는 설정
appender xml 파일 설명
console-appender 콘솔에 출력되는 로그에 관한 설정
info-file-appender info 레벨 로그를 파일에 남길 때 사용하는 설정
warn-file-appender warn 레벨 로그를 파일에 남길 때 사용하는 설정
error-file-appender error 레벨 로그를 파일에 남길 때 사용하는 설정
query-file-appender DB 쿼리를 파일에 남길 때 사용하는 설정
http-console-appender 요청과 응답을 콘솔에 출력할 때 사용하는 설정
http-file-appender 요청과 응답을 파일에 남길 때 사용하는 설정

3. logback-spring.xml 구조

출력 양식

앞서 말했듯, 애플리케이션에서 발생하는 로그를 설정한다.

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

    <property name="BOTOBO_BINDER_LOG_PATTERN"
              value="%green(    > %msg%n) "/>

    <property name="BOTOBO_FILE_LOG_PATTERN"
              value="%d{yyyy-MM-dd HH:mm:ss}:%-4relative [%C.%M]:%L] %n    > %msg%n"/>

콘솔과 파일에 어떤 식으로 로그를 만들지 그 패턴을 만든다. 잘 보면 색상, 날짜, 시간, 그리고 메시지등 다앙한 정보를 넣을 수 있다.

위와 같은 패턴은 아래의 로그를 출력한다.

  • 기존
# 색상은 반영되지 않음
21-07-22 17:25:48 INFO  [botobo.core.BotoboApplication            :664 ] - The following profiles are active: local
21-07-22 17:25:49 INFO  [o.s.d.r.c.RepositoryConfigurationDelegate:128 ] - Bootstrapping Spring Data JPA repositories in DEFAULT mode.
  • 변경
2021-09-29 19:12:21:575  INFO  [org.springframework.boot.SpringApplication.logStartupProfileInfo]:664] 
    > The following profiles are active: local

실행 환경에 따른 출력 장치

springProfile 태그를 사용하여 실행환경에 따라 콘솔에 로그를 출력하거나 파일로 만들 수 있다.

현재 보또보는 local과 test 환경에서는 콘솔을 사용하고, dev와 prod 환경에서 파일에 로그 정보를 나누어 저장한다.

로그는 INFO 레벨부터 보여지고 기록되도록 했다.

    <springProfile name="local, test">
        <include resource="logback/console-appender.xml"/>
        <root level="INFO">
            <appender-ref ref="CONSOLE"/>
        </root>
    </springProfile>

    <springProfile name="dev, prod">
        <include resource="logback/info-file-appender.xml"/>
        <include resource="logback/warn-file-appender.xml"/>
        <include resource="logback/error-file-appender.xml"/>
        <include resource="logback/query-file-appender.xml"/>

        <root level="INFO">
            <appender-ref ref="INFO_FILE"/>
            <appender-ref ref="WARN_FILE"/>
            <appender-ref ref="ERROR_FILE"/>
            <appender-ref ref="QUERY_FILE"/>
        </root>
    </springProfile>

4. logback-access.xml?

요청과 응답에 대한 로그를 설정하는 파일로, logback-spring과 동일한 형태.

5. appender

출력 형식에 따라 다양한 appender xml 파일이 resources/logback 디렉토리에 있다.

각각의 appender는

  1. 어떤 정보를 (what)
  2. 어떻게 출력할지 (how) 를 정한다.

대표적으로 info-file-appender.xml을 보면:

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

위와 같은 필터가 있어서 INFO 레벨 로그만 출력되도록 하고,

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

어떤 식으로 기록할지 패턴도 설정할 수 있다!

        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${INFO_LOG_PATH}/${INFO_LOG_FILE_NAME}.%d{yyyy-MM-dd}_%i.log</fileNamePattern>
            <maxFileSize>3MB</maxFileSize>
            <maxHistory>100</maxHistory>
        </rollingPolicy>

마지막으로 파일을 어떤 식으로 생성하고 보관할지 정할 수 있다.

위의 설정은 매일 새로운 파일을 그 날의 날짜를 제목에 포함하여 생성하며, 파일의 최대 크기는 3MB로 설정하겠다는 의미이다.

3MB를 넘길 때를 대비해서 파일 제목의 끝 부분에 숫자를 더한다. (%i 부분) 같은 날 여러 파일이 생성되면 이 숫자가 올라가며 만들어진다.

보관하는 파일의 최대 개수는 100개로, 100개가 넘으면 가장 오래된 파일을 지우고 새로운 파일이 생성된다!

6. LogConfiguration과 TeeFilter

@Configuration
public class LogConfiguration {

    @Bean
    public TeeFilter teeFilter() {
        return new TeeFilter();
    }
}

LogConfiguration.java 소스코드를 보면 TeeFilter라는 필터를 등록한 것을 볼 수 있다.

로그백을 이용해서 HTTP 요청과 응답에 포함되는 body를 로깅할 때는 해당 필터를 등록해야 기록이 된다! 여기 간단하게 그 역할이 적혀있다. 요청과 응답을 복사해서 로그를 만드는 방식이라 서비스를 느리게 만든다고 하는데, 로그에 요청과 응답에 어떤 내용이 있었는지 기록하면 좋다고 생각하여 일단 추가했다.

7. WebConfig의 extendMessageConverters

  • 기존
    @Override
    public void extendMessageConverters(List<HttpMessageConverter<?>> converters) {
        for (HttpMessageConverter<?> converter : converters) {
            if (converter instanceof MappingJackson2HttpMessageConverter) {
                MappingJackson2HttpMessageConverter jacksonConverter = (MappingJackson2HttpMessageConverter) converter;
                jacksonConverter.setPrettyPrint( true );
            }
        }
    }

위에서 말한 요청과 응답의 body를 볼 때 json이 문자열 형식으로 나와서 한 줄에 쭉 나열되어 아래처럼 출력되었다.

{"code": "botoboFighting", "array":[{"name": "object1", "property": 1}, {"name": "object2", "property": 2}]}

아무래도 json 형태로 출력하는게 읽기 편하다고 생각하여 json 관련 메시지 컨버터인 Jackson에 예쁘게 출력해달라는 설정을 추가함!

{
    "code": "botoboFighting", 
    "array": [
        {
            "name": "object1", 
            "property": 1
        }, 
        {
            "name": "object2", 
            "property": 2
        }
    ]
}

  • 변경
    json 로그를 출력하는 것은 콘솔에서 볼 때엔 prettyPrint 적용이, cloudwatch에서 확인할 때엔 한줄로 나와 펼쳐서 보는 것이 더 가독성이 좋았다. 따라서 PrettyPrint 설정은 local 및 테스트 환경에서만 실행되도록 변경하였다.

    • 기존 PrettyPrint 적용 시 cloudwatch의 모습
      image

    • 변경 후 cloudwatch 모습
      image

7. AsyncAppender의 도입

현재 develop 환경에서는 hibernate query가 trace레벨 이상이면 남겨지도록 설정되어있다. 이는 쿼리가 길거나 반복적으로 많은 db 요청 수행 시 애플리케이션의 성능을 저하시킨다.

  • Async 적용 전 k6 smoke test 결과

image

따라서 비동기로깅을 적용하였다.

  <!-- AsyncAppender 추가 -->
  <appender name="file-async" class="ch.qos.logback.classic.AsyncAppender">
    <appender-ref ref="RollingFile" />
    <queueSize>1</queueSize>
    <discardingThreshold>0</discardingThreshold>
    <includeCallerData>false</includeCallerData>
    <neverBlock>false</neverBlock>
  </appender>

AsyncAppender에서 설정할 수 있는 옵션은 다음과 같다.

  1. queueSize
    async로 동작하기 위해서 log들을 BlockingQueue를 이용해 버퍼에 저장해 둔다.버퍼에 저장해두는 queue의 사이즈를 의미하며 해당 queue의 사이즈의 80%가 초과하게 되면 warn, error를 제외하고는 drop한다. 따라서 적절한 queueSize를 사용해야한다. default는 256이다.

  2. discardingThreshold
    기본적으로 blocking queue에 20% 용량이 남아 있으면 TRACE, DEBUG 및 INFO 수준의 이벤트를 삭제하고 WARN 및 ERROR 수준의 이벤트만 유지한다. 이 값을 0으로 설정하면 모든 이벤트를 유지한다. default는 20이다.

  3. includeCallerData
    발신자의 정보 (class명, 줄번호 등)가 추가되어 수집 서버로 전송여부를 결정합니다. true 설정 시, 성능 저하를 일으킬 수 있습니다. default는 false이다. 성능 문제로 인해 false를 권장하지만 false로 설정할 경우에는 class, method, line 수 등을 로그에서 확인할 수 없다.

  4. maxFlushTime

Depending on the queue depth and latency to the referenced appender, the AsyncAppender may take an unacceptable amount of time to fully flush the queue. When the LoggerContext is stopped, the AsyncAppender stop method waits up to this timeout for the worker thread to complete. Use maxFlushTime to specify a maximum queue flush timeout in milliseconds. Events that cannot be processed within this window are discarded. Semantics of this value are identical to that of Thread.join(long). default: 1000ms

  1. neverBlock
    queue에 가득차게 되는 경우 다른 쓰레드의 작업들이 blocking 상태에 빠지게 되는데 해당 옵션을 true하게 되면 blocking 상태에 빠지지 않고 log를 drop하며 계속 진행할 수 있게 해준다. 로그의 버퍼가 꽉차서 application이 blocking되지 않기 위해 반드시 true 를 적용하는 것을 권장한다. default는 false이다.

Async는 다음과 같이 적용할 수 있다.

    <appender name="QUERY_FILE" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>TRACE</level>
        </filter>

        <encoder>
            <charset>utf8</charset>
            <pattern>
                %d{yyyy-MM-dd HH:mm:ss} %n    > %msg%n
            </pattern>
        </encoder>

        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>${QUERY_LOG_PATH}/${QUERY_LOG_FILE_NAME}.%d{yyyy-MM-dd}_%i.log</fileNamePattern>
            <maxFileSize>3MB</maxFileSize>
            <maxHistory>100</maxHistory>
        </rollingPolicy>
    </appender>

    <appender name="QUERY_FILE_ASYNC" class="ch.qos.logback.classic.AsyncAppender">
        <appender-ref ref="QUERY_FILE" />
        <queueSize>256</queueSize>
        <discardingThreshold>20</discardingThreshold>
        <includeCallerData>false</includeCallerData>
        <neverBlock>true</neverBlock>
        <maxFlushTime>3000</maxFlushTime>
    </appender>

AsyncAppender를 추가하여 appender-ref에 RollingFileAppender를 연결해 준다. 그리고 root에서 AsyncAppender로 셋팅 해주면 RollingFileAppender를 async하게 사용할 수 있다.

  • AsyncAppender 적용 후 k6 smoke test 결과

image

Copyright © 2021 WoowaCourse Level3 Project botobo 🐸  

보고 또 보고 (보또보)

Documents 📃

팀 규칙 🤝

Code Convention

기술 공유 🐸

데일리 미팅 및 회의록 🐳

2차 ~ 4차 회의 및 데일리 미팅은 디스코드에서 진행되어 이슈로 반영되었습니다.

이후 회의 및 데일리 미팅은 디스코드에서 진행되어 이슈로 반영되었습니다.

Clone this wiki locally