[logging] logback을 이용하여 로그를 찍어봅시다!

logback을 이용하여 운영 환경 및 콘솔에서 로그를 찍어봅시다!

공식 팀의 깃허브에서 자세한 코드를 확인하실 수 있습니다.

로그를 왜 찍어야할까?

클라우드를 사용하는 운영 환경에선 application의 상태를 알지 못합니다.
그렇다면 클라이언트가 알 수 없는 에러가 발생한 경우를 대비하여 로그를 찍고 문제를 해결해야합니다.
지속가능한 개발을 하기위해서 로그는 개발자들에게 꼭 필요하다고 할 수 있습니다.

로깅 라이브러리

로깅 라이브러리는 크게 log4j, logback, java util logger가 있습니다
로그 라이브러리들의 특징은 다음과 같습니다.

• log4j : 전반적으로 환경에 영향을 받지 않고 일관된 결과를 보여줍니다.
  • 2.6버전 이후 로그 찍는 시간이 오래걸리는 문제를 정상 상태의 가지비 프리한 로거로 해결하는 것을 목표로 출시
  • 성능이 향상된 비결 : 각 로그 메세지마다 임시 객체를 생성했던 로직을 객체를 재사용하는 방향(객체 풀 패턴)으로 수정
    • ThreadLocal 필드를 이용해 String → Byte 변환 시 버퍼를 재사용하는 식으로 객체를 재사용
    • 근데 ThreadLocal 객체는 웹 어플리케이션과 웹 컨테이너 사이에 로드/언로드 하는 시점에 문제 → 웹 컨테이너 내부에서 실행 시 ThreadLocal을 안쓰지만 성능 향상을 위해 공유,캐시된 구조체를 사용
• logback : 실행 시간 측면에서 성능이 좋다, slf4j의 구현체, 의존성 추가 없이 사용이 가능하다.
• java util logger : 가장 성능 나쁘다.

공식팀에서는 여러 로깅 라이브러리중 log4j와 logback중 고민을 하였는데요.
log4j가 어느 환경에서든 실행시간이 가장 비슷하다고 하지만, 우리 운영 환경에서 어떤 로그 프레임워크를 사용하는 것이 메모리, 실행시간 측면에서 좋을지 확인해봐야합니다.
따라서 현재는 의존성 추가가 필요 없이 비교적 간단하게 사용 가능한 logback을 사용하고 있습니다.
추후에 운영 환경에서 기회 비용을 따져 다시 결정할 예정입니다.

로그 레벨

• ERROR : 당장 해결해야 할 문제가 될 로그
• WARN : 잠재적으로 ERROR가 될 로그
• INFO : 어플리케이션의 상태나 예측 가능한 예외를 모은 로그
• DEBUG : dev 환경에서 확인해야할 로그
• TRACE : DEBUG보다 더 자세하게 확인해야할 로그

Logback의 구조

Logback은 logback-core, logback-classic, logback-access 이렇게 3가지 모듈로 나뉘어져 있습니다.

Logback은 3개의 주요 클래스(Logger, Appender, Layout)를 기반으로 합니다.

개발자들은 이 3개의 클래스를 이용하여 로그를 남길 수 있습니다.

• logback-core : Appender(어디에?) , Layout(어떻게) 가 core에 속하고 classic, access에 모두 쓰인다.
• logback-classic : Logger (무엇을?)
• logback-access : Jetty 또는 Tomcat과 같은 서블릿 컨테이너와 통합되어 풍부하고 강력한 HTTP 액세스 로그 기능을 제공한다.

기본 설정

먼저 main-resource에 logback-spring.xml 파일을 만듭니다.(위치가 꼭 여기여야합니다!)
logback-spring.xml에 logback-classic(logger, root)을 작성하여 어떤 로그를 찍을지 작성하고, appender.xml 파일을 로그 레벨 별로 생성합니다.

Where

그렇다면 공식팀은 로그를 어디에 기록할까요?
로그백의 로그는 console과 file에 기록할 수 있습니다.
어디에 기록할지 설정하는 곳을 appender라고 합니다.

어느 위치에 기록할지에 따라 appender가 존재합니다.
아래는 콘솔 appender의 예시입니다.

<included>
    <appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>"[%d{yyyy-MM-dd HH:mm:ss}:%-4relative] %green([%thread]) %highlight(%-5level) %boldWhite([%C.%M:%yellow(%L)]) - %msg%n"</pattern>
        </encoder>
    </appender>

    <appender name="CONSOLE-DB" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <charset>utf8</charset>
            <Pattern>"%green(    > %msg%n)"</Pattern>
        </encoder>
    </appender>
</included>

아래는 file-info레벨 appender의 예시입니다.

<included>
    <appender name="FILE-INFO" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>./log/info/info-%d{yyyy-MM-dd}.log</file>
        <filter class="ch.qos.logback.classic.filter.LevelFilter">
            <level>INFO</level>
            <onMatch>ACCEPT</onMatch>
            <onMismatch>DENY</onMismatch>
        </filter>
        <encoder>
            <pattern>"[%d{yyyy-MM-dd HH:mm:ss}:%-4relative] %green([%thread]) %highlight(%-5level) %boldWhite([%C.%M:%yellow(%L)]) - %msg%n"</pattern>
        </encoder>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>$./log/info/info-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxFileSize>10MB</maxFileSize>
            <maxHistory>7</maxHistory>
        </rollingPolicy>
    </appender>
</included>

appender

• name : logback-classic(logger, root)을 작성할 때, 어떤 appender를 사용할지 명시하기 위해서 사용합니다.

• class : 해당 appender의 구현 class입니다.
  

• ch.qos.logback.core.ConsoleAppender : 콘솔에 찍을 경우 사용하며 이 때, System.out 또는 System.err를 이용합니다.

• ch.qos.logback.core.rolling.RollingFileAppender : 시간이나 용량에 따라 타겟 파일을 바꾸기 위해 이용합니다. 현재는 시간에 따라 다른 파일을 사용하기 위해 사용합니다.

• ch.qos.logback.classic.filter.LevelFilter : 로그 레벨로 필터링을 해주기 위해서 사용합니다. 현재는 각 로그레벨 별로 appender를 만들어 사용하고 있습니다.

• ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy : 로그 파일의 크기나, 저장 시간을 지정하기 위해서 사용합니다. 현재는 한 파일당 10MB, 7일간 저장하기위해 사용합니다.

공식팀의 appender

• console-appender.xml
• file-error-appender.xml
• file-warn-appender.xml
• file-info-appender.xml
• file-debug-appender.xml
• access-console-appender.xml
• access-file-appender.xml

How

그렇다면 공식팀은 어떤 모양으로 로그를 찍고 있을까요?
appender 내에 encoder는 로그를 어떻게 찍을 것인지를 결정합니다.

encoder(layout)

현재는 db관련, http관련, 그 외로 나눠서 사용합니다.

db 관련

"%green(    > %msg%n)"

예시

db관련해서는 binder, extractor를 보기 위해 사용하고 있고, 많은 양이 예상 되므로 필요한 정보인 msg만 출력합니다.

http 관련

"%n###### HTTP Request ###### %n%fullRequest%n###### HTTP Response ###### %n%fullResponse"

현재는 http request, response 전체를 로그로 찍고 있는데 이대로 운영해보면서 filter를 이용하여 필요한 정보만 볼 수 있도록 수정할 예정입니다.

그 외

"[%d{yyyy-MM-dd HH:mm:ss}:%-4relative] %green([%thread]) %highlight(%-5level) %boldWhite([%C.%M:%yellow(%L)]) - %msg%n"

예시

db, http를 제외한 로그들에 일반적으로 사용되는 포멧입니다.
어떤 정보들을 로그에 포함하는지는 아래와 같습니다.

• [%d{yyyy-MM-dd HH:mm:ss}:%-4relative] : 시간 -> 어느 시점에 발생한 로그인지 확인하기 위해 사용합니다.
• %green([%thread]) : 스레드 -> 어떤 스레드에서 실행된 로그인지 확인하기 위해 사용합니다.
• %highlight(%-5level) : 로그 레벨 -> 운영 환경에서는 레벨 별로 로그를 찍고 있으므로 상관 없지만, 콘솔 환경에서 확인하기 위해 사용합니다.
• %boldWhite([%C.%M:%yellow(%L)]) : 클래스, 메서드, 클래스에서의 메서드 위치 -> 해당 로그가 어느 위치에서 실행된 것인지 확인하기 위해 사용합니다.
• %msg : 메세지 -> 어떤 내용의 로그인지 확인하기 위해 사용합니다.

What

그렇다면 공식팀은 어떤 로그를 찍을까요?

공식팀의 로깅 전략

• dev, prod - 파일

  • HTTP 요청 응답 ⇒ 운영을 해보니, 어떤 요청에 대한 어떤 api가 문제인지 알지 못했고 로그를 볼 때마다 알 수 없는 에러가 나오는데 이게 대체 어떤 요청인지 알 수 없어서 출력하기로 결정했습니다.
  • com.woowacourse.gongseek : Application Exception(info),UnHandled Exception(error) dev에선 debug, prod에선 info로 출력중이나, 운영 환경이 안정화되면 prod를 error로 수정할 예정합니다.
  • DB query ⇒ 추후에 분석 혹은 확인 용도로 dev에만 debug로 사용중입니다.
  • org.springframework.boot : 설정 관련해서는 확인해보기위해 info level까지 사용중입니다.

• local, test - 콘솔

  • com.woowacourse.gongseek(debug)
  • org.springframework.boot(info)
  • org.hibernate.SQL(debug)
  • org.hibernate.type.descriptor.sql.BasicBinder(trace)
  • org.hibernate.type.descriptor.sql.BasicExtractor(trace)

참고참고
[Logging] Logback이란?
logback 공식 사이트
[10분 테코톡] ☂️ 검프의 Logging(로깅) #2