ELK 환경에서 좀 더 정교한 이슈 트래킹 Part1 - 이슈 트래킹 기반 마련하기

요약: 이 글은 ELK 환경에서 ThreadContext와 Sentry를 사용하여 이슈 트래킹 전략을 개선하는 방법을 다룹니다. Part 1에서는 RequestLoggingFilter를 통해 요청 로깅을 설정하고, Logstash와 ElasticSearch를 사용해 로그를 처리하는 방법을 설명합니다. 또한, Sentry를 활용한 예외 처리와 이슈 알림 설정을 통해 문제를 빠르게 인식하고 대응하는 방식을 소개합니다. 이러한 방식을 이용하여 더욱 정교한 이슈 트래킹을 위한 기반을 마련하는 과정을 설명합니다.

💡 리뷰어 한줄평

bread.young ELK 환경에서 로그를 어떻게 쌓고, 보여주는지 쉽게 설명된 글입니다. 이슈 트래킹을 쉽게 하는 방법은 개발자라면 누구나 고민하는 부분인데 어떻게 풀어내었는지 궁금하네요🧐!!

rain.drop ELK 환경에서의 로깅 방식과 Sentry를 이용한 이슈 트래킹 전략을 쉽게 풀어쓴 글입니다. ELK 환경을 구축하려는 분, 혹은 동일한 문제에 고민을 갖고 계신 분들께 추천드립니다~!

시작하며

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

지난 포스팅인 Kotlin으로 Spring AOP 극복하기!에 이어 이번 글에서는, Spring 기반의 서비스를 운영하는 개발자를 대상으로 이슈 트래킹 전략을 다룹니다. 복잡한 비즈니스 로직과 트랜잭션을 처리하는 환경에서 효과적인 이슈 트래킹을 고민하는 개발자에게 유용할 것입니다.

이번에 다루게 될 내용은, 이슈 트래킹 전략을 단계적으로 발전시키는 과정을 3개의 Part로 나누어 설명하려고 합니다. 또한, 앞으로 소개될 내용의 전반적인 코드는 hello-elk-thread에서 확인하실 수 있습니다.

• 먼저 이번 포스팅인 Part1에서는, ELK 환경에서의 Request 요청 로깅과 Sentry를 사용한 이슈 트래킹 전략의 기반을 마련합니다. 그리고 몇 가지 문제점을 설명하려고 합니다.
• Part2에서는, Part1에서 설명한 문제점을 해결하기 위해 ThreadContext를 활용하여 이슈 트래킹 전략을 발전시킨 과정을 설명하려고 합니다.
• 마지막인 Part3에서는, Part2에서 다루지 못하는 배치성 API, 비동기 상황에서의 극복을 위해 Multi Thread Context를 활용하여 발전시킨 과정을 설명하려고 합니다.

만약에 ELK, Sentry를 사용한 이슈 트래킹 전략을 이미 사용하고 있다면, Part2부터 읽기를 시작하는 것을 추천드립니다.

Part1은 hello-elk-thread 레포지터리에 part1 브랜치를 참조하시기를 바랍니다.

ELK 환경에서 로그 기반 마련하기

ELK 스택을 사용한 로그 분석

이슈 발생 시 원인을 분석하기 위해서는 로그 정보를 확인하는 과정은 필수적입니다. 하지만 로그를 분석하기 위한 별도의 환경이 구성되어 있지 않다면, 파일로 쌓아둔 로그 파일들을 하나하나 찾아가며 원인 분석을 해야 할 것입니다.

ELK 스택은 애플리케이션에서 출력한 로그를 ElasticSearch에 저장하고, Kibana 대시보드를 통해서 로그 데이터의 가시성을 확보할 수 있는 환경을 제공합니다. 예를 들어 본 포스팅에서 설명할 내용처럼 Request 요청에 대한 로그 정보를 Kibana 대시보드를 통해 정보를 획득할 수 있습니다.

따라서 이슈 발생 시 쌓아둔 로그 파일에 접근하는 것이 아닌, Kibana 대시보드에 접근하여 로그 데이터를 빠르게 획득하여 보다 기민한 원인 분석을 할 수 있습니다. 만약에 로그 분석을 하기 위한 별도의 환경이 구성되어 있지 않다면, ELK 스택을 활용한 본 포스팅의 내용이 도움이 될 것입니다.

RequestLoggingFilter를 사용한 Request 요청 로깅

Java Servlet의 기술 중 Servlet Filter는 클라이언트의 요청과 서버의 응답 사이에 위치하여 요청 또는 응답 데이터를 가로채고 처리할 수 있는 기능을 제공합니다. 따라서 Servlet Filter는 Spring의 DispatcherServlet 앞단에서 클라이언트 요청에 대한 부가적인 작업을 처리할 수 있게 합니다. 예를 들어 인증, 암호화, 그리고 본 포스팅에서 내용인 로깅과 같은 전략이 예시가 될 수 있습니다.

Servlet Filter를 활용하여 Request 요청의 앞단에서 요청에 대한 로깅을 출력하는 코드를 구현하려고 합니다. 여기서 적용할 Servlet Filter를 RequestLoggingFilter라고 정의하겠습니다.

class RequestLoggingFilter : OncePerRequestFilter() {

    override fun doFilterInternal(
        servletRequest: HttpServletRequest,
        servletResponse: HttpServletResponse,
        filterChain: FilterChain
    ) {
        val request = ContentCachingRequestWrapper(servletRequest)
        val response = ContentCachingResponseWrapper(servletResponse)

        val requestAt = LocalDateTime.now()

        try {
            filterChain.doFilter(request, response)
        } finally {
            val responseAt = LocalDateTime.now()

            ElkLogger.info(
                "Request Log",
                RequestLog(
                    request = createRequestLog(request, requestAt),
                    response = createResponseLog(response, requestAt, responseAt)
                )
            )

            response.copyBodyToResponse()
        }
    }
    // ...
}

RequestLoggingFilter의 코드를 살펴보면 역할은 간단합니다. Request 요청의 비즈니스 흐름을 마무리하고, 요청, 응답에 대한 정보들을 로그로 출력하는 것입니다. 이때 ElkLogger를 사용하여 RequestLog 데이터 클래스 형태로 로그를 출력합니다.

💡 ContentCaching(Request/Response)Wrapper 클래스를 사용한 이유는?

RequestLoggingFilter의 코드를 살펴보면 ContentCaching(Request/Response)Wrapper 클래스의 인스턴스로 변환한 코드를 확인할 수 있습니다. request, response의 Body Stream은 읽게 되면 Stream을 다시 읽을 수 없기 때문입니다. ContentCaching(Request/Response)Wrapper 클래스는 내부적으로 읽은 데이터를 캐싱하여, 다시 읽더라도 동일한 데이터를 반환하도록 하도록 도와줍니다. 따라서 로그 출력을 위해서 Body Stream 데이터를 읽은 이후에도 동일한 데이터를 반환하여 요청 정보의 유실 없이 정상적인 요청, 응답할 수 있습니다.

RequestLog 데이터 클래스의 형태를 살펴보면 Request 요청, 응답에 대한 정보들을 담고 있습니다. 예를 들어, 요청 시간, 요청 URL, 응답시간, 응답 소요 시간과 같은 정보들입니다.

data class RequestLog(
    val request: Request,
    val response: Response,
) {

    data class Request(
        val url: String,
        val queryString: String,
        val method: String,
        val body: String,
        val headers: String,
        val requestAt: String,
    )

    data class Response(
        val status: Int,
        val body: String,
        val bodySize: Int,
        val headers: String,
        val elapseTime: Long,
        val responseAt: String
    )
}

물론 RequestLog는 하나의 예시일 뿐입니다. 실제 운영 환경에서는 필요한 부분이 있다면, 더 많은 정보를 포함할 수 있는 형태의 데이터 클래스를 정의할 수도 있습니다.

코드를 다시 복기하면, RequestLog 데이터 클래스는 ElkLogger를 사용하여 출력되었습니다. ELKLogger는 ELK_LOGGER 로거를 가져와, info() 함수를 호출하는 코드를 실행하게 됩니다.

object ElkLogger {
    private val logger: Logger = LoggerFactory.getLogger("ELK_LOGGER")

    fun info(message: String = "", requestLog: RequestLog) {
        logger.info(message, StructuredArguments.fields(requestLog))
    }
}

그러면 ELK_LOGGER로 호출된 info() 함수가, 어떤 처리를 하는지 설정을 살펴봐야 합니다.

logback-spring.xml 설정하기

ELK 환경에서의 로그 파이프라인은 구성된 인프라의 환경에 따라 다릅니다. 단순하게는 LogStash를 사용하여 로그를 수집 후 ElasticSearch로 저장하기도 하며 복잡하게는 수 단계의 로그 파이프라인을 거쳐 대규모 애플리케이션의 로그들을 ElasticSearch 클러스터에 저장하기도 합니다.

이번 포스팅에서의 ELK 환경은 다음과 같은 구성을 기반으로 합니다.

애플리케이션에서는 LogStash로 로그 데이터를 출력합니다. 로그 파이프라인은 최종적으로 ElasticSearch로 로그를 저장하고, Kibana는 ElasticSearch에 저장된 로그 가시성을 확보하는 간단한 구성입니다.

먼저 애플리케이션에서 LogStash로 로그를 출력하기 위해서 LogstashTcpSocketAppender 클래스를 사용하려고 합니다. LogstashTcpSocketAppender 클래스를 사용하기 위해, 다음 라이브러리에 의존을 필요로 합니다.

dependencies {
   implementation("net.logstash.logback:logstash-logback-encoder:${VERSION}")
}

다음으로는 logback-spring.xml 파일의 작성을 필요로 합니다. Spring Boot에서는 resources 폴더의 위치에 logback-spring.xml 을 파일을 작성하여 Logger를 정의할 수 있습니다. 아래의 logback-spring.xml 코드를 살펴보면 ELK_LOGGER가 어떻게 로그를 처리하는지 확인할 수 있습니다.

<?xml version="1.0" encoding="UTF-8"?>
<configuration>
    //..
    <springProperty scope="context" name="application-name" source="spring.application.name"/>

    <logger name="ELK_LOGGER" additivity="false" level="INFO">>
        <appender-ref ref="LOG_STASH"/>
    </logger>


    <appender name="LOG_STASH" class="net.logstash.logback.appender.LogstashTcpSocketAppender">
        <destination>logstash:5044</destination>
        <encoder class="net.logstash.logback.encoder.LogstashEncoder">
            <customFields>{"index":"${application-name}"}</customFields>
        </encoder>
    </appender>
    //..
</configuration>

ELKLogger는 로그 출력 시, LogstashTcpSocketAppender 클래스의 인스턴스를 사용하여 출력을 진행합니다. Logstash 서버의 주소(logstash:5044)로 로그를 출력하는 것입니다.

이렇게 LogStash로 출력된 로그는 로그 파이프라인 흐름을 지나, 최종적으로는 로그 저장소인 ElasticSearch에 저장될 것입니다. 따라서 다음 코드는 결국 LogStash의 로그 출력을 의미하고, RequestLog는 ElasticSearch로 저장되는 것으로 이해할 수 있습니다.

object ElkLogger {
    private val logger: Logger = LoggerFactory.getLogger("ELK_LOGGER")

    fun info(message: String = "", requestLog: RequestLog) {
        logger.info(message, StructuredArguments.fields(requestLog))
    }
}

Kibana에서 로그 확인하기

그러면 이제 지금까지의 모든 구현의 조합들을 하나의 흐름으로 확인해 보겠습니다. 다음과 같이 HealthController를 구현하고 /api/ping을 요청해 보려고 합니다.

@RestController
class HealthController {

    @GetMapping("/api/ping")
    fun ok(): String {
        return "pong"
    }
}

그러면 HealthController로 요청이 들어오기 전후로 RequestLoggingFilter의 부가적인 코드들이 실행됩니다. 위에서 정의한 Request 요청에 대한 로깅, 즉 RequestLog 데이터 클래스 로그를 LogStash로 출력하는 코드입니다. 출력된 로그는 로그 파이프라인에 인입되어, 파이프라인 흐름을 타고 최종적으로 ElasticSearch에 저장될 것입니다. 따라서 다음과 같이 ElasticSearch에는 helloprice-elk-thread-{날짜} 인덱스가 생성된 것을 확인할 수 있습니다.

💡 helloprice-elk-thread-{날짜} 형태의 인덱스는?

이는 데모 환경에서 LogStash에서 ElasticSearch에 로그 저장 시, 인덱스에 대한 설정을 추가하였습니다. logback-spring.xml 설정을 보면, 로그 출력 시 로그에 index 데이터를 추가하였습니다. LogStash에서는 인입된 로그의, index 데이터와 날짜를 덧붙여 {index}-{날짜} 형태로 ElasticSearch 로그 저장 시 인덱스로 저장합니다. 따라서 최종적으로 데모 실행 시점인 hello-elk-thread-2024.09.08 인덱스로 로그가 저장되었습니다.

Kibana 구동 시, 사전에 설정한 ElasticSearch 주소를 기반으로 로그 데이터를 대시보드에서 바로 확인할 수 있습니다.

먼저 Kibana에서 ElasticSearch 인덱스를 보기 위해 대시보드에 접근해 인덱스 패턴을 정의해야 합니다. 이 패턴을 사용해 인덱스를 하나로 묶어 데이터를 조회할 수 있습니다. 다음과 같이 helloprice-elk-thread-*의 인덱스 패턴을 정의하여, 애플리케이션의 로그에 대한 가시성을 확보합니다.

가시성이 확보된 데이터를 보면 request.body, request.headers 와 같은 필드와 값들을 확인할 수 있습니다. RequestLoggingFilter에서 로그 출력 시 정의한 RequestLog 데이터 클래스와 동일한 형태입니다.

즉, RequestLoggingFilter에서 출력한 RequestLog 데이터 클래스를, 이제 Kibana에서 확인할 수 있는 것을 의미합니다.

이제 이슈 트래킹의 하나의 기반을 완성하였습니다. Request 요청에 대한 정보들을 확인할 수 있는 기반입니다. 애플리케이션이 요청받는 수많은 요청 로그를 확인하며 어떠한 요청이 있고, 응답은 어떻게 되었는지 확인할 수 있습니다. 이슈가 발생하였다면, 어떤 요청으로 이슈가 발생하였는지 확인이 필요합니다. 이제는 Kibana에 접근하여 요청에 대한 로그를 확인하고 이를 분석할 것입니다.

Sentry를 사용한 이슈 리포트

서비스 운영자는 이슈 발생을 모니터링하고, 빠르게 대응할 수 있어야 합니다. 따라서 이슈를 빠르게 인지하고 분석할 수 있는 구성을 필요로 합니다. 이를 위해 Sentry를 적극적으로 활용하고 있습니다.

Sentry란?

Sentry는 에러 분석 플랫폼으로 애플리케이션에서 발생하는 예외를 수집하고, 이를 분석할 수 있는 기능을 제공하는 플랫폼입니다. Sentry에 Report 된 이슈는 예외 메시지와, Stacktrace 등 예외와 관련된 다양한 정보를 확인할 수 있습니다. 확보한 정보를 기반으로 개발자는 이슈를 분석하고, 원인을 파악합니다.

Sentry Report 설정하기

Spring은 Java 진영의 대표적인 애플리케이션 프레임워크입니다. Sentry를 사용하기 위한 라이브러리도 역시 제공합니다.

dependencies {
  implementation("io.sentry:sentry-spring-boot-starter-jakarta:${VERSION}")
}

라이브러리에 의존한다면 설정은 더욱 간단해집니다. Sentry는 프로젝트 생성 시 DSN 주소를 제공합니다. Sentry DSN 주소는 Sentry 플랫폼과 애플리케이션 간의 통신을 위한 고유 식별자입니다. Sentry 프로젝트 설정 페이지 접근하면, 다음과 같이 프로젝트에 발급된 고유의 DSN 주소를 확인할 수 있습니다.

application.yaml에 다음과 같이 sentry.dsn을 설정하는 것으로 Sentry의 설정을 마무리할 수 있습니다.

sentry:
  dsn: DSN 주소

예외 발생 시, Sentry Report 하기

설정을 완료하였다면, Sentry Spring Boot Starter는 처리되지 않은 예외를 감지하고 Sentry Report를 진행합니다. 하나의 예시로 다음과 같은 API를 정의하였습니다.

@RestController
class HealthController {

    @GetMapping("/api/throw")
    fun throwException(): String {
        throw Exception("Throw Test Exception")
    }
}

/api/throw 는 호출 시 예외를 발생시킵니다. 발생한 예외는 DSN 주소로 Sentry Report가 진행될 것입니다.

이제 Sentry 대시보드를 확인하면, 발생한 Throw Test Exception 예외를 확인할 수 있습니다. 대시보드에서는 해당 예외를 자세히 살펴볼 수 있습니다. 예외 메시지, StackTrace, 예외 발생 시간 등 원인 분석을 위한 다양한 메타 정보들이 제공됩니다.

물론 처리되지 않은 예외 외에도 Sentry Report를 진행할 수 있습니다. 다음과 같이 Error 레벨의 로그를 출력하거나, Sentry 싱글톤 클래스로 명시적으로 Report 하는 방법도 제공하고 있습니다.

// build.gradle.kts
dependencies {
    implementation("io.sentry:sentry-logback:7.14.0")
}

// error log 출력
val logger = Loggerfactory.getLogger(HealthController::class.java)
logger.error("Throw Test Exception")

Sentry.captureException(throw Exception("Throw Test Exception"))

알림 기능은 빠른 대응을 위해서는 필수적인 요소일 것입니다. Sentry 또한 빠른 대응을 위한 알림 기능을 제공합니다. Sentry 알림은 특정한 조건을 설정하고, 해당 조건의 포함되는 이슈 발생 시에 다양한 채널로 알림을 받을 수 있습니다. Email, Slack, Webhook과 같은 다양한 채널로 빠르게 대응해야 하는 이슈에 대한 알림을 설정한다면, 서비스 운영자는 좀 더 빠르게 대응할 수 있을 것입니다.

이제 Sentry를 활용한 이슈 트래킹의 또 하나의 기반을 완성하였습니다. 애플리케이션에서 예외를 발생한다면, Sentry DSN 주소로 예외가 Report 될 것입니다. 그리고 서비스 운영자는 예외 발생 알림을 받아 보다 빠르게 인지하고, Sentry 대시보드로 접근하여 정보를 확인하고 분석할 것입니다.

이슈 트래킹 기반의 완성

앞서 예시로 살펴본 /api/throw 호출은 예외가 발생하여 Sentry Report가 되기도 하였지만, 재밌는 부분은 API 호출 과정에서 RequestLoggingFilter의 역할이 곁들여진 것입니다. 다음과 같이 Kibana 대시보드에서 /api/throw 요청에 대한 정보도 확보할 수 있는 것입니다.

따라서 다음과 같은 이슈 트래킹 흐름을 생각해 볼 수 있습니다.

1. 서비스 운영자는 이슈 발생 시 Sentry 알림을 받고 이를 인지합니다.
2. Sentry 대시보드에 접근하여, 해당 이슈의 예외 메시지, Stacktrace, 발생시간 등 관련 정보를 확인하고 원인을 분석합니다.
3. Sentry의 정보만으로 이슈 트래킹이 어려운 상황이 발생하기도 합니다. 코드가 아닌 Request 요청의 정보가 있어야 원인 분석을 할 수 있는 상황입니다.
4. 이제 Kibana 대시보드에 접근하여 Request 요청, 응답 정보를 확보합니다.
5. 예외가 발생한 Request 요청 정보와, Sentry에서 확보한 이슈 정보와 결합하여 이슈를 분석합니다.

이제 ELK 환경, Sentry를 활용한 이슈 트래킹 전략의 기반이 완성되었습니다.

아쉬운 문제점

하지만 아쉽게도, 지금까지의 이슈 트래킹 전략은 몇 가지 문제점을 가지고 있습니다.

로그까지의 여정

Sentry 대시보드에서 제공되는 정보만으로 원인 분석에 어려움을 겪게 될 때는, 해당 Request 요청의 추가적인 정보를 찾기 위해에 Kibana로 접근하여 요청, 응답 정보들을 찾고자 할 것입니다. 하지만 실제로 운영 서비스에서는, Kibana에서 수많은 Request 로그를 확인할 수 있습니다.

예를 들어 TPS 100인 서비스를 운영한다면, 1초에 100개씩 쌓이는 로그에서 예외가 발생한 요청의 로그를 찾아야 할 것입니다. 생각만 해도 불필요하고, 번거로운 작업이 예상됩니다. 따라서 이런 문제점을 해결하기 위해서 여러 가지 스킬들을 사용할 수 있습니다.

하나의 예시로 들면, 코드상에서 문제가 발생하여 예외를 발생시키는 try/catch를 작성할 때 에러 메시지에 키값을 추가하는 것입니다. 예를 들어, 다음과 같이 결제 트랜잭션 ID 같은 키값을 활용하는 것입니다.

@GetMapping("/api/throw-with-try-catch")
fun throwExceptionWithTryCatch(txId: String): String {
    try {
        throw RuntimeException("Test Exception")
    } catch (e: Exception) {
        throw RuntimeException("$txId 결제건에서 예외가 발생하였습니다.")
    }
}

그러면 Sentry 대시보드의 예외 메시지에서 결제 트랜잭션 ID을 확인할 수 있습니다.

이제 Kibana에서 결제트랜잭션ID을 키로 로그로 검색하여, Request 요청 로그를 찾는 것입니다.

아쉽게도 이 방식은 위의 문제점을 모두 해결할 수 없습니다. 예외는 우리가 생각하지 못한 곳에서도 발생하기 때문입니다. 그리고 생각하지 못하게 발생한 예외는 키값이 없는 에러 메시지일 것입니다.

그리고, 로그에 원인 분석에 필요한 정보가 (없)습니다.

예외가 발생한 Request 요청 로그를 찾는데 여러 번거로움이 있지만, 최종적으로는 로그를 찾을 수 있을 것입니다. 그리고 로그를 확인하고 원인을 분석하기 위한 요청, 응답 정보들을 확인할 것입니다. RequestLog 데이터 클래스에 정의된 정보들입니다.

하지만 예외를 분석하기 위해서 찾은 로그에는 이슈 트래킹에 필요한 정보가 없을 수도 있습니다. RequestLog 데이터 클래스에는 원인 분석에 필요한 정보가 없는 것입니다. 경험상 이런 상황은 다분히 발생하였습니다. Request 요청, 응답 정보만 가지고 복잡한 비즈니스의 흐름에서 원인을 찾아내는 것은 꽤 어려운 일이 될 수도 있습니다.

문제점들을 정리하며

ELK 환경에서의 Request 요청 로깅과 Sentry를 사용한 이슈 트래킹 전략의 기반을 마련하였습니다. 하지만 아쉽게도 예외가 발생 시, 추가적인 정보를 찾기 위해 예외가 발생한 요청 로그를 찾는 과정은 어려움을 겪게 합니다. 빠르게 이슈를 대응할 수 없게 하는 방해요소가 되는 것입니다. 또한, 그렇게 찾은 요청 로그에서도 이슈 원인을 분석하기 위한 추가정보를 확보하지 못할 수도 있습니다. 서비스 운영자로서 정말 급박하게 처리해야 하는 이슈가 발생했다면, 해당 문제점들은 더 크게 와닿으실 것입니다.

이제 본 포스팅에서의 이슈 트래킹 전략의 문제점을 극복하기 위한 방법을 고민해 봐야 할 것입니다.

마치며

Part1에서는 Sentry 이슈 알림을 받고, 예외 정보와 Request 요청 로그를 획득하여 이슈 트래킹을 할 수 있는 기반을 마련하였습니다. 본 포스팅에서 소개한 이슈 트래킹 전략은 좀 더 기민한 이슈 대응을 위해서는 서비스 운영에 필수적인 요소라 생각이 됩니다.

해외결제서비스유닛에서 운영하는 모든 애플리케이션들은 이를 기본적으로 구성하여 개발 및 운영이 진행됩니다. Part1의 전략 기반이 마련되어 있지 않는 서비스라면, 본 포스팅 내용을 적용해 보는 것도 추천해 드립니다.

하지만 앞서 말씀드린 내용과 같이, 몇 가지 문제점으로 인하여 이슈 트래킹의 어려움에 부딪칠 수 있습니다. 이어서 포스팅될 Part2에서는 설명한 문제점을 해결하기 위한 발전 과정을 공유하도록 하겠습니다.

마지막으로 이슈 트래킹의 고민을 하고 있는 개발자라면, 본 포스팅이 좀 더 정교한 이슈 트래킹에 도움이 되기를 희망하며 마치겠습니다.

감사합니다🙂