[EFK 구축] 스프링 로깅 데모 애플리케이션 만들기

EFK 구축에 앞서 먼저 로깅을 생성하는 HTTP API 애플리케이션을 만들어 보자. 실제로 진행 중인 프로젝트에서 클라이언트가 HTTP API를 호출했을 때 INTERNAL SERVER ERROR가 발생한 적이 있다. 원인을 파악하기 위해서 해당 API 요청과 관련된 로그만 조회해서 보고 싶었지만 쿠버네티스에서 기본적으로 제공하는 로깅 기능으로는 관련된 로그만 찾는 것이 매우 불편했다. 따라서 요청마다 고유한 ID를 부여하고 모든 로그 포맷을 변경하여 모든 로그에 요청 ID를 출력하도록 변경하면 해당 요청과 관련된 로그를 검색하기 쉬울 것이라고 생각했다. 따라서 이번 데모 애플리케이션을 통해 로그 포맷에 요청 ID를 추가하는 로그 포맷을 작성해 본다.

요청 당 유니크한 식별자를 할당하는 일은 Servlet Filter를 통해 직접 구현할 수 있다. 하지만 Spring Cloud Sleuth를 이용하면 의존성만 추가해도 같은 기능을 사용할 수 있다. 따라서 이번 데모 프로젝트는 요청에 ID를 부여하는 작업을 직접 하지 않고 Spring Cloud Sleuth를 사용한다.

Spring Cloud Sleuth 의존성 설정

plugins {
    id 'java'
    id 'org.springframework.boot' version '2.7.13'
    id 'io.spring.dependency-management' version '1.0.15.RELEASE'
}

group = 'com.example'
version = '0.0.1-SNAPSHOT'

java {
    sourceCompatibility = '17'
}

configurations {
    compileOnly {
        extendsFrom annotationProcessor
    }
}

repositories {
    mavenCentral()
}

ext {
    set('springCloudVersion', "2021.0.7")
}

dependencies {
    implementation 'org.springframework.boot:spring-boot-starter-web'
    implementation 'org.springframework.cloud:spring-cloud-starter-sleuth'
    compileOnly 'org.projectlombok:lombok'
    annotationProcessor 'org.projectlombok:lombok'
    testImplementation 'org.springframework.boot:spring-boot-starter-test'
}

dependencyManagement {
    imports {
        mavenBom "org.springframework.cloud:spring-cloud-dependencies:${springCloudVersion}"
    }
}

tasks.named('test') {
    useJUnitPlatform()
}

• 'org.springframework.cloud:spring-cloud-starter-sleuth' 의존성을 추가한다.

spring:
  application:
    name: logging-demo-application

• application.yaml 파일에 애플리케이션의 이름을 지정한다.

import com.example.loggingsample.service.DemoService;
import lombok.RequiredArgsConstructor;
import lombok.extern.slf4j.Slf4j;
import org.springframework.web.bind.annotation.RequestMapping;
import org.springframework.web.bind.annotation.RestController;

@Slf4j
@RestController
@RequiredArgsConstructor
public class DemoController {
    private final DemoService demoService;

    @RequestMapping("/")
    public String home() {
        log.info("DemoController");
        demoService.method();
        return "Hello World";
    }

}

• 데모 컨트롤러를 작성한다.

import lombok.extern.slf4j.Slf4j;
import org.springframework.stereotype.Service;

@Slf4j
@Service
public class DemoService {

    public void method() {
        log.info("DemoService");
    }

}

• 데모 서비스를 작성한다.

2023-07-06 09:08:45.248  INFO [logging-demo-application,079d1543de12b2a4,079d1543de12b2a4] 67590 --- [nio-8080-exec-2] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2023-07-06 09:08:45.248  INFO [logging-demo-application,079d1543de12b2a4,079d1543de12b2a4] 67590 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2023-07-06 09:08:45.249  INFO [logging-demo-application,079d1543de12b2a4,079d1543de12b2a4] 67590 --- [nio-8080-exec-2] o.s.web.servlet.DispatcherServlet        : Completed initialization in 1 ms
2023-07-06 09:08:45.264  INFO [logging-demo-application,079d1543de12b2a4,079d1543de12b2a4] 67590 --- [nio-8080-exec-2] c.e.l.controller.DemoController          : DemoController
2023-07-06 09:08:45.264  INFO [logging-demo-application,079d1543de12b2a4,079d1543de12b2a4] 67590 --- [nio-8080-exec-2] c.e.loggingsample.service.DemoService    : DemoService

• http://localhost:8080/ 로 요청을 보내면 위와 같은 로그를 확인할 수 있다.
• 첫 번째 중괄호로 감싼 부분을 집중해서 보자.
  - [애플리케이션 이름, trace id, span id] 형식으로 출력된다.
  • trace id와 span id가 궁금하다면 참조
• 여기서 trace id는 요청당 고유하게 부여되는 요청의 식별자라고 생각하면 된다.

Logback 포맷 설정

Logback의 기본 포맷을 사용해도 되지만 나의 상황에 적합하게 포맷을 변경할 수 있다. logback-spring.xml 파일에 Logback을 설정한다. logback-spring.xml은 src/main/resources/logback-spring.xml에 위치한다.

logback-spring.xml 파일

<configuration>
    <include resource="org/springframework/boot/logging/logback/defaults.xml"/>
    <springProperty scope="context" name="springAppName" source="spring.application.name"/>

    <conversionRule conversionWord="color" converterClass="org.springframework.boot.logging.logback.ColorConverter" />

    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>${springAppName} %date{yyyy-MM-dd HH:mm:ss.SSS} %-5level [%thread] [%X{traceId:-none}] %logger{36} - %message%n</pattern>
        </encoder>
    </appender>

    <root level="INFO">
        <appender-ref ref="STDOUT"/>
    </root>

</configuration>

logging-demo-application 2023-07-06 09:08:09.863 INFO  [http-nio-8080-exec-2] [96e5e5fc41b2ba87] o.a.c.c.C.[Tomcat].[localhost].[/] - Initializing Spring DispatcherServlet 'dispatcherServlet'
logging-demo-application 2023-07-06 09:08:09.864 INFO  [http-nio-8080-exec-2] [96e5e5fc41b2ba87] o.s.web.servlet.DispatcherServlet - Initializing Servlet 'dispatcherServlet'
logging-demo-application 2023-07-06 09:08:09.864 INFO  [http-nio-8080-exec-2] [96e5e5fc41b2ba87] o.s.web.servlet.DispatcherServlet - Completed initialization in 0 ms
logging-demo-application 2023-07-06 09:08:09.878 INFO  [http-nio-8080-exec-2] [96e5e5fc41b2ba87] c.e.l.controller.DemoController - DemoController
logging-demo-application 2023-07-06 09:08:09.878 INFO  [http-nio-8080-exec-2] [96e5e5fc41b2ba87] c.e.l.service.DemoService - DemoService

다시 http://localhost:8080/로 요청을 보내면 로그 포맷이 위와 같이 변경되었다.

@Component
@RequiredArgsConstructor
public class TraceIdFilter implements Filter {
    private final Tracer tracer;

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain) throws IOException, ServletException {
        if (response instanceof HttpServletResponse) {
            HttpServletResponse httpServletResponse = (HttpServletResponse) response;
            httpServletResponse.setHeader("trace-id", tracer.currentSpan().context().traceIdString());
        }

        chain.doFilter(request, response);
    }
}

추가적으로 검색 용이성을 위해 요청 응답으로 해당 요청의 ID를 내려주는 필터를 추가했다.

http://localhost:8080/로 다시 요청을 보내보면 응답 헤더에 trace-id가 있는 것을 알 수 있다.

logging-demo-application 2023-07-06 09:10:38.085 INFO  [http-nio-8080-exec-2] [82113a80911e6d08] o.a.c.c.C.[Tomcat].[localhost].[/] - Initializing Spring DispatcherServlet 'dispatcherServlet'
logging-demo-application 2023-07-06 09:10:38.086 INFO  [http-nio-8080-exec-2] [82113a80911e6d08] o.s.web.servlet.DispatcherServlet - Initializing Servlet 'dispatcherServlet'
logging-demo-application 2023-07-06 09:10:38.087 INFO  [http-nio-8080-exec-2] [82113a80911e6d08] o.s.web.servlet.DispatcherServlet - Completed initialization in 1 ms
logging-demo-application 2023-07-06 09:10:38.102 INFO  [http-nio-8080-exec-2] [82113a80911e6d08] c.e.l.controller.DemoController - DemoController
logging-demo-application 2023-07-06 09:10:38.102 INFO  [http-nio-8080-exec-2] [82113a80911e6d08] c.e.l.service.DemoService - DemoService

로그를 확인해 보면 응답 헤더로 받은 trace id가 로그에 찍힌 것을 볼 수 있다.

마무리

요청 당 부여되는 유니크한 trace id를 Spring Cloud Sleuth를 통해 구현했고 로그 포맷을 변경해 로그에 trace id를 찍도록 변경했다. 추가적으로 응답 헤더에 trace id를 내려줘 검색을 용이하게 했다. 이제 이어서 진짜 EFK를 구축해 보자.