feign icon indicating copy to clipboard operation
feign copied to clipboard

feign-micrometer: spanId/parentId information lost

Open maecval opened this issue 1 year ago • 3 comments

Hi all, We are logging the outgoing FeignClient requests in our Spring Boot applications. These logs include traceId, spanId and parentId. On the called service side the same information gets logged (e.g. when logging the incoming HTTP request). Since the migration to micrometer (i.e. Spring Boot 2.7 to Spring Boot 3.1/3.2 migration) the "chain of spanId" is missing.

Note: a sample application with minimal dependencies has been created to demonstrate the issue. The sample app provides a /doit endpoint which invokes its second endpoint /execute using a FeignClient.

in Spring Boot 2.7

Previous to the migration to micrometer it used to look like:

...
2024-02-01 13:24:18.189 DEBUG [traceId-demo,ac648962656d9825,ac648962656d9825,] 53547 --- [nio-8080-exec-1] o.s.w.f.CommonsRequestLoggingFilter      : Before request [GET /doit, headers=[host:"localhost:8080", user-agent:"curl/8.2.1", accept:"*/*"]]
2024-02-01 13:24:18.217  INFO [traceId-demo,ac648962656d9825,ac648962656d9825,] 53547 --- [nio-8080-exec-1] o.m.traceiddemo.TraceIdDemoApplication   : doIt()
2024-02-01 13:24:18.234 DEBUG [traceId-demo,ac648962656d9825,468b1628cf4058a1,ac648962656d9825] 53547 --- [nio-8080-exec-2] o.s.w.f.CommonsRequestLoggingFilter      : Before request [GET /execute, headers=[x-b3-traceid:"ac648962656d9825", x-b3-spanid:"468b1628cf4058a1", x-b3-parentspanid:"ac648962656d9825", x-b3-sampled:"1", accept:"*/*", user-agent:"Java/17.0.9", host:"localhost:8080", connection:"keep-alive"]]
2024-02-01 13:24:18.235  INFO [traceId-demo,ac648962656d9825,468b1628cf4058a1,ac648962656d9825] 53547 --- [nio-8080-exec-2] o.m.traceiddemo.TraceIdDemoApplication   : execute()
...

Where the parentId on the called server side is equals to the spanId logged on the client side. In the example above: ac648962656d9825

in Spring Boot 3.2

After the migration to micrometer i.e. Spring Boot 3.1/3.2 it looks like:

...
2024-02-01T13:29:17.941+01:00 DEBUG [traceId-demo,65bb8e9da8001e399361afdcea28771e,9361afdcea28771e,] 54088 --- [traceId-demo] [nio-8080-exec-1] [65bb8e9da8001e399361afdcea28771e-9361afdcea28771e] o.s.w.f.CommonsRequestLoggingFilter      : Before request [GET /doit, headers=[host:"localhost:8080", user-agent:"curl/8.2.1", accept:"*/*"]]
2024-02-01T13:29:17.965+01:00  INFO [traceId-demo,65bb8e9da8001e399361afdcea28771e,9361afdcea28771e,] 54088 --- [traceId-demo] [nio-8080-exec-1] [65bb8e9da8001e399361afdcea28771e-9361afdcea28771e] o.m.traceiddemo.TraceIdDemoApplication   : doIt()
2024-02-01T13:29:17.990+01:00 DEBUG [traceId-demo,65bb8e9da8001e399361afdcea28771e,bb68df5602dcb801,61609605eb741c8d] 54088 --- [traceId-demo] [nio-8080-exec-2] [65bb8e9da8001e399361afdcea28771e-bb68df5602dcb801] o.s.w.f.CommonsRequestLoggingFilter      : Before request [GET /execute, headers=[b3:"65bb8e9da8001e399361afdcea28771e-61609605eb741c8d-0-9361afdcea28771e", traceparent:"00-65bb8e9da8001e399361afdcea28771e-61609605eb741c8d-00", x-b3-parentspanid:"9361afdcea28771e", x-b3-sampled:"0", x-b3-spanid:"61609605eb741c8d", x-b3-traceid:"65bb8e9da8001e399361afdcea28771e", accept:"*/*", user-agent:"Java/17.0.9", host:"localhost:8080", connection:"keep-alive"]]
2024-02-01T13:29:17.990+01:00  INFO [traceId-demo,65bb8e9da8001e399361afdcea28771e,bb68df5602dcb801,61609605eb741c8d] 54088 --- [traceId-demo] [nio-8080-exec-2] [65bb8e9da8001e399361afdcea28771e-bb68df5602dcb801] o.m.traceiddemo.TraceIdDemoApplication   : execute()
...

Where the spanId 9361afdcea28771e logged on the client side is not present in the log on the server side.

Can this be configured? How can we get the whole "chain of spanId" back? It is very important to us so we can chain the logs correctly together.

Please find 2 samples in the attachment:

Just start the Spring Boot app and call the /doit endpoint:

curl http://localhost:8080/doit

Kind regards, Valentin

maecval avatar Feb 01 '24 12:02 maecval

I do have the same issue.

I do have Spring Cloud Gateway running and behind that several microservices. To all projects, I added the dependencies io.micrometer:micrometer-tracing and io.micrometer:micrometer-tracing-bridge-otel. Now the gateway creates a new traceId and forwards this id to the downstream microservices via the traceparent header. But the traceId is not forwarded when making feign calls from one microservice to another. For that i added io.github.openfeign:feign-micrometer to the microservice which makes the call. But unfortunately the traceId is still not passed on and no traceparent header is attached to the feign call.

The feign client is generated via the OpenAPI Generator from a swagger file.

What do i miss here?

HeneryHawk avatar Mar 11 '24 12:03 HeneryHawk

I had the same issue some weeks ago. Adding a TaskDecorator Bean and setting it to the taskDecorator of the threadPoolTaskExecutor Bean worked for me.

 @Bean
    fun taskDecorator(): TaskDecorator {
        return TaskDecorator { runnable: Runnable? ->
            ContextSnapshot.captureAll(*arrayOfNulls(0)).wrap(
                runnable!!,
            )
        }
    }

@Bean
    fun threadPoolTaskExecutor(): ThreadPoolTaskExecutor = ThreadPoolTaskExecutor().apply {
        setTaskDecorator(taskDecorator())
    }

ysbc1247 avatar Apr 25 '24 05:04 ysbc1247