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

로깅 시스템 #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을 로그 프레임웍과 연결해서 마이크로 서비스 환경에서 스프링 부트 기반으로 서비스간의 로그 추적을 어떻게할 수 있는지에 대해서 알아보도록 한다.