📗 새로운 로그 추적기 개발

이전의 로그 추적기의 문제점은 TraceId값을 모두 동일하게(=동기화) 가져가기 위해 모든 메서드의 파라미터로 TraceId 값을 받아서 사용해야했다. 그럼 이후에도 모든 메서드를 생성할 때마다 파라미터가 기본 1개씩 추가되어야하는 일이 생기는데 이 부분을 해결할 수 있도록 새로운 로그 추적기를 개발해보자!

📄 interface로 정의하기

개발하기 이전에 앞으로 로그 추적기를 계속해서 개발할거 같으니 interface로 먼저 정의해서 상속받아가지고 개발을 진행해보자.

public interface LogTrace {
    TraceStatus begin(String message);

    void end(TraceStatus status);

    void exception(TraceStatus status, Exception e);
}

📄 구현하기

@Slf4j
public class FieldLogTrace implements LogTrace {

    private static final String START_PREFIX = "-->";
    private static final String COMPLETE_PREFIX = "<--";
    private static final String EX_PREFIX = "<X-";

    private TraceId traceIdHolder; // traceId 동기화, (동시성 이슈가 발생할 수 있음)

    @Override
    public TraceStatus begin(String message) {
        syncTraceId(); // traceId를 생성 or netx id 값을 가져옴
        TraceId traceId = traceIdHolder;
        Long startTimeMs = System.currentTimeMillis();
        log.info("[{}] {}{}", traceId.getId(), addSpace(START_PREFIX, traceId.getLevel()), message);
        return new TraceStatus(traceId, startTimeMs, message);
    }

    private void syncTraceId() {
        if (traceIdHolder == null) {
            traceIdHolder = new TraceId();
        } else {
            traceIdHolder = traceIdHolder.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 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()),
                    status.getMessage(), resultTimeMs);
        } else {
            log.info("[{}] {}{} time={}ms ex={}", traceId.getId(), addSpace(EX_PREFIX, traceId.getLevel()),
                    status.getMessage(), resultTimeMs, e.toString());
        }

        // 완료된 이후의 traceId 상태를 조절
        releaseTraceId();
    }

    private void releaseTraceId() {
        if (traceIdHolder.isFirstLevel()) {
            traceIdHolder = null;
        } else {
            traceIdHolder = traceIdHolder.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();
    }
}

이전에 구현한 로그 추적기와 동일한 동작을 하지만 syncTraceId()와 releaseTraceId()를 통해 traceIdHolder 값을 계속해서 추적하고 상태를 조절한다는 차이점이 있다.

📄 테스트

public class FieldLogTraceTest {
    FieldLogTrace trace = new FieldLogTrace();

    @Test
    void begin_end_level2() {
        TraceStatus status1 = trace.begin("status1");
        TraceStatus status2 = trace.begin("status2");
        trace.end(status2);
        trace.end(status1);
    }

    @Test
    void begin_exception_level2() {
        TraceStatus status1 = trace.begin("status1");
        TraceStatus status2 = trace.begin("status2");
        trace.exception(status2, new IllegalStateException());
        trace.exception(status1, new IllegalStateException());
    }
}

테스트 코드를 작성해서 실행해보자.

모두 정상적으로 실행되었다.

테스트 코드를 통해 알수 있는 것은 이제 각 controller, service, repository 마다 trace의 level을 체크할 필요 없이 모두 begin이라는 메서드 하나로 통일해서 사용하면 내부적으로 알아서 판단해서 level을 체크해주고 로그를 찍어낸다. 그렇기 때문에 traceId 값도 따로 명시할 필요 없이 내부적으로 돌아간다는 것을 확인할 수 있었다.

📄 프로젝트에 새로운 로그 추적기 적용

@Configuration
public class LogTraceConfig {
    @Bean
    public LogTrace logTrace() {
        return new FieldLogTrace();
    }
}

우선 Spring Container에 LogTrace를 FieldLogTrace로 반환받을 수 있도록 Bean을 등록해준다.

그리고 v2를 복사해서 v3로 모두 변경한 뒤 이전에 사용한 HelloLogTraceV2 대신 bean으로 주입받을 LogTrace로 변경한다.

@RestController
@RequiredArgsConstructor
public class OrderControllerV3 {
    private final OrderServiceV3 orderService;
    private final LogTrace trace;

    @GetMapping("/v3/request")
    public String request(String itemId) {
        TraceStatus status = null;
        try {
            status = trace.begin("OrderController.request()");
            orderService.orderItem(itemId);
            trace.end(status);
            return "ok";
        } catch (Exception e) {
            trace.exception(status, e);
            throw e; // 예외를 위 코드에서 먹어버리고 return 되는 값이 없어서 꼭 다시 예외를 돌려주어야한다.
        }
    }
}

@Service
@RequiredArgsConstructor
public class OrderServiceV3 {
    private final OrderRepositoryV3 orderRepository;
    private final LogTrace trace;

    public void orderItem(String itemId) {
        TraceStatus status = null;
        try {
            status = trace.begin("OrderService.orderItem()");
            orderRepository.save(itemId);
            trace.end(status);
        } catch (Exception e) {
            trace.exception(status, e);
            throw e; // 예외를 위 코드에서 먹어버리고 return 되는 값이 없어서 꼭 다시 예외를 돌려주어야한다.
        }
    }
}

@Repository
@RequiredArgsConstructor
public class OrderRepositoryV3 {
    private final LogTrace trace;

    public void save(String itemId) {

        TraceStatus status = null;
        try {
            status = trace.begin("OrderRepository.save()");

            if (itemId.equals("ex")) {
                throw new IllegalStateException("예외 발생!");
            }
            sleep(1000);

            trace.end(status);
        } catch (Exception e) {
            trace.exception(status, e);
            throw e; // 예외를 위 코드에서 먹어버리고 return 되는 값이 없어서 꼭 다시 예외를 돌려주어야한다.
        }

    }

    private void sleep(int millis) {
        try {
            Thread.sleep(millis);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

각 수정된 소스들은 다음과 같다.

http://localhost:8080/v3/request?itemId=hee 요청하면

다음과 같이 동일하게 로그를 찍어낼 수 있고 코드를 보면 이제 traceId값을 찾기 위해 TraceId 값을 넘기던 파라미터가 모두 삭제된 것을 확인할 수 있다.

여기까지 진행했을 때 해당 코드의 문제점을 알아야한다. 개발 부분에서 진행했을 때 전혀 문제가 일어나지 않고 있지만 만약 해당 소스를 실제 배포했을 때 어떤 문제가 일어날지 생각해보자! (동시성 문제가 발생한다!)

📄 동시성 문제 발생!

http://localhost:8080/v3/request?itemId=hee 해당 url로 1초 안에 2번 이상 요청해보자

그럼 우리가 예상하지 않은 이상한 로그가 찍혀 나온다. 왜 이럴까?

그 이유는 간단하다. 우리는 traceIdHolder라는 객체를 싱글톤으로 application 상 단 1개만 존재하고 모든 Thread는 해당 필드 값을 공유해서 사용하도록 설계하였다. 그렇기 때문에 위의 로그를 예로 들었을 때 6번 쓰레드와 7번 쓰레드가 동시에 traceIdHolder 필드 값을 사용하게 되었고 우리가 작성한 코드대로 traceIdHolder값이 존재하기 때문에 level이 더 증가하고 실행되어진것이다.

📄 동시성 문제 테스트 코드로 발생시켜보기

dependencies {
	
    ...
    
    testCompileOnly 'org.projectlombok:lombok'
	testAnnotationProcessor 'org.projectlombok:lombok'
}

@Slf4j
public class FieldService {
    private String nameStore;

    public String logic(String name) {
        log.info("저장 name = {} -> nameStore = {}", name, nameStore);
        nameStore = name;
        sleep(1000);
        log.info("조회 nameStore = {}", nameStore);
        return nameStore;
    }

    private void sleep(int millis) {
        try {
            Thread.sleep(millis);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }

}

@Slf4j
public class FielServiceTest {
    private FieldService fieldService = new FieldService();

    @Test
    void field() {
        log.info("main start");

        Runnable userA = () -> {
            fieldService.logic("userA");
        };
        Runnable userB = () -> {
            fieldService.logic("userB");
        };

        Thread threadA = new Thread(userA);
        threadA.setName("thread-A");
        Thread threadB = new Thread(userB);
        threadB.setName("thread-B");

        threadA.start();
        sleep(2000); // 2초를 쉬기 때문에 동시성 문제가 발생하지 않음
        threadB.start();

        sleep(3000); // main 쓰레드 종료 대기
        log.info("main exist");
    }

    private void sleep(int millis) {
        try {
            Thread.sleep(millis);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

다음과 같이 테스트 코드를 작성했을 때 결과를 보면

우리가 예상한 순서대로 실행된다.

하지만 만약 중간의 sleep을 제외시키게 된다면?

@Slf4j
public class FielServiceTest {
    private FieldService fieldService = new FieldService();

    @Test
    void field() {
        log.info("main start");

        Runnable userA = () -> {
            fieldService.logic("userA");
        };
        Runnable userB = () -> {
            fieldService.logic("userB");
        };

        Thread threadA = new Thread(userA);
        threadA.setName("thread-A");
        Thread threadB = new Thread(userB);
        threadB.setName("thread-B");

        threadA.start();
        //sleep(2000); // 2초를 쉬기 때문에 동시성 문제가 발생하지 않음
        threadB.start();

        sleep(3000); // main 쓰레드 종료 대기
        log.info("main exist");
    }

    private void sleep(int millis) {
        try {
            Thread.sleep(millis);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

sleep을 주석처리 했다. 결과를 확인해보자

두개의 쓰레드가 동시에 실행되며 nameStore의 값에 넣는 값을 하나도 출력하지 못했으며 조회 해오는 데이터도 마지막에 들어간 userB값을 동일하게 가져오는 에러가 발생하게 된다.

이 처럼 여러 쓰레드가 동시에 같은 인스턴스의 필드 값을 변경하면서 발생하는 문제를 동시성 문제라고 한다. 트래픽이 적은 상황에서는 잘 나타나지 않는 현상이지만 트래픽이 많아질 수록 자주 발생하기 시작하는 문제다. 특히 스프링의 싱글톤 객체의 필드를 변경하면서 사용할 때는 이런 문제를 조심해야 한다.

이런 문제를 해결하는 방법 중 하나로 사용하는 것이 Thread Local 이다.

📗 Thread Local

📄 Thread Local이란?

쓰레드 로컬은 해당 쓰레드만 접근할 수 있는 특별한 저장소를 말한다. 위의 문제와 같이 같은 인스턴스에 접근해도 문제가 없다.

📄 Thread Local로 다시 테스트 작성해보기

@Slf4j
public class ThreadLocalService {
    private ThreadLocal<String> nameStore = new ThreadLocal<>();

    public String logic(String name) {
        log.info("저장 name = {} -> nameStore = {}", name, nameStore.get());
        nameStore.set(name);
        sleep(1000);
        log.info("조회 nameStore = {}", nameStore.get());
        return nameStore.get();
    }

    private void sleep(int millis) {
        try {
            Thread.sleep(millis);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

@Slf4j
public class ThreadLocalServiceTest {
    private ThreadLocalService fieldService = new ThreadLocalService();

    @Test
    void field() {
        log.info("main start");

        Runnable userA = () -> {
            fieldService.logic("userA");
        };
        Runnable userB = () -> {
            fieldService.logic("userB");
        };

        Thread threadA = new Thread(userA);
        threadA.setName("thread-A");
        Thread threadB = new Thread(userB);
        threadB.setName("thread-B");

        threadA.start();
        // sleep(2000); // 2초를 쉬기 때문에 동시성 문제가 발생하지 않음
        threadB.start();

        sleep(3000); // main 쓰레드 종료 대기
        log.info("main exist");
    }

    private void sleep(int millis) {
        try {
            Thread.sleep(millis);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}

이제 실행해보자!

코드를 보면 thread가 각각 거의 동시에 실행이 되었다. 하지만 이전과 달리 결과는 각 nameStore에 알맞은 값이 들어가있는 것을 확인할 수 있다. 또한 로그의 위쪽을 보면 nameStore에는 모두 null이 들어가 있는데 그 이유는 각각의 객체를 저장하는 공간을 따로 가져가고 있기 때문에 nameStore는 모두 null로 제공되는 것이다.

📗 프로젝트에 적용해보기

📄 Thread Local이 적용된 로그 추적기 만들기

@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-";

    private ThreadLocal<TraceId> traceIdHolder = new ThreadLocal<>(); // traceId 동기화, (동시성 이슈가 발생할 수 있음)

    @Override
    public TraceStatus begin(String message) {
        syncTraceId(); // traceId를 생성 or netx id 값을 가져옴
        TraceId traceId = traceIdHolder.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 = traceIdHolder.get();
        if (traceId == null) {
            traceIdHolder.set(new TraceId());
        } else {
            traceIdHolder.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 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()),
                    status.getMessage(), resultTimeMs);
        } else {
            log.info("[{}] {}{} time={}ms ex={}", traceId.getId(), addSpace(EX_PREFIX, traceId.getLevel()),
                    status.getMessage(), resultTimeMs, e.toString());
        }

        // 완료된 이후의 traceId 상태를 조절
        releaseTraceId();
    }

    private void releaseTraceId() {
        TraceId traceId = traceIdHolder.get();
        if (traceId.isFirstLevel()) {
            traceIdHolder.remove();
        } else {
            traceIdHolder.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();
    }
}

이전에 만들었던 로그 추적기를 다음과 같이 ThreadLocal을 사용하도록 수정했다.

여기서 중요한 점은 ThreadLocal을 사용한 뒤 꼭 remove() 메서드를 사용해서 저장공간을 지워줘야한다는 것이다. 그 이유는 메모리가 쌓여서 나중에 메모리릭이 날수도 있기 때문에 메모리를 잘 관리해줘야한다.

📄 테스트 코드 작성

public class ThreadLocalLogTraceTest {
    ThreadLocalLogTrace trace = new ThreadLocalLogTrace();

    @Test
    void begin_end_level2() {
        TraceStatus status1 = trace.begin("status1");
        TraceStatus status2 = trace.begin("status2");
        trace.end(status2);
        trace.end(status1);
    }

    @Test
    void begin_exception_level2() {
        TraceStatus status1 = trace.begin("status1");
        TraceStatus status2 = trace.begin("status2");
        trace.exception(status2, new IllegalStateException());
        trace.exception(status1, new IllegalStateException());
    }
}

다음 코드를 실행하면

결과가 잘 나오는 것을 확인할 수 있다. 아직 Thread Local을 적용한 결과를 볼수 있는 코드는 아니고 실제 프로젝트에 적용시켜서 이전의 오류가 나는지 확인해보자.

📄 프로젝트에 적용해보기

@Configuration
public class LogTraceConfig {
    @Bean
    public LogTrace logTrace() {
        return new ThreadLocalLogTrace();
    }
}

이전에 작성했더 config 파일에 반환 값을 ThreadLocalLogTrace로 변경만 해주면 Spring에서 인터페이스로 작성했던 것으로 인해 주입되는 bean값이 달라지면서 모두 우리가 생각한대ㅗㄹ 돌아가게 될것이다.

연속으로 호출했을 때 이전과 다르게 level이 잘 맞게 나오며 로그를 각 쓰레드 별로 확인해보면 우리가 최초에 예상했던 방향으로 흘러가는 것을 확인할 수 있다.

📙 Thread Local 주의 사항

톰캣과 같은 WAS를 사용할 경우 Thread Pool 기능을 사용하여 Thread를 관리하게 되는데

이렇게 최초 요청이 이뤄진 후

다음 사용자의 요청이 일어났을 때 해당 Thread가 Thread Pool에 의해 삭제되지 않고 관리되어 지다가 다음 사용자 요청에서 보관되어져 있던 데어터가 삭제되어지지 않았기 때문에 다음 사용자에게 노출되거나 데이터의 혼란이 올 수 있다.

그래서 아까 위에서 언급했던 대로 꼭 꼭 꼭 remove()를 해줘야한다!