MdcInstrumenter fails to propagate correct mdc context for Micronaut client response logging

phillipdriver commented 1 year ago

Expected Behavior

MdcInstrumenter propagates correct mdc context per client request/responses for traceability purposes

Actual Behaviour

The MdcInstrumenter appears to propagate the mdc correctly the first time a client makes a request, however, on subsequent requests, the client response logging retains the context from the first request...? This makes traceability rather difficult.

The following shows the console output of the supplied sample project (Note: the tracing uuid is contained within the second square brackets of each log statement): 1st request - matching tracing id 16:03:31.476 [default-nioEventLoopGroup-1-3] [e58ea7bb-7e3f-4949-bc03-dff57628b85d] TRACE i.m.h.server.netty.NettyHttpServer - Server localhost:51864 Received Request: GET /api/v1/user/1/hello 16:03:31.478 [default-nioEventLoopGroup-1-3] [e58ea7bb-7e3f-4949-bc03-dff57628b85d] DEBUG i.m.h.s.netty.RoutingInBoundHandler - Request GET /api/v1/user/1/hello ... 16:03:31.505 [default-nioEventLoopGroup-1-4] [e58ea7bb-7e3f-4949-bc03-dff57628b85d] DEBUG i.m.h.client.netty.DefaultHttpClient - Sending HTTP GET to http://localhost:9090/some-service/user/1/name ... 16:03:31.575 [default-nioEventLoopGroup-1-4] [e58ea7bb-7e3f-4949-bc03-dff57628b85d] DEBUG i.m.h.client.netty.DefaultHttpClient - Received response 200 from http://localhost:9090/some-service/user/1/name ... 16:03:31.585 [default-nioEventLoopGroup-1-3] [e58ea7bb-7e3f-4949-bc03-dff57628b85d] DEBUG i.m.h.s.netty.RoutingInBoundHandler - Response 200 - GET /api/v1/user/1/hello

Second request - incorrect tracing ids for client response log statements 16:03:31.610 [default-nioEventLoopGroup-1-6] [776a2db3-357b-4a3d-ab40-46ba3b81e99b] TRACE i.m.h.server.netty.NettyHttpServer - Server localhost:51864 Received Request: GET /api/v1/user/1/hello 16:03:31.610 [default-nioEventLoopGroup-1-6] [776a2db3-357b-4a3d-ab40-46ba3b81e99b] DEBUG i.m.h.s.netty.RoutingInBoundHandler - Request GET /api/v1/user/1/hello ... 16:03:31.612 [default-nioEventLoopGroup-1-7] [776a2db3-357b-4a3d-ab40-46ba3b81e99b] DEBUG i.m.h.client.netty.DefaultHttpClient - Sending HTTP GET to http://localhost:9090/some-service/user/1/name ... 16:03:31.614 [default-nioEventLoopGroup-1-7] [e58ea7bb-7e3f-4949-bc03-dff57628b85d] DEBUG i.m.h.client.netty.DefaultHttpClient - Received response 200 from http://localhost:9090/some-service/user/1/name ... 16:03:31.615 [default-nioEventLoopGroup-1-6] [776a2db3-357b-4a3d-ab40-46ba3b81e99b] DEBUG i.m.h.s.netty.RoutingInBoundHandler - Response 200 - GET /api/v1/user/1/hello

For some reason, for every subsequent client request, the mdc context used when logging the client response, is the context from the very first client request...?

Steps To Reproduce

I have created a sample project to demonstrate the issue: https://github.com/phillipdriver/micronaut-mdc-issue

This sample project contains a simple Micronaut app with:

a @Controller with a GET method that returns a hello message
a HttpClient for retrieving a user name
a ChannelDuplexHandler to add and clear tracing ids to the MDC per server request
micronaut-tracing gradle dependency

The controller fetches a user name string from a downstream API and returns a hello message for said user name.

The logging format is (see logback.xml): %cyan(%d{HH:mm:ss.SSS}) %gray([%thread]) [%X{tracingId}] %highlight(%-5level) %magenta(%logger{36}) - %msg%n

git clone https://github.com/phillipdriver/micronaut-mdc-issue
Execute HelloControllerTest (https://github.com/phillipdriver/micronaut-mdc-issue/blob/main/src/test/java/com/example/api/v1/hello/HelloControllerTest.java) via IDE or ./gradlew build
Check application log statements paying close attention to the tracing uuid logged by the i.m.h.client.netty.DefaultHttpClient for the client response

Note: The log statements without a tracing id, are those created by the test - not the app..!

Environment Information

Mac OS 13.2.1
Corretto JDK 17

Example Application

https://github.com/phillipdriver/micronaut-mdc-issue

Version

3.9.1

mayank-pant commented 10 months ago

Happening with me too. Following this thread.

dstepanov commented 10 months ago

Getting the MDC propagated is very complicated, considering we have all kinds of even pools etc. The propagation was rewritten in v4 for that reason.

micronaut-projects / micronaut-core