블로그 이미지
평범하게 살고 싶은 월급쟁이 기술적인 토론 환영합니다.같이 이야기 하고 싶으시면 부담 말고 연락주세요:이메일-bwcho75골뱅이지메일 닷컴. 조대협


Archive»


 
 

로깅 시스템 #4 - Correlation id & MDC

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

Correlation id

하나의 프로그램은 여러개의 메서드들로 조합이 된다. 하나의 요청을 처리하기 위해서는 여러개의 메서드들이 순차적으로 실행이 되는데, 멀티 쓰레드 프로그램에서 여러개의 쓰레드 동시에 각각의 요청을 처리할때, 각 메서드에 로그를 남기게 되면, 멀티 쓰레드 프로그램에서는 쓰레드들이 서로 컨택스트를 바꿔가며 실행이 되기 때문에, 로그 메시지가 섞이게 된다

아래 그림을 보자.


요청 A와 B가 호출되어 각각 다른 쓰레드에서 실행이 되었을때, 위의 그림과 같이 로그 메시지가 섞이게 된다. 이런 경우 요청 A에 대한 처리 내용을 확인하기 위해서 요청 A에 대한 로그만을 보고 싶을때 로그가 섞여 버려서 요청 A에 대한 로그만을 분리해내는 것이 어렵다.


이런 문제를 해결하기 위해서는 로그를 기록할때, 요청 마다 고유의 ID를 부여해서 로그를 기록하게 되면, 그 ID를 이용해서 각 요청마다의 로그를 묶어서 볼 수 있다.


위의 그림을 보면 요청 A에 대해서는 “1”이라는 ID를 지정하고, 두번째로 들어온 요청 B에 대해서는 “A”라는 ID를 지정하면, 이 ID로 각 요청에 대한 로그들을 묶어서 조회할 수 있다. 이를 Correlation ID라고 한다.

ThreadLocal

그러면 이 Correlation ID를 어떻게 구현해야 할까?

요청을 받은 메서드에서 Correlation ID를 생성한 후, 다른 메서드를 호출할때 마다 이 ID를 인자로 넘기는 방법이 있지만, 이 방법은 현실성이 떨어진다. ID를 넘기기 위해서 모든 메서드에 공통적으로 ID 필드를 가져야 하기 때문이다.

이런 문제는 자바에서는 ThreadLocal이라는 변수를 통해서 해결할 수 있다.

ThreadLocal을 쓰레드의 로컬 컨텍스트 변수로 Thread 가 존재하는 한 계속해서 남아 있는 변수이다.

무슨 이야기인가 하면, 작업 요청이 들어왔을때, 하나의 쓰레드가 생성이 되고 작업이 끝나면 쓰레드가 없어진다고 하면, 쓰레드가 살아있을 동안에, 계속 유지되는 변수이다. 즉 쓰레드가 생성되어 있는 동안에, 쓰레드 안에서 계속 참고해서 쓸수 있는 쓰레드 범위의 글로벌 변수라고 생각하면 된다.

그래서 요청을 처음 받았을때 Correlation ID를 생성하고, 이를 ThreadLocal에 저장했다가 로그를 쓸때 매번 이 ID를 ThreadLocal에서 꺼내서 같이 출력하면 된다. 이 개념을 그림으로 표현해보면 다음과 같다.


ThreadLocal의 ID 변수에 Correlation ID를 저장해놓고, 각 메서드에서 이 값을 불러서 로그 출력시 함께 출력하는 방법이다.

MDC

그러나 이걸 일일이 구현하기에는 불편할 수 있기 때문에, slf4j,logback,log4j2등의 자바 로그 프레임워크에서는 이런 기능을 MDC(Mapped Diagnostic Context)로 제공한다.

단순하게 CorrelationID 뿐만 아니라 map 형식으로 여러 메타 데이타를 넣을 수 있다. Correlation ID는 여러 요청을  묶을 수 는 있지만 다양한 요청에 대한 컨텍스트는 알 수 없다. 실행되는 요청이 어떤 사용자로 부터 들어온것인지, 또는 상품 주문시 상품 주문 ID를 넣는다던지, 요청에 대한 다양한 컨텍스트 정보를 MDC에 저장하고 로그 출력시 함께 출력하면 더 의미 있는 로그를 출력할 수 있다.


MDC를 사용한 코드를 작성해보자

이 예제에서는 slf4j와 logback을 사용한다. 아래처럼 logback과 json 관련 의존성을 pom.xml 에 정의한다.


<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>



그리고 로그를 json 포맷으로 출력하기 위해서 아래와 같이 logback.xml 을 작성하여, main/resources/logback.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>



다음 아래와 같이 간단하게 MDC를 테스트 하는 코드를 작성한다.

package com.terry.logging.logbackMDC;


import org.slf4j.Logger;

import org.slf4j.LoggerFactory;

import org.slf4j.MDC;



public class App

{

   private static Logger log = LoggerFactory.getLogger(App.class);

   public static void main( String[] args )

   {

    log.info("Hello logback");

   

    MDC.put("userid", "terrycho");

    MDC.put("event", "orderProduct");

    MDC.put("transactionId", "a123");

    log.info("mdc test");

   

    MDC.clear();

    log.info("after mdc.clear");

   }

}


MDC를 사용하는 방법은 MDC에 값을 넣을때는 mdc.put(key,value)를 이용하여, 값을 넣고 지울때는  mdc.remove(key)를 이용해서 특정 키를 삭제한다. 전체를 지울때는 mdc.clear()를 사용한다. mdc에 저장된 내용은 logger를 이용해서 로그를 출력할때 마다 mdc 라는 element로 자동으로 함께 출력된다.

위의 예제를 보면 log.info(“hello logback”)으로 로그를 출력하였고 그 다음 mdc에 userid,event,transactionid 라는 키들로 값을 채운 다음에 log.info(“mdc test”)라는 로그를 출력하였다. 그리고 마지막에는 mdc를 모두 지운 후에 “after mdc clear”라는 로그를 출력하는 코드이다. 결과는 다음과 같다.


{

 "timestamp" : "2019-03-23T05:42:19.102Z",

 "level" : "INFO",

 "thread" : "main",

 "logger" : "com.terry.logging.logbackMDC.App",

 "message" : "Hello logback",

 "context" : "default"

}{

 "timestamp" : "2019-03-23T05:42:19.118Z",

 "level" : "INFO",

 "thread" : "main",

 "mdc" : {

   "event" : "orderProduct",

   "userid" : "terrycho",

   "transactionId" : "a123"

 },

 "logger" : "com.terry.logging.logbackMDC.App",

 "message" : "mdc test",

 "context" : "default"

}{

 "timestamp" : "2019-03-23T05:42:19.119Z",

 "level" : "INFO",

 "thread" : "main",

 "logger" : "com.terry.logging.logbackMDC.App",

 "message" : "after mdc.clear",

 "context" : "default"

}


첫번째 로그는 “Hello logback”이라는 메시지가 출력된 후에, 두번째 로그는 mdc 가 세팅되어 있기 때문에, mdc라는 element가 출력되는데, 그 안에 mdc에 저장한 event,userid,transactionid  값이 함께 출력되는 것을 볼 수 있다. 그리고 마지막에는 mdc를 clear 한후에, 로그를 출력하였기 때문에, 메시지만 출력이 되고 mdc 라는 element없이 출력된것을 확인할 수 있다.


slf4j+logback 을 사용할 경우에는 앞의 글에서 설명하였듯이 json으로 로그 출력시 message 문자열 하나면 json element로 출력할 수 있었다. 그래서 custom layout 등 다른 대체 기법을 사용하였는데, mdc를 사용하여 컨텍스트 정보를 넘기게 되면, slf4j와 logback의 제약 사항을 넘어서 json으로 여러 element를 로깅 할 수 있다.





본인은 구글 클라우드의 직원이며, 이 블로그에 있는 모든 글은 회사와 관계 없는 개인의 의견임을 알립니다.

댓글을 달아 주세요

로그 시스템 #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

}



본인은 구글 클라우드의 직원이며, 이 블로그에 있는 모든 글은 회사와 관계 없는 개인의 의견임을 알립니다.

댓글을 달아 주세요

로그 시스템 #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}



본인은 구글 클라우드의 직원이며, 이 블로그에 있는 모든 글은 회사와 관계 없는 개인의 의견임을 알립니다.

댓글을 달아 주세요

로그 시스템 #1 - 자바 로그 프레임웍

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

로그 시스템

로그 시스템은 소프트웨어의 이벤트를 기록 함으로써, 소프트웨어 동작 상태를 파악하고 문제가 발생했을때 이 동작 파악을 통해서 소프트웨어의 문제를 찾아내고 해결하기 위해서 디자인 되었다.

주로 로그 파일이라는 형태로 하나의 파일에 이벤트들을 기록하였다.


그러나 소프트웨어 스택이 OS, 미들웨어, 사용자 애플리케이션 (자바나 파이썬등으로 구현된 애플리케이션)으로 점점 다중화되고 시스템이 대형화 되면서 한대가 아니라 여러대의 서버에 로그를 기록하고 또한 마이크로 서비스 아키텍처로 인하여 서버 컴포넌트가 분산됨에 따라서 로그를 수집해야할 포인트가 많아지게 되었다. 이로 인해서 로그 시스템이 분산 환경을 지원해야 할 필요가 되었고, 단순히 파일로 로그를 기록하는 것만으로는 이러한 여러 시스템과 다중 계층에 대한 모니터링이 불가능하게 되었다.


또한 데이터 분석의 중요성이 대두됨에 따라서, 에러등의 동작 파악성의 로그 뿐만 아니라 사용자의 액티버티를 수집하여 데이터 분석에 사용하기 위해서 데이터 수집 역시 로그 시스템을 통하기 시작하였다.


그래서 몇개의 글에 걸쳐서 좋은 로그 시스템을 개발하기 위한 아키텍처에 대해서 설명하고자 한다.

좋은 로그 시스템이란

먼저 좋은 로그 시스템의 기본 개념을 정의 해보면 다음과 같다.

  • 로그 메시지는 애플리케이션의 동작을 잘 이해할 수 있도록 충분히 구체적이어야 한다.

  • 로그 메시지를 기록하는데 성능 저하가 없어야 한다.

  • 어떤 배포 환경이라도 로그를 수집하고 저장할 수 있도록 충분히 유연해야 한다. (분산 환경 지원, 대용량 데이타 지원등)

자바 로깅 프레임워크

각 프로그래밍 언어마다 고유의 로깅 프레임워크을 지원하지만, 특히 자바의 경우에는 그 프레임웍 수가 많고 발전된 모델이 많아서 자바 프레임워크를 살펴보고 넘어가고자 한다.  

자바는 역사가 오래된 만큼 많은 로깅 프레임웍을 가지고 있다. log4j, logback, log4j2,apache common logging, SLF4J 등 다양한 프레임워크 들이 있는데, 그 개념과 장단점을 알아보도록 하자.

SLF4J

SLF4J는 (Simple Logging Facade for Java)의 약자로 이름이 뜻하는 것과 같이 로깅에 대한 Facade 패턴이다. SLF4J는 자체가 로깅 프레임웍이 아니라, 다양한 로깅 프레임웍을 같은 API를 사용해서 접근할 수 있도록 해주는 추상화 계층이다. 그래서 다른 로그프레임웍과 같이 사용해야 하는데, 보통 Log4J, Logback, Log4J2등이 많이 사용된다. 즉 애플리케이션은 SLF4J API 인터페이스를 통해서 호출하지만, 실제로 호출되는 로깅 프레임웍은 다른 프레임웍이 호출된다는 이야기이다. 이렇게 추상화를 통해서 용도와 목적에 맞게 다른 로깅 프레임워크 으로 쉽게 전환이 가능함은 물론이고, 로깅에 필요한 코드들을 추상화해주기 때문에, 훨씬 쉽고 간단하게 로깅이 가능하다. apache common logging 역시, SLF4J와 같이 다른 로깅 프레임워크 들을 추상화 해주는 기능을 제공한다.



<그림 : SLF4J 가 다른 로깅 프레임웍을 추상화 하는 개념도 >

출처 source


그러나 SLF4J 이전에 개발된 레거시 시스템들의 경우에는 이러한 추상화 계층이 없어서 로그 프레임웍을 변경하고 있기 때문에 로깅 프레임웍을 교체하기가 어렵다. 이런 상황을 해결하기 위해서 SLF4J는 기존 로그 프레임웍에 대한 브릿지를 제공한다. 예를 들어 log4J로 개발된 로깅을 브릿지를 이용해서 SLF4J를 사용하도록 전환할 수 있다. 이런 구조는 레거시 로깅 시스템을 사용해서 개발된 시스템에 대해서, 로그 프레임웍에 대한 코드를 변경하지 않고, 뒷단에 로그 프레임웍을 변경할 수 있게 해주기 때문에, 로깅 프레임웍에 대한 마이그레이션을 쉽게 해준다.



<그림 : SLF4J 브릿지를 이용해서, 기존 로그 시스템을 연동 하는 개념도 >


자바 로깅 프레임워크

자바 로그 프레임웍에는 여러가지 종류가 있지만 그중에서 대표적을 사용되는 로그 프레임웍은 log4j,logback,log4j2 세가지 이다.

Log4J

Log4J는 이 중에서 가장 오래된 로그프레임웍으로 로그 프레임웍에 대한 초반 개념을 설정했다고 볼 수 있다. 현재는 개발이 중지되고, Log4J2로 새로운 버전으로 변경되었다.

Logback

아마 현재 국내에서 가장 널리 많이 사용되고 있는 로그 프레임워크일것이다. Log4J 개발자가 개발한 로그 프레임워크로 주로 Log4J 성능 부분에 대한 개선 작업이 많이 이루어 졌다. SLF4J와 네이티브로 연동이 가능하다.

Log4J2

가장 근래에 나온 프레임워크로 Logback 보다 후에 나오고, 가장 빠른 성능을 제공한다. Logback과 SLF4J사이의 연동 문제를 해결하였으며 비동기 로깅 ( asynchronous logging ) 을 제공하여, 특히 멀티 쓰레드 환경에서 높은 성능을 제공한다.



(source : https://logging.apache.org/log4j/2.x/performance.html )


또한 근래의 로깅 시스템들은 로그를 파일로 기록하기 보다는 ELK(Elastic Search)나 Kafka 등 외부 시스템으로 로그를 전송하여 모으는 형태를 많이 취하기 때문에 이에 대한 연동을 Appender를 통해서 제공한다.


제공되는 Appender는 다음과 같다.

  • Console

  • File, RollingFile, MemoryMappedFile

  • Flume, Kafka, JDBC, JMS, Socket, ZeroMQ

  • SMTP (emails on errors, woo!)

  • … much more


만약에 새로운 시스템을 개발한다면, Logback 보다는 그 다음 세대인 격인 Lob4j2를 사용하는 것을 권장한다.

본인은 구글 클라우드의 직원이며, 이 블로그에 있는 모든 글은 회사와 관계 없는 개인의 의견임을 알립니다.

댓글을 달아 주세요

  1. 2019.04.03 09:29  댓글주소  수정/삭제  댓글쓰기

    비밀댓글입니다

Python 공부 노트 6. - Logging

프로그래밍/Python | 2013.01.21 19:21 | Posted by 조대협

http://docs.python.org/2/howto/logging-cookbook.html


# Add the log message handler to the logger

handler = logging.handlers.RotatingFileHandler(

              LOG_FILENAME, maxBytes=20, backupCount=5)

              

my_logger.addHandler(handler)

my_logger.debug('log message here....')


Logger

: 일종의 identifier로, 애플리케이션 마다 logger를 정하 수 있음


handler

: 파일 핸들러, 소켓 핸들러,  Rotating 파일 핸들러등,스트림 핸들러(Console 등)

※ DB Handler는 없는 듯 하고, 소켓 핸들러를 이용하면, 분산 시스템에서 중앙 집중화된 Logger를 만들 수 있음

(단, 로그 서버가 별도로 있는게 아니기 때문에, 분산 환경용 로거는 만들기 나름)


formater

: 핸들러 마다 붙일 수 있음


logging 메서드

: debug,info,warn,error,critical

: setLevel로 로그 출려 레벨 정함


단순 예제


import logging


logger = logging.getLogger("logging_sample")

logger.setLevel(logging.DEBUG)

# file log handler

fh = logging.FileHandler("/temp/python.log")

fh.setLevel(logging.ERROR)

# console log handler

ch = logging.StreamHandler()

ch.setLevel(logging.DEBUG)

#create formmater

formatter = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')

ch.setFormatter(formatter)

fh.setFormatter(formatter)

logger.addHandler(ch)

logger.addHandler(fh)


logger.debug("this is debugging")

logger.info("this is info")



본인은 구글 클라우드의 직원이며, 이 블로그에 있는 모든 글은 회사와 관계 없는 개인의 의견임을 알립니다.

댓글을 달아 주세요