분산환경은 서비스 트레이싱을 어떻게 할까

Spring Cloud Sleuth:3.0.4 docs

개요

최종적으로 trace를 통해 각 서비스의 로그를 파악하기 위한 수단은 Kibana인데 어떻게 각 서비스에서 수집된 데이터가 하나로 뭉쳐지는지에 대해서 궁금증이 생겼다.
현재 프로젝트에서 구성되어있는 트레이싱을 예측해보면 아래와 같다.
각각의 도메인 서버에서 spring-cloud-sleuth를 통해 수집된 정보를 logback 설정을 통해 JSON으로 샘플링하고 logstash -> Elasticsearch -> Kibana로 가는 구조로 보인다. 차례로 서비스들의 역할을 정리하고 예시로 기동까지 해볼예정이다.
이 글에서는 Spring-cloud-sleuth와 zipkin을 살펴볼것이다.

 

spring-cloud-sleuth

Spring Cloud Sleuth는 마이크로서비스 아키텍처 환경에서 서비스 간 호출 추적을 위한 라이브러리다. Spring Cloud Sleuth는 애플리케이션의 모든 요청에 대해 고유한 추적 정보를 자동으로 생성하고, 이 정보를 로그 메시지에 함께 출력한다. 이를 통해 서비스 간 호출 흐름을 추적하고, 문제가 발생했을 때 문제 해결에 필요한 충분한 정보를 제공한다.

document 초입에 Dapper's라는 용어를 차용했다고 나온다. 2010년에 구글에서 발표한 대규모 분산시스템 추적 인프라 에 대한 논문인데 용어정도만 알아두면 될것같다.

System내부에서 본 Span, Trace, Zipkin annotations

개인적으로 아래 이미지를 먼저 보고 용어의 뜻을 찾아 보는게 더 이해가 쉬웠다.

용어

TLTR

시간(Timestamp)정보를 가진 span을 annotation과 함께 저장하고 이것들의 집합은 하나의 Trace내에서 관리된다.

Span

Tracer 인터페이스는 새로운 Span이 생성되거나, Span정보를 가져오거나 등의 작업을 한다. 이러한 Span정보는 ThreadLocal에 저장되므로 하나의 Thread내에서는 Span정보를 공유 할 수 있다. 그말인 즉 multi-thread에서는 별개의 Span이 생성된다는것을 반대로 유추 해 볼 수 있다.
작업의 가장 기본단위이다. 위 그림의 Service1 request-response가 동일한 Span인걸 볼 수 있다. Span은 유니크한 64-bit의 ID값과 64-bit의 TraceID 로 식별된다. 또한 Span은 설명(descriptions), 시간(timestamped event), 태그(key-value annotation), ProcessId(보통 IP주소) 그리고 부모 span인 ParentSpanId 값이 있다.

최초의 span(trace 시작)은 root span 이라고 불린다. 이때 spanId와 traceId는 동일하다.

Trace

tree구조로 구성된 Span의 set이다. 즉 Span은 Trace값을 통해 서로 연결된다.

Annotation

event와 시간을 기록하기 위해 사용된다. Brave가 도입됨으로써 Zipkin을 위해 client가 누구고 server가 누구이며, 어디서 request가 시작되고 어디서 끝났는지에 대한 이벤트정보들을 설정해줄 필요가 없다고 한다.
Annotation의 특정 이벤트들은 아래와 같다.

• cs: Client Sent. Request를 만든 클라이언트이며 Span의 시작을 가르킨다.
• sr: Server Received. 서버사이드에서 request를 받고 프로세스를 시작하는 행위이다. 네트워크 지연시간을 알 수 있다.(Server Received - Client Sent)
• ss: Server Sent. Requst프로세스의 완료(Response가 client로 전해졌을때)의 이벤트이다. 서버사이드의 request 수행시간을 알 수 있다.(Server Sent - Server Received)
• cr: Client Received. Span의 종료를 의미한다. 즉 client가 성공적으로 서버사이드의 Response를 받았을때이다. client가 서버로부터 response를 받을때까지의 시간을 알 수 있다.(Client Received - Client Sent)

그래서 누가 context를 저장하는데?

2.0.0버전부터 Spring-cloud-sleuth는 Brave를 tracing library로 사용하여 context를 저장하고 관리하는 작업들을 Brave에게 위임시켰다.
Brave core에 있는 Tracer가 context 정보를 생성하고 ThreadLocal에 저장하다가 Request가 종료되는 시점에 zipkin으로 전송하는 모든 일을 개발자를 대신해 직접 수행한다.

실제 구동하며 span과 trace 확인해보기전에

2개의 SpringBoot프로젝트를 생성하여 A서비스(rpc)에서 B서비스(context)를 feign으로 호출하고 zipkin에서 trace를 확인해보기 전에 zipkin에 대해서 알아보고 테스트 해보도록 한다.

zipkin

zipkin은 분산환경 트레이싱 시스템이다. 분산환경에서 생기는 latency(네트워크지연)문제등 트러블슈팅에 필요한 timing data들을 수집하고 표현하는 일을 한다. 또한 dependency diagram을 표현함으로써 특정 서비스의 영향도 파악에도 도움을 준다. zipkin에게 trace data를 주기 위해선 각 어플리케이션에서 trace 혹은 instrumentation 라이브러리 설정(우리에게는 slueth)이 있어야 한다.

zipkin Architecture

Transport

어플리케이션에서 instrumented library를 통해 zipkin Collectors 컴포넌트로 데이터를 전송하는 방식은 http, Kafka, Scribe를 3가지이다.(zipkin내 구성요소는 아니지만 포함시켜놨다)

Collector

계측된 클라이언트에서 보내짐 trace data들은 collector demon에 도달하면 collector에 의해 정규화 및 인덱싱을 거쳐 검색하기 좋게 저장한다.

Storage

최초의 zipkin은 Cassandra의 확장성, 유연한 스키마 그리고 Twitter에서 아주 많이 사용됬기 때문에 Cassandra에 데이터를 저장하도록 만들어졌었다. 현재는 Cassandra뿐만 아니라 Elasitcsearch, MySQL도 native하게 지원하고 다양한 커뮤니티 의해 다양한 백엔드들이 추가로 지원되고있다.

Query Service

색인되고 저장된 데이터들을 추출할필요가있고 그 일을 Query데몬이 수행한다. JSON API로 검색된 데이터들은 Web UI에서 표현된다.

Web UI

시간, 어노테이션, 서비스에 기반한 Trace들을 시각적으로 표현해준다. UI에는 별도의 빌트인 authentication이 없다.

프로젝트 구성

유의할점

1. spring version과 spring-cloud version을 유의하여서 의존성을 추가시켜줘야한다. 버전이 안맞을때 deprecated되는 클래스가 겹치게될때 Bean생성관련해서 컴파일시 오류가 발생하는 경우가 많다.

2. spring.application.name은 꼭 지정해줘야한다. application name이 존재해야 zipkin에서 제대로 디스플레이를 할수 있다고 document에 나온다.

To ensure that your application name is properly displayed in Zipkin, set the spring.application.name property in bootstrap.yml.

프로젝트 예시

위 그림의 Service1 - Service2를 예시 프로젝트로 생성한다.
Service1(rpc) -Service2(context) 서비스간 통신을 테스트 해보면서 sleuth와 zipkin의 역할을 zipkin Web UI에서 확인 해볼 예정이다.

zipkin

앞으로도 추가될 서비스들을 있으므로 docker compose로 zipkin을 실행한다.

# docker-compose.yml
name: elk-container

services:
  zipkin:  
  image: openzipkin/zipkin  
  container_name: zipkin  
  ports:  
    - "9411:9411"

Service1(rpc)

Service1은 8080포트를 사용하며, Service2로 REST통신을 하는 컨트롤러와 http통신을 도와줄 feign을 사용한다.

public class RpcController {  
    private final Tracer tracer;  

    @GetMapping("/span")  
    public String getSpanId(){  
        log.info("traceId={}",tracer.currentSpan().context().traceIdString());  
        return contextClient.getSpanId();  
    }
...

위와 같이 Tracer를 Bean으로 주입하여 사용할수있다. Tracer는 slueth 의존성 내에 있는 Brave모듈에서 가져오는데, 현재 context 정보들을 코드로 확인 할 수 있다.

Service2(context)

Span은 비동기처리 혹은 api통신시에 새로운 Span을 생성하는걸 확인 할 수 있었다.

@FeignClient(name="ETC", url="https://www.naver.com/")  
public interface ExternalClient {  

    @GetMapping("/search")  
    public String getSearchResult();
...

public class ContextController {  

    private final Tracer trace;  
    private final ExternalClient externalClient;  

    @GetMapping("/span-id")  
    public String getSpanId() throws InterruptedException {  
        log.info("getSpanId() Start");  

        String spanId = trace.currentSpan().context().spanIdString();  
        log.info("trace.spanId={}",spanId);  
        log.info("trace.traceId={}", trace.currentSpan().context().traceIdString());  

        Thread.sleep(2000);  
        try {  
            externalClient.getSearchResult();  
        }catch(Exception e){  
         log.warn("rpcClient.getSearchResult() got error");  
         e.printStackTrace();  
        }  
        return spanId;  
    };

+zipkin query의 default baseUrl은 http://localhost:9411이다.

// spring-cloud-sleuth-zipkin-3.1.3/META-INF/spring-configuration-metadata.json 
...
{  
  "name": "spring.zipkin.base-url",  
  "type": "java.lang.String",  
  "description": "URL of the zipkin query server instance. You can also provide the service id of the Zipkin server if Zipkin's registered in service discovery (e.g. https:\/\/zipkinserver\/).",  
  "sourceType": "org.springframework.cloud.sleuth.zipkin2.ZipkinProperties",  
  "defaultValue": "http:\/\/localhost:9411\/"  
}
...

baseUrl을 별도로 지정하기 위해 yml을 사용할 수 있다.

#application.yml
spring:
  zipkin:
    base-url: {$MY_HOST}:9411

Slueth와 zipkin이 함께 동작하는 방식

1. 클라이언트가 서버에 요청을 보내면, 이 요청은 Spring Cloud Sleuth를 통해 트레이싱 된다. 이 과정에서 트레이싱을 위한 고유한 Trace ID와 Span ID가 생성된다. 이것들은 request headers인 'X-B3-TraceId' 와 'X-B3-SpanId' 에 저장된 정보를 가져와 생성하는데, 만약 이들이 존재하지 않는다면, 새로운 것을 생성하는 방식이다.
2. 이들 Trace ID와 Span ID는 Spring Cloud Sleuth의 Tracer 인터페이스에 의해 Context, 즉 ThreadLocal에 저장된다.
3. 이후에 클라이언트의 요청에 대해 서버가 어떤 처리를 수행(timestamps, annotations)하는지 등 정보 외에 추가적으로 수집 하는 것은 개발자의 영역으로, 원하는 로직에 대한 처리 시점에서 추가적인 정보를 Tracer를 이용하여 Sleuth의 Span에 추가할 수 있다.
4. 서버에서 Response를 반환할 때, Tracer 인터페이스는 ThreadLocal에 저장된 정보들을 얻어온다. 이때 해당 요청에대한 모든 Trace 정보를 가진 Span이 완료된 것이다.
5. 스프링 애플리케이션의 별도 스레드인 reporter는 이 완료된 Span를 가져와서 Zipkin 서버에 보낸다.
6. 이렇게 보내진 데이터는 Zipkin 서버에서 수집하고 저장한다. 이후 이 데이터를 이용해서 Zipkin UI에서 시각화하여 보여준다.

zipkin 연동 테스트

프로세스 흐름은 아래와 같다.

외부서버와내에 context를 담을수 없어서 Service2에 2개의 context를 표현했다

Request을 보내고, 서비스들의 흐름을 zipkin을 확인해본다.

### getSpanId  
GET http://localhost:8080/rpc/span  
Content-Type: application/json

# Service1(rpc) logs
...
2023-09-26 17:00:02.814  INFO [rpc,57b792f200330694,57b792f200330694] 72076 --- [nio-8080-exec-1] o.a.c.c.C.[Tomcat].[localhost].[/]       : Initializing Spring DispatcherServlet 'dispatcherServlet'
2023-09-26 17:00:02.815  INFO [rpc,57b792f200330694,57b792f200330694] 72076 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2023-09-26 17:00:02.816  INFO [rpc,57b792f200330694,57b792f200330694] 72076 --- [nio-8080-exec-1] o.s.web.servlet.DispatcherServlet        : Completed initialization in 1 ms
2023-09-26 17:00:02.831  INFO [rpc,57b792f200330694,57b792f200330694] 72076 --- [nio-8080-exec-1] c.e.rpcexample.controller.RpcController  : getSpanId Start
2023-09-26 17:00:02.832  INFO [rpc,57b792f200330694,57b792f200330694] 72076 --- [nio-8080-exec-1] c.e.rpcexample.controller.RpcController  : now traceId = 57b792f200330694
...

최초 /rpc/span Request와 함께 57b792f200330694 라는 TraceID와 SpanID가 생성됬다.

# Service2(context) logs
...
2023-09-26 17:00:02.898  INFO [context,57b792f200330694,9e7ffc6d96f86dcf] 39720 --- [nio-8888-exec-1] c.a.c.controller.ContextController       : getSpanId() Start
2023-09-26 17:00:02.898  INFO [context,57b792f200330694,9e7ffc6d96f86dcf] 39720 --- [nio-8888-exec-1] c.a.c.controller.ContextController       : trace.spanId=9e7ffc6d96f86dcf
2023-09-26 17:00:02.899  INFO [context,57b792f200330694,9e7ffc6d96f86dcf] 39720 --- [nio-8888-exec-1] c.a.c.controller.ContextController       : trace.traceId=57b792f200330694
2023-09-26 17:00:05.092  WARN [context,57b792f200330694,9e7ffc6d96f86dcf] 39720 --- [nio-8888-exec-1] c.a.c.controller.ContextController       : rpcClient.getSearchResult() got error
...

[applicationName, traceId, spanId] 구조로 로깅되는것을 확인할 수 있다. Service2는 Service1에서 보내온 traceId를 쥐고 있으며 별도의 span을 생성한것을 확인 할 수 있다.

최종적으로 UI에서 확인하면 하나의 TraceId로 3개의 Span이 생성된것을 확인 할 수 있었다.
각 Span당 막대가 생겼고 각 span을 클릭하면 span이 가진 정보와 annotation들을 확인 할 수 있다. 이를 통해 3번째 Span에서 오류가 발생했다는것도 Tags를 통해 확인 할 수 있다.

또 zipkin에 대해서 설명할때 언급하였듯이 Dependencies탭을 통해서 서비스 영향도를 시각화하여 볼수있었다. 예시 프로젝트는 2개의 서비스가 단방향으로 이루어진 형태를 보였으나, 현업에서 여러개의 마이크로서비스를 사용하고있다면 어떤 서비스가 영향도가 큰지 한눈에 파악이 용이할것으로 보인다.

별도의 설정 없이 Zipkin Storage에 저장된 data들은 in-memory에 저장되어 docker가 종료되면서 같이 사라진다.

Line opentracing with zipkin

근데 로깅 포맷이 다른 블로그에서 본것과 다른데?

블로그에서 보던 로깅은 [appname,traceId,spanId,exportable]의 형태였는데 내 콘솔에서는 왜 이렇게 나오는지 궁금했다.
현재 각 모듈들은 Spring Cloud BOM에 의해 의존성이 관리되고있고 2021.0.1버전으로 설정되었으며 spring-cloud-sleuth는 3.1.1을 사용하고있다.
java-spring-sleuth-zipkin-x-span-export-not-being-displayed의 내용을 보면 3.0.0 버전에서 exportable디스플레이가 제거되었다고 나오는데 정확하게 코드로 확인하기 위해 TraceEnvironmentPostProcessor 파일을 찾아보았다.

// spring-cloud-sleuth 2.2.8
public class TraceEnvironmentPostProcessor implements EnvironmentPostProcessor {

    private static final String PROPERTY_SOURCE_NAME = "defaultProperties";

    @Override
    public void postProcessEnvironment(ConfigurableEnvironment environment,
            SpringApplication application) {
        Map<String, Object> map = new HashMap<String, Object>();
        // This doesn't work with all logging systems but it's a useful default so you see
        // traces in logs without having to configure it.
        if (sleuthEnabled(environment)
                && sleuthDefaultLoggingPatternEnabled(environment)) {
            map.put("logging.pattern.level", "%5p [${spring.zipkin.service.name:"
                    + "${spring.application.name:}},%X{X-B3-TraceId:-},%X{X-B3-SpanId:-},%X{X-Span-Export:-}]");
        }
        addOrReplace(environment.getPropertySources(), map);
    }
...

3.0.0 바로 전버전인 2.2.8버전의 설정을 보면 별도의 설정이 없더라도 로깅패턴을 [appname,traceId,spanId,exportable] 로 변경하는것을 확인 할 수 있었다.

// spring-cloud-sleuth 3.1.1
class TraceEnvironmentPostProcessor implements EnvironmentPostProcessor {  

    static final String PROPERTY_SOURCE_NAME = "defaultProperties";  

    @Override  
    public void postProcessEnvironment(ConfigurableEnvironment environment, SpringApplication application) {  
       Map<String, Object> map = new HashMap<String, Object>();  
       // This doesn't work with all logging systems but it's a useful default so you see  
       // traces in logs without having to configure it.      
       if (Boolean.parseBoolean(environment.getProperty("spring.sleuth.enabled", "true"))) {  
          map.put("logging.pattern.level",  
                "%5p [${spring.zipkin.service.name:" + "${spring.application.name:}},%X{traceId:-},%X{spanId:-}]");  
          String neverRefereshables = environment.getProperty("spring.cloud.refresh.never-refreshable",  
                "com.zaxxer.hikari.HikariDataSource");  
          map.put("spring.cloud.refresh.never-refreshable",  
                neverRefereshables + ",org.springframework.cloud.sleuth.instrument.jdbc.DataSourceWrapper");  
       }       addOrReplace(environment.getPropertySources(), map);  
    }

spring.sleuth.enabled가 true일때만 로깅패턴을 변경하는것으로 코드가 수정되었다. 나는 yml에 별도로 설정을 하지 않았는데 왜 로깅패턴이 변경되었지 싶었는데 defalut값이 true였다.

spring-configuration-metadata.json
...
{  
  "name": "spring.sleuth.enabled",  
  "type": "java.lang.Boolean",  
  "sourceType": "org.springframework.cloud.sleuth.autoconfig.brave.SleuthProperties",  
  "defaultValue": true  
},
...

이렇게 직접 코드를 확인함으로써 왜 로깅패턴이 변경되었는지 확인 할 수 있었다.

---

마무리

이렇게 Spring-cloud-sleuth를 추가하여 context관리의 위임을 받은 brave.Tracer인터페이스에 의해 별도의 코딩 없이 context가 관리되는것을 확인해보았고, zipkin의 base-url로 전달되는 context정보를 토대로 zipkin UI에서 context정보를 볼 수 있었다.
다음엔 ELK를 간단하게 연동해보고 분산환경의 로깅을 알아볼 예정이다.