스프링 핵심 원리 - 로그 추적기 1(기본 로그 추적기 이해, 객체 공유 문제)
[ 로그 추적기 ]
영한님의 스프링 핵심 원리 강의를 보았는데, 기본이라고 생각했을 수도 있지만 설명이 조금 부족했다고 느꼈고 이 부분에 대한 해석을 공유해봤으면 하는 바람으로 코드는 내가 생각한게 아니지만 공개 설정으로 열어 두었다.
로그로 작성을 할 때에 오류가 일어나는 부분을 찾기 위해 어떤 프로세스가 어떤 메서드를 찾다가 에러가 발생했는지를 작성하려고 한다. 결과적으로 아래처럼 계층적으로 출력이 되게 된다. 요구사항은 어떤 쓰레드에서 어떤 계층의 어떤 메서드를 호출했는지를 호출하고 이를 잘 구분될 수 있게 계층적으로 출력하라는 것이다. 마지막엔 시간 혹은 에러도 출력을 해야 한다.
우선 트리 형태의 코드를 작성하기 위해서는 두 가지가 필요하다. 첫 번째는 계층 별로 level과 같은 걸 저장하고 다음으로 넘길 때마다 하위 계층으로 가면 level을 감소시키고 상위 계층으로 가면 level을 증가시켜주어야 한다. 또한 어떤 쓰레드에서 호출했는지 확인하기 위한 id를 저장해야 한다.
스프링은 기본적으로 쓰레드 풀에서 쓰레드를 가져와서 해당 쓰레드가 URI에 들어온 요청에 따라 적절한 컨트롤러를 호출해준다. 그렇기 때문에 컨트롤러에서 동일한 쓰레드에서 처리한 것임을 기록하기 위해 임의로 만든 UUID의 앞 8자리를 id로 사용하고 트리 구조를 위해 level 변수를 넣어주었다. 처음 TraceId가 생성될 때에는 id값을 생성해주어야 하니 임의의 값을 만들고 level을 0으로 지정해준다.
확인용 코드:
TraceId.java
@Getter
public class TraceId {
private String id;
private int level;
public TraceId(){
this.id = createId();
this.level = 0;
}
private String createId() {
// 생성된 UUID의 앞 8자리만 사용
return UUID.randomUUID().toString().substring(0, 8);
}
그리고 이제 level을 올릴 때와 내릴 때인데 다음과 같이 레벨을 올릴 때 내릴 때에는 기존 id에 level만 바꾸어주는 메서드 createNextId와 createPreviousId 그리고 삭제 직전을 알기 위한 isFirstLevel이 있다.
여기서 왜 TraceId를 새로운 생성자를 통해서 만들어주는지 궁금할 수 있다. 그 이유는 호출 위치에 관한 정보를 담고 변경할 때 생기는 문제를 예방하기 위함인데, 이는 모든 코드를 설명하고 다시 설명하도록 하겠다.
확인용 코드:
private TraceId(String id, int level){
this.id = id;
this.level = level;
}
public TraceId createNextId(){
return new TraceId(id, level + 1);
}
public TraceId createPreviousId(){
return new TraceId(id, level-1);
}
public boolean isFirstLevel(){
return level == 0;
}
이제 시간 정보를 출력하기 위해 TraceStatus를 만들 것이다. 해당 객체에는 TraceId와 시작 시간, 호출 장소와 메서드에 관한 정보가 들어있다.
확인용 코드:
TraceStatus.java
@Getter
@AllArgsConstructor
public class TraceStatus {
private TraceId traceId;
private Long startItemMs;
private String message;
}
이제 TraceStatus와 계층 정보를 받아서 각 계층에서 적절한 level값을 설정하고 해당 level에 맞는 로그 출력값을 만들어줄 클래스를 만들어주어야 한다.
계층에 맞는 출력은 반복문을 사용하면 된다. 해당 반복문은 삼항 연산자가 들어있어서 그렇지 각 계층 깊이에 맞게 level * '| '를 출력해준다. 만약 마지막 부분이면 화살표를 출력해야하니 해당 부분에는 '|' + prefix로 놔둔 것이다.
// level=0
// level=1 |-->
// level=2 | |-->
// level=2 ex | |<X-
// level=1 ex |<X-
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();
}
그리고 계층에서 더 하위 계층으로 갈 때에는 level을 높여주어야 한다. 그래야지 Repository에서 가장 높은 level을 가지기 때문이다. 출력값에 대한 특별한 설명은 하지 않도록 하겠다. 여기서도 주목해야 할 부분은 새로 begin혹은 beginSync가 호출될 때마다 각 계층 별 TraceId를 따로 가지고 있다는 점과 Status도 새로 만들어진다는 것이다.
확인용 코드:
@Slf4j
@Component
public class HelloTraceV2 {
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);
}
// 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는 TraceStatus를 받아서 특정 로직을 처리만 해주지 특정 정보를 저장하지 않기 때문에 싱글톤으로 만들어도 되며, DI를 위해 SpringBoot의 컴포넌트 스캔 대상이 되기 위해서 @Component를 붙였다. 따로 @Bean으로 Configuration으로 수동등록해도 상관은 없긴 하다.
확인용 코드:
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.getStartItemMs();
TraceId traceId = status.getTraceId();
if(e == null){
log.info("[{}] {}{} time={}ms", traceId.getId(), addSpace(COMPLETE_PREFIX, traceId.getLevel()), status.getMessage(), resultTimeMs);
} else{
log.info("[{}] {}{} time={}ms ex={}", traceId.getId(), addSpace(EX_PREFIX, traceId.getLevel()), status.getMessage(), resultTimeMs, e.toString());
}
}[ 리포지토리, 서비스, 컨트롤러 적용 ]
위에서 유의깊게 보라고 한 이유는 이제 실제로 적용할 때에 문제가 생기게 된다. 우선 컨트롤러 코드, 서비스 코드, 리포지토리 코드를 보자.
컨트롤러 코드 확인용:
@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);
} catch(Exception e){
trace.exception(status, e);
throw e; // 예외를 꼭 다시 던져줘야 한다. 로그 때문에 예외가 삼켜지면 안된다.
}
return "ok";
}
}
서비스 코드 확인용:
@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; // 예외를 꼭 다시 던져줘야 한다. 로그 때문에 예외가 삼켜지면 안된다.
}
}
}
리포지토리 확인용:
@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();
}
}
}
해당 코드들과 이전에 작성한 TraceId, TraceStatus의 흐름을 정리하면 아래 그림과 같이 표현을 할 수 있다. 처음 출력 값 요구사항에 맞게 잘 출력이 되는 걸 확인할 수 있고 각 과정에서 다음과 같은 흐름이 나오게 된다.
하지만 아까 주의깊게 보라고 한 TraceId에서 level을 올리는데 새로운 객체를 만들고 TraceStatus 부분에서도 매번 새로운 객체로 생성하는 이유는 아래의 그림을 보면 알 수 있다. 만약 해당 객체들을 공유하고 setter 비슷한 거로 내부를 바꿔버리는 코드를 짰다면 다음처럼 Controller에서는 아무런 문제가 없다가 Service 때 TraceId와 Status가 Controller에 적용되고 Repository에서 결과가 다음처럼 Controller와 Service 모두에 영향을 준다. 그럼 위의 계층 코드를 그대로 사용한다면 End와 Exception 호출시 원하지 않는 값이 나오게 된다. 그렇기 때문에 setter를 열어두거나 객체 자체를 넘겨주는 방식을 선택하는게 아니라 새로운 객체를 생성하는 방식으로 한 것 같다는 생각이 든다.
아직 많은 문제가 남아있는 코드이지만 해당 부분은 강의에서 잘 설명이 되어있으니 그 부분을 참고하길 바라고 나머지는 저작권이 있는 자료이기 때문에 비공개로 해놓을 예정이다. 아무튼 이런 객체 공유에 관한 예시를 확인할 수 있는 좋은 예시인 것 같다는 생각이 들었고 정리를 하는 김에 같이 정리를 해보았다.
[ 참고 자료 ]
스프링 핵심 원리 - 고급편 - 김영한 강의
https://tecoble.techcourse.co.kr/post/2020-06-11-value-object/