spring sleuth Executor를 bean으로 생성했을때 traceId가 공유되는 방식

오늘은 간단한 내용을 작성해보려 합니다.

 

Spring 에서 로그 추적을 위해 traceId를 남기고자 sleuth를 사용하고 있습니다.

운영과정에서 일부 비동기 로직에서 traceId가 남지않는것을 확인하였고, 이 부분에 대해 확인한것을 기록하고자 합니다.

 

사실 해결법은 매우 간단하지만(검색하면 바로) 왜 동작하는지는 알고 바꾸고자 한번 작성하게되었습니다.

 

먼저 bean으로 생성하는경우를 확인하고자 합니니다.

   @Bean(name = "예시니까 세팅은 전부 1")
    public Executor threadPoolTaskExecutor() {
        ThreadPoolTaskExecutor taskExecutor = new ThreadPoolTaskExecutor();
        taskExecutor.setCorePoolSize(1);
        taskExecutor.setMaxPoolSize(1);
        taskExecutor.setQueueCapacity(1.);
        taskExecutor.setThreadNamePrefix("test-");
        taskExecutor.initialize();
        return taskExecutor;
    }

다음과 같은 로직을 통하여 Executor를 생성하는경우, 그리고 sleuth를 dependency에 가지고 있는 경우, 

 

sleuth package에 있는 다음 클레스를 통해 빈 등록과정에서 조금 특이한 과정을 거치게 됩니다.
아래는 그 코드의 설정 부분을 가져왔습니다.

/**
 * Bean post processor that wraps a call to an {@link Executor} either in a JDK or CGLIB
 * proxy. Depending on whether the implementation has a final method or is final.
 *
 * @author Marcin Grzejszczak
 * @author Jesus Alonso
 * @author Denys Ivano
 * @author Vladislav Fefelov
 * @since 1.1.4
 */
class ExecutorBeanPostProcessor implements BeanPostProcessor {
.....
	@Override
	public Object postProcessAfterInitialization(Object bean, String beanName)
			throws BeansException {
		if (bean instanceof LazyTraceThreadPoolTaskExecutor
				|| bean instanceof TraceableScheduledExecutorService
				|| bean instanceof TraceableExecutorService
				|| bean instanceof LazyTraceAsyncTaskExecutor
				|| bean instanceof LazyTraceExecutor) {
			log.info("Bean is already instrumented " + beanName);
			return bean;
		}
		if (bean instanceof ThreadPoolTaskExecutor) {
			if (isProxyNeeded(beanName)) {
				return wrapThreadPoolTaskExecutor(bean);
			}
			else {
				log.info("Not instrumenting bean " + beanName);
			}
		}
		else if (bean instanceof ScheduledExecutorService) {
			if (isProxyNeeded(beanName)) {
				return wrapScheduledExecutorService(bean);
			}
			else {
				log.info("Not instrumenting bean " + beanName);
			}
		}
		else if (bean instanceof ExecutorService) {
			if (isProxyNeeded(beanName)) {
				return wrapExecutorService(bean);
			}
			else {
				log.info("Not instrumenting bean " + beanName);
			}
		}
		else if (bean instanceof AsyncTaskExecutor) {
			if (isProxyNeeded(beanName)) {
				return wrapAsyncTaskExecutor(bean);
			}
			else {
				log.info("Not instrumenting bean " + beanName);
			}
		}
		else if (bean instanceof Executor) {
			return wrapExecutor(bean);
		}
		return bean;
	}
.....
}

보면 빈을 등록하는 과정에서 각 Executor를 생성하는 로직이 들어있습니다. 

제가 설정한건 ThreadPoolTaskExecutor 였으니 이 내부에 생성하는 로직을 보면 다음과 같이 LazyTraceThreadPoolTaskExecutor

를 생성하는 로직이 있습니다.

Object createThreadPoolTaskExecutorProxy(Object bean, boolean cglibProxy,
    ThreadPoolTaskExecutor executor) {
  if (!cglibProxy) {
    return new LazyTraceThreadPoolTaskExecutor(this.beanFactory, executor);
  }
  return getProxiedObject(bean, cglibProxy, executor,
      () -> new LazyTraceThreadPoolTaskExecutor(this.beanFactory, executor));
}

그러면 LazyTraceThreadPoolTaskExecutor에서 execute할때 무슨 동작이 일어날까 해서 보았더니 아래 코드와 같이 bean에서 Tracing을 꺼내와 사용합니다.

@Override
public void execute(Runnable task) {
  this.delegate.execute(ContextUtil.isContextUnusable(this.beanFactory) ? task
      : new TraceRunnable(tracing(), spanNamer(), task));
}

private Tracing tracing() {
  if (this.tracing == null) {
    this.tracing = this.beanFactory.getBean(Tracing.class);
  }
  return this.tracing;
}

 

이러한 설정 덕분에 bean으로 초기 생성한경우, 별도의 설정없이도 각 thread간 traceId가 잘 유지되는데요. 

 

 

그렇다면 운영중에는 대체 왜 traceId가 전파가 안되었을까 하여 찾아보는 도중.. 각 @Component에서 threadPool을 생성하여 사용하는 로직을 발견했습니다.  예를 들자면..

 this.executorService = (ThreadPoolExecutor) Executors.newFixedThreadPool(1); // 예시니까 1

bean 생성자에 요런건 생성해두고 이런 thread를 사용하는 코드들이 남아있었고.. 공교롭게 이코드가 대부분의 로그를 찍고있었고 이를 이유로 traceId가 정상적으로 노출이 안되는 문제가 발생했었습니다.

 

이부분을 ThreadPoolExecutor를  bean으로 생성하여 주입하는 방식으로 문제를 해결하였습니다.