스프링 클라우드 슬루스(Spring Cloud Sleuth)
강준현
- spring-boot
- spring-cloud
이 글의 목차
1. Spring Cloud Sleuth
Spring Cloud Sleuth API Reference
Spring Cloud Sleuth provides Spring Boot auto-configuration for distributed tracing.
마이크로서비스 아키텍처를 지원하는 Spring Cloud 프로젝트 중 하나다. 서비스들 사이에 발생하는 요청과 응답들 사이의 연결 고리를 쉽게 추적할 수 있도록 돕는 라이브러리다. 다음과 같은 역할을 수행한다.
- TRACE, SPAN ID를 Slf4j MDC에 추가하여, TRACE 혹은 SPAN_ID를 로그에 출력하여 연결된 요청 정보를 추출해낼 수 있다.
- 다음과 같은 Spring 애플리케이션의 일반적인 수신 및 송신 지점을 계측한다.
- servlet filter
- rest template
- scheduled actions
- message channels
- feign client
spring-cloud-sleuth-zipkin라이브러리를 사용 가능하다면 zipkin 서비스를 통해 추적 리포트를 만들 수 있다.
2. Sleuth 동작 과정
Sleuth를 사용하면 서비스들 사이에 다음과 같은 일들이 일어난다.
- 사용자 요청은 다음과 같은 흐름으로 진행된다.
- CLIENT > SERVICE1 > SERVICE2 > SERVICE3 > SERVICE2 > SERVICE4 > SERVICE2 > SERVICE1 > CLIENT
- 사용자 요청이 처음 SERVICE1에 도달하면 TRACE_ID와 SPAN_ID가 생성된다.
- TRACE_ID - X
- SPAN_ID - A
- SERVICE1에서 SERVICE2로 요청할 때 새로운 SPAN_ID를 만들어 전달한다.
- TRACE_ID - X
- SPAN_ID - B
- SERVICE2는 TRACE_ID는 유지하면서 새로운 SPAN_ID를 사용한다.
- TRACE_ID - X
- SPAN_ID - C
- SERVICE2에서 SERVICE3로 요청할 때 새로운 SPAN_ID를 만들어 전달한다.
- TRACE_ID - X
- SPAN_ID - D
- SERVICE3는 TRACE_ID는 유지하면서 새로운 SPAN_ID를 사용한다.
- TRACE_ID - X
- SPAN_ID - E
- 서비스를 이동할 때마다 위와 같은 과정이 반복된다.
- 클라이언트의 첫 요청 시에 생성되는 TRACE_ID는 여러 서비스를 거치더라도 변경되지 않는다.
- 각 서비스 별로 SPAN_ID는 변경된다.
3. Sleuth 라이브러리 테스트
3.1. 테스트 시나리오
Sleuth 라이브러리 적용을 다음과 같은 시나리오로 테스트하였다.
- 터미널에서 cURL 호출을 클라이언트 요청으로 가정한다.
- 다음과 같은 요청 파라미터를 전달한다.
- 하나의 터미널에서는
key=allow값을 전달한다. - 또 다른 터미널에서는
key=deny값을 전달한다.
- A-SERVICE는 요청을 전달 받고 5초 후에 B-SERVICE로 요청을 전달한다.
- B-SERVICE는 요청을 전달 받고 5초 후에 key 값이
deny라면 예외(exception)을 던진다.
3.2. 애플리케이션 코드
각 서비스의 컨트롤러 코드를 살펴보겠다.
3.2.1. A-SERVICE의 AController 클래스
- 반복문을 5회 수행하며, 1회 수행마다 1초씩 기다린다.
processing...로그가 비즈니스 로직이라고 가정한다.- 5회 반복 수행이 끝나면
RestTemplate를 이용하여 B-SERVICE로 파라미터와 함께 요청을 전달한다.
package action.in.blog.controller;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.context.annotation.Bean;
import org.springframework.context.annotation.Configuration;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestHeader;
import org.springframework.web.bind.annotation.RequestParam;
import org.springframework.web.bind.annotation.RestController;
import org.springframework.web.client.RestTemplate;
import java.util.Map;
@RestController
public class AController {
private final Logger logger = LoggerFactory.getLogger(AController.class);
private final RestTemplate restTemplate;
public AController(RestTemplate restTemplate) {
this.restTemplate = restTemplate;
}
private void sleep() {
try {
Thread.sleep(1000);
} catch (Exception e) {
logger.warn(e.getMessage());
}
}
@GetMapping(path = {"", "/"})
public void index(@RequestHeader Map<String, Object> headers, @RequestParam("key") String key) {
logger.info("header: " + headers + ", key: " + key);
for (int index = 0; index < 5; index++) {
logger.info("processing...");
sleep();
}
restTemplate.getForObject("http://b-service:8081?key=" + key, String.class);
}
}
@Configuration
class Config {
@Bean
public RestTemplate restTemplate() {
return new RestTemplate();
}
}3.2.2. B-SERVICE의 BController 클래스
- 반복문을 5회 수행하며, 1회 수행마다 1초씩 기다린다.
processing...로그가 비즈니스 로직이라고 가정한다.- 5회 반복 수행이 끝나면 전달받은 파라미터에 따라 의도적으로 예외를 발생시킨다.
- 전달 받은 파라미터가
deny인 경우RuntimeException을 던진다.
- 전달 받은 파라미터가
package action.in.blog.controller;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import org.springframework.web.bind.annotation.GetMapping;
import org.springframework.web.bind.annotation.RequestHeader;
import org.springframework.web.bind.annotation.RequestParam;
import org.springframework.web.bind.annotation.RestController;
import java.util.Map;
@RestController
public class BController {
private final Logger logger = LoggerFactory.getLogger(BController.class);
private void sleep() {
try {
Thread.sleep(1000);
} catch (Exception e) {
logger.warn(e.getMessage());
}
}
private void throwException(String key) {
if ("deny".equals(key)) {
throw new RuntimeException("throw error");
}
}
@GetMapping(path = {"", "/"})
public void index(@RequestHeader Map<String, Object> headers, @RequestParam("key") String key) {
logger.info("header: " + headers + ", key: " + key);
for (int index = 0; index < 5; index++) {
logger.info("processing...");
sleep();
}
throwException(key);
}
}3.3. 테스트 하기
로그를 한 눈에 보기 쉽도록 docker-compose를 사용하여 attatch 모드로 서비스를 실행하였다.
3.3.1. 서비스 별 application.yml
A-SERVICE’s application.yml
server:
port: 8080
spring:
application:
name: a-serviceB-SERVICE’s application.yml
server:
port: 8081
spring:
application:
name: b-service3.3.2. 프로젝트 별 Dockerfile
- a-service, b-service 프로젝트에
Dockerfile을 하나씩 만든다. - 전반적인
Dockerfile내용은 동일하며,EXPOSE키워드로 노출하는 포트 번호만 다르다.- a-service’s dockerfile -
EXPOSE 8080 - b-service’s dockerfile -
EXPOSE 8081
- a-service’s dockerfile -
FROM maven:3.8.6-jdk-11 as MAVEN_BUILD
WORKDIR /build
COPY pom.xml .
RUN mvn dependency:go-offline
COPY src ./src
RUN mvn package -Dmaven.test.skip=true
FROM openjdk:11-jdk-slim-buster
WORKDIR /app
ARG JAR_FILE=*.jar
COPY --from=MAVEN_BUILD /build/target/${JAR_FILE} ./app.jar
EXPOSE 8080
CMD ["java", "-jar", "app.jar"]3.3.3. docker-compose.yml
docker-compose.yml파일을 통해 두 서비스를 실행한다.- a-service는 8080 포트로 노출한다.
- b-service는 외부에 노출될 필요가 없으므로 별도로 포트를 매칭하지 않는다.
version: '3.8'
services:
a-service:
container_name: a-service
build: ./a-service
ports:
- '8080:8080'
b-service:
container_name: b-service
build: ./b-service3.3.4. 서비스 실행
docker-compose up명령어로 서비스를 실행한다.- docker-compose.yml 파일이 위치한 디렉토리에서 실행한다.
--build옵션 - 매번 이미지를 새로 빌드한다.
$ docker-compose up --build
Creating network "2022-06-27-spring-cloud-sleuth_default" with the default driver
Building a-service
[+] Building 230.1s (15/15) FINISHED
=> [internal] load build definition from Dockerfile 0.0s
=> => transferring dockerfile: 37B 0.0s
=> [internal] load .dockerignore 0.0s
=> => transferring context: 2B 0.0s
=> [internal] load metadata for docker.io/library/openjdk:11-jdk-slim-buster 1.2s
=> [internal] load metadata for docker.io/library/maven:3.8.6-jdk-11 1.1s
=> [maven_build 1/6] FROM docker.io/library/maven:3.8.6-jdk-11@sha256:35d9b4c76cece0781cec2a0cd92a11694d7af01adb758779266d8cf1173a34e0 0.0s
=> [stage-1 1/3] FROM docker.io/library/openjdk:11-jdk-slim-buster@sha256:72816c4c23395f37a31b3637cabb62a290cb9063e7fbcec492ceec56efd5548d 0.0s
=> [internal] load build context 0.0s
=> => transferring context: 3.04kB 0.0s
=> CACHED [maven_build 2/6] WORKDIR /build 0.0s
=> [maven_build 3/6] COPY pom.xml . 0.0s
=> [maven_build 4/6] RUN mvn dependency:go-offline 221.3s
=> [maven_build 5/6] COPY src ./src 0.0s
=> [maven_build 6/6] RUN mvn package -Dmaven.test.skip=true 7.1s
=> CACHED [stage-1 2/3] WORKDIR /app 0.0s
=> [stage-1 3/3] COPY --from=MAVEN_BUILD /build/target/*.jar ./app.jar 0.0s
=> exporting to image 0.1s
=> => exporting layers 0.1s
=> => writing image sha256:50282c8a353adda8208fd21e7837aafb9cc92c69c923fef38d67f20d3bf4a721 0.0s
=> => naming to docker.io/library/2022-06-27-spring-cloud-sleuth_a-service 0.0s
Building b-service
[+] Building 228.7s (17/17) FINISHED
=> [internal] load build definition from Dockerfile 0.0s
=> => transferring dockerfile: 37B 0.0s
=> [internal] load .dockerignore 0.0s
=> => transferring context: 2B 0.0s
=> [internal] load metadata for docker.io/library/openjdk:11-jdk-slim-buster 2.5s
=> [internal] load metadata for docker.io/library/maven:3.8.6-jdk-11 2.5s
=> [auth] library/openjdk:pull token for registry-1.docker.io 0.0s
=> [auth] library/maven:pull token for registry-1.docker.io 0.0s
=> [internal] load build context 0.0s
=> => transferring context: 3.00kB 0.0s
=> [stage-1 1/3] FROM docker.io/library/openjdk:11-jdk-slim-buster@sha256:72816c4c23395f37a31b3637cabb62a290cb9063e7fbcec492ceec56efd5548d 0.0s
=> [maven_build 1/6] FROM docker.io/library/maven:3.8.6-jdk-11@sha256:35d9b4c76cece0781cec2a0cd92a11694d7af01adb758779266d8cf1173a34e0 0.0s
=> CACHED [maven_build 2/6] WORKDIR /build 0.0s
=> [maven_build 3/6] COPY pom.xml . 0.0s
=> [maven_build 4/6] RUN mvn dependency:go-offline 218.6s
=> [maven_build 5/6] COPY src ./src 0.0s
=> [maven_build 6/6] RUN mvn package -Dmaven.test.skip=true 7.1s
=> CACHED [stage-1 2/3] WORKDIR /app 0.0s
=> [stage-1 3/3] COPY --from=MAVEN_BUILD /build/target/*.jar ./app.jar 0.1s
=> exporting to image 0.1s
=> => exporting layers 0.1s
=> => writing image sha256:5fd16ee8844f7e8c2dca3c2417ddecf2d8a612fb7bb7ca830ef7ae0d5486f88f 0.0s
=> => naming to docker.io/library/2022-06-27-spring-cloud-sleuth_b-service 0.0s
Creating a-service ... done
Creating b-service ... done
Attaching to b-service, a-service
b-service |
b-service | . ____ _ __ _ _
b-service | /\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
b-service | ( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
b-service | \\/ ___)| |_)| | | | | || (_| | ) ) ) )
b-service | ' |____| .__|_| |_|_| |_\__, | / / / /
b-service | =========|_|==============|___/=/_/_/_/
b-service | :: Spring Boot :: (v2.7.1)
b-service |
a-service |
a-service | . ____ _ __ _ _
a-service | /\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
a-service | ( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
a-service | \\/ ___)| |_)| | | | | || (_| | ) ) ) )
a-service | ' |____| .__|_| |_|_| |_\__, | / / / /
a-service | =========|_|==============|___/=/_/_/_/
a-service | :: Spring Boot :: (v2.7.1)
a-service |3.3.5. cURL 서비스 호출
- 두 개의 터미널을 통해 a-service를 호출한다.
- 한 터미널에서는 파라미터 값을
allow로 전달한다. - 다른 터미널에서는 파라미터 값을
deny로 전달한다.
- 한 터미널에서는 파라미터 값을
$ curl "http://localhost:8080?key=allow"
$ curl "http://localhost:8080?key=deny"
{"timestamp":"2022-06-27T08:04:32.337+00:00","status":500,"error":"Internal Server Error","path":"/"}%3.3.6. Spring Cloud Sleuth 미적용 시 로그
- Spring Cloud Sleuth 미적용 시 a-service, b-service의 로그다.
- 어떤 요청인 경우에 예외가 발생했는지 추적이 어렵다.
- 서비스 사이에서 발생하는 API 호출의 연결 고리 파악이 쉽지 않다.
a-service |
a-service | . ____ _ __ _ _
a-service | /\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
a-service | ( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
a-service | \\/ ___)| |_)| | | | | || (_| | ) ) ) )
a-service | ' |____| .__|_| |_|_| |_\__, | / / / /
a-service | =========|_|==============|___/=/_/_/_/
a-service | :: Spring Boot :: (v2.7.1)
a-service |
b-service |
b-service | . ____ _ __ _ _
b-service | /\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
b-service | ( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
b-service | \\/ ___)| |_)| | | | | || (_| | ) ) ) )
b-service | ' |____| .__|_| |_|_| |_\__, | / / / /
b-service | =========|_|==============|___/=/_/_/_/
b-service | :: Spring Boot :: (v2.7.1)
b-service |
a-service | 2022-06-27 08:12:23.920 INFO 1 --- [ main] action.in.blog.AServiceApplication : Starting AServiceApplication v0.0.1-SNAPSHOT using Java 11.0.15 on 415d2a554888 with PID 1 (/app/app.jar started by root in /app)
a-service | 2022-06-27 08:12:23.922 INFO 1 --- [ main] action.in.blog.AServiceApplication : No active profile set, falling back to 1 default profile: "default"
b-service | 2022-06-27 08:12:24.014 INFO 1 --- [ main] action.in.blog.BServiceApplication : Starting BServiceApplication v0.0.1-SNAPSHOT using Java 11.0.15 on c1f9c6ba61fd with PID 1 (/app/app.jar started by root in /app)
b-service | 2022-06-27 08:12:24.017 INFO 1 --- [ main] action.in.blog.BServiceApplication : No active profile set, falling back to 1 default profile: "default"
a-service | 2022-06-27 08:12:24.893 INFO 1 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8080 (http)
a-service | 2022-06-27 08:12:24.906 INFO 1 --- [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
a-service | 2022-06-27 08:12:24.906 INFO 1 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.64]
a-service | 2022-06-27 08:12:24.983 INFO 1 --- [ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
a-service | 2022-06-27 08:12:24.983 INFO 1 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 1006 ms
b-service | 2022-06-27 08:12:24.991 INFO 1 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8081 (http)
b-service | 2022-06-27 08:12:25.002 INFO 1 --- [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
b-service | 2022-06-27 08:12:25.002 INFO 1 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.64]
b-service | 2022-06-27 08:12:25.089 INFO 1 --- [ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
b-service | 2022-06-27 08:12:25.089 INFO 1 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 1017 ms
a-service | 2022-06-27 08:12:25.354 INFO 1 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8080 (http) with context path ''
a-service | 2022-06-27 08:12:25.364 INFO 1 --- [ main] action.in.blog.AServiceApplication : Started AServiceApplication in 1.956 seconds (JVM running for 2.342)
b-service | 2022-06-27 08:12:25.425 INFO 1 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8081 (http) with context path ''
b-service | 2022-06-27 08:12:25.435 INFO 1 --- [ main] action.in.blog.BServiceApplication : Started BServiceApplication in 2.028 seconds (JVM running for 2.418)
a-service | 2022-06-27 08:12:29.029 INFO 1 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring DispatcherServlet 'dispatcherServlet'
a-service | 2022-06-27 08:12:29.030 INFO 1 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
a-service | 2022-06-27 08:12:29.031 INFO 1 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : Completed initialization in 1 ms
a-service | 2022-06-27 08:12:29.087 INFO 1 --- [nio-8080-exec-1] action.in.blog.controller.AController : header: {host=localhost:8080, user-agent=curl/7.79.1, accept=*/*}, key: allow
a-service | 2022-06-27 08:12:29.087 INFO 1 --- [nio-8080-exec-1] action.in.blog.controller.AController : processing...
a-service | 2022-06-27 08:12:29.640 INFO 1 --- [nio-8080-exec-2] action.in.blog.controller.AController : header: {host=localhost:8080, user-agent=curl/7.79.1, accept=*/*}, key: deny
a-service | 2022-06-27 08:12:29.640 INFO 1 --- [nio-8080-exec-2] action.in.blog.controller.AController : processing...
a-service | 2022-06-27 08:12:30.087 INFO 1 --- [nio-8080-exec-1] action.in.blog.controller.AController : processing...
a-service | 2022-06-27 08:12:30.641 INFO 1 --- [nio-8080-exec-2] action.in.blog.controller.AController : processing...
a-service | 2022-06-27 08:12:31.088 INFO 1 --- [nio-8080-exec-1] action.in.blog.controller.AController : processing...
a-service | 2022-06-27 08:12:31.642 INFO 1 --- [nio-8080-exec-2] action.in.blog.controller.AController : processing...
a-service | 2022-06-27 08:12:32.088 INFO 1 --- [nio-8080-exec-1] action.in.blog.controller.AController : processing...
a-service | 2022-06-27 08:12:32.644 INFO 1 --- [nio-8080-exec-2] action.in.blog.controller.AController : processing...
a-service | 2022-06-27 08:12:33.089 INFO 1 --- [nio-8080-exec-1] action.in.blog.controller.AController : processing...
a-service | 2022-06-27 08:12:33.644 INFO 1 --- [nio-8080-exec-2] action.in.blog.controller.AController : processing...
b-service | 2022-06-27 08:12:34.161 INFO 1 --- [nio-8081-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring DispatcherServlet 'dispatcherServlet'
b-service | 2022-06-27 08:12:34.161 INFO 1 --- [nio-8081-exec-1] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
b-service | 2022-06-27 08:12:34.163 INFO 1 --- [nio-8081-exec-1] o.s.web.servlet.DispatcherServlet : Completed initialization in 1 ms
b-service | 2022-06-27 08:12:34.200 INFO 1 --- [nio-8081-exec-1] action.in.blog.controller.BController : header: {accept=text/plain, application/json, application/*+json, */*, user-agent=Java/11.0.15, host=b-service:8081, connection=keep-alive}, key: allow
b-service | 2022-06-27 08:12:34.200 INFO 1 --- [nio-8081-exec-1] action.in.blog.controller.BController : processing...
b-service | 2022-06-27 08:12:34.649 INFO 1 --- [nio-8081-exec-2] action.in.blog.controller.BController : header: {accept=text/plain, application/json, application/*+json, */*, user-agent=Java/11.0.15, host=b-service:8081, connection=keep-alive}, key: deny
b-service | 2022-06-27 08:12:34.649 INFO 1 --- [nio-8081-exec-2] action.in.blog.controller.BController : processing...
b-service | 2022-06-27 08:12:35.201 INFO 1 --- [nio-8081-exec-1] action.in.blog.controller.BController : processing...
b-service | 2022-06-27 08:12:35.650 INFO 1 --- [nio-8081-exec-2] action.in.blog.controller.BController : processing...
b-service | 2022-06-27 08:12:36.202 INFO 1 --- [nio-8081-exec-1] action.in.blog.controller.BController : processing...
b-service | 2022-06-27 08:12:36.650 INFO 1 --- [nio-8081-exec-2] action.in.blog.controller.BController : processing...
b-service | 2022-06-27 08:12:37.202 INFO 1 --- [nio-8081-exec-1] action.in.blog.controller.BController : processing...
b-service | 2022-06-27 08:12:37.651 INFO 1 --- [nio-8081-exec-2] action.in.blog.controller.BController : processing...
b-service | 2022-06-27 08:12:38.203 INFO 1 --- [nio-8081-exec-1] action.in.blog.controller.BController : processing...
b-service | 2022-06-27 08:12:38.652 INFO 1 --- [nio-8081-exec-2] action.in.blog.controller.BController : processing...
b-service | 2022-06-27 08:12:39.662 ERROR 1 --- [nio-8081-exec-2] o.a.c.c.C.[.[.[/].[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.RuntimeException: throw error] with root cause
b-service |
b-service | java.lang.RuntimeException: throw error
b-service | at action.in.blog.controller.BController.throwException(BController.java:27) ~[classes!/:0.0.1-SNAPSHOT]
b-service | at action.in.blog.controller.BController.index(BController.java:38) ~[classes!/:0.0.1-SNAPSHOT]
b-service | at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
b-service | at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na]
b-service | at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
b-service | at java.base/java.lang.reflect.Method.invoke(Method.java:566) ~[na:na]
b-service | at org.springframework.web.method.support.InvocableHandlerMethod.doInvoke(InvocableHandlerMethod.java:205) ~[spring-web-5.3.21.jar!/:5.3.21]
b-service | at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:150) ~[spring-web-5.3.21.jar!/:5.3.21]
b-service | at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:117) ~[spring-webmvc-5.3.21.jar!/:5.3.21]
b-service | at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:895) ~[spring-webmvc-5.3.21.jar!/:5.3.21]
b-service | ...
b-service |
a-service | 2022-06-27 08:12:39.715 ERROR 1 --- [nio-8080-exec-2] o.a.c.c.C.[.[.[/].[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.springframework.web.client.HttpServerErrorException$InternalServerError: 500 : "{"timestamp":"2022-06-27T08:12:39.669+00:00","status":500,"error":"Internal Server Error","path":"/"}"] with root cause
a-service |
a-service | org.springframework.web.client.HttpServerErrorException$InternalServerError: 500 : "{"timestamp":"2022-06-27T08:12:39.669+00:00","status":500,"error":"Internal Server Error","path":"/"}"
a-service | at org.springframework.web.client.HttpServerErrorException.create(HttpServerErrorException.java:100) ~[spring-web-5.3.21.jar!/:5.3.21]
a-service | at org.springframework.web.client.DefaultResponseErrorHandler.handleError(DefaultResponseErrorHandler.java:170) ~[spring-web-5.3.21.jar!/:5.3.21]
a-service | at org.springframework.web.client.DefaultResponseErrorHandler.handleError(DefaultResponseErrorHandler.java:122) ~[spring-web-5.3.21.jar!/:5.3.21]
a-service | at org.springframework.web.client.ResponseErrorHandler.handleError(ResponseErrorHandler.java:63) ~[spring-web-5.3.21.jar!/:5.3.21]
a-service | at org.springframework.web.client.RestTemplate.handleResponse(RestTemplate.java:819) ~[spring-web-5.3.21.jar!/:5.3.21]
a-service | at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:777) ~[spring-web-5.3.21.jar!/:5.3.21]
a-service | at org.springframework.web.client.RestTemplate.execute(RestTemplate.java:711) ~[spring-web-5.3.21.jar!/:5.3.21]
a-service | at org.springframework.web.client.RestTemplate.getForObject(RestTemplate.java:334) ~[spring-web-5.3.21.jar!/:5.3.21]
a-service | at action.in.blog.controller.AController.index(AController.java:41) ~[classes!/:0.0.1-SNAPSHOT]
a-service | ...3.3.4. Spring Cloud Sleuth 적용
pom.xml
- 다음과 같은 의존성을 추가하면
Spring Cloud Sleuth가 자동으로 적용된다.
<dependencies>
...
<dependency>
<groupId>org.springframework.cloud</groupId>
<artifactId>spring-cloud-starter-sleuth</artifactId>
</dependency>
</dependencies>
<dependencyManagement>
<dependencies>
<dependency>
<groupId>org.springframework.cloud</groupId>
<artifactId>spring-cloud-dependencies</artifactId>
<version>${spring-cloud.version}</version>
<type>pom</type>
<scope>import</scope>
</dependency>
</dependencies>
</dependencyManagement>애플리케이션 로그
- 적용 후 애플리케이션 로그를 살펴보면 다음과 같은 정보가 추가된다.
- [APPLICATION_NAME, TRACE_ID, SPAN_ID]
- ex) [a-service,a8c3719def75eb27,a8c3719def75eb27]
b-service에서 확인된 에러 로그의TRACE_ID인59447c50de81e252로 요청 정보를 추적한다.a-service의 어떤 요청이 해당 예외를 유발시켰는지 쉽게 확인이 가능하다.
b-service |
b-service | . ____ _ __ _ _
b-service | /\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
b-service | ( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
b-service | \\/ ___)| |_)| | | | | || (_| | ) ) ) )
b-service | ' |____| .__|_| |_|_| |_\__, | / / / /
b-service | =========|_|==============|___/=/_/_/_/
b-service | :: Spring Boot :: (v2.7.1)
b-service |
a-service |
a-service | . ____ _ __ _ _
a-service | /\\ / ___'_ __ _ _(_)_ __ __ _ \ \ \ \
a-service | ( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
a-service | \\/ ___)| |_)| | | | | || (_| | ) ) ) )
a-service | ' |____| .__|_| |_|_| |_\__, | / / / /
a-service | =========|_|==============|___/=/_/_/_/
a-service | :: Spring Boot :: (v2.7.1)
a-service |
b-service | 2022-06-27 08:19:34.981 INFO [b-service,,] 1 --- [ main] action.in.blog.BServiceApplication : Starting BServiceApplication v0.0.1-SNAPSHOT using Java 11.0.15 on 81a7981709e3 with PID 1 (/app/app.jar started by root in /app)
b-service | 2022-06-27 08:19:34.984 INFO [b-service,,] 1 --- [ main] action.in.blog.BServiceApplication : No active profile set, falling back to 1 default profile: "default"
a-service | 2022-06-27 08:19:35.045 INFO [a-service,,] 1 --- [ main] action.in.blog.AServiceApplication : Starting AServiceApplication v0.0.1-SNAPSHOT using Java 11.0.15 on 4cff3c34052e with PID 1 (/app/app.jar started by root in /app)
a-service | 2022-06-27 08:19:35.048 INFO [a-service,,] 1 --- [ main] action.in.blog.AServiceApplication : No active profile set, falling back to 1 default profile: "default"
b-service | 2022-06-27 08:19:35.802 INFO [b-service,,] 1 --- [ main] o.s.cloud.context.scope.GenericScope : BeanFactory id=ecc11721-3014-3c26-9b7e-557ffb30cefc
a-service | 2022-06-27 08:19:35.887 INFO [a-service,,] 1 --- [ main] o.s.cloud.context.scope.GenericScope : BeanFactory id=811c3f2d-6b23-3962-88a9-2326a6e70bdd
b-service | 2022-06-27 08:19:36.336 INFO [b-service,,] 1 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8081 (http)
b-service | 2022-06-27 08:19:36.347 INFO [b-service,,] 1 --- [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
b-service | 2022-06-27 08:19:36.347 INFO [b-service,,] 1 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.64]
b-service | 2022-06-27 08:19:36.413 INFO [b-service,,] 1 --- [ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
b-service | 2022-06-27 08:19:36.413 INFO [b-service,,] 1 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 1361 ms
a-service | 2022-06-27 08:19:36.419 INFO [a-service,,] 1 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat initialized with port(s): 8080 (http)
a-service | 2022-06-27 08:19:36.430 INFO [a-service,,] 1 --- [ main] o.apache.catalina.core.StandardService : Starting service [Tomcat]
a-service | 2022-06-27 08:19:36.430 INFO [a-service,,] 1 --- [ main] org.apache.catalina.core.StandardEngine : Starting Servlet engine: [Apache Tomcat/9.0.64]
a-service | 2022-06-27 08:19:36.497 INFO [a-service,,] 1 --- [ main] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring embedded WebApplicationContext
a-service | 2022-06-27 08:19:36.497 INFO [a-service,,] 1 --- [ main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 1377 ms
b-service | 2022-06-27 08:19:37.407 INFO [b-service,,] 1 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8081 (http) with context path ''
b-service | 2022-06-27 08:19:37.420 INFO [b-service,,] 1 --- [ main] action.in.blog.BServiceApplication : Started BServiceApplication in 2.977 seconds (JVM running for 3.414)
a-service | 2022-06-27 08:19:37.504 INFO [a-service,,] 1 --- [ main] o.s.b.w.embedded.tomcat.TomcatWebServer : Tomcat started on port(s): 8080 (http) with context path ''
a-service | 2022-06-27 08:19:37.518 INFO [a-service,,] 1 --- [ main] action.in.blog.AServiceApplication : Started AServiceApplication in 3.035 seconds (JVM running for 3.479)
a-service | 2022-06-27 08:20:09.569 INFO [a-service,a8c3719def75eb27,a8c3719def75eb27] 1 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring DispatcherServlet 'dispatcherServlet'
a-service | 2022-06-27 08:20:09.569 INFO [a-service,a8c3719def75eb27,a8c3719def75eb27] 1 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
a-service | 2022-06-27 08:20:09.571 INFO [a-service,a8c3719def75eb27,a8c3719def75eb27] 1 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet : Completed initialization in 2 ms
a-service | 2022-06-27 08:20:09.612 INFO [a-service,a8c3719def75eb27,a8c3719def75eb27] 1 --- [nio-8080-exec-1] action.in.blog.controller.AController : header: {host=localhost:8080, user-agent=curl/7.79.1, accept=*/*}, key: allow
a-service | 2022-06-27 08:20:09.612 INFO [a-service,a8c3719def75eb27,a8c3719def75eb27] 1 --- [nio-8080-exec-1] action.in.blog.controller.AController : processing...
a-service | 2022-06-27 08:20:09.992 INFO [a-service,59447c50de81e252,59447c50de81e252] 1 --- [nio-8080-exec-2] action.in.blog.controller.AController : header: {host=localhost:8080, user-agent=curl/7.79.1, accept=*/*}, key: deny
a-service | 2022-06-27 08:20:09.992 INFO [a-service,59447c50de81e252,59447c50de81e252] 1 --- [nio-8080-exec-2] action.in.blog.controller.AController : processing...
a-service | 2022-06-27 08:20:10.613 INFO [a-service,a8c3719def75eb27,a8c3719def75eb27] 1 --- [nio-8080-exec-1] action.in.blog.controller.AController : processing...
a-service | 2022-06-27 08:20:10.992 INFO [a-service,59447c50de81e252,59447c50de81e252] 1 --- [nio-8080-exec-2] action.in.blog.controller.AController : processing...
a-service | 2022-06-27 08:20:11.613 INFO [a-service,a8c3719def75eb27,a8c3719def75eb27] 1 --- [nio-8080-exec-1] action.in.blog.controller.AController : processing...
a-service | 2022-06-27 08:20:11.993 INFO [a-service,59447c50de81e252,59447c50de81e252] 1 --- [nio-8080-exec-2] action.in.blog.controller.AController : processing...
a-service | 2022-06-27 08:20:12.614 INFO [a-service,a8c3719def75eb27,a8c3719def75eb27] 1 --- [nio-8080-exec-1] action.in.blog.controller.AController : processing...
a-service | 2022-06-27 08:20:12.994 INFO [a-service,59447c50de81e252,59447c50de81e252] 1 --- [nio-8080-exec-2] action.in.blog.controller.AController : processing...
a-service | 2022-06-27 08:20:13.616 INFO [a-service,a8c3719def75eb27,a8c3719def75eb27] 1 --- [nio-8080-exec-1] action.in.blog.controller.AController : processing...
a-service | 2022-06-27 08:20:13.995 INFO [a-service,59447c50de81e252,59447c50de81e252] 1 --- [nio-8080-exec-2] action.in.blog.controller.AController : processing...
b-service | 2022-06-27 08:20:14.736 INFO [b-service,a8c3719def75eb27,4248dac991ff2062] 1 --- [nio-8081-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/] : Initializing Spring DispatcherServlet 'dispatcherServlet'
b-service | 2022-06-27 08:20:14.737 INFO [b-service,a8c3719def75eb27,4248dac991ff2062] 1 --- [nio-8081-exec-1] o.s.web.servlet.DispatcherServlet : Initializing Servlet 'dispatcherServlet'
b-service | 2022-06-27 08:20:14.739 INFO [b-service,a8c3719def75eb27,4248dac991ff2062] 1 --- [nio-8081-exec-1] o.s.web.servlet.DispatcherServlet : Completed initialization in 2 ms
b-service | 2022-06-27 08:20:14.777 INFO [b-service,a8c3719def75eb27,4248dac991ff2062] 1 --- [nio-8081-exec-1] action.in.blog.controller.BController : header: {accept=text/plain, application/json, application/*+json, */*, x-b3-traceid=a8c3719def75eb27, x-b3-spanid=4248dac991ff2062, x-b3-parentspanid=a8c3719def75eb27, x-b3-sampled=0, user-agent=Java/11.0.15, host=b-service:8081, connection=keep-alive}, key: allow
b-service | 2022-06-27 08:20:14.777 INFO [b-service,a8c3719def75eb27,4248dac991ff2062] 1 --- [nio-8081-exec-1] action.in.blog.controller.BController : processing...
b-service | 2022-06-27 08:20:15.000 INFO [b-service,59447c50de81e252,e80b00875dcbca39] 1 --- [nio-8081-exec-2] action.in.blog.controller.BController : header: {accept=text/plain, application/json, application/*+json, */*, x-b3-traceid=59447c50de81e252, x-b3-spanid=e80b00875dcbca39, x-b3-parentspanid=59447c50de81e252, x-b3-sampled=0, user-agent=Java/11.0.15, host=b-service:8081, connection=keep-alive}, key: deny
b-service | 2022-06-27 08:20:15.000 INFO [b-service,59447c50de81e252,e80b00875dcbca39] 1 --- [nio-8081-exec-2] action.in.blog.controller.BController : processing...
b-service | 2022-06-27 08:20:15.778 INFO [b-service,a8c3719def75eb27,4248dac991ff2062] 1 --- [nio-8081-exec-1] action.in.blog.controller.BController : processing...
b-service | 2022-06-27 08:20:15.980 INFO [b-service,59447c50de81e252,e80b00875dcbca39] 1 --- [nio-8081-exec-2] action.in.blog.controller.BController : processing...
b-service | 2022-06-27 08:20:16.758 INFO [b-service,a8c3719def75eb27,4248dac991ff2062] 1 --- [nio-8081-exec-1] action.in.blog.controller.BController : processing...
b-service | 2022-06-27 08:20:16.981 INFO [b-service,59447c50de81e252,e80b00875dcbca39] 1 --- [nio-8081-exec-2] action.in.blog.controller.BController : processing...
b-service | 2022-06-27 08:20:17.759 INFO [b-service,a8c3719def75eb27,4248dac991ff2062] 1 --- [nio-8081-exec-1] action.in.blog.controller.BController : processing...
b-service | 2022-06-27 08:20:17.981 INFO [b-service,59447c50de81e252,e80b00875dcbca39] 1 --- [nio-8081-exec-2] action.in.blog.controller.BController : processing...
b-service | 2022-06-27 08:20:18.759 INFO [b-service,a8c3719def75eb27,4248dac991ff2062] 1 --- [nio-8081-exec-1] action.in.blog.controller.BController : processing...
b-service | 2022-06-27 08:20:18.982 INFO [b-service,59447c50de81e252,e80b00875dcbca39] 1 --- [nio-8081-exec-2] action.in.blog.controller.BController : processing...
b-service | 2022-06-27 08:20:19.989 ERROR [b-service,59447c50de81e252,e80b00875dcbca39] 1 --- [nio-8081-exec-2] o.a.c.c.C.[.[.[/].[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is java.lang.RuntimeException: throw error] with root cause
b-service |
b-service | java.lang.RuntimeException: throw error
b-service | at action.in.blog.controller.BController.throwException(BController.java:27) ~[classes!/:0.0.1-SNAPSHOT]
b-service | at action.in.blog.controller.BController.index(BController.java:38) ~[classes!/:0.0.1-SNAPSHOT]
b-service | at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[na:na]
b-service | at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) ~[na:na]
b-service | at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[na:na]
b-service | at java.base/java.lang.reflect.Method.invoke(Method.java:566) ~[na:na]
b-service | ...
b-service |
a-service | 2022-06-27 08:20:20.046 ERROR [a-service,59447c50de81e252,59447c50de81e252] 1 --- [nio-8080-exec-2] o.a.c.c.C.[.[.[/].[dispatcherServlet] : Servlet.service() for servlet [dispatcherServlet] in context with path [] threw exception [Request processing failed; nested exception is org.springframework.web.client.HttpServerErrorException$InternalServerError: 500 : "{"timestamp":"2022-06-27T08:20:19.997+00:00","status":500,"error":"Internal Server Error","path":"/"}"] with root cause
a-service |
a-service | org.springframework.web.client.HttpServerErrorException$InternalServerError: 500 : "{"timestamp":"2022-06-27T08:20:19.997+00:00","status":500,"error":"Internal Server Error","path":"/"}"
a-service | at org.springframework.web.client.HttpServerErrorException.create(HttpServerErrorException.java:100) ~[spring-web-5.3.21.jar!/:5.3.21]
a-service | at org.springframework.web.client.DefaultResponseErrorHandler.handleError(DefaultResponseErrorHandler.java:170) ~[spring-web-5.3.21.jar!/:5.3.21]
a-service | at org.springframework.web.client.DefaultResponseErrorHandler.handleError(DefaultResponseErrorHandler.java:122) ~[spring-web-5.3.21.jar!/:5.3.21]
a-service | at org.springframework.web.client.ResponseErrorHandler.handleError(ResponseErrorHandler.java:63) ~[spring-web-5.3.21.jar!/:5.3.21]
a-service | at org.springframework.web.client.RestTemplate.handleResponse(RestTemplate.java:819) ~[spring-web-5.3.21.jar!/:5.3.21]
a-service | at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:777) ~[spring-web-5.3.21.jar!/:5.3.21]
a-service | at org.springframework.web.client.RestTemplate.execute(RestTemplate.java:711) ~[spring-web-5.3.21.jar!/:5.3.21]
a-service | at org.springframework.web.client.RestTemplate.getForObject(RestTemplate.java:334) ~[spring-web-5.3.21.jar!/:5.3.21]
a-service | at action.in.blog.controller.AController.index(AController.java:41) ~[classes!/:0.0.1-SNAPSHOT]
a-service | ...CLOSE
Spring Cloud Sleuth는 마이크로서비스 아키텍처 같은 분산 시스템의 로그 추적성을 향상시키기 위한 라이브러리다. 더불어 특정 요청을 쉽게 필터링하여 조회할 수 있다는 관점에서 모놀리식 서비스에서 사용해도 큰 이점이 있을 것 같다. 시간이 된다면 log4j2.xml 파일의 로그 레이아웃(layout)을 변경하여 좀 더 보기 쉬운 로그를 구성하는 방법에 대해 정리해보겠다.
TEST CODE REPOSITORY
REFERENCE
KEEP READING
함께 읽으면 좋은 글
DISCUSSION