revisiting MDC in slf4j broken because of CompletableFuture

[Dean Hiller]

slf4j is pretty much the defacto logging standard these days allowing one
to bring in libraries using any logging framework.  (commons logging fell
short and had classloading bugs).

Summary: MDC works fine in twitter scala Futures but not java
CompletableFutures.

Unfortunately, one of the best features(brought over from log4j which is
also broken now) is the MDC. The MDC no longer works with
CompletableFutures so people will have to move to scala where it does work.

Documentation on MDC if you don't know what that is....
https://logback.qos.ch/manual/mdc.html

or for a more concrete example, as a developer a request comes in and you
set MDC.put("requestId", requestId) and now whenever you log, that request
id is added to your log line.  No developer has to 'remember' to add it
every time he adds a log statement.

This is due to the lack of Local.java file that should exist and transfer
context over the .thenApply/.thenCompose methods like twitter Futures has
in scala land. (see Local.scala in twitter Futures and the twitter Future
code for how this works)

In scala, it works and we have all the same methods as CompletableFuture
for the most part and yes, we can't transfer the context over some methods,
but at least our MDC in scala servers is not broken.

Lack of this feature is forcing our hand to code in scala where it is not
broken.  ie. we need logging and we definitely need the request id or
client id or whatever attached automatically to every log(as humans have
trouble remembering to add it themselves every single time).

thanks for reconsidering,
Dean

On Tue, May 23, 2017 at 10:20 AM, Dean Hiller <dhiller at twitter.com> wrote:

> All, this post is all about 3rd party code that I do not control so
> therefore the solutions above do not work as those libraries may predate my
> library.  more specifically.....
>
> Martin,
>    If I roll my own slf4j MDC only works in my code and stops working in
> 3rd party code!  because the 3rd party code does not transfer the context.
>
> Viktor,
>   You hit the head on the nail with "It's easy to lose context when
> intermediate libraries/Executors".  This is solved on twitter futures until
> we hit libraries not using twitter futures because no matter the executor,
> the future transfers the context for us the way it was written.
>
>    "It's unclear what fan-in behaviors like zip, merge etc mean in terms
> of what the local values should be?"
> This is a very good question.  I wonder what twitter futures do here.  I
> would be ok with dropping the context in this case or combining it.  I do
> not really care yet here since I have not run into it but it is a very good
> question and would need a lot of thought
>
> Josh,
>    I cannot expect all 3rd party libraries that are brought in will be
> using ContextPropagatingExecutor so that solution breaks down as Viktor
> eludes to.
>
> Alex,
>    tuples do not solve the issue.  in fact twitter futures have a
> Local.scala file that does solve the issue.  The main issue is 3rd party
> code and having the context continue into "unknown code" using
> CompletableFuture.  I cannot control that code BUT want every log.info in
> that code to use and log the request id.  it is awesome at twitter as I can
> just follow that request id in the logs.  If CompletableFuture had such a
> context, I could transfer this info into it and into the 3rd party java
> libraries.
>
> I am writing a webserver for fun based on CompletableFutures and therefore
> cannot control the controllers as the app developer writes that and the
> request id stops getting logged on the request path which is mostly
> .thenApply and .thenCompose.  even if the Controllers do you my future,
> they will bring in libraries NOT using my future :(
>
> thanks
> Dean
>
>
>
>
>
> On Tue, May 23, 2017 at 3:12 AM, Alex Otenko <oleksandr.otenko at gmail.com>
> wrote:
>
>> Why would someone want to rely on state they cannot control?
>>
>> Is the idea to subvert some API that does not provide a way to pass
>> state? This is strange especially in the context of Scala, where you can
>> easily form tuples.
>>
>> Alex
>>
>> On 22 May 2017, at 20:44, Martin Buchholz <martinrb at google.com> wrote:
>>
>> There's not likely to be any support for local context anywhere in
>> java.util.concurrent, but it seems not too hard to roll your own support
>> with a custom executor to be used with CompletableFuture that kept track of
>> any local context.
>>
>> On Fri, May 19, 2017 at 1:16 PM, Pavel Rappo <pavel.rappo at oracle.com>
>> wrote:
>>
>>> General questions on concurrency in Java should be asked here:
>>>
>>>    http://altair.cs.oswego.edu/mailman/listinfo/concurrency-interest
>>>
>>> > On 18 May 2017, at 21:57, Dean Hiller <dhiller at twitter.com> wrote:
>>> >
>>> > Way more detail here...
>>> >
>>> > http://stackoverflow.com/questions/37933713/does-completable
>>> future-have-a-corresponding-local-context
>>> >
>>> > So I was wondering if this was going to be added at some point to the
>>> jdk
>>> > as I could not figure out how to set something so it was still
>>> available on
>>> > the thread at a later time when traversing async thenCompose,
>>> thenAccept.
>>> >
>>> > thanks,
>>> > Dean
>>>
>>>
>> _______________________________________________
>> Concurrency-interest mailing list
>> Concurrency-interest at cs.oswego.edu
>> http://cs.oswego.edu/mailman/listinfo/concurrency-interest
>>
>>
>>
>