로그 프레임워크 #3 - JSON 로그에 필드 추가하기

로그 시스템 #3 - JSON 로그에 필드 추가하기

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

JSON 로그에 필드 추가

앞에 예제에서 로그를 Json 포맷으로 출력하였다. 그런데, 실제로 출력된 로그 메세지는 log.info(“문자열") 로 출력한 문자열 하나만 json log의 message 필드로 출력된것을 확인 할 수 있다.

그렇지만, 단순한 디버깅 용도의 로그가 아니라 데이터를 수집하는 용도등의 로깅의 message라는 하나의 필드만으로는 부족하다. 여러개의 필드를 추가하고자 할때는 어떻게 할까? Json Object를 log.info(jsonObject) 식으로 데이터 객체를 넘기면 좋겠지만 불행하게도 slf4j에서 logging에 남길 수 있는 인자는 String  타입만을 지원하고, 데이터 객체를 (json 객체나, Map 과 같은 데이타형) 넘길 수 가 없다.

slf4j + logback

slf4j + logback 의 경우에는 앞에서 언급한것과 같이 로그에 객체를 넘길 수 없고 문자열만 넘길 수 밖에 없기 때문에, json 로그에 여러개의 필드를 넘겨서 출력할 수 가 없다. 아래는 Map 객체를 만든 후에, Jackson json 라이브러리를 이용하여, Json 문자열로 변경하여 slf4j로 로깅한 코드이다.

package com.terry.logging.jsonlog; 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 Slf4j { private static Logger log = LoggerFactory.getLogger(Slf4j.class);    public static void main( String[] args ) throws JsonProcessingException    {        Map<String,String> map = new TreeMap();     map.put("name", "terry");     map.put("email","terry@mycompany.com");     String msg = new ObjectMapper().writeValueAsString(map);     System.out.println("MSG:"+msg);     log.info(msg);    } }

실행을 하면 message 엘리먼트 안에 json 문자열로 출력이 되는 것이 아니라 “ 등을 escape 처리하여 json 문자열이 아닌 형태로 출력이 된다.

{  "thread" : "main",  "level" : "INFO",  "loggerName" : "com.terry.logging.jsonlog.Slf4j",  "message" : "{\"email\":\"terry@mycompany.com\",\"name\":\"terry\"}",  "endOfBatch" : false,  "loggerFqcn" : "org.apache.logging.slf4j.Log4jLogger",  "instant" : {    "epochSecond" : 1553182988,    "nanoOfSecond" : 747493000  },  "contextMap" : { },  "threadId" : 1,  "threadPriority" : 5 }

그래서 다른 방법을 사용해야 하는데, 로그를 남길때 문자열로 여러 필드를 넘기고 이를 로그로 출력할때 이를 파싱해서 json 형태로 출력하는 방법이 있다.

log.info("event:order,name:terry,address:terrycho@google.com");

와 같이 key:value, key:value, ..  식으로 로그를 남기고, Custom Layout에서 이를 파싱해서 json 으로

{

 “key”:”value”,

 “key”:”value”,

 “key”:”value”

}

형태로 출력하도록 하면 된다. 이렇게 하기 위해서는 log message로 들어온 문자열을 파싱해서 json으로 변환해서 출력할 용도로 Layout을 customization 하는 코드는 다음과 같다.

{package com.terry.logging.logbackCustom; import ch.qos.logback.classic.spi.ILoggingEvent; import ch.qos.logback.contrib.json.classic.JsonLayout; import java.util.Map; import java.util.StringTokenizer; import java.util.TreeMap; import com.fasterxml.jackson.core.JsonProcessingException; import com.fasterxml.jackson.databind.ObjectMapper; public class CustomLayout extends JsonLayout {    @Override    protected void addCustomDataToJsonMap(Map<String, Object> map, ILoggingEvent event) {        long timestampMillis = event.getTimeStamp();        map.put("timestampSeconds", timestampMillis / 1000);        map.put("timestampNanos", (timestampMillis % 1000) * 1000000);        map.put("severity", String.valueOf(event.getLevel()));        map.put("original_message", event.getMessage());        map.remove("message");                StringTokenizer st = new StringTokenizer(event.getMessage(),",");        Map<String,String> json = new TreeMap();        while(st.hasMoreTokens()) {        String elmStr = st.nextToken();        StringTokenizer elmSt = new StringTokenizer(elmStr,":");        String key = elmSt.nextToken();        String value = elmSt.nextToken();        json.put(key, value);        }             String msg; try { msg = new ObjectMapper().writeValueAsString(json); } catch (JsonProcessingException e) { // TODO Auto-generated catch block e.printStackTrace(); }     map.put("jsonpayload", json);        } }

먼저 JsonLayout을 상속받아서 CustomLayout 이라는 클래스를 만든다. 그리고 addCustomDataToJsonMap 이라는 메서드를 오버라이딩한다. 이 메서드는 로그로 출력할 메시지와 각종 메타 정보(쓰레드명, 시간등)을 로그로 최종 출력하기 전에, Map객체에 그 내용을 저장하여 넘기는 메서드이다.

이 메서드 안에서 앞에서 로그로 받은 문자열을 파싱해서 json 형태로 만든다. 아래 코드가 파싱을 해서 파싱된 내용을 Map에 key/value 형태로 저장하는 코드이고

       StringTokenizer st = new StringTokenizer(event.getMessage(),",");

       Map<String,String> json = new TreeMap();

       while(st.hasMoreTokens()) {

       String elmStr = st.nextToken();

       StringTokenizer elmSt = new StringTokenizer(elmStr,":");

       String key = elmSt.nextToken();

       String value = elmSt.nextToken();

       json.put(key, value);

       }

다음 코드는 이 Map을 json으로 변환한 후, 이를 다시 String으로 변환하는 코드이다.

msg = new ObjectMapper().writeValueAsString(json);

그 후에 이 json 문자열을 jsonpayload 라는 json element 이름으로 해서, json 내용을 json으로 집어 넣는 부분이다.

map.put("jsonpayload", json);

   

그리고, 이 CustomLayout을 사용하기 위해서 src/main/logback.xml에서 아래와 같이 CustomLayout 클래스의 경로를 지정한다.

<?xml version="1.0" encoding="UTF-8"?> <configuration>    <appender name="CONSOLE-JSON" class="ch.qos.logback.core.ConsoleAppender">        <encoder class="ch.qos.logback.core.encoder.LayoutWrappingEncoder">            <layout class="com.terry.logging.logbackCustom.CustomLayout">                <jsonFormatter class="ch.qos.logback.contrib.jackson.JacksonJsonFormatter">                    <prettyPrint>true</prettyPrint>                </jsonFormatter>                <timestampFormat>yyyy-MM-dd'T'HH:mm:ss.SSSXXX</timestampFormat>                <appendLineSeparator>true</appendLineSeparator>            </layout>        </encoder>    </appender>    <root level="info">        <appender-ref ref="CONSOLE-JSON"/>    </root> </configuration>

설정이 끝난 후에, 로그를 출력해보면 다음과 같이 jsonpayload element 부분에 아래와 같이 json 형태로 로그가 출력된다.

{  "timestamp" : "2019-03-22T17:48:56.434+09:00",  "level" : "INFO",  "thread" : "main",  "logger" : "com.terry.logging.logbackCustom.App",  "context" : "default",  "timestampSeconds" : 1553244536,  "timestampNanos" : 434000000,  "severity" : "INFO",  "original_message" : "event:order,name:terry,address:terrycho@google.com",  "jsonpayload" : {    "address" : "terrycho@google.com",    "event" : "order",    "name" : "terry"  } }

log4j2

log4j2의 경우 slf4+logback 조합보다 더 유연한데, log.info 와 같이 로깅 부분에 문자열뿐만 아니라 Object를 직접 넘길 수 있다. ( log4j2의 경우에는 2.11 버전부터 JSON 로깅을 지원 : https://issues.apache.org/jira/browse/log4j2-2190 )

즉 log.info 등에 json 을 직접 넘길 수 있다는 이야기다. 그렇지만 이 기능은 log4j2의 기능이지 slf4j의 인터페이스를 통해서 제공되는 기능이 아니기 때문에, slf4j + log4j2 조합으로는 사용이 불가능하고  log4j2만을 이용해야 한다.

log4j2를 이용해서 json 로그를 남기는 코드는 아래와 같다.

package com.terry.logging.jsonlog; import java.util.Map; import java.util.TreeMap; import org.apache.logging.log4j.message.ObjectMessage; import org.apache.logging.log4j.LogManager; import org.apache.logging.log4j.Logger; public class App {   private static Logger log = LogManager.getLogger(App.class);    public static void main( String[] args )    {     Map<String,String> map = new TreeMap();     map.put("name", "terry");     map.put("email","terry@mycompany.com");     ObjectMessage msg = new ObjectMessage(map);     log.info(msg);    } }

Map 객체를 만들어서 json 포맷처럼 key/value 식으로 데이타를 넣은 다음에 ObjectMessage 객체 타입으로 컨버트를 한다. 그리고 로깅에서 log.info(msg)로 ObjectMessage 객체를 넘기면 된다.

그리고 아래는 위의 코드를 실행하기 위한 pom.xml 에서 dependency 부분이다.

<dependency> <groupId>org.apache.logging.log4j</groupId> <artifactId>log4j-slf4j18-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>

실행을 해보면 아래와 같이 json 포맷으로 메세지가 출력된 결과이다. message element를 보면, 위에서 넣은 key/value 필드인 email과, name 항목이 출력된것을 확인할 수 있다.

{  "thread" : "main",  "level" : "INFO",  "loggerName" : "com.terry.logging.jsonlog.App",  "message" : {    "email" : "terry@mycompany.com",    "name" : "terry"  },  "endOfBatch" : false,  "loggerFqcn" : "org.apache.logging.log4j.spi.AbstractLogger",  "instant" : {    "epochSecond" : 1553245991,    "nanoOfSecond" : 414157000  },  "contextMap" : { },  "threadId" : 1,  "threadPriority" : 5 }