위 내용은 인프런 - 스프링 핵심 원리(고급편) 을 듣고 혼자 정리한 내용입니다.
틀리거나 잘못된 내용이 있으면 댓글로 알려주세요.
상황
프로젝트가 잘 동작하는지 확인하기 위해 로그를 찍어야 하는데 아래와 같이 프로젝트 요청의 깊이가 보여야하고 같은 요청이라는 것을 알기위해 요청마다 ID도 같이 출력할 것.
현재 프로젝트 흐름
OrderControllerV3 -> log 출력 -> OrderServiceV3 -> log 출력 -> OrderRepositoryV3 -> log 출력 -> OrderRepositoryV3 end log 출력 -> OrderServiceV3 end log 출력 -> OrderControllerV3 end log 출력
프로젝트 구조
Log 관련
LogTraceConfig
@Configuration
public class LogTraceConfig {
@Bean
public LogTrace logTrace(){
return new FieldLogTrace();
}
}
TraceStatus
// 요청 Id, level을 가지는 class
public class TraceId {
private String id;
private int level;
public TraceId() {
this.id = createId();
this.level = 0;
}
private TraceId(String id, int i) {
this.id = id;
this.level = i;
}
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;
}
}
TraceStatus
// 로그의 상태 정보를 나타냄
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;
}
}
interface LogTrace
public interface LogTrace {
TraceStatus begin(String message); // 로그 시작
void end(TraceStatus status); // 로그 끝
void exception(TraceStatus status, Exception e); // 로그 에러 발생
}
FieldLogTrace
@Slf4j
// LogTrace의 구현체. log를 출력하는 class.
public class FieldLogTrace implements LogTrace{
// 깊이에 따른 화살표 표시
private static final String START_PREFIX = "-->";
private static final String COMPLETE_PREFIX = "<--";
private static final String EX_PREFIX = "<x-";
// Id를 필드에 두고 계속 사용.
private TraceId traceHolder;
@Override
public TraceStatus begin(String message) {
syncTraceId();
TraceId traceId = traceHolder;
long startTimeMs = System.currentTimeMillis();
log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX, traceId.getLevel()), message);
return new TraceStatus(traceId, startTimeMs, message);
}
// 현재 Id의 상태에 따라 생성 or level 증가
private void syncTraceId(){
if (traceHolder == null){
traceHolder = new TraceId();
} else {
traceHolder = traceHolder.createNextId();
}
}
@Override
public void end(TraceStatus status) {
complete(status, null);
}
@Override
public void exception(TraceStatus status, Exception e) {
complete(status, e);
}
// 메서드 종료, 에러 발생 시 로그 출력
private void complete(TraceStatus status, Exception e){
Long stopTime = System.currentTimeMillis();
long resultTime = stopTime - status.getStartTimeMs();
TraceId traceId = status.getTraceId();
if (e == null) log.info("[{}] {}{} time={}ms", traceId.getId(), addSpace(COMPLETE_PREFIX, traceId.getLevel()),
status.getMessage(), resultTime);
else log.info("[{}] {}{} time={}ms ex={}", traceId.getId(), addSpace(EX_PREFIX, traceId.getLevel()),
status.getMessage(), resultTime, e.toString());
releaseTraceId(); // 3 -> 2 -> 1 줄어든다
}
// level이 줄어드는 메서드
private void releaseTraceId(){
if (traceHolder.isFirstLevel()){
traceHolder = null;
} else {
traceHolder = traceHolder.createPreviousId();
}
}
// 현재 level에 따라 그림 입력
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();
}
}
요청 관련
OrderControllerV3
@RestController
@RequiredArgsConstructor
public class OrderControllerV3 {
private final OrderServiceV3 orderService;
private final LogTrace trace; // log의 정보를 가지고 있는 class.
@GetMapping("/v3/request") // http 요청 주소
public String request(@RequestParam("itemId") String itemId){ // itemId를 Param으로 받는다
TraceStatus status = null;
try {
// 로그 시작 메서드 호출(파라미터로 현재 호출 메서드 넘김)
status = trace.begin("OrderController.request()");
// service로 itemId 넘기면서 호출
orderService.orderItem(itemId);
trace.end(status);
return "ok";
} catch (Exception e) {
trace.exception(status, e);
throw e;
}
}
}
OrderServiceV3
@Service
@RequiredArgsConstructor
public class OrderServiceV3 {
private final OrderRepositoryV3 orderRepository;
private final LogTrace trace;
// 아이템을 주문하는 로직
public void orderItem( String itemId){
TraceStatus status = null;
try {
// controller에서 깊이가 1개 들어갔으므로 beginSync로 level + 1
status = trace.begin("OrderService.orderItem()");
orderRepository.save(itemId);
trace.end(status);
} catch (Exception e) {
trace.exception(status, e);
throw e;
}
}
}
OrderRepositoryV3
@Repository
@RequiredArgsConstructor
public class OrderRepositoryV3 {
private final LogTrace trace;
public void save (String itemId){
TraceStatus status = null;
try {
// controller -> service -> repository 총 3 깊이.
status = trace.begin("OrderRepository.save()");
trace.end(status);
if (itemId.equals("ex")){
throw new IllegalStateException("예외 발생!!");
}
sleep(1000);
} catch (Exception e) {
trace.exception(status, e);
throw e;
}
}
private void sleep(int millis){
try {
Thread.sleep(millis);
} catch (InterruptedException e) {
throw new RuntimeException(e);
}
}
}
위와 같은 구조일 때 실행을 시키면 어떻게 동작할까
실행결과를 보면 예상과는 다르게 로그가 찍히는 모습을 볼 수있다.
[177a70ec] 와 [efaa35c2] 요청이 동시에 들어왔는데 아래 로그부터는 177a70ec 요청의 모습을 볼 수 없다.
또, Repository.save() 를 했으면 | |<--OrderRepository.save() time= , |<--OrderService.orderItem() time=
OrderController.request() 순서로 로그가 찍히고 ID가 null로 변경되어야 하는데 현재 efaa35c2 라는 ID는 계속 사용되고 있는 것을 볼 수 있다.
왜 이런 일이 발생할까?
현재 프로젝트에는 아주 큰 문제가 있는데 동시성 문제이다.
해당 프로젝트에서 동시성이 일어나는 이유는 현재 FieldLogTrace가 singleton으로 등록이 되기 때문이다.
FieldLogTrace가 싱글톤으로 등록이 되면서 FieldLogTrace 내부 필드인 TraceId의 값이 동시에 수정이 되면서 일어난 문제이다.
해결방법
ThreadLocal을 사용해서 해결할 수 있다.
ThreadLocal이란
ThreadLocal은 자바에서 기본으로 제공해주는 기능으로 각 Thread마다 공간이 할당되어 데이터를 저장하는 방식이다.
공식문서에 보면 친절하게 어떤 기능인지 나와있다.
ThreadLocal을 이용해서 각 Thread마다 다른 저장공간을 갖게하여 더 이상 같은 값을 참조하지 않도록 하자.
ThreadLocalLogTrace 라는 class를 새로 생성해서 코드를 아래와 같이 작성해주자.
package com.spring.advanced.logtrace;
import com.spring.advanced.trace.TraceId;
import com.spring.advanced.trace.TraceStatus;
import lombok.extern.slf4j.Slf4j;
@Slf4j
public class ThreadLocalLogTrace implements LogTrace{
private static final String START_PREFIX = "-->";
private static final String COMPLETE_PREFIX = "<--";
private static final String EX_PREFIX = "<x-";
/*
FieldLogTrace와 다른점
ThreadLocal 사용하기
*/
private ThreadLocal<TraceId> traceHolder = new ThreadLocal<>();
@Override
public TraceStatus begin(String message) {
syncTraceId();
TraceId traceId = traceHolder.get();
long startTimeMs = System.currentTimeMillis();
log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX, traceId.getLevel()), message);
return new TraceStatus(traceId, startTimeMs, message);
}
private void syncTraceId(){
TraceId traceId = traceHolder.get();
if (traceId == null){
traceHolder.set(new TraceId());
} else {
traceHolder.set(traceId.createNextId());
}
}
@Override
public void end(TraceStatus status) {
complete(status, null);
}
@Override
public void exception(TraceStatus status, Exception e) {
complete(status, e);
}
private void complete(TraceStatus status, Exception e){
Long stopTime = System.currentTimeMillis();
long resultTime = stopTime - status.getStartTimeMs();
TraceId traceId = status.getTraceId();
if (e == null) log.info("[{}] {}{} time={}ms", traceId.getId(), addSpace(COMPLETE_PREFIX, traceId.getLevel()),
status.getMessage(), resultTime);
else log.info("[{}] {}{} time={}ms ex={}", traceId.getId(), addSpace(EX_PREFIX, traceId.getLevel()),
status.getMessage(), resultTime, e.toString());
releaseTraceId(); // 3 -> 2 -> 1 줄어든다
}
// level이 줄어드는 메서드
private void releaseTraceId(){
TraceId traceId = traceHolder.get();
if (traceId.isFirstLevel()){
// 다 사용시 꼭 remove 하기
traceHolder.remove();
} else {
traceHolder.set(traceId.createPreviousId());
}
}
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();
}
}
LogTraceConfig
@Configuration
public class LogTraceConfig {
@Bean
public LogTrace logTrace(){
return new ThreadLocalLogTrace();
}
}
실행을 해보자.
이제 각 Thread마다 개별적으로 동작하는 것을 확인할 수 있다!
참조
자바 공식 문서 : https://docs.oracle.com/javase/8/docs/api/