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


Archive»


 
 

Spring Boot + slf4j + MDC + Zipkin

 

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

 

아래 예제는 MDC를 이용해서 여러 메서드간의 컨텍스트를 연결하는 것을 확장해서, 서로 다른 프로세스와 서버간에 로그를 연결하는 방법이다. 서로 다른 프로세스 또는 서버간에 컨텍스트를 전달하려면 HTTP 헤더등을 통해러 리모트로 컨텍스트를 전달해야 하는데, 이를 가능하게 하는 오픈소스로 Zipkin이 있다. (자세한 설명은 이글을 참고하기 바란다. )

Zipkin은 원래 분산 로그 추적용으로 개발된 오픈소스가 아니라 원래 목적은 분산 시스템에서 각 구간별 레이턴시(지연시간)을 측정해서 구간별 소요 시간을 측정하는 트레이스용도로 개발이 되었지만, 구간별 소요 시간을 측정하기 위해서는 각 개별 서비스를 연결해야 하기 때문에, 트레이스 ID가 필요하게 되었고, 트레이스 ID를 로그에 같이 저장하였기 때문에, 부가적인 효과로 분산 로그 추적에도 사용할 수 있다.

Zipkin을 Spring Boot와 연결하는 방법은 오픈소스인 Spring Sleuth를 이용하면 쉽게 된다.

 

아래 예제는 앞의 글인  Spring Boot에서 MDC를 사용하는 예제에 Zipkin 연동만을 추가한 예제이다.

Spring Boot로 간단한 REST API를 구현한후, 로깅을 하는 예제이다. 로거는 slf4j와 logback을 사용하였고,  MDC를 이용해서 userId와 같은 컨택스트 정보를 넘기도록 하였고, JSON 포맷으로 로그를 출력하였다. 마이크로 서비스와 같은 분산 서비스간에 로그 추적성을 제공하기 위해서 ZipKin 라이브러리를 사용하였다. 스프링에서는 ZipKin 라이브러리 통합을 Spring Sleuth를 통해서 지원하기 때문에, Spring Sleuth와 Zipkin을 연결하여 코드를 작성하였다. 전체 코드는 여기를 참고하면 된다.

 

아래는 Spring Boot에서 Zipkin을 사용하기 위해서 메이븐 pom.xml에 의존성을 추가한 내용이다.

<dependency>

<groupId>org.springframework.boot</groupId>

<artifactId>spring-boot-starter-web</artifactId>

</dependency>

<dependency>

<groupId>org.springframework.cloud</groupId>

<artifactId>spring-cloud-starter-sleuth</artifactId>

<version>2.1.1.RELEASE</version>

</dependency>

<dependency>

<groupId>org.springframework.cloud</groupId>

<artifactId>spring-cloud-starter-zipkin</artifactId>

<version>2.1.1.RELEASE</version>

</dependency>

<dependency>

<groupId>org.springframework.boot</groupId>

<artifactId>spring-boot-starter-test</artifactId>

<scope>test</scope>

</dependency>

<dependency>

<groupId>com.google.cloud</groupId>

<artifactId>google-cloud-logging-logback</artifactId>

<version>0.84.0-alpha</version>

</dependency>


<!-- slf4j & logback 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>

<코드.pom.xml >

 

다음은 logback 로거를 사용하기 위해서 logback에 대한 설정을 한 logback.xml이다. JSON 포맷으로 로깅을 하도록 설정 하였다.

 

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

               <appendLineSeparator>true</appendLineSeparator>


               <jsonFormatter class="ch.qos.logback.contrib.jackson.JacksonJsonFormatter">

                   <!--

                   <prettyPrint>true</prettyPrint>

                    -->`

               </jsonFormatter>

           </layout>

       </encoder>

   </appender>


   <root level="info">

       <appender-ref ref="stdout"/>

   </root>

</configuration>

<코드. /resources/logback.xml >

 

Zipkin을 사용할 경우, 트레이스 정보를 zipkin 서버로 전송해야 하는데, 이를 위해서 zipkin 서버에 대한 정보를 설정해야 한다. 보통 zipkin 에이전트가 로컬에서 돌기 때문에, 포트만 지정하면 된다. 아래와 같이 zipkin 서버에 대한 포트를 8081로 지정하였고, 이 애플레케이션의 이름을 zipkin-server1으로 지정하였다. 이 예제에서는 zipkin을 분산로그 추적용으로만 사용하였기 때문에, 실제로 zipkin 서버 에이전트는 실행하지 않았다.

server.port = 8081

spring.application.name = zipkin-server1

<코드. /resources/application.properties >

 

다음은 Spring Boot의 REST API Controller 코드의 일부이다.

@RestController
@RequestMapping("/orders")
public class OrderController {
Logger log = LoggerFactory.getLogger("com.terry.logging.controller.OrderController");
@RequestMapping(value="/{id}",method=RequestMethod.GET)
public Order getOrder(@PathVariable int id,
      @RequestHeader(value="userid") String userid) {
  MDC.put("userId", userid);
  MDC.put("ordierId",Integer.toString(id));
  Order order = queryOrder(id,userid);
  log.info("Get Order");
  MDC.clear();
  return order;
}

Order queryOrder(int id,String userid) {
  String name = "laptop";
  Order order = new Order(id,name);
  order.setUser(userid);
  order.setPricePerItem(100);
  order.setQuantity(1);
  order.setTotalPrice(100);
  log.info("product name:"+name);
  return order;
}

<코드. /resources/application.properties >

 

Spring Sleuth를 사용하게 되면 자동으로 Zipkin 코드를 의존성 주입 (Dependency Injection)을 이용해서 코드에 삽입해주는데, 이때 몇가지 제약사항이 있다. Spring Boot로 들어오는 트래픽은 Servlet Filter를 통해서 의존성 주입을 하는데, Spring Boot에서 다른 서비스로 나가는 트래픽의 경우에는 Rest Template 이나, Feign Client 와 같은 특정한 방법만을 지원한다. 지원되는 라이브러리의 범위에 대해서는 이 링크를 참고하기 바란다.

 

위의 예제는 HTTP Header에서 들어온 userId를 MDC 컨텍스트에 저장하는 예제이다.

위의 REST 서비스를 호출해보면 다음과 같은 결과가 나온다.

<그림. PostMan을 통해서 REST 요청과 응답을 받은 화면 >

 

그리고, 호출후에 나온 로그는 다음과 같다.

 

{  

  "timestamp":"2019-04-14T05:49:52.573Z",

  "level":"INFO",

  "thread":"http-nio-8081-exec-1",

  "mdc":{  

     "traceId":"270b7b7b5a8d4b5c",

     "spanId":"270b7b7b5a8d4b5c",

     "spanExportable":"false",

     "X-Span-Export":"false",

     "ordierId":"1",

     "X-B3-SpanId":"270b7b7b5a8d4b5c",

     "X-B3-TraceId":"270b7b7b5a8d4b5c",

     "userId":"terry"

  },

  "logger":"com.terry.logging.controller.OrderController",

  "message":"Get Order",

  "context":"default"

}

<코드. /resources/application.properties >

 

위의 결과와 같이 MDC 부분에, Zipkin이 자동으로 traceId를 선언해서 삽입해 준다. MDC에 저장한 userId도 위처럼 한꺼번에 출력되는 것을 확인할 수 있다.

 

Spring Sleuth는 slf4j를 사용하는 경우에만 MDC 컨텍스트에 트레이스 ID를 넣어주기 때문에, 다른 자바 로깅 프레임웍을 slf4j없이 사용하는 경우 자동으로 트레이스 ID를 넣어주지 않기 때문에 이점을 주의하기 바란다.

(참고 : "Adds trace and span ids to the Slf4J MDC, so you can extract all the logs from a given trace or span in a log aggregator.")

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

댓글을 달아 주세요

스택드라이버 로깅을 테스트 하고자 로컬 환경에서 로그를 올리기 위해서 fluentd를 설치했는데

일단 설치는 서비스 어카운트를 다운 받아서 하면 되긴 하는데, 실행을 하고 로그를 전송하려면 아래와 같은 이유가 난다.

2019-04-02 01:20:36 +0900 [error]: #0 Failed to access metadata service:  error_class=Errno::EHOSTUNREACH error="Failed to open TCP connection to 169.254.169.254:80 (No route to host - connect(2) for \"169.254.169.254\" port 80)"
2019-04-02 01:20:36 +0900 [info]: #0 Unable to determine platform
2019-04-02 01:20:36 +0900 [error]: #0 Failed to set monitored resource labels for gce_instance:  error_class=RuntimeError error="Cannot construct a gce_instance resource without vm_id and zone"

169.254.169.254 로 호출을 하게 되어 있는데, 이게 구글 클라우드와 AWS IP대역에서만 호출할 수 있는듯.

이론적으로는 Fluentd를 사용하기 때문에, 다른 인프라에서도 될줄 알았는데. IP 대역을 막아놨네 그랴..

테스트 하려면 애플리케이션들도 같이 올려야 하는데...

도커로 말아서 AWS에서 올려보고 해야 쓰겄다. ㅜㅜ

 

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

댓글을 달아 주세요

로깅 시스템 #5 - Spring boot에서 JSON 포맷 로깅과 MDC 사용하기

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


실제로 백앤드 애플리케이션을 자바로 개발할때는 스프링 부트를 사용하는 경우가 대부분이기 때문에 앞에서 적용한 JSON 로그 포맷과 MDC 로깅을 스프링 부트에 적용해보자

스프링 부트라고 해도, 일반 자바 애플리케이션에 대비해서 로그 설정 부분에 다른점은 없다.

아래와 같이 pom.xml에 logback과 json 의존성을 추가한다.


<!-- slf4j & logback dependency -->

<dependency>

<groupId>ch.qos.logback</groupId>

<artifactId>logback-classic</artifactId>

<version>1.2.3</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>


다음 로그 포맷팅을 JSON으로 하기 위해서 아래와 같이 logback.xml 파일을 작성하여 main/resources 디렉토리에 저장한다. 이번 예제에서는 스프링 부트로 기동할 경우 스프링 부트 자체에 대한 로그가 많기 때문에, JSON 으로 엘리먼트 단위로 출력하면 줄바꿈이 많아서, 로그를 보는데 어려움이 있으니 엘리먼트 단위로 줄을 바꾸지 않도록 <prettyPrint> 옵션을 false 로 처리하고, 대신 이벤트마다는 줄을 바꾸는게 좋으니, <appendLineSeperator>를 true로 설정하였다.


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

               <appendLineSeparator>true</appendLineSeparator>


               <jsonFormatter class="ch.qos.logback.contrib.jackson.JacksonJsonFormatter">

                   <!--

                   <prettyPrint>true</prettyPrint>

                    -->`

               </jsonFormatter>

           </layout>

       </encoder>

   </appender>


   <root level="debug">

       <appender-ref ref="stdout"/>

   </root>

</configuration>


다음으로 아래와 같이 간단한 Controller를 작성하였다. /orders/{id} 형태의 REST API로 사용자 이름을 userid라는 키로 HTTP Header를 통해서 받도록 하였다.


package com.terry.logging.controller;

import org.springframework.web.bind.annotation.PathVariable;


import org.springframework.web.bind.annotation.RequestHeader;

import org.springframework.web.bind.annotation.RequestMapping;

import org.springframework.web.bind.annotation.RequestMethod;

import org.springframework.web.bind.annotation.RequestParam;

import org.springframework.web.bind.annotation.RestController;

import com.terry.logging.model.*;


import org.slf4j.Logger;

import org.slf4j.LoggerFactory;

import org.slf4j.MDC;


@RestController

@RequestMapping("/orders")


public class OrderController {

Logger log = LoggerFactory.getLogger("com.terry.logging.controller.OrderController");

@RequestMapping(value="/{id}",method=RequestMethod.GET)

public Order getOrder(@PathVariable int id,

@RequestHeader(value="userid") String userid) {

MDC.put("userId", userid);

MDC.put("ordierId",Integer.toString(id));

Order order = queryOrder(id,userid);

log.info("Get Order");

MDC.clear();

return order;

}

Order queryOrder(int id,String userid) {

String name = "laptop";

Order order = new Order(id,name);

order.setUser(userid);

order.setPricePerItem(100);

order.setQuantity(1);

order.setTotalPrice(100);


log.info("product name:"+name);

return order;

}

}


userid와 orderid를 MDC에 넣어서 매번 로그때 마다 출력하도록 하였다.

아래 코드는 위에서 사용된 Order Value Class 내용이다.


package com.terry.logging.model;


public class Order {

public Order(int id,String item) {

this.item=item;

this.id = id;

}

public String getItem() {

return item;

}

public void setItem(String item) {

this.item = item;

}

public int getPricePerItem() {

return pricePerItem;

}

public void setPricePerItem(int pricePerItem) {

this.pricePerItem = pricePerItem;

}

public int getQuantity() {

return quantity;

}

public void setQuantity(int quantity) {

this.quantity = quantity;

}

public int getTotalPrice() {

return totalPrice;

}

public void setTotalPrice(int totalPrice) {

this.totalPrice = totalPrice;

}

String item;

int pricePerItem;

int quantity;

int totalPrice;

int id;

String user;

public String getUser() {

return user;

}

public void setUser(String user) {

this.user = user;

}

public int getId() {

return id;

}

public void setId(int id) {

this.id = id;

}

}



코드를 실행한후 REST API 클라이언트 도구 (여기서는 Postman을 사용하였다.)를 호출하면 브라우져에는 다음과 같은 결과가 출력된다.

그리고 로그는 아래와 같이 출력된다.


MDC를 이용한 저장한 컨택스트는 아래와 같이 JSON의 mdc 컨택스에 출력되었고, log.info()로 출력한 로그는 message 엘리먼트에 출력된것을 확인할 수 있다.

{"timestamp":"2019-03-25T15:16:16.394Z","level":"DEBUG","thread":"http-nio-8080-exec-2","logger":"org.springframework.web.servlet.DispatcherServlet","message":"Last-Modified value for [/orders/1] is: -1","context":"default"}

{"timestamp":"2019-03-25T15:16:16.395Z","level":"INFO","thread":"http-nio-8080-exec-2","mdc":{"ordierId":"1","userId":"terry"},"logger":"com.terry.logging.controller.OrderController","message":"product name:laptop","context":"default"}

{"timestamp":"2019-03-25T15:16:16.395Z","level":"INFO","thread":"http-nio-8080-exec-2","mdc":{"ordierId":"1","userId":"terry"},"logger":"com.terry.logging.controller.OrderController","message":"Get Order","context":"default"}


전체 소스코드는 https://github.com/bwcho75/javalogging/tree/master/springbootmdc 에 저장되어 있다.


이렇게 하면, 스프링 부트를 이용한 REST API에서 어떤 요청이 들어오더라도, 각 요청에 대한 ID를 Controller에서 부여해서, MDC를 통하여 전달하여 리턴을 할때 까지 그 값을 유지하여 로그로 출력할 수 있다.


그러나 이 방법은 하나의 스프링 부트 애플리케이션에서만 가능하고, 여러개의 스프링 부트 서비스로 이루어진 마이크로 서비스에서는 서비스간의 호출이 있을 경우 이 서비스간 호출에 대한 로그를 묶을 수 없는 단점이 있다.

예를 들어 서비스 A → 서비스 B로 호출을 하였을 경우에는 서비스 A에서 요청에 부여한 ID와 서비스 B에서 요청에 부여한 ID가 다르기 때문에 이를 묶기가 어렵다. 물론 HTTP 헤더로 ID를 전달하는 등의 방법은 있지만, 그다지 구성이 깔끔 하지 않다. 이렇게 마이크로 서비스에서 서비스간의 ID를 추적할 수 있는 방법으로 분산 환경에서 서비스간의 지연 시간을 측정하는 프레임웍으로 Zipkin이라는 프레임웍이 있다. 다음 글에서는 이 Zipkin을 로그 프레임웍과 연결해서 마이크로 서비스 환경에서 스프링 부트 기반으로 서비스간의 로그 추적을 어떻게할 수 있는지에 대해서 알아보도록 한다.


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

댓글을 달아 주세요

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



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

댓글을 달아 주세요


쿠버네티스 #15

모니터링 3/3 구글 스택드라이버를 이용한 모니터링

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



구글 클라우드 쿠버네티스 스택드라이버 모니터링

쿠버네티스 모니터링 시스템을 구축하는 다른 방법으로는 클라우드 서비스를 사용하는 방법이 있다. 그중에서 구글 클라우드에서 제공하는 스택 드라이버 쿠버네티스 모니터링에 대해서 소개하고자한다.

https://cloud.google.com/monitoring/kubernetes-engine/


현재는 베타 상태로, 구글 클라우드 쿠버네티스 서비스 (GKE)에서만 지원이 되며, 쿠버네티스 버전 1.10.2 와 1.11.0 (또는 그 상위버전)에서만 지원이 되고, 모니터링 뿐 아니라, 쿠버네티스 서비스에 대한 로깅을 스택드라이버 로깅 서비스를 이용해서 함께 제공한다.


스택드라이버 쿠버네티스 모니터링을 설정하는 방법은 간단하다. 쿠버네티스 클러스터를 설정할때, 아래 그림과 같이 Additional features 항목에서 “Try the new Stackdriver beta monitoring and Logging experience” 항목을 체크하면 된다.



클러스터를 생성한 후에, 구글 클라우드 콘솔에서 Monitoring 메뉴를 선택한 후에



스택드라이버 메뉴에서 Resources 메뉴에서 아래 그림과 같이 Kubernetes 메뉴를 선택하면 쿠버네티스 모니터링 내용을 볼 수 있다.



모니터링 구조

스택드라이버 쿠버네티스 모니터링의 가장 큰 장점 중의 하나는 단순한 단일 뷰를 통해서 대부분의 리소스 모니터링 과 이벤트에 대한 모니터링이 가능하다는 것이다.

아래 그림이 스택드라이버 모니터링 화면인데, “2”라고 표시된 부분이 시간에 따른 이벤트이다. 장애등이 발생하였을 경우 아래 그림과 같이 붉은 색으로 표현되고, 3 부분을 보면, 여러가지 뷰 (계층 구조)로 각 자원들을 모니터링할 수 있다. 장애가 난 부분이 붉은 색으로 표시되는 것을 확인할 수 있다.



<출처 : https://cloud.google.com/monitoring/kubernetes-engine/observing >


Timeline에 Incident가 붉은 색으로 표시된 경우 상세 정보를 볼 수 있는데, Timeline에서 붉은 색으로 표시된 부분을 누르면 아래 그림과 같이 디테일 이벤트 카드가 나온다. 이 카드를 통해서 메모리,CPU 등 이벤트에 대한 상세 내용을 확인할 수 있다.



<출처 : https://cloud.google.com/monitoring/kubernetes-engine/observing >


반대로 정상적인 경우에는 아래 그림과 같이 이벤트 부분에 아무것도 나타나지 않고, 모든 자원이 녹색 동그라미로 표시되어 있는 것을 확인할 수 있다.


개념 구조

쿠버네티스 모니터링중에 어려운 점중의 하나는 어떤 계층 구조로 자원을 모니터링 하는가 인데, 이런점을 해결하기 위해서 구글 스택드라이버 쿠버네티스 모니터링은 3가지 계층 구조에 따른 모니터링을 지원한다. 모니터링 화면을 보면 아래와 같이 Infrastructure, Workloads, Services 와 같이 세가지 탭이 나오는 것을 볼 수 있다.



어떤 관점에서 클러스터링을 모니터링할것인가인데,

  • Infrastructure : 하드웨어 자원 즉, node를 기준으로 하는 뷰로,  Cluster > Node > Pod > Container 의 계층 구조로 모니터링을 제공한다.

  • Workloads : 워크로드, 즉 Deployment를 중심으로 하는 뷰로 Cluster > Namespace > Workload (Deployment) > Pod > Container 순서의 계층 구조로 모니터링을 제공한다.

  • Services : 애플리케이션 즉 Service 를 중심으로 하는 뷰로 Cluster > Namespace > Service > Pod > Container 계층 순서로 뷰를 제공한다.

Alert 에 대한 상세 정보

각 계층 뷰에서 리소스가 문제가 있을 경우에는 앞의 동그라미가 붉은색으로 표시가 되는데,  해당 버튼을 누르게 되면, Alert 에 대한 상세 정보 카드가 떠서, 아래 그림과 같이 이벤트에 대한 상세 정보를 확인할 수 있다.


<출처 : https://cloud.google.com/monitoring/kubernetes-engine/observing >

결론

지금까지 간단하게 쿠버네티스에 대한 모니터링과 로깅에 대해서 알아보았다. 프로메테우스나 그라파나와 같은 최신 기술을 써서 멋진 대쉬 보드를 만드는 것도 중요하지만 모니터링과 로깅은 시스템을 안정적으로 운영하고 장애전에 그 전조를 파악해서 대응하고, 장애 발생시에는 해결과 향후 예방을 위한 분석 및 개선 활동이 일어나야 한다. 이를 위해서 모니터링과 로깅은 어디까지나 도구일 뿐이고, 어떤 지표를 모니터링 할것인지 (SLI : Service Level Indicator), 지표의 어느값까지를 시스템 운영의 목표로 삼을 것인지 (SLO : Service Level Object)를 정하는 프렉틱스 관점이 더 중요하다.  이를 구글에서는 SRE (Site Reliability Engineering)이라고 하는데, 이에 대한 자세한 내용은 https://landing.google.com/sre/book.html 를 참고하기 바란다.

이런 프렉틱스를 구축하는데 목적을 두고, 모니터링을 위한 툴링등은 직접 구축하는 것보다는 클라우드에서 제공하는 스택 드라이버와 같은 솔루션이나 데이타독(Datadog)와 같은 전문화된 모니터링 툴로 구축을 해서 시간을 줄이고, 프렉틱스 자체에 시간과 인력을 더 투자하는 것을 권장한다.



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

댓글을 달아 주세요

Heroku에서 logentries를 이용하여 node.js 로그 모니터링 하기


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

 

Heroku에서 제공하는 로깅은 heroku logs –tail 명령을 이용해서 모니터링 할 수 있는데, 이 로그의 경우 최대 1500줄만 저장을 지원한다. 실제 운영 환경에서 1500줄의 로그란 부족해도 많이 부족한 양이다. 그래서 추가적인 서비스를 이용하는 것이 좋은데, 많은 로깅 서비스가 있지만, 간단하게 사용할 수 있는 로깅 서비스로 logentries 라는 서비스가 있다.

 



Figure 1 http://www.logentries.com

 

무료로 사용이 가능하고, 무료 사용시 최대 7일간의 로그를 저장해주고, 일 최대 33M 까지 로그를 저장할 수 있다.

가장 저렴한 Entry 플랜은 한달에 9$로 일 133M 로그를 최대 7일간 저장하고, 가장 비싼 Platium 플랜은 월 1399$로 일 최대 40GB의 로그를 최대 7일간 저장할 수 있게 해준다. (에러나 일반적인 시스템 로그라면, 왠만한 시스템이면 40GB정도면 충분하지 않나 싶다.)

 

그러면 앞서 작성하여 heroku에 배포한 node.js 애플리케이션에 이 logentires를 적용해 보자.

적용은 매우 간단하다. 명령창에서 간단하게 다음 명령을 실행하자

heroku addons:create logentries

 

명령을 실행하면 다음과 같이 logentries 가 설치되었다고 나온다.



Figure 2 logentries 설치

 

설치가 완료되었으면 이제 사용을 해보자. Heroku  대쉬 보드로 접속해서, 생성한 애플리케이션을 선택한다.



Figure 3 heroku dashboard에서 애플리케이션 선택

 

애플리케이션을 클릭해서 들어가면 하단 add-on 리스트에 logentries가 아래 그림과 같이 활성화가 되어 있는 것을 확인할 수 있다.



Figure 4 heroku 애플리케이션에서 add-onsLogentries가 설치된 화면

 

logentries를 클릭해서 들어가면, logentries를 이용한 로그 모니터링 화면이 나온다.

아래 그림과 같이 좌측에 “heroku”라는 Log set이 나오는데, 이를 클릭하고, 우측 상단에 “Live tail” 이라는 버튼을 누르면 현재 node.js의 로그를 실시간으로 보여준다. 실제로 해보면 heroku logs –tail 보다 약 1초 정도 지연이 발생한다.



Figure 5 logentries를 이용한 실시간 로그 모니터링

 

다음 화면은 node.js의 로그를 heroku logs –tail로 모니터링한 화면으로 위의 logentrieslive tail과 동일함을 확인할 수 있다.



Figure 6 heroku logs를 이용한 실시간 로그 모니터링

 

heroku 기본 로깅 시스템에 비해서 더 많은 로그를 볼 수 있는 것은 물론이고, 로그에 대한 검색이 가능하고, 특정 데이타를 기반으로 한 그래프등 다양한 기능을 지원한다.

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

댓글을 달아 주세요

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



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

댓글을 달아 주세요