로그 프레임워크 #2 - 기본 로깅 및 JSON 포맷으로 로깅하기

로그 시스템 #2- 자바 로그 & JSON 로그 포맷

조대협 (http://bcho.tistory.com)

앞 글에서 간단하게 자바 로깅 프레임워크에 대해서 알아보았다. 그러면 앞에서 추천한 slf4j와 log4j2로 실제 로깅을 구현해보자

SLF4J + log4j2

메이븐 프로젝트를 열고 dependencies 부분에 아래 의존성을 추가한다. 버전은 최신 버전을 확인하도록 한다. artifactid가 log4j-slf4j-impl 이지만, log4j가 아니라 log4j2가 사용된다.

<dependency> <groupId>org.apache.logging.log4j</groupId> <artifactId>log4j-slf4j-impl</artifactId> <version>2.11.2</version> </dependency>

다음 log4j2의 설정 정보 파일인 log4j2.properties 파일을 src/main/resources 디렉토리 아래에 다음과 같이 생성한다. Appender나, Layout등 다양한 정보 설정이 있지만 그 내용은 나중에 자세하게 설명하도록 한다.

appenders=xyz appender.xyz.type = Console appender.xyz.name = myOutput appender.xyz.layout.type = PatternLayout appender.xyz.layout.pattern = [MYLOG %d{yy-MMM-dd HH:mm:ss:SSS}] [%p] [%c{1}:%L] - %m%n rootLogger.level = info rootLogger.appenderRefs = abc rootLogger.appenderRef.abc.ref = myOutput

그리고 아래와 같이 코드를 만든다.

LoggerFactory를 이용해서 Logger를 가지고 온다. 현재 클래스 명에 대한 Logger 를 가지고 오는데, 위의 설정 파일을 보면 rootLogger만 설정하였기 때문에, rootLogger가 사용된다.

package com.terry.logging.helloworld; import org.slf4j.Logger; import org.slf4j.LoggerFactory; public class App {    private static Logger log = LoggerFactory.getLogger(App.class);    public static void main( String[] args )    {        System.out.println( "Hello World!" );                log.info("Hello slf4j");    } }

가저온 logger를 이용해서 log.info로 로그를 출력한다.

콘솔로 출력된 로그는 아래와 같다.

[MYLOG 19-Mar-18 23:07:01:373] [INFO] [App:71] - Hello slf4j

JSON 포맷으로 로그 출력

근래에는 시스템이 분산 구조를 가지고 있기 때문에 텍스트 파일로 남겨서는 여러 분산된 서비스의 로그를 모아서 보기가 어렵다. 그래서, 이런 로그를 중앙 집중화된 서버로 수집 및 분석하는 구조를 가지는데, 수집 서버에서는 이 로그들을 구조화된 포맷으로 저장하는 경우가 일반적이다. 각 로그의 내용을 저장 구조의 개별 자료 구조(예를 들어 테이블의 컬럼)에 맵핑해서 저장하는데, 이를 위해서는 로그가 JSON,XML 또는 CSV와 같은 형태로 구조화가 되어 있어야 한다.

이런 구조화된 로그를 structured logging 이라고 한다. 로그 엔트리 하나를 JSON에 포함해서 출력하는 방법에 대해서 알아본다.

slf4j + logback

SLF4 + logback을 이용하여 레이아웃을 JSON으로 출력하는 코드이다.

package com.terry.logging.logback; import java.util.Map; import java.util.TreeMap; import org.slf4j.Logger; import org.slf4j.LoggerFactory; import com.fasterxml.jackson.core.JsonProcessingException; import com.fasterxml.jackson.databind.ObjectMapper; public class App {    private static Logger log = LoggerFactory.getLogger(App.class);    public static void main( String[] args ) throws JsonProcessingException    {        log.info("hello log4j");    } }

pom.xml에 아래와 같이 logback과 json 관련 dependency를 추가한다.

<dependencies> <dependency> <groupId>ch.qos.logback</groupId> <artifactId>logback-classic</artifactId> <version>1.1.7</version> </dependency> <dependency> <groupId>ch.qos.logback.contrib</groupId> <artifactId>logback-json-classic</artifactId> <version>0.1.5</version> </dependency> <dependency> <groupId>ch.qos.logback.contrib</groupId> <artifactId>logback-jackson</artifactId> <version>0.1.5</version> </dependency> <dependency> <groupId>com.fasterxml.jackson.core</groupId> <artifactId>jackson-databind</artifactId> <version>2.9.3</version> </dependency> </dependencies>

마지막으로 src/main/resources.xml 파일을 아래와 같이 작성한다.  

<?xml version="1.0" encoding="UTF-8"?> <configuration>    <appender name="stdout" class="ch.qos.logback.core.ConsoleAppender">        <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">            <layout class="ch.qos.logback.contrib.json.classic.JsonLayout">                <timestampFormat>yyyy-MM-dd'T'HH:mm:ss.SSSX</timestampFormat>                <timestampFormatTimezoneId>Etc/UTC</timestampFormatTimezoneId>                <jsonFormatter class="ch.qos.logback.contrib.jackson.JacksonJsonFormatter">                    <prettyPrint>true</prettyPrint>                </jsonFormatter>            </layout>        </encoder>    </appender>    <root level="debug">        <appender-ref ref="stdout"/>    </root> </configuration>

아래는 출력 결과이다. message 필드에 로그가 출력 된것을 볼 수 있다.

{  "timestamp" : "2019-03-19T07:24:31.906Z",  "level" : "INFO",  "thread" : "main",  "logger" : "com.terry.logging.logback.App",  "message" : "hello log4j",  "context" : "default" }

slf4j + log4j2

다음은 slft4+log4j2 를 이용한 예제이다.  logback과 크게 다르지는 않다.

아래와 같이 pom.xml 의 dependencies에 아래 내용을 추가하자. json layout은 jackson을 사용하기 때문에 아래와 같이 jackson에 대한 의존성도 함께 추가한다.

<dependency> <groupId>org.apache.logging.log4j</groupId> <artifactId>log4j-slf4j-impl</artifactId> <version>2.11.2</version> </dependency> <dependency> <groupId>com.fasterxml.jackson.core</groupId> <artifactId>jackson-core</artifactId> <version>2.7.4</version> </dependency> <dependency> <groupId>com.fasterxml.jackson.core</groupId> <artifactId>jackson-databind</artifactId> <version>2.7.4</version> </dependency> <dependency> <groupId>com.fasterxml.jackson.core</groupId> <artifactId>jackson-annotations</artifactId> <version>2.7.4</version> </dependency>

다음 아래와 같이 log4j2.properties 파일을 src/main/resources 폴더에 저장한다.

status = info appender.ana_whitespace.type = Console appender.ana_whitespace.name = ana_whitespace appender.ana_whitespace.layout.type = JsonLayout appender.ana_whitespace.layout.propertiesAsList = false appender.ana_whitespace.layout.compact = false appender.ana_whitespace.layout.eventEol = true appender.ana_whitespace.layout.objectMessageAsJsonObject = true appender.ana_whitespace.layout.complete= true appender.ana_whitespace.layout.properties= true rootLogger.level = info rootLogger.appenderRef.ana_whitespace.ref = ana_whitespace

위에 보면 layout.type을 JsonLayout으로 지정하였다. 기타 다른 필드에 대한 정보는

정보는 https://logging.apache.org/log4j/2.0/manual/layouts.html 를 참고하기 바란다.

그리고 아래와 같이 코드를 이용해서 info 레벨의 로그를 출력해보자

package com.terry.logging.jsonlog; import org.slf4j.Logger; import org.slf4j.LoggerFactory; public class App { private static Logger log = LoggerFactory.getLogger(App.class);    public static void main( String[] args )    {                log.info("Hello json log");        log.error("This is error");        log.warn("this is warn");    } }

코드를 컴파일 하고 실행하면 아래와 같은 형태로 로그가 출력된다. 로그 출력 형태는 logback과는 많이 차이가 있다.

[ {  "thread" : "main",  "level" : "INFO",  "loggerName" : "com.terry.logging.jsonlog.App",  "message" : "Hello json log",  "endOfBatch" : false,  "loggerFqcn" : "org.apache.logging.slf4j.Log4jLogger",  "instant" : {    "epochSecond" : 1552923302,    "nanoOfSecond" : 38337000  },  "contextMap" : { },  "threadId" : 1,  "threadPriority" : 5 } , {  "thread" : "main",  "level" : "ERROR",  "loggerName" : "com.terry.logging.jsonlog.App",  "message" : "This is error",  "endOfBatch" : false,  "loggerFqcn" : "org.apache.logging.slf4j.Log4jLogger",  "instant" : {    "epochSecond" : 1552923302,    "nanoOfSecond" : 109170000  },  "contextMap" : { },  "threadId" : 1,  "threadPriority" : 5 } , {  "thread" : "main",  "level" : "WARN",  "loggerName" : "com.terry.logging.jsonlog.App",  "message" : "this is warn",  "endOfBatch" : false,  "loggerFqcn" : "org.apache.logging.slf4j.Log4jLogger",  "instant" : {    "epochSecond" : 1552923302,    "nanoOfSecond" : 109618000  },  "contextMap" : { },  "threadId" : 1,  "threadPriority" : 5 } ]

json을 여러가지 포맷으로 출력할 수 있다. 위의 로그를  잘보면 로그 시작과 끝에 json 포맷을 맞추기 위해서 “[“와 “]”를 추가하고, 로그 레코드 집합당 “,”로 레코드를 구별한것을 볼 수 있다. 만약에 “[“,”]”를 로그 처음과 마지막에서 제거하고, 로그 레코드 집합동 “,”를 제거하고 newline으로만 분류하고 싶다면 log4j2.properties 파일에서 appender.ana_whitespace.layout.complete = false로 하면 된다.

아래는 layout.complete를 false로 하고 출력한 결과 이다.

{ ←  이부분에 “[” 없음  "thread" : "main",  "level" : "INFO",  "loggerName" : "com.terry.logging.jsonlog.App",  "message" : "Hello json log",  "endOfBatch" : false,  "loggerFqcn" : "org.apache.logging.slf4j.Log4jLogger",  "instant" : {    "epochSecond" : 1552923722,    "nanoOfSecond" : 98574000  },  "contextMap" : { },  "threadId" : 1,  "threadPriority" : 5 } ←  이부분에 콤마가 없음 {  "thread" : "main",  "level" : "ERROR",  "loggerName" : "com.terry.logging.jsonlog.App",  "message" : "This is error",  "endOfBatch" : false,  "loggerFqcn" : "org.apache.logging.slf4j.Log4jLogger",  "instant" : {    "epochSecond" : 1552923722,    "nanoOfSecond" : 167047000  },  "contextMap" : { },  "threadId" : 1,  "threadPriority" : 5 } {  "thread" : "main",  "level" : "WARN",  "loggerName" : "com.terry.logging.jsonlog.App",  "message" : "this is warn",  "endOfBatch" : false,  "loggerFqcn" : "org.apache.logging.slf4j.Log4jLogger",  "instant" : {    "epochSecond" : 1552923722,    "nanoOfSecond" : 167351000  },  "contextMap" : { },  "threadId" : 1,  "threadPriority" : 5 } ←  이부분에 “]” 없음

그리고 로그파일을 보는데, JSON의 경우에는 위와 같이 각 element 마다 줄을 바꿔서 사람이 읽기 좋은 형태이기는 하지만, 대신 매번 줄을 바꾸기 때문에 검색이 어려운 경우가 있다. 그래서 로그 레코드 하나를 줄 바꿈 없이 한줄에 모두 출력할 수 있도록 할 수 있는데, appender.ana_whitespace.layout.compact = true로 주면 된다. 아래는 옵션을 적용한 결과 이다.

{"thread":"main","level":"INFO","loggerName":"com.terry.logging.jsonlog.App","message":"Hello json log","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","instant":{"epochSecond":1552923681,"nanoOfSecond":430798000},"contextMap":{},"threadId":1,"threadPriority":5} {"thread":"main","level":"ERROR","loggerName":"com.terry.logging.jsonlog.App","message":"This is error","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","instant":{"epochSecond":1552923681,"nanoOfSecond":491757000},"contextMap":{},"threadId":1,"threadPriority":5} {"thread":"main","level":"WARN","loggerName":"com.terry.logging.jsonlog.App","message":"this is warn","endOfBatch":false,"loggerFqcn":"org.apache.logging.slf4j.Log4jLogger","instant":{"epochSecond":1552923681,"nanoOfSecond":492095000},"contextMap":{},"threadId":1,"threadPriority":5}