❗이 게시물은 김영한님의 인프런 강좌 스프링 핵심 원리 - 고급편의 내용을 개인 정리를 위한 목적으로 작성하였습니다.
개발자라면 개발 뿐 아니라 개발한 애플리케이션의 확장에 따라 모니터링과 운영에 대한 준비된 전문성 또한 있어야 한다. 이때 모니터링되는 데이터는 대부분 로그를 활용하게 된다. 그러나 문제가 발생한 부분을 어렵게 찾아 로그를 만들어내기보다는 문제 발생이 예상되는 부분에 미리 로그를 남기도록 하는 로그 추적기를 별도로 만드는 일이 중요할 것이다.
요구사항 및 예시
요구사항
- 모든 PUBLIC 메서드의 호출과 응답 정보를 로그로 출력
- 애플리케이션의 흐름을 변경하면 안됨
- 로그를 남긴다고 해서 비즈니스 로직의 동작에 영향을 주면 안됨
- 메서드 호출에 걸린 시간
- 정상 흐름과 예외 흐름 구분
- 예외 발생시 예외 정보가 남아야 함
- 메서드 호출의 깊이 표현
- HTTP 요청을 구분
- HTTP 요청 단위로 특정 ID를 남겨서 어떤 HTTP 요청에서 시작된 것인지 명확하게 구분이 가능해야 함
- 트랜잭션 ID(DB 트랜잭션X), 여기서는 하나의 HTTP 요청이 시작해서 끝날 때 까지를 하나의 트랜잭션이라 함
예시
//정상 요청
[796bccd9] OrderController.request()
[796bccd9] |-->OrderService.orderItem()
[796bccd9] | |-->OrderRepository.save()
[796bccd9] | |<--OrderRepository.save() time=1004ms
[796bccd9] |<--OrderService.orderItem() time=1014ms
[796bccd9] OrderController.request() time=1016ms
//예외 발생
[b7119f27] OrderController.request()
[b7119f27] |-->OrderService.orderItem()
[b7119f27] | |-->OrderRepository.save()
[b7119f27] | |<X-OrderRepository.save() time=0ms
ex=java.lang.IllegalStateException: 예외 발생!
[b7119f27] |<X-OrderService.orderItem() time=10ms
ex=java.lang.IllegalStateException: 예외 발생!
[b7119f27] OrderController.request() time=11ms
ex=java.lang.IllegalStateException: 예외 발생!위 요구사항 중 트랜잭션 ID와 깊이를 표현하는 방법은 기존 정보를 이어 받아야하는 부분이라서 단순히 로그를 남기는 것만으로는 해결하기 어렵다. 따라서 요구사항에 맞춘 효과적인 로그 추적기가 필요하며, 그리고 이를 위한 프로토타입 버전을 개발할 필요가 있다.
로그 추적기 V1 - 프로토타입 개발
로그 추적기를 위한 기반 데이터를 갖고 있는 TraceId, TraceStatus 클래스를 만들어보자.
TraceId.java
package hello.advanced.trace;
import java.util.UUID;
public class TraceId {
private String id;
private int level;
public TraceId() {
this.id = createId();
this.level = 0;
}
private TraceId(String id, int level) {
this.id = id;
this.level = level;
}
private String createId() {
return UUID.randomUUID().toString().substring(0, 8);
}
public TraceId createNextId() {
return new TraceId(id, level + 1);
}
public TraceId createPreviousId() {
return new TraceId(id, level - 1);
}
public boolean isFirstLevel() {
return level == 0;
}
public String getId() {
return id;
}
public int getLevel() {
return level;
}
}TraceId는 id(트랜잭션ID)와 level(깊이)을 묶어 표현하기 위한 클래스이다. 그리고 UUID 자체는 너무 길어서 앞 8자리만을 사용하고, 깊이가 증가 또는 감소해도 트랜잭션ID는 그대로 두고서 사용하기 위한 등의 메서드들도 생성하였다.
TraceStatus.java
package hello.advanced.trace;
public class TraceStatus {
private TraceId traceId;
private Long startTimeMs;
private String message;
public TraceStatus(TraceId traceId, Long startTimeMs, String message) {
this.traceId = traceId;
this.startTimeMs = startTimeMs;
this.message = message;
}
public TraceId getTraceId() {
return traceId;
}
public Long getStartTimeMs() {
return startTimeMs;
}
public String getMessage() {
return message;
}
}TraceStatus는 로그의 상태 정보를 나타내기 위한 클래스이다. 각 로그의 상태는 시작과 끝을 갖게 되는데, 로그의 시작 시간 startTimeMs를 두면, 로그 종료시 로그의 전체 수행 시간을 계산할 수 있다.
그럼 이제 TraceId, TraceStatus를 사용해서 실제 로그를 생성하고, 처리하는 기능을 개발해보자.
HelloTraceV1.java
package hello.advanced.trace.hellotrace;
import hello.advanced.trace.TraceId;
import hello.advanced.trace.TraceStatus;
import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Component;
@Slf4j
@Component
public class HelloTraceV1 {
private static final String START_PREFIX = "-->";
private static final String COMPLETE_PREFIX = "<--";
private static final String EX_PREFIX = "<X-";
public TraceStatus begin(String message) {
TraceId traceId = new TraceId();
Long startTimeMs = System.currentTimeMillis();
log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX, traceId.getLevel()), message);
return new TraceStatus(traceId, startTimeMs, message);
}
public void end(TraceStatus status) {
complete(status, null);
}
public void exception(TraceStatus status, Exception e) {
complete(status, e);
}
private void complete(TraceStatus status, Exception e) {
Long stopTimeMs = System.currentTimeMillis();
long resultTimeMs = stopTimeMs - status.getStartTimeMs();
TraceId traceId = status.getTraceId();
if (e == null) {
log.info("[{}] {}{} time={}ms", traceId.getId(), addSpace(COMPLETE_PREFIX, traceId.getLevel()), resultTimeMs);
} else {
log.info("[{}] {}{} time={}ms ex={}", traceId.getId(), addSpace(EX_PREFIX, traceId.getLevel()), resultTimeMs, e.toString());
}
}
private static String addSpace(String prefix, int level) {
StringBuilder sb = new StringBuilder();
for (int i = 0; i < level; i++) {
sb.append( (i == level - 1) ? "|" + prefix : "| ");
}
return sb.toString();
}
}HelloTraceV1에서는 앞서 만든 TraceId와 TraceStatus를 통해 실제 로그를 시작하고 종료할 수 있으며, 로그의 시작과 종료, 예외를 나타내는 *_PREFIX와 깊이를 나타내는 addSpace()를 통해 상태를 확인할 수 있다. 그리고 실행시간도 측정할 수 있다.
@Component: 싱글톤으로 사용하기 위해 스프링 빈으로 등록한다. 컴포넌트 스캔의 대상이 된다.
HelloTraceV1Test.java
package hello.advanced.trace.hellotrace;
import hello.advanced.trace.TraceStatus;
import org.junit.jupiter.api.Test;
public class HelloTraceV1Test {
@Test
void begin_end() {
HelloTraceV1 trace = new HelloTraceV1();
TraceStatus status = trace.begin("hello");
trace.end(status);
}
@Test
void begin_exception() {
HelloTraceV1 trace = new HelloTraceV1();
TraceStatus status = trace.begin("hello");
trace.exception(status, new IllegalStateException());
}
}HelloTraceV1을 테스트하기 위해 HelloTraceV1Test를 만들었다. begin_end()는 로그의 시작과 종료 로그를 출력하고, begin_exception()는 로그의 시작과 예외 로그를 출력한다. 각각의 실행 결과는 다음과 같다.
//begin_end()
21:12:16.867 [main] INFO hello.advanced.trace.hellotrace.HelloTraceV1 -- [58328110] hello
21:12:16.867 [main] INFO hello.advanced.trace.hellotrace.HelloTraceV1 -- [58328110] hello time=0ms
//begin_exception()
21:12:16.857 [main] INFO hello.advanced.trace.hellotrace.HelloTraceV1 -- [9c146ee4] hello
21:12:16.860 [main] INFO hello.advanced.trace.hellotrace.HelloTraceV1 -- [9c146ee4] hello time=4ms ex=java.lang.IllegalStateExceptiontime=java.lang.IllegalStateExceptionms ex={}해결한 요구사항
- 모든 PUBLIC 메서드의 호출과 응답 정보를 로그로 출력
- 애플리케이션의 흐름을 변경하면 안됨
- 로그를 남긴다고 해서 비즈니스 로직의 동작에 영향을 주면 안됨
- 메서드 호출에 걸린 시간
- 정상 흐름과 예외 흐름 구분
- 예외 발생시 예외 정보가 남아야 함
로그 추적기 V2 - 파라미터로 동기화 개발
남은 요구사항
- 메서드 호출의 깊이 표현
- HTTP 요청을 구분
- HTTP 요청 단위로 특정 ID를 남겨서 어떤 HTTP 요청에서 시작된 것인지 명확하게 구분이 가능해야 함
- 트랜잭션 ID(DB 트랜잭션X)
HelloTraceV2.java
package hello.advanced.trace.hellotrace;
import hello.advanced.trace.TraceId;
import hello.advanced.trace.TraceStatus;
import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Component;
@Slf4j
@Component
public class HelloTraceV2 {
//생략
//V2에서 추가
public TraceStatus beginSync(TraceId beforeTraceId, String message) {
TraceId nextId = beforeTraceId.createNextId();
Long startTimeMs = System.currentTimeMillis();
log.info("[{}] {}{}", nextId.getId(), addSpace(START_PREFIX, nextId.getLevel()), message);
return new TraceStatus(nextId, startTimeMs, message);
}
}HelloTraceV2는 HelloTraceV1의 코드를 복사하여 beginSync() 메서드 하나만 추가하였다. 기존 TraceId에서 createNextId()를 통해 다음 ID를 구한다. 테스트 코드를 통해 잘 동작하는지 확인해보자.
HelloTraceV2Test.java
package hello.advanced.trace.hellotrace;
import hello.advanced.trace.TraceStatus;
import org.junit.jupiter.api.Test;
public class HelloTraceV2Test {
@Test
void begin_end() {
HelloTraceV2 trace = new HelloTraceV2();
TraceStatus status1 = trace.begin("hello1");
TraceStatus status2 = trace.beginSync(status1.getTraceId(), "hello2");
TraceStatus status3 = trace.beginSync(status2.getTraceId(), "hello3");
trace.end(status3);
trace.end(status2);
trace.end(status1);
}
@Test
void begin_exception() {
HelloTraceV2 trace = new HelloTraceV2();
TraceStatus status1 = trace.begin("hello1");
TraceStatus status2 = trace.beginSync(status1.getTraceId(), "hello2");
TraceStatus status3 = trace.beginSync(status2.getTraceId(), "hello3");
trace.exception(status3, new IllegalStateException());
trace.exception(status2, new IllegalStateException());
trace.exception(status1, new IllegalStateException());
}
}트랜잭션의 첫 호출은 begin()을 사용하고, 이후에는 beginSync()를 사용하면 된다. beginSync()를 호출할 때 직전 로그의 traceId 정보를 넘겨주어야 한다. 이에 따라 각각의 실행 결과를 확인해보자.
//begin_end()
21:55:24.166 [main] INFO hello.advanced.trace.hellotrace.HelloTraceV2 -- [4f97e640] hello1
21:55:24.166 [main] INFO hello.advanced.trace.hellotrace.HelloTraceV2 -- [4f97e640] |-->hello2
21:55:24.166 [main] INFO hello.advanced.trace.hellotrace.HelloTraceV2 -- [4f97e640] | |-->hello3
21:55:24.166 [main] INFO hello.advanced.trace.hellotrace.HelloTraceV2 -- [4f97e640] | |<--hello3 time=0ms
21:55:24.166 [main] INFO hello.advanced.trace.hellotrace.HelloTraceV2 -- [4f97e640] |<--hello2 time=0ms
21:55:24.166 [main] INFO hello.advanced.trace.hellotrace.HelloTraceV2 -- [4f97e640] hello1 time=0ms
//begin_exception()
21:55:24.150 [main] INFO hello.advanced.trace.hellotrace.HelloTraceV2 -- [a027788f] hello1
21:55:24.150 [main] INFO hello.advanced.trace.hellotrace.HelloTraceV2 -- [a027788f] |-->hello2
21:55:24.150 [main] INFO hello.advanced.trace.hellotrace.HelloTraceV2 -- [a027788f] | |-->hello3
21:55:24.150 [main] INFO hello.advanced.trace.hellotrace.HelloTraceV2 -- [a027788f] | |<X-hello3 time=0ms ex=java.lang.IllegalStateException
21:55:24.150 [main] INFO hello.advanced.trace.hellotrace.HelloTraceV2 -- [a027788f] |<X-hello2 time=0ms ex=java.lang.IllegalStateException
21:55:24.150 [main] INFO hello.advanced.trace.hellotrace.HelloTraceV2 -- [a027788f] hello1 time=0ms ex=java.lang.IllegalStateException
21:55:24.166 [main] INFO hello.advanced.trace.hellotrace.HelloTraceV2 -- [4f97e640] hello1로그 추적기 V2 - 적용
이제는 HelloTraceV2를 컨트롤러, 서비스, 리포지토리에 적용하여 각 계층별로 로그를 출력해보기로 하자.
OrderControllerV2.java
package hello.advanced.app.v2;
import hello.advanced.trace.TraceStatus;
import hello.advanced.trace.hellotrace.HelloTraceV2;
import lombok.RequiredArgsConstructor;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestParam;
import org.springframework.web.bind.annotation.RestController;
@RestController
@RequiredArgsConstructor
public class OrderControllerV2 {
private final OrderServiceV2 orderService;
private final HelloTraceV2 trace;
@GetMapping("/v2/request")
public String request(@RequestParam("itemId") String itemId) {
TraceStatus status = null;
try {
status = trace.begin("orderController.request()");
orderService.orderItem(status.getTraceId(), itemId);
trace.end(status);
return "ok";
} catch (Exception e) {
trace.exception(status, e);
throw e;
}
}
}컨트롤러에서는 트랜잭션을 생성하여 처음으로 호출하므로 begin()을 사용하고, 서비스로 status.getTraceId()를 통해 트랜잭션ID를 전달한다.
OrderServiceV2.java
package hello.advanced.app.v2;
import hello.advanced.trace.TraceId;
import hello.advanced.trace.TraceStatus;
import hello.advanced.trace.hellotrace.HelloTraceV2;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Service;
@Service
@RequiredArgsConstructor
public class OrderServiceV2 {
private final OrderRepositoryV2 orderRepository;
private final HelloTraceV2 trace;
public void orderItem(TraceId traceId, String itemId) {
TraceStatus status = null;
try {
status = trace.beginSync(traceId, "orderService.orderItem()");
orderRepository.save(status.getTraceId(), itemId);
trace.end(status);
} catch (Exception e) {
trace.exception(status, e);
throw e;
}
}
}서비스에서는 컨트롤러의 트랜잭션을 이어받으므로 beginSync()를 사용하고, 리포지토리로 status.getTraceId()를 통해 트랜잭션ID를 전달한다.
OrderRepositoryV2.java
package hello.advanced.app.v2;
import hello.advanced.trace.TraceId;
import hello.advanced.trace.TraceStatus;
import hello.advanced.trace.hellotrace.HelloTraceV2;
import lombok.RequiredArgsConstructor;
import org.springframework.stereotype.Repository;
@Repository
@RequiredArgsConstructor
public class OrderRepositoryV2 {
private final HelloTraceV2 trace;
public void save(TraceId traceId, String itemId) {
TraceStatus status = null;
try {
status = trace.beginSync(traceId, "OrderRepository.save()");
//저장 로직
if (itemId.equals("ex")) {
throw new IllegalStateException("예외 발생!");
}
sleep(1000);
trace.end(status);
} catch (Exception e) {
trace.exception(status, e);
throw e;
}
}
private void sleep(int millis) {
try {
Thread.sleep(millis);
} catch (InterruptedException e) {
e.printStackTrace();
}
}
}리포지토리에서도 서비스의 트랜잭션을 이어받으므로 beginSync()를 사용한다.
실행 결과를 확인해보자.
실행 결과
//정상 요청
2024-02-13T22:15:40.057+09:00 INFO 17140 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring DispatcherServlet 'dispatcherServlet'
2024-02-13T22:15:40.057+09:00 INFO 17140 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
2024-02-13T22:15:40.064+09:00 INFO 17140 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : Completed initialization in 0 ms
2024-02-13T22:15:40.083+09:00 INFO 17140 --- [nio-8080-exec-1] h.a.trace.hellotrace.HelloTraceV2 : [9797b183] orderController.request()
2024-02-13T22:15:40.083+09:00 INFO 17140 --- [nio-8080-exec-1] h.a.trace.hellotrace.HelloTraceV2 : [9797b183] |-->orderService.orderItem()
2024-02-13T22:15:40.083+09:00 INFO 17140 --- [nio-8080-exec-1] h.a.trace.hellotrace.HelloTraceV2 : [9797b183] | |-->OrderRepository.save()
2024-02-13T22:15:41.097+09:00 INFO 17140 --- [nio-8080-exec-1] h.a.trace.hellotrace.HelloTraceV2 : [9797b183] | |<--OrderRepository.save() time=1014ms
2024-02-13T22:15:41.097+09:00 INFO 17140 --- [nio-8080-exec-1] h.a.trace.hellotrace.HelloTraceV2 : [9797b183] |<--orderService.orderItem() time=1014ms
2024-02-13T22:15:41.097+09:00 INFO 17140 --- [nio-8080-exec-1] h.a.trace.hellotrace.HelloTraceV2 : [9797b183] orderController.request() time=1014ms
//예외 발생
2024-02-13T22:16:48.693+09:00 INFO 17140 --- [nio-8080-exec-4] h.a.trace.hellotrace.HelloTraceV2 : [fa0a916d] orderController.request()
2024-02-13T22:16:48.693+09:00 INFO 17140 --- [nio-8080-exec-4] h.a.trace.hellotrace.HelloTraceV2 : [fa0a916d] |-->orderService.orderItem()
2024-02-13T22:16:48.693+09:00 INFO 17140 --- [nio-8080-exec-4] h.a.trace.hellotrace.HelloTraceV2 : [fa0a916d] | |-->OrderRepository.save()
2024-02-13T22:16:48.693+09:00 INFO 17140 --- [nio-8080-exec-4] h.a.trace.hellotrace.HelloTraceV2 : [fa0a916d] | |<X-OrderRepository.save() time=0ms ex=java.lang.IllegalStateException: 예외 발생!
2024-02-13T22:16:48.693+09:00 INFO 17140 --- [nio-8080-exec-4] h.a.trace.hellotrace.HelloTraceV2 : [fa0a916d] |<X-orderService.orderItem() time=0ms ex=java.lang.IllegalStateException: 예외 발생!
2024-02-13T22:16:48.693+09:00 INFO 17140 --- [nio-8080-exec-4] h.a.trace.hellotrace.HelloTraceV2 : [fa0a916d] orderController.request() time=0ms ex=java.lang.IllegalStateException: 예외 발생!
2024-02-13T22:16:48.693+09:00 ERROR 17140 --- [nio-8080-exec-4] o.a.c.c.C.[.[.[/].[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed: java.lang.IllegalStateException: 예외 발생!] with root cause
java.lang.IllegalStateException: 예외 발생!이로써 모든 요구사항을 해결하였다. 그러나 남은 문제가 있다.
남은 문제
- HTTP 요청을 구분하고 깊이를 표현하기 위해서
TraceId동기화가 필요하다. TraceId의 동기화를 위해서 관련 메서드의 모든 파라미터를 수정해야 한다.- 만약 인터페이스가 있다면 인터페이스까지 모두 고쳐야 하는 상황이다.
- 로그를 처음 시작할 때는
begin()을 호출하고, 처음이 아닐때는beginSync()를 호출해야 한다.- 만약에 컨트롤러를 통해서 서비스를 호출하는 것이 아니라, 다른 곳에서 서비스를 처음으로 호출하는 상황
이라면 파리미터로 넘길TraceId가 없다.
- 만약에 컨트롤러를 통해서 서비스를 호출하는 것이 아니라, 다른 곳에서 서비스를 처음으로 호출하는 상황
HTTP 요청을 구분하고 깊이를 표현하기 위해서 TraceId를 파라미터로 넘기는 것 말고 다른 대안은 없을까?
이에 대한 대안으로 다음 게시물에서 ThreadLocal을 알아보자.
유랑하는 백엔드 개발자 새싹 블로그