ELK 환경에서 좀 더 정교한 이슈 트래킹 Part3 - Multi Thread Context 적극 활용하기

ELK 환경에서 좀 더 정교한 이슈 트래킹 Part3 - Multi Thread Context 적극 활용하기

요약: 이 글은 ELK 환경에서 이슈 트래킹을 정교하게 개선하는 전략을 다룹니다. Part3에서는 특히 Multi Thread Context를 활용하여 배치성 API와 비동기 로직에서 발생할 수 있는 문제를 해결하는 방법을 설명합니다. 기존의 단일 Thread Context 기반 이슈 트래킹의 한계를 극복하기 위해 새로운 ContextId를 도입하고, 이 과정에서 로그 가시성을 높이고자 했습니다. 이 전략은 다양한 서비스 환경에서 발생하는 복잡한 문제를 보다 체계적으로 관리하고 추적할 수 있게 합니다​.

💡 리뷰어 한줄평

bread.young 비동기 관련 로깅은 항상 고민하는 포인트 중 하나라고 생각하는데요, 비동기를 독립적인 새로운 Context로 생각하여 신규 고윳값을 부여해 관리하는 아이디어가 인상 깊었습니다.💡

rain.drop 시리즈의 마지막 포스팅이네요! 개발을 하다 보면 상황에 따라 WebFlux 환경에서 개발하기도, 혹은 배치성 API를 개발하기도 하는데요. 이러한 상황 속에서 겪게 되는 로깅의 불편함은 Part 2와 달리 새로운 해결책이 필요합니다! 포도는 어떻게 개선했을까요? 같이 들여다보아요~!!

시작하며

안녕하세요. 해외결제서비스유닛에서 서버 개발 업무를 맡고 있는 포도입니다.

지난 포스팅인 Part1 - 이슈 트래킹 기반 마련하기, Part2 - Thread Context 적극 활용하기에서는 좀 더 정교한 이슈 트래킹을 위해서 발전하는 과정을 설명하였습니다. 이번 포스팅은 “좀 더 정교한 이슈 트래킹”의 마지막 편으로 Multi Thread Context를 통해 한층 더 발전한 이슈 트래킹 전략을 설명하려고 합니다.

앞서 Part2에서는 좀 더 기민하게 대응할 수 있는 이슈 트래킹 전략을 구성했습니다. 하지만 실제로 서비스를 운영해 보면 몇 가지 Edge 케이스에서 한계점을 겪게 됩니다. 바로 다음과 같은 상황입니다.

  • 배치성 API의 이슈 트래킹
  • 비동기 로직의 이슈 트래킹

이번 포스팅인 Part3의 본문에서는 하나의 Thread Context가 아닌 Multi Thread Context를 사용하여 위의 한계점을 극복하는 내용을 설명하려고 합니다. Part3는 Part1, Part2의 내용을 기반으로 작성되었습니다.

따라서 본문 내용에 앞서 Part1, Part2 내용을 읽어보시기를 권장합니다.

Part3는 hello-elk-thread 레포지터리에 part3 브랜치를 참조부탁드립니다.

Part1, Part2 복기하기

본문에 앞서 Part1, Part2의 내용을 정리하면 다음과 같습니다.

Part1에서는 ELK 환경에서의 Request 요청 로깅과, Sentry를 사용하여 이슈 트래킹의 기반을 마련하였습니다. 따라서 이슈를 파악할 수 있는 정보들의 가시성을 확보하고, 개발자에게 알림을 제공하여 이슈 발생 시 기민하게 대응할 수 있는 기반을 마련하였습니다.

Part2에서는 Part1 기반의 문제점을 Thread Context를 사용하여 좀 더 발전한 과정을 설명하였습니다. 수많은 요청 로그에서 예외가 발생한 로그를 찾는 어려움을, Thread Context에 requestId라는 요청 키값을 공유함으로써 원클릭으로 로그에 접근하는 지름길을 만들어 해결했습니다.

또한 요청 로그에 남기지 못한 정보들을 MDC(Thread-Local 로그 메타데이터 저장소)를 사용하여, 비즈니스에서 가시성을 확보하고 싶은 데이터의 정보들을 자유롭게 담을 수 있는 구조를 완성하였습니다. 그 결과 debug라는 필드를 통해 다음과 같이 원인 분석에 필요한 정보들의 가시성을 자유롭게 확보할 수 있었습니다.

이제 Part3에서는 Part2의 전략을 사용하면서 발견한 Edge 케이스들을 Multi Thread Context를 사용하여 극복한 방법을 공유드리겠습니다.

배치성 API의 이슈 트래킹

서비스를 설계하다 보면 배치성 API가 필요할 때가 있습니다.

배치성 API는 API 요청 시 배치성 비즈니스가 실행되는 것을 의미합니다. 해외결제서비스도 JobScheduler를 활용하여 주기적으로 배치성 API를 호출하여 운영에 필요한 배치성 로직들을 수행하고 있습니다.

예약 결제

이번 내용은 하나의 예시로 설명하려고 합니다. 예를 들어, 예약 결제라는 기능을 한 번 생각해 보겠습니다. 예약 결제란 사용자가 특정 시점에 결제를 예약하고, 예약 시점이 되었을 때 결제가 이루어지는 기능을 의미합니다.

이를 처리하기 위하여 아래의 흐름을 지닌 배치성 API를 활용해 보겠습니다. 배치성 API는 10분 단위로 호출되어, 10분 전부터 요청 시점까지 예약 결제 건들의 결제를 진행합니다.

  1. DB에서 (10분 전 ~ 현재시간) 예약 결제 데이터를 조회
  2. 조회된 예약결제 List를 for문을 순회하며 payService.pay() 호출

이제 API는 호출되고, 해당 시간에 예약 결제 데이터가 1000건이 조회되었다고 가정합니다. 그러면 다음과 같이 for문 1000번을 돌며 예약 결제를 진행합니다.

@Component
class ReservePayJob(
    private val reservePayRepository: ReservePayRepository,
    private val payService: PayService,
) {

    fun run(now: LocalDateTime = LocalDateTime.now()) {
        reservePayRepository.findByBetweenAt(now.minusMinutes(10L), now)
            .forEach {
                // 1000번!!!!
                payService.pay(it.txId)
            }
    }

}

아쉽게도 여기서 Part2에서의 이슈 트래킹 전략 문제가 발생하였습니다.

한 번의 payService.pay() 함수 호출로 실행되는 코드의 흐름에서 MDC의 debug에 쌓이는 문자열이 대략 100줄이 쌓인다고 가정한다면, 1,000개의 예약 결제 건을 순회하며 payService.pay()를 호출하는 것은 100 * 1,000 줄의 debug가 쌓이게 됩니다.

100 * 1,000 줄의 debug는 이슈 트래킹을 위한 정보로 활용하기 어렵습니다. 이슈가 발생한 지점은 1,000개의 순회 중 하나의 지점일 테지만, 이슈 분석을 위해 필요한 데이터를 식별하기에는 하나의 로그에 문자열이 너무 많기 때문입니다.

로그를 분리하자, onNewContext

이 문제를 극복하기 위해 도달해야 하는 목표는 간단합니다. 바로 로그를 분리하는 것입니다.

배치성 API는 Request 요청 시 WAS에서 할당받은 하나의 Thread에서 동작합니다. 따라서 for문을 돌아도 동일한 Thread 내에 MDC에 debug의 문자열이 계속 누적되는 것이 문제입니다.

따라서 문제를 해결하기 위한 해결책으로 for문 순회할 때마다 새로운 Thread Context를 만들어야 합니다. 새로운 Thread Context는 MDC, Sentry 모두 비워있는 상태이며, 이 상태에서 새로운 debug가 쌓이게 됩니다.

그리고 각 순회가 끝났을 때, 새로운 Thread 안에서 한 번의 로그를 더 출력합니다.

이를 위해서 MDCHelper.onNewContext{} 함수를 구현하였습니다. 다음은 onNewContext{}의 대략적인 코드입니다.

object MDCHelper{
    fun <T> onNewContext(title: String = "", function: () -> T): T {

        return Executors.newSingleThreadExecutor().submit<T> {
            // 여기서부터 새로운 Thread!!
            ...
            function.invoke() // 함수 호출
            ...
            ElkLogger.info(...) // 로그 출력
            ...
        }.get()
    }
}

onNewContext{} 함수는 새로운 Thread를 생성합니다, 생성된 Thread에는 onNewContext{} 함수의 인자로 받은 function()을 호출하고, 로그를 출력하는 Task를 submit 합니다. 그리고 submit의 반환값인 Future의 get() 함수를 호출하여, Task가 완료될 때까지 기다립니다. 이는 Thread를 동기로 사용하는 것을 의미합니다. 새로운 Thread의 목적은 병렬로 실행하는 것이 아니라, 새로운 Thread Context를 만들고 새로운 debug를 다시 쌓아 올리는 것이 목표이기 때문입니다.

이제 다음 코드는 for문을 차례차례 동기로 순회하면서, 의도한 대로 새로운 Threaed Context에서 각 결제 건에서 로그를 출력할 것입니다. 각 순회에서 로그를 분리합니다.

fun run(now: LocalDateTime = LocalDateTime.now()) {
    reservePayRepository.findByBetweenAt(now.minusMinutes(10L), now)
        .forEach {
            MDCHelper.onNewContext("결제 진행, txId: ${it.txId}") {
                payService.pay(it.txId)
            }
        }
}

RequestId 전파로 로그 연계하기

하지만 여기서 놓친 부분이 있습니다. 이슈 트래킹을 위해서는 기존 Thread와, 기존 Thread에서 만든 자식 Thread의 로그와 연결점을 만들어 주어야 합니다. 그렇지 않으면 Kibana에 접근해서 requestId로 로그를 검색하면 for문을 순회하면서 출력한 로그는 보이지 않을 것입니다.

즉, 기존 Thread에서 자식 Thread로 requestId를 전파해야 합니다. 따라서 다음과 같이 requestId를 추가하는 코드를 작성하였습니다.

object MDCHelper {

    fun init(requestId: String, contextId: String) {
        clear()
        MDC.put(Key.REQUEST_ID, requestId)
    }

    fun <T> onNewContext(title: String = "", function: () -> T): T {
        val parentRequestId = requestId // 부모 Thread의 RequestId

        return Executors.newSingleThreadExecutor().submit<T> {
            // 여기서부터 새로운 Thread
            init(parentRequestId) // 부모의 requestId 주입

            Sentry.setTag(SentryTag.REQUEST_ID, parentRequestId) // 부모의 requestId 주입

            appendDebug(this::class, ">>>>> New Context Start, ContextId: '$childContextId' <<<<<")

            return@submit try {
                function.invoke()
            } catch (e: Exception) {
                Sentry.captureException(e)
                throw e
            } finally {
                ElkLogger.info(
                    message = "NEW_CONTEXT",
                    requestLog = RequestLog(
                        requestId = requestId, // 부모의 requestId 주입
                        url = title,
                        ...
                    )
                )

                Sentry.removeTag(SentryTag.REQUEST_ID)
                MDCHelper.clear()
            }
        }.get()
    }
}

먼저 requestId 전파 과정을 살펴보겠습니다. onNewContext()의 코드 시작점에서는 현재 Thread인 부모 Thread에서 requestId의 값을 가져와 parentRequestId 변수에 저장하였습니다. 그리고 자식 Thread인, 새로운 Thread의 Task 시작점에서 parentRequestId 값을 MDC, Sentry, RequestLog에도 주입하였습니다. 이는 자식 Thread로 requestId를 전파한 것을 의미합니다.

이제 requestId로 검색하면, requestId에서 파생된 자식 Thread의 로그를 함께 볼 수 있게 되었습니다.

ContextId를 활용한 Thread별 로그 가시성 확보하기

여기서 한 가지 문제점이 더 발생하였습니다. Part2의 구현에서는 예외 발생 시 Sentry로 알림을 받고, Sentry 대시보드에서 requestId를 확인하였습니다. 그리고 Kibana에서 requestId를 검색 조건으로 예외가 발생한 요청 로그를 찾았습니다. 그러나 이제는 Kibana에서 requestId를 사용하여 요청 로그를 찾으면 로그가 너무 많이 나옵니다.

위의 예시를 살펴봅시다. 가령 1번의 배치API를 호출한다면 총 1,001개의 로그가 보일 것입니다. 천 개가 넘는 이 로그는 API 요청 로그와 1,000번의 순회를 하면서 로그가 출력된 결과입니다. 이렇게 requestId로 검색해서 찾은 1001개의 로그에서, 예외가 발생한 자식 Thread의 로그를 다시 찾아야 하는 문제가 발생합니다.

이러한 문제점을 해결하기 위해서 contextId를 도입하였습니다. contextId는 onNewContext{}에서 자식 Thread를 생성 시 부모로부터 전파받는 것이 아닌, 새로운 고윳값을 생성합니다. requestId는 요청 Thread에 대한 고윳값이라면, contextId는 Thread Context의 개별 고윳값이 됩니다.

💡 Request 요청 로그의 contextId는?

Request 요청 로그의 contextId는 requestId와 동일한 고윳값을 가집니다. 따라서 생성된 고윳값을 requestId 조건으로 검색한다면 요청에 대한 로그와, 요청에서 파생된 자식 Thread 로그 모두 확인할 수 있습니다. 반대로 생성된 고윳값을 contextId 조건으로 검색한다면 요청에 대한 단 하나의 로그를 볼 수 있습니다.

contextId가 적용된 onNewContext{} 함수는 다음과 같이 구현됩니다.

object MDCHelper {

    fun init(requestId: String, contextId: String) {
        clear()
        MDC.put(Key.REQUEST_ID, requestId)
        MDC.put(Key.CONTEXT_ID, contextId)
    }

    fun <T> onNewContext(title: String = "", function: () -> T): T {
        val parentRequestId = requestId // 부모 Thread의 RequestId
        val parentContextId = contextId // 부모 Thread의 ContextId

        return Executors.newSingleThreadExecutor().submit<T> {
            // 여기서부터 새로운 MDC Context
            // 여기서부터 새로운 Sentry Context
            val childContextId = generateUUID()
            init(parentRequestId, childContextId)

            Sentry.setTag(SentryTag.REQUEST_ID, parentRequestId)
            Sentry.setTag(SentryTag.CONTEXT_ID, childContextId) // ContextId 주입
            Sentry.setExtra(SentryExtra.KIBANA_URL, createKibanaUrl(contextId))

            appendDebug(this::class, ">>>>> New Context Start, ContextId: '$childContextId' <<<<<")

            val requestAt = LocalDateTime.now()

            return@submit try {
                function.invoke()
            } catch (e: Exception) {
                Sentry.captureException(e)
                throw e
            } finally {
                val responseAt = LocalDateTime.now()

                ElkLogger.info(
                    message = "NEW_CONTEXT",
                    requestLog = RequestLog(
                        requestId = requestId,
                        contextId = childContextId,
                        request = RequestLog.Request(
                            url = "New Context From ContextId: '$parentContextId'" + if (title.isNotBlank()) " (${title})" else "",
                            requestAt = requestAt.toISO()
                        ),
                        response = RequestLog.Response(
                            responseAt = responseAt.toISO()
                        ),
                        metadata = MDCHelper.getMetadata()
                    )
                )


                Sentry.removeTag(SentryTag.REQUEST_ID)
                Sentry.removeTag(SentryTag.CONTEXT_ID)
                Sentry.removeExtra(SentryExtra.KIBANA_URL)
                MDCHelper.clear()
            }
        }.get()
    }
}

기존의 onNewContext{} 구현처럼 requestId는 부모 Thread에서 전파되었지만, contextId는 자식 Thread 마다 고유하게 새로 생성되었습니다. contextId도 마찬가지로 MDC, Sentry, RequestLog 데이터 클래스에 동일하게 주입됩니다. 따라서 로그 출력 시에는 다음과 같이 contextId를 확인할 수 있습니다.

그러면 이제 Sentry 대시보드에서 클릭 한 번으로 로그를 보는 과정에도 변화가 있어야 합니다. requestId가 아닌, contextId가 검색 조건이 되어야 합니다. 마찬가지로 Sentry Tag에도 contextId를 주입하였기 때문에, Sentry 대시보드에서는 contextId를 확인할 수 있습니다.

contextId를 검색 조건으로 요청 로그를 찾는다면, 찾고자 하는 단 하나의 Thread Context의 로그를 확인할 수 있습니다.

동일하게 Sentry Extra를 사용하여 KibanaUrl 또한 contextId 검색 조건으로 변경할 수 있습니다.

Sentry.setExtra(SentryExtra.KIBANA_URL, createKibanaUrl(contextId))

fun createKibanaUrl(contextId: String) = "http://kibana.local/app/kibana#/discover?_g=(time:(from:now-7d)&_a=(index:'103c2e10-77da-11ef-a17a-07241150b3ca',query:(language:kqeury,query:'contextId:%22${contextId}%22'))"

그리고 이제 한 번의 클릭으로 찾고자 하는 Thread Context의 로그를 찾을 수 있습니다.

배치성 API 로그 분리하기 정리

배치성 API는 하나의 API 요청에 배치성 비즈니스 흐름을 진행하면서, 너무 많은 debug가 쌓이는 게 문제였습니다. 이를 극복하기 위해서 새로운 자식 Thread Context를 생성하여, 새로운 문맥을 만들고 로그를 출력하는 방법을 구현하였습니다. 로그를 분리하여 이를 극복했습니다.

또한, 새롭게 생성된 Thread Context에는 고유한 contextId 값을 도입하였습니다. 이제 요청에 대해서 파생된 전체 로그를 보고 싶다면 requestId를, 하나의 Thread Context에 대한 로그를 보고 싶다면 contextId를 사용하여, 좀 더 정교한 로그 가시성을 확보할 수 있습니다.

비동기에서의 이슈 트래킹

지금까지 ELK 환경에서 ThreadContext와 Sentry를 활용한 이슈 트래킹 전략을 살펴보았습니다. 이 전략을 이용하여 요청 로그를 효과적으로 관리하고, 동기적인 흐름의 비즈니스에서 이슈를 빠르게 파악할 수 있었습니다. 하지만 비동기 환경에서 기존의 이슈 트래킹 전략을 적용하자니 한계가 있었습니다. 앞서 설명한 이슈 트래킹 전략은 Request 요청 시 할당받은 하나의 Thread를 계속 사용하며, 비동기 흐름을 고려하지 않고 구현했기 때문입니다. 그렇다면 비동기 환경에서는 어떻게 접근했는지 지금부터 살펴보겠습니다.

비동기 Thread에서의 로깅 전략

지금까지의 Thread Context 전략을 비동기에서 해결하고자 하는 방법은 쉽지 않습니다.

예를 들어 다음과 같은 상황을 생각해 볼 수 있습니다. 비동기의 자식 Thread에서 코드의 흐름을 진행하면서, 요청 시 할당받은 부모 Thread의 debug에 정보를 담는다고 가정해 봅니다. 비동기 Thread는 별도의 흐름을 병렬적으로 진행하며, 부모 Thread에 debug 정보를 계속 기록합니다.

하지만 부모 Thread는 자기의 비즈니스 흐름을 먼저 마칩니다. 즉, 클라이언트에게 응답을 하고 WAS에 Thread를 반환하게 됩니다.

이런 상황이 발생한다면 자식 Thread는 코드 흐름을 진행하면서, 부모 Thread에 참조하는 데이터를 찾지 못해 예외가 발생하게 됩니다. 또는 자식 Thread가 부모 Thread의 debug에 추가한 정보가 누락되어 실제 흐름과 다른 로그가 출력됩니다. 이는 오히려 이슈 원인 분석을 위해 정보를 획득하고자 하는 개발자에게 혼선을 주게 됩니다.

따라서 비동기 Thread 로그에 대한 관점을 달리하려고 합니다.

위의 예시를 머릿속으로 상상해 보면, 왜 이런 상황이 발생하는지를 근본적인 의구심을 생각할 수 있습니다. 그리고 비동기 전략에서의 로그를 출력하기 위한 관점을 달리하려고 합니다.

  1. 먼저, 비동기는 개발자가 의도한 새로운 코드의 흐름입니다.
  2. 따라서 새로운 코드의 흐름에서, 기존 흐름의 로그에 정보를 덧붙이는 것이 문제의 원인입니다.
  3. 그러면 새로운 흐름에는, 새로운 로그의 출력이 필요합니다.
  4. 하지만 모든 비동기 흐름에 새로운 로그가 필요한지는 의문입니다.

결론적으로 비동기의 흐름은 개발자가 의도한 새로운 흐름이고, 이를 부모의 흐름과 개별적인 흐름으로 보기로 하였습니다. 그리고 비동기에서도 onNewContext{} 함수를 활용해 보려고 합니다.

AsyncTaskExecutor

Spring에서 함수의 정의 위에 @Async 어노테이션을 명시하면, 해당 함수 호출 시 비동기로 함수가 실행됩니다.

@Async
fun asyncFunction(message: String) {
   ..
}

이때 다음과 같이 TaskExecutor를 Spring Bean으로 등록한다면, Bean으로 등록된 TaskExcutor를 사용하여 @Async 어노테이션이 명시된 함수가 비동기로 실행됩니다.

@Configuration
class AsyncConfig {

    @Bean
    fun asyncTaskExecutor(): TaskExecutor =
        ThreadPoolTaskExecutor().apply {
            corePoolSize = 30
            maxPoolSize = 30
            threadNamePrefix = "DEFAULT-ASYNC-TASK-EXECUTOR"
            setWaitForTasksToCompleteOnShutdown(true)
            setAwaitTerminationSeconds(60)
            initialize()
        }

}

TaskExecutor는 TaskDecorator를 설정할 수 있는 인터페이스를 제공합니다. TaskDecorator는 의미 그대로 실행되는 비동기 Task에 Decorate를 해주어, Task 실행 전후로 부가적인 작업을 추가합니다.

따라서 여기서 부가적인 작업으로 MDC, requestId, contextId 값을 Task 실행 시점에 전파합니다. 다음과 같이 Thread Context 전파를 구현할 수 있습니다.

@Bean
fun asyncTaskExecutor(): TaskExecutor =
    ThreadPoolTaskExecutor().apply {
        ...
        setTaskDecorator(AsyncTaskDecorator())
        ...
    }

 class AsyncTaskDecorator : TaskDecorator {

    override fun decorate(runnable: Runnable): Runnable {
        val contextMap = MDC.getCopyOfContextMap()
        val parentRequestId = MDCHelper.requestId
        val parentContextId = MDCHelper.contextId

        return Runnable {
            MDC.setContextMap(contextMap)
            Sentry.setTag(SentryTag.REQUEST_ID, parentRequestId)
            Sentry.setTag(SentryTag.CONTEXT_ID, parentContextId)

            runnable.run()

            Sentry.removeTag(SentryTag.REQUEST_ID)
            Sentry.removeTag(SentryTag.CONTEXT_ID)
            MDC.clear()
        }
    }
}

Task 실행 전에 부모 Thread Context에 있는 MDC, requestId, contextId 값을 꺼내어, Task를 실행할 때 비동기의 자식 Thread Context에 전파하였습니다. 이를 그림으로 표현하면 다음과 같습니다.

비동기에서의 onNewContext

이제 코드의 흐름을 진행 중, @Async 어노테이션이 있는 비동기 함수를 호출하는 흐름의 진행을 살펴보겠습니다. 하나의 예로, 위의 배치성 API인 예약 결제에 비동기 함수를 곁들이려고 합니다. Job을 실행하기 전/후에 관리자에게 알림을 비동기로 전송합니다.

class ReservePayJob(
    ..
){
    fun run(now: LocalDateTime = LocalDateTime.now()) {

        adminNotifyService.sendAsync("$now, 예약 결제 배치 시작")
        ..
        adminNotifyService.sendAsync("$now, 예약 결제 배치 종료")
    }
}
@Service
class AdminNotifyService(
    private val emailSendAdapter: EmailSendAdapter
) {

    @Async
    fun sendAsync(message: String) {
        emailSendAdapter.send("관리자 알림", message)
    }
}

비동기로 Thread Context 전파를 진행하는 AsyncTaskExecutor를 Bean으로 등록하였기 때문에, 부모 Thread의 모든 내용이 전파됩니다.

하지만 이렇게 전파된 비동기 함수는 어떠한 로그도 출력하지 않습니다. Thread Context는 전파하였지만, 별도의 로그 출력을 하는 코드 구현은 하지 않았기 때문입니다. 여기서 개발자는 판단을 해야 합니다. 너무 많은 로그는 오히려 원인 분석을 위한 가시성에 해가 되기도 합니다. 서비스 영향이 없는 간단한 로직이라면, 오히려 로그를 출력하지 않는 것도 방법입니다.

따라서 관리자에게 알림을 보내는 로직에서 로그 출력이 필요하다고 판단한다면, 이제 onNewContext{} 함수를 사용하면 됩니다.

@Async
fun sendAsync(message: String) {
    MDCHelper.onNewContext("관리자 알림 전송") {
        emailSendAdapter.send("관리자 알림", message)
    }
}

onNewContext{} 함수를 사용한다면, 결국 Thread Context는 다음과 같은 흐름의 전파가 진행됩니다. 부모 Thread -> 비동기 Thread -> New Context Thread로의 전파되는 흐름입니다.

이제 onNewContext{} 블록 안의 모든 흐름이 종료되면, 다음과 같이 비동기에서의 로그가 출력됩니다.

비동기에서의 Sentry Report

비동기에서의 Sentry Report는 기존의 배치성 API의 메커니즘과 동일한 모습일 것입니다. 부모 Thread -> 비동기 Thread -> New Context Thread 로의 Sentry Tag가 모두 전파되었기 때문입니다.

비동기 함수의 onNewContext{} 안에서 예외가 발생한다면, 고유한 contextId 값의 Tag로 포함하여 Sentry Report 될 것입니다. 또한 부모 Thread의 requestId 값도 포함해서 Sentry Report 될 것입니다.

그렇다면 지금까지와 마찬가지로 contextId 값을 검색 조건으로 해서 비동기 함수의 로그만을 찾을 수 있습니다. 그리고 requestId를 검색 조건으로 한다면, 요청 로그에서 파생된 모든 로그들을 확인할 수 있습니다.

비동기에서의 이슈 트래킹 정리

Thread Context를 활용한 이슈 트래킹 전략에서, 비동기 환경에서의 전략은 해결하기 쉽지 않습니다. 이에 비동기의 로직도 새로운 흐름으로 취급하여, 새로운 Thread Context 흐름을 만드는 방법을 사용하였습니다.

이 과정에서 TaskDecorater를 사용하여 비동기 상황에서도 Thread Context의 데이터를 비동기 Thread에 전파하도록 하였습니다. 따라서 Request 요청 시 생성한 요청에 대한 고윳값인 requestId를 검색 조건으로 한다면 요청 로그뿐 아니라, 비동기에서도 출력한 로그를 확인할 수 있습니다. 만약에 비동기 함수 내에서 예외 발생 시, 비동기 내에서의 Thread Context는 고유한 contextId 값을 Sentry Tag에 포함해, 비동기 호출 대한 고유한 로그를 찾을 수 있습니다.

마치며

이번 포스팅인 Part3에서는 Part2의 한계점을 극복하기 위해서 여러 Thread Context를 사용하는 방법을 설명하였습니다. onNewContext{} 함수를 사용하여 새로운 Thread Context를 만들고 로그를 분리하는 것이 핵심이라 생각합니다. 또 다른 Edge 케이스의 한계점이 발생하더라도, 새로운 흐름을 만드는 위의 아이디어를 조금 더 활용한다면 극복할 수 있을 것으로 생각합니다.

Part3를 마지막으로 좀 더 정교한 이슈 트래킹 전략을 주제로 시작한 내용은 모두 설명하였습니다. Part1, Part2, Part3 전략은 해외결제서비스유닛에서 운영하는 서비스를 단계적으로 발전시킨 모습이기도 합니다.

전략을 적용하기 전에는 예외가 발생 시 획득 가능한 정보가 없어, 원인 분석을 하지 못하여 여러 가지 재현을 해보며 불필요한 시간을 소요한 기억이 남습니다. 하지만 이제 해외결제서비스유닛에서 운영하는 서비스는 서비스 API, 배치성 API, 비동기 상황에서도 한계점 없이 예외를 분석하고, 한 번의 클릭으로 개발자가 쌓아 올린 정보들을 확인하여 원인을 분석하고 있습니다.

서비스를 운영하면서 이슈는 필연적으로 발생할 수밖에 없다고 생각합니다. 좀 더 정교한 이슈 트래킹을 위해서 Part1 ~ Part3까지의 소개된 내용을 운영하시는 서비스에 적용해 보시는 것도 추천해 드립니다.

마지막으로 지금까지 포스팅이 좀 더 정교한 이슈 트래킹을 위해 도움이 되었기를 희망합니다.
감사합니다. 🙂

podo.c
podo.c

문제 해결에 희열을 느끼는 서버 개발자입니다. 🙂
태그
추천 콘텐츠