Retrofit: MDC context is not passed correctly to retrofit client when using suspend functionality (coroutine)

[niom]

What kind of issue is this?

• [X] Bug report. If you’ve found a bug, spend the time to write a failing test. Bugs with tests
  get fixed. Failing test setup is found from here: https://github.com/niom/retrofit2_mdc_sample/blob/master/src/test/kotlin/FailingMdcContextTest.kt

I faced a problem with latest retrofit with Kotlin suspend functions and passing MDC parameters to retrofit.

Problem is that when the MDC has parameters that I would like to see logged for tracing the calls in a transaction the retrofit logging will lose the MDC parameters when using the suspend functions.

Weird thing is that when the same call is done while using Call and a blocking resolving it with the execute method the MDC context is preserved so my best guess is that this has something to do with sharing the coroutineContext is not shared correctly with the kotlin application and retrofit client.

I see that there is a PR open for improving the CoroutineContext sharing. I haven’t tried that yet but I will comment if it changes anything in my sample application that I made. https://github.com/square/retrofit/pull/3240

Here's the brief code example what I'm trying to achieve. Full example in the link above to the test repository.

    interface SampleClient {
        @GET("/api/call")
        suspend fun getSomething(): ResponseBody

        @GET("/api/call")
        fun getSomethingWithCall() : Call<ResponseBody>
    }

    @Test
    fun suspendClientLogEventsShouldContainMdcId() {
       ...
        val client = createRetrofitClient(mockWebServer)
        runBlocking {
            MDC.putCloseable("txId", expectedTxId).run {
                log.info("Message")
                client.getSomething()
            }
        }
     ....
    }

    @Test
    fun callClientLogEventsShouldContainMdcId() {
        ....
        val client = createRetrofitClient(mockWebServer)
        runBlocking {
            MDC.putCloseable("txId", expectedTxId).run {
                log.info("Message")
                client.getSomethingWithCall().execute()
            }
        }
     ....
    }

       fun createRetrofitClient(mockServer: MockWebServer): SampleClient {
        return Retrofit.Builder()
            .baseUrl(mockServer.url("/"))
            .client(
                createOkHttpClient()
            )
            .build()
            .create(SampleClient::class.java)

    }

    fun createOkHttpClient(): OkHttpClient {
        val logging = HttpLoggingInterceptor { message ->
            log.info(message)
        }
        logging.setLevel(HttpLoggingInterceptor.Level.BASIC)
        return OkHttpClient.Builder()
            .addInterceptor(logging)
            .build()
    }

logback.xml

<configuration scan="false">
    <appender name="STDOUT" class="ch.qos.logback.core.ConsoleAppender">
        <encoder>
            <pattern>%date %level tx-id=%X{txId} [%file:%line] %msg %n</pattern>
        </encoder>
    </appender>

    <root level="DEBUG">
        <appender-ref ref="STDOUT"/>
    </root>
</configuration>

The first test will produce the following output to log:
MDC txId is missing from the client calls.

2021-01-16 18:22:25,077 INFO tx-id=6f9456e6-aab8-44c3-b846-6f6c40d1773d [FailingMdcContextTest.kt:56] Message
2021-01-16 18:22:25,098 INFO tx-id= [FailingMdcContextTest.kt:115] --> GET http://localhost:56406/api/call
2021-01-16 18:22:25,121 INFO tx-id= [FailingMdcContextTest.kt:115] <-- 200 OK http://localhost:56406/api/call (23ms, 0-byte body)

The second test will produce the following output to log:
MDC txId is present in the client calls.

2021-01-16 18:32:20,854 INFO tx-id=a4d2e9f9-54aa-452f-a31c-e7c88dd1085b [FailingMdcContextTest.kt:83] Message 
2021-01-16 18:32:20,870 INFO tx-id=a4d2e9f9-54aa-452f-a31c-e7c88dd1085b [FailingMdcContextTest.kt:114] --> GET http://localhost:56468/api/call 
2021-01-16 18:32:20,894 INFO tx-id=a4d2e9f9-54aa-452f-a31c-e7c88dd1085b [FailingMdcContextTest.kt:114] <-- 200 OK http://localhost:56468/api/call (24ms, 0-byte body) 

[JakeWharton]

This is mostly expected since we use OkHttp's enqueue method, not execute. The internals are not based on coroutines. If the linked PR is rebased and merged you would still need to unpack the context manually inside the interceptor.

[swankjesse]

Yep! The fix for this looks like a CallAdapter that works with an Interceptor. The CallAdapter stashes MDC stuff into the request, and the interceptor unpacks it and applies it to whichever thread ends up performing the async request.

[niom]

Thanks for the information. I'll poke around with the CallAdapter and Interceptor path a little. I'll get back to this after I have more familiar with the CallAdapter concept.

[niom]

Ok I have the basic understanding of this.

I can create a basic CallAdaptor and Factory but I have difficulties to figure out how to put the MDC context to the request in CallAdapters adapt method.

The closest I got was to create an anonymous inner class extending the retrofit2.Call and then just wrapping the original call to that and then trying to modify the Request but request it self is a final class and cannot be extended.

Recreating the Request by using the Request.Builder and then trying to hack the MDC context to the Request.tag is also a dead end. At the interceptor the request in chain does not have the MDC context copy in it any more.

I have a strong feeling that I'm trying to over engineer and extending the whole Call feels just a little over kill.

@swankjesse how can I stash the MDC context to the request since it's final?

I created a branch to my repository: call-adapter that contains my trial and error.

[niom]

Since this is not a bug I don't see a lot of value to keep this open here. For me this now feels more like a question to Stackoverflow.

Also this is not a problem for our project anymore since we figured out a way to make handle the MDC context by using Call as the retrofit return type and then resolving it inside a Java Callable runner with MDC context.

Does it feel right: No
Does it do the job: Yes