Spring Batch 강의 #3 (Logging편)

시스템을 개발하면서 로깅은 왜 꼭넣어야 하는지? 로깅을 하면 어떤 이점이 있어 로깅을 하게 되는지를 먼저 알고자 합니다.

로깅시 이점

• 로그 출력 형식을 지정할수 있다.
• 로그 레벨을 지정하여 보고 싶은 로그만 볼수 있다
• 콘솔 로그만 아니라, 파일, 별도에 로그처리(ELK)등으로 보낼 수 있다.
• 성능이 System.out보다 월등히 좋다.

로그레벨

종류	내용
TRACE	DEBUG 보다 더 자세한 예외 로그
DEBUG	INFO 보다 더 자세한 정보가 필요한 경우, 주로 DEV 환경에서 많이 사용
INFO	명확한 의도가 있는 에러나, 시스템 정보를 남길경우, QA / PRD 환경에서 많이 사용
WARN	에러가 될수도 있는 잠재적 가능성이 있는경우
ERROR	의도 하지 않은 에러가 발생한 경우나, 시스템적인 오류가 발생한 경우
FATAL	매우 심각한 오류로, 시스템이 종료되는 경우가 많음

로그 출력 레벨을 지정할때 최상단에 있는 Level로 하면 하위에 있는 로그도 모두 찍히게 됩니다.
예로 INFO 레벨로 지정하면 WARN,ERROR,FATAL에 대한 로그도 모두 출력하게 됩니다.

디버깅 필요성

운영 중 시스템 디버깅을 하는 방법은 여러 종류가 존재하지만 현재도 제일 많이 보는 것은 로그 입니다.
운영중인 시스템을 멈추거나, 배포를 자유롭게 할 수 없어 현재 출력 되고 있는 로그를 분석해 문제점을 찾게 됩니다.
운영중인 시스템에 문제점을 찾기 위해서는 많은 로그를 미리 찍어 디버깅을 해야 합니다.

SLF4J 동작과정

log4j / JUL / JCL API 호출 => bridge(log4j-over-slf4j, jcl-over-slf4j, jul-to-slf4j) => slf4j API => binging(logback-classic) => logback (Logging framework, logback-core)

개발진행시에는 SLF4J API를 사용하여 로깅 코드를 작성하고, 배포시에는 바인딩된 Logging Framework가 실제 로깅 코드를 수행하게 됩니다.
이 과정은 SLF4J에서 제공하는 Bridge, API, Bingind 모듈에 의해 수행 됩니다.

• Bridge 모듈
  • SLF4J 이외의 다른 로깅 API로 Logger 호출을 SLF4J 인터페이스로 연결하여 SLF4J API가 대신 처리할수 있는 일종의 어댑터 역활의 라이브러리
  • 레거시 로깅 프레임워크를 위한 라이브러리
  • Binding 모듈에서 사용될 프레임워크와 달아야 함
• SLF4J API
  • 로깅에 대한 인터페이스 제공
  • 로깅에 대한 역할을 수행할 추상메서드 제공
  • 하나의 API 모듈에 하나의 Binding 모듈이 필요
• Binding 모듈
  • SLF4J API를 로깅 구현제와 연결하는 어댑터 역활 모듈
  • SLF4J를 구현한 클래스에서 Binding으로 연결된 logger의 API를 호출
• Logback
  • 로깅 구현제의 종류 중 하나로 스프링부트가 디폴트로 사용하는 라이브러리

간단 로깅 실습 코드

@RestController
public class LoggingController {

	private final Logger logger = LoggerFactory.getLogger(getClass());

	@GetMapping("/logging")
	public String loggingTest() {
		String name = "Spring Log4j";

		logger.trace("TRACE log={}",name);
		logger.debug("DEBUG log={}",name);
		logger.info("INFO log={}",name);
		logger.warn("WARN log={}",name);
		logger.error("ERROR log={}",name);

		return "Good Logging";
	}

}

위 코드를 실행하면 아래와 같은 로그가 출력되는것을 볼수 있습니다.

로그가 출력된 모습 INFO / WARN / ERROR 3개만 출력됨.

SpringBoot 기본 환경에서는 INFO Level부터 출력되기 때문에 INFO, WARN, ERROR 3개에 로그만 출력 됩니다.

LogBack 설정

LogBack은 SLF4J의 구현체로 Log4J를 토대로 만들어진 프레임워크 입니다.
스프링에서도 SLF4J와 LogBack을 디폴트로 사용하고 있습니다.

LogBack은 3가지 모듈로 나뉩니다.

• logback-core
  • 다른 두 모듈 기반 역활을 하는 모듈
  • Appender와 Layout 인터페이스가 여기에 속함
• logback-classic
  • logback-core에서 확장된 모듈로 logback-core를 가지고 SLF4J API를 구현함.
  • Logger 클래스가 여기에 속함.
• logback-access
  • Servlet 컨테이너와 통합되어 HTTP 액세스에 대한 로깅 기능을 제공
  • logback-core는 logback-access의 기반기술이기에 필요, logback-classic와 SLF4J와는 무관
  • 웹 어플리케이션 레벨이 아닌 컨테이너 레벨에서 설치 되어야 함.
• Logger
  • 어떡해 기록할것인가?
  • 실제 로깅을 수행하는 구성요소 입니다.
  • 출력레벨: TRACE > DEBUG > INFO > WARN > ERROR
• Appender
  • 어디에 기록할것인가?
  • LogBack은 로그를 쓰는 작업을 Appender에게 위임합니다.
  • 로그 메시지가 출력될 대상을 결정합니다.
  • consoleAppender, FileAppender, RollingFileAppender등 제공
• Layout
  • 어떤 모양으로 출력할 것인가?
  • 로그 이벤트를 바이트 배열로 변환하고, 해당 내용을 OutputStream에 쓰는 작업을 담당
  • Appender에 포함되어 사용자가 지정한 형식으로 로그 메시지를 변환하는 역활
  • FileAppender와 하위 클래스 Encoder를 필요로 하고, 더이상 layout은 사용하지 않기에 layout보다는 Encoder를 사용함.

로그 설정 파일

로그 설정을 yml 파일로도 하지만 아직까지 logback.xml 파일로 세부적인 설정을 관리 합니다.

Log Pattern

로그 설정에 사용되는 패턴입니다.

• %logger: 패키지 포함 클래스 정보
• %logger{0}: 패키지를 제외한 클래스 이름만 출력
• %logger{length}: Logger name을 축약할 수 있음. {length}는 최대 자리 수, ex)logger{35}
• %-5level: 로그 레벨, -5는 출력의 고정폭 값(5글자), 로깅레벨이 Info일 경우 빈칸 하나 추가
• ${PID:-}: 프로세스 아이디
• %d: 로그 기록시간 출력
• %p: 로깅 레벨 출력
• %F: 로깅이 발생한 프로그램 파일명 출력
• %M: 로깅일 발생한 메소드의 명 출력
• %line: 로깅이 발생한 호출지의 라인
• %L: 로깅이 발생한 호출지의 라인
• %thread: 현재 Thread 명
• %t: 로깅이 발생한 Thread 명
• %c: 로깅이 발생한 카테고리
• %C: 로깅이 발생한 클래스 명 (%C{2}는 somePackage.SomeClass 가 출력됨)
• %m: 로그 메시지
• %msg: - 로그 메시지 (=%message)
• %n: 줄바꿈(new line)
• %%: %를 출력
• %r : 애플리케이션 시작 이후부터 로깅이 발생한 시점까지의 시간(ms)
• %d{yyyy-MM-dd-HH:mm:ss:sss}: %d는 date를 의미하며 중괄호에 들어간 문자열은 dateformat을 의미. 따라서 [2021-07-12 12:42:78]과 같은 날짜가 로그에 출력됨.
• %-4relative: %relative는 초 아래 단위 시간(밀리초)을 나타냄. -4를하면 4칸의 출력폼을 고정으로 가지고 출력. 따라서 숫자에 따라 [2021-07-12 12:42:78:232] 혹은 [2021-07-12 12:42:78:2332]와 같이 표현됨

logback-spring.xml 설정

• logback의 설정은 main/resource 위치에서 logback-spring.xml 파일을 만들면 됩니다.

<?xml version="1.0" encoding="UTF-8"?>

<configuration>
    <timestamp key="BY_DATE" datePattern="yyyy-MM-dd"/>
    <property name="LOG_PATTERN"
              value="[%d{yyyy-MM-dd HH:mm:ss}:%-4relative] %green([%thread]) %highlight(%-5level) %boldWhite([%C.%M:%yellow(%L)]) - %msg%n"/>

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

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

</configuration>

• property
  • 변수를 저장해는 곳이라고 생각하면 됩니다.
• timestamp
  • property와 마찬가지로 변수로 사용됩니다.
  • key가 변수의 이름이 되고, datePattern을 이용해서 년-월-일 을 나타냈습니다.
• springProfile
  • logback에서는 여러 개의 프로파일 설정이 가능합니다.
  • 위에서는 prod 환경이 아닐 때 사용하는 설정입니다.
• appender
  • 어디다가 쓸지 정하는 부분으로 위에서는 consoleAppender을 사용했습니다.
• encoder
  • Encoder는 로그 이벤트를 바이트 배열로 변환하고, 해당 바이트 배열을 OutputStream에 쓰는 작업을 담당합니다.
  • Appender에 포함되어 사용자가 지정한 형식으로 표현 될 로그메시지를 변환하는 역할을 담당하는 요소입니다.
  • 위에서는 pattern을 지정 형식으로 주었습니다.
  • 이 부분이 위에서 언급했던 Log Pattern을 사용하는 곳입니다.
• root
  • 등록되어 있는 로그들의 최상위 클래스로 레벨을 정하는 곳입니다.
  • INFO로 설정해주었으므로 전체 로그가 이제 error, warn, info 만 찍히게 됩니다.
  • appender-ref를 통해 위에서 작성한 appender을 넣어줍니다.

위 logback-spring.xml에서 root level을 "INFO" 에서 "TRACE"로 변경하면 아래와 같은 로그가 출력 됩니다.

로그 레벨 TRACE 변경시

로그 정리(필요로그만 설정)

logback-spring.xml에 설정을 TRACE로 변경하여 실행하게 되면 상당히 많은 로그가 출력이 됩니다.
다른 Spring 라이브러리에 있는 로그도 찍히고, DB가 연결되어 있으면 DB Connection정보도 찍히고, 이런 많은 로그를 찍게 되면 정착 개발에 필요한 로그는 보기 어렵습니다.

개발에 필요한 로그를 찍고자 하면 logback-spring.xml에 관련된 package를 추가 하면 됩니다. 
<logger name="com.spring.logging" level="DEBUG"/>
com.spring.logging 패키지에 있는 로그는 DEBUG Level로 출력을 하게 지정합니다.

<?xml version="1.0" encoding="UTF-8"?>

<configuration>
    <timestamp key="BY_DATE" datePattern="yyyy-MM-dd"/>
    <property name="LOG_PATTERN"
              value="[%d{yyyy-MM-dd HH:mm:ss}:%-4relative] %green([%thread]) %highlight(%-5level) %boldWhite([%C.%M:%yellow(%L)]) - %msg%n"/>

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

        <logger name="com.spring.logging" level="DEBUG"/>
        <root level="INFO">
            <appender-ref ref="CONSOLE"/>
        </root>
    </springProfile>

</configuration>

위와 같은 logback-spring.xml에 대상 패키지를 추가 하면 대상 패키지 로그만 출력되게 됩니다.

복잡 로그 설정

서버 Level별 여러 profile별 설정을 만들고, 설정별 로그양식을 다르게 출력 해보겠습니다.

<?xml version="1.0" encoding="UTF-8"?>

<configuration>
    <timestamp key="BY_DATE" datePattern="yyyy-MM-dd"/>
    <property name="LOG_PATTERN"
              value="[%d{yyyy-MM-dd HH:mm:ss}:%-4relative] %green([%thread]) %highlight(%-5level) %boldWhite([%C.%M:%yellow(%L)]) - %msg%n"/>

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

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

    <springProfile name="prod">
        <appender name="FILE-INFO" class="ch.qos.logback.core.rolling.RollingFileAppender">
            <file>./log/info/info-${BY_DATE}.log</file>
            <filter class = "ch.qos.logback.classic.filter.LevelFilter">
                <level>INFO</level>
                <onMatch>ACCEPT</onMatch>
                <onMismatch>DENY</onMismatch>
            </filter>
            <encoder>
                <pattern>${LOG_PATTERN}</pattern>
            </encoder>
            <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
                <fileNamePattern> ./backup/info/info-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
                <maxFileSize>100MB</maxFileSize>
                <maxHistory>30</maxHistory>
                <totalSizeCap>3GB</totalSizeCap>
            </rollingPolicy>
        </appender>

        <appender name="FILE-WARN" class="ch.qos.logback.core.rolling.RollingFileAppender">
            <file>./log/warn/warn-${BY_DATE}.log</file>
            <filter class = "ch.qos.logback.classic.filter.LevelFilter">
                <level>WARN</level>
                <onMatch>ACCEPT</onMatch>
                <onMismatch>DENY</onMismatch>
            </filter>
            <encoder>
                <pattern>${LOG_PATTERN}</pattern>
            </encoder>
            <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
                <fileNamePattern> ./backup/warn/warn-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
                <maxFileSize>100MB</maxFileSize>
                <maxHistory>30</maxHistory>
                <totalSizeCap>3GB</totalSizeCap>
            </rollingPolicy>
        </appender>

        <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>
            <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
                <fileNamePattern> ./backup/error/error-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
                <maxFileSize>100MB</maxFileSize>
                <maxHistory>30</maxHistory>
                <totalSizeCap>3GB</totalSizeCap>
            </rollingPolicy>
        </appender>

        <root level="INFO">
            <appender-ref ref="FILE-INFO"/>
            <appender-ref ref="FILE-WARN"/>
            <appender-ref ref="FILE-ERROR"/>
        </root>
    </springProfile>


</configuration>

SpringProfile설정을 서버 환경별 로그 설정을 다르게 할 수 있습니다.

• appender
  • 이번에는 RollingFileAppender를 등록했습니다.
  • RollingFileAppender는 FileAppender를 상속하여 로그 파일을 rollover합니다. rollover는 타깃 파일을 바꾸는 것으로 이해할 수 있습니다.
  • 예를 들어, 타깃 파일로 log.txt에 로그 메시지를 append 하다가 어느 지정한 조건에 다다르면 타킷 파일을 다른 파일로 바꿀 수 있습니다.
• file
  • 파일의 저장 위치입니다.
  • 앞서 위쪽에 timestampe태그로 정의했던 BY_DATE를 사용하게 되면 파일명이 날짜별로 바뀌어 저장됩니다.
• filter
  • 로그 레벨에 따른 필터 LevelFilter를 사용했습니다.
  • <level>는 필터의 조건이 되는 로그 레벨을 입력합니다.
  • <onMatch>의 ACCEPT는 위에 조건이 되는 레벨이 되면 실행, <onMismatch>의 DENY는 위 조건이 아닐 경우 실행되지 않게 하는 것입니다.
  • if문이라고 생각하면 됩니다.
• rollingPolicy
  • RollingFileAppender를 어떻게 사용할지에 대한 정책을 정하는 곳입니다.
  • 보통 TimeBasedRollingPolicy와 SizeAndTimeBasedRollingPolicy를 사용한다고 합니다.
  • SizeAndTimeBasedRollingPolicy은 시간과 사이즈를 기준하는 정책입니다.
• fileNamePattern
  • 처음에 로그들은 file에 설정한 위치에 저장되다가 maxFileSize, maxHistory, totalSizeCap 옵션 중 어느 하나에 일치하게 되면 fileNamePattern대로 파일이 옮겨지게 되고, 다시 생성되는 로그는 file로 설정한 위치에 저장됩니다.
• maxFileSize
  • 파일 분할 용량으로 KB, MB, GB가 있습니다.
• maxHistory
  • 파일이 저장될 수 있는 기간을 설정합니다.
• totalSizeCap
  • 전체 파일 크기를 제어하여, 전체 크기 제한을 초과하면 가장 오래된 파일을 삭제합니다.
• root
  • 전체 프로젝트의 로그 레벨을 설정합니다.
• appender-ref
  • 사용하고자 하는 appender을 등록합니다.
  • 위에서 작성한 appender의 name을 적어주면 됩니다.

로그 설정 분리 하기

위와 같이 하나에 파일에 설정을 하게 되면 가독성 이슈가 있어, 필요한 영역별 분리를 하여 가독성을 높일 수 있습니다.

console-appender.xml 파일

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

file-error-appender.xml 파일

<included>
    <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>
        <rollingPolicy class="ch.qos.logback.core.rolling.SizeAndTimeBasedRollingPolicy">
            <fileNamePattern>./backup/error/error-%d{yyyy-MM-dd}.%i.log</fileNamePattern>
            <maxFileSize>100MB</maxFileSize>
            <maxHistory>30</maxHistory>
            <totalSizeCap>3GB</totalSizeCap>
        </rollingPolicy>
    </appender>
</included>

logback-spring.xml 파일

<?xml version="1.0" encoding="UTF-8"?>

<configuration>
    <timestamp key="BY_DATE" datePattern="yyyy-MM-dd"/>
    <property name="LOG_PATTERN"
              value="[%d{yyyy-MM-dd HH:mm:ss}:%-4relative] %green([%thread]) %highlight(%-5level) %boldWhite([%C.%M:%yellow(%L)]) - %msg%n"/>

    <springProfile name="!prod">
        <include resource="console-appender.xml"/>

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

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

        <root level="INFO">
            <appender-ref ref="FILE-INFO"/>
            <appender-ref ref="FILE-WARN"/>
            <appender-ref ref="FILE-ERROR"/>
        </root>
    </springProfile>
</configuration>

로그 색상 설정

지원되는 색상 목록은 blue, cyan, faint, green, magenta, red, yellow입니다.

%clr(LOG_DATEFORMAT_PATTERN){green} 이런식으로 색상 지정이 가능하다.

GitHub 로그 설정 코드

위에서 설명한 가이드 대로 작성된 코드를 보고 싶으면 아래 GitHub에 있는 코드를 참조 하면 됩니다.

https://github.com/abilitybobr/logging

GitHub - abilitybobr/logging: Spring Boot Logging 샘플

 

 

※ logging 관련 참고 사이트
https://github.com/backtony/blog-code/tree/master/spring-logback