Using logging MDC type functionality with vertx.

[javadevmtl]

When using something like log4j you can put stuff on the MDC and NDC, but these are thread based. Since in vertx each thread can handle more then one request we simply can't just push/pop stuff on/off the MDC/NDC.

Is there a way to be able to share some common data between verticles and a single "application request" to achieve MDC/NDC like functionslity?

[javadevmtl]

Am I the only one who thinks this is an issue?

[Tim Fox]

Why do you mean by "application request", I think it would help if you explained the "issue" a bit more, as I don't have a clear understanding at this point. Perhaps illustrate with some examples?

[javadevmtl]

Well basically, have some kind of MDC/NDC functionality of log4j but for vertx "context" (just thinking out loud here not sure this where it would go or even possible).

So for instance when you receive an HTTP request you can log 

- The actual request, maybe the headers

- Log some steps of the actual business execution

- Log maybe some debug info

- Maybe log the query made to a "database"

- Log the response

So this particular request has 5 logs entries that are logged at various levels of the application I.e: inside the web handler, maybe inside the "business" handler, etc...

Now lets say you want to associate those 5 log entries to a particular user or tag each log for a specific request with a UUID.

With log4j you can push a common value onto the MDC/NDC and all subsequent log entries will be tagged with that value. One you are done with that request you pop the value of the MDC. Unfortunately lo4j MDC/NDC works by thread, since with vertx multiple requests can be received on the same event loop/thread you cannot push/pop values on to the log4j MDC/NDC.

So

public void myRoute(RoutingContext rc) {

   String uuid = ....

   JsonObject request = rc.getBodyAsJsonObject();

   logger.info("UUID: {}, Request received: {}", uuid, request.encode());

   myService.doSomething(uuid, request, result -> {

       logger.info("UUID: {}, Processed", uuid);

   })

}

We have to pass UUID everywhere and make sure we tag each log with it.

[Tim Fox]

On Wednesday, 7 June 2017 18:46:38 UTC+1, javadevmtl wrote:

Well basically, have some kind of MDC/NDC functionality of log4j but for vertx "context" (just thinking out loud here not sure this where it would go or even possible).

So for instance when you receive an HTTP request you can log 

- The actual request, maybe the headers

- Log some steps of the actual business execution

- Log maybe some debug info

- Maybe log the query made to a "database"

- Log the response

So this particular request has 5 logs entries that are logged at various levels of the application I.e: inside the web handler, maybe inside the "business" handler, etc...

Now lets say you want to associate those 5 log entries to a particular user or tag each log for a specific request with a UUID.

With log4j you can push a common value onto the MDC/NDC and all subsequent log entries will be tagged with that value. One you are done with that request you pop the value of the MDC. Unfortunately lo4j MDC/NDC works by thread, since with vertx multiple requests can be received on the same event loop/thread you cannot push/pop values on to the log4j MDC/NDC.

As you point out, the concept of assumes the same thread is exclusive used for the lifetime of the system. This isn't true in any async system (this is not specific to Vert.x), so, in the absence of a thread to tie things together you need something else to tie things together for the lifetime of the request. In vertx-web that thing is called the RoutingContext, but you could use any object to do this.

Outside of vertx-web it's not possible to provide some generic functionality as the concept of "request" is completely application defined and nothing something Vert.x can know about.

[Tim Fox]

On Wednesday, 7 June 2017 20:13:12 UTC+1, Tim Fox wrote:

On Wednesday, 7 June 2017 18:46:38 UTC+1, javadevmtl wrote:

Well basically, have some kind of MDC/NDC functionality of log4j but for vertx "context" (just thinking out loud here not sure this where it would go or even possible).

So for instance when you receive an HTTP request you can log 

- The actual request, maybe the headers

- Log some steps of the actual business execution

- Log maybe some debug info

- Maybe log the query made to a "database"

- Log the response

So this particular request has 5 logs entries that are logged at various levels of the application I.e: inside the web handler, maybe inside the "business" handler, etc...

Now lets say you want to associate those 5 log entries to a particular user or tag each log for a specific request with a UUID.

With log4j you can push a common value onto the MDC/NDC and all subsequent log entries will be tagged with that value. One you are done with that request you pop the value of the MDC. Unfortunately lo4j MDC/NDC works by thread, since with vertx multiple requests can be received on the same event loop/thread you cannot push/pop values on to the log4j MDC/NDC.

As you point out, the concept of assumes the same thread is exclusive used for the lifetime of the system.

Sorry, that was a bit garbled! Meant to say: "the concept of MDC assumes the same thread is exclusively used for the lifetime of the request".

[Alexander Lehmann]

The MDC/NDC construct uses the current thread to store the objects, either in log4j 1.x or slf4j, but log4j2 2.7 has a construct to be able to use something other than the current thread to store the info, that should be possible to use the current context. (https://logging.apache.org/log4j/2.x/manual/thread-context.html)

This would mean that you have to use log4j2 and cannot use the vertx logger (but that doesn't a MDC anyway)

[Tim Fox]

On Wednesday, 7 June 2017 20:24:33 UTC+1, Alexander Lehmann wrote:

The MDC/NDC construct uses the current thread to store the objects, either in log4j 1.x or slf4j, but log4j2 2.7 has a construct to be able to use something other than the current thread to store the info, that should be possible to use the current context. (https://logging.apache.org/log4j/2.x/manual/thread-context.html)

The context is not the right place for this, and in any case you already have the ability to get and set data there.

A vert.x context is typically tied to a verticle instance. During the lifetime of a single request the same context can handle many different requests (and do many other things). If the goal here is to tie things together at a request level, the context is not going to help.

[javadevmtl]

So I guess no choice we have to pass around that common data through the layers... 

[Tim Fox]

On Wednesday, 7 June 2017 20:35:15 UTC+1, javadevmtl wrote:

So I guess no choice we have to pass around that common data through the layers... 

Yes, you either have to pass it explicitly or, if it can be passed implicitly if you have lambdas closing over variables in its declaring scope.

[Alexander Lehmann]

You're right that doesn't work.

[Garrick Olson]

I also consider these to be important use cases, and was a little surprised how hard it is to do. I have had some success using the slf4j MDC (and log4j underneath) for these purposes. Vertx doesn't guarantee you will have exclusive access to threads, but as Tim noted it does have certain guarantees around lambdas. You can control values in the MDC for logging to use as long as you are careful about cases where you might get transferred onto another thread, such as calls to executeBlocking().

I put some utilities in my database access code you might be able to use:

https://github.com/susom/database/blob/master/src/main/java/com/github/susom/database/VertxUtil.java

If you play around with that database library, you can see it logs database operations using slf4j and propagates the MDC through all operations. I use those same utilities in my other code, which also works, but obviously this approach doesn't help when your third party libraries make blocking calls and the like off the original event thread.

I've been tempted to try modifying the vertx code for executeBlocking() to call new hooks in the logging spi (LogDelegateFactory?) to optionally save/restore state similarly. Seems it could work, but I haven't tried yet.

[Tim Fox]

Hi Garrick,

On Thursday, 8 June 2017 08:02:09 UTC+1, Garrick Olson wrote:

I also consider these to be important use cases, and was a little surprised how hard it is to do.

I don't think it should be surprising. MDC, by definition, requires thread affinity. So if you don't have that, it's not going to work. Btw, that's nothing specific to Vert.x, it would be the same in any async system. MDC only works with an "old school" thread per request model, which hopefully is a dying breed.

 

I have had some success using the slf4j MDC (and log4j underneath) for these purposes. Vertx doesn't guarantee you will have exclusive access to threads, but as Tim noted it does have certain guarantees around lambdas.

This isn't a Vert.x guarantee. It's a consequence of the Java language. Any lambda (closure) will capture effectively final variables from it's declaring scope.It's just how Java works and you can do it in any Java program, with or without Vert.x :)

[Tim Fox]

On Wednesday, 7 June 2017 20:41:23 UTC+1, Tim Fox wrote:

On Wednesday, 7 June 2017 20:35:15 UTC+1, javadevmtl wrote:

So I guess no choice we have to pass around that common data through the layers... 

Yes, you either have to pass it explicitly or, if it can be passed implicitly if you have lambdas closing over variables in its declaring scope.

Or... forgot to add.. if you are using vertx-web you already have a context that is passed for you into every handler (RoutingContext) which is designed for any request scoped data. Obvs this is specific to the web use case though.

[Garrick Olson]

On Thursday, June 8, 2017 at 12:09:53 AM UTC-7, Tim Fox wrote:

I don't think it should be surprising.

Of course not. You understand vertx too well. :)

 

MDC, by definition, requires thread affinity. So if you don't have that, it's not going to work. Btw, that's nothing specific to Vert.x, it would be the same in any async system. MDC only works with an "old school" thread per request model, which hopefully is a dying breed.

I understand MDC uses thread state, but that doesn't mean everything has to be tied to one thread or be synchronous. It just means whoever is managing threads needs to worry about how MDC state gets copied around. If I spin up a worker thread I copy the current MDC to the worker. If I use a thread pool, I set MDC state before the pooled thread starts its task (or better yet, implement it in the thread pool).

Vertx knows about all of the threads and facilitates the hand-offs between threads. Since it also knows about slf4j (provides built-in support), what surprised me was that Vertx made no attempt to copy MDC state around when moving between threads. Maybe I am missing something, but I don't see why it couldn't do that to provide better compatibility with existing code and libraries. The fact that it doesn't can be difficult to work-around because third party code might call executeBlocking() and I don't see a way to intercept or customize how thread state is initialized or cleaned up.

This isn't a Vert.x guarantee. It's a consequence of the Java language. Any lambda (closure) will capture effectively final variables from it's declaring scope.It's just how Java works and you can do it in any Java program, with or without Vert.x :)

True enough. I was beginning to doubt that part of the spec when debugging MDC work-arounds, but then I discovered runOnContext(), and the world made sense again. :)

[Tim Fox]

On Thursday, 8 June 2017 10:04:13 UTC+1, Garrick Olson wrote:

On Thursday, June 8, 2017 at 12:09:53 AM UTC-7, Tim Fox wrote:

I don't think it should be surprising.

Of course not. You understand vertx too well. :)

 

MDC, by definition, requires thread affinity. So if you don't have that, it's not going to work. Btw, that's nothing specific to Vert.x, it would be the same in any async system. MDC only works with an "old school" thread per request model, which hopefully is a dying breed.

I understand MDC uses thread state, but that doesn't mean everything has to be tied to one thread or be synchronous. It just means whoever is managing threads needs to worry about how MDC state gets copied around. If I spin up a worker thread I copy the current MDC to the worker. If I use a thread pool, I set MDC state before the pooled thread starts its task (or better yet, implement it in the thread pool).

Vertx knows about all of the threads and facilitates the hand-offs between threads. Since it also knows about slf4j (provides built-in support), what surprised me was that Vertx made no attempt to copy MDC state around when moving between threads. Maybe I am missing something, but I don't see why it couldn't do that to provide better compatibility with existing code and libraries.

Can you give a specific example of what you think Vert.x should do, that it currently doesn't do, using some code? Just so I can understand what you're saying a bit better.

[Garrick Olson]

On Thursday, June 8, 2017 at 2:29:02 AM UTC-7, Tim Fox wrote:

Can you give a specific example of what you think Vert.x should do, that it currently doesn't do, using some code? Just so I can understand what you're saying a bit better.

When slf4j is being used, vertx could implement the various executeBlocking() calls more like this:

 

https://github.com/susom/database/blob/master/src/main/java/com/github/susom/database/VertxUtil.java

I could imagine instead of hard-coding slf4j stuff, it could delegate some of that to whichever logging system is in use.

Here is test I was using to verify the MDC behavior with handlers and timers and multiple nested asynchronous calls:

https://github.com/susom/database/blob/master/src/test/java/com/github/susom/database/test/VertxLoggingTest.java#L96

[Tim Fox]

A wrapping of handlers approach like this could work, but for Vert.x to do something like this for you automatically would be tricky:

1. It would require huge changes in the codebase. Everywhere in the Vert.x API (and APIs of any Vert.x stack projects) where you provide a handler to a method would have to be changed, the current "request context" intercepted and saved, and the handler wrapped. 

2. Vert.x currently doesn't know about SLF4j (other than the SLF4J logger factory impl) - 

it wouldn't be good for Vert.x to be tightly coupled to SLF4J.

3. These would impose an overhead on the majority of users who don't care about MDC.

Having said that, there might be a case for some kind of generic "CallerContext" that can be passed from handler to handler, and in that you could place your logging context. That would suffer from the problem of 1 though.

There's no harm in adding a feature request, and see what the core team think.

[Julien Viet]

Hi,

I have in mind for the near future (3.5?) to provide a facility to achieve this, it is actually related to enable distributed tracing use case.

Internally, Vert.x would require changes related to allow this (basically now AsyncResult are constructed, timers and runOnContext).

Vert.x itself would not implement this use case but provide hooks to implement this kind of use cases. When not implement these hooks would provide no overhead.

Julien

-- 
You received this message because you are subscribed to the Google Groups "vert.x" group.
To unsubscribe from this group and stop receiving emails from it, send an email to vertx+un...@googlegroups.com.
Visit this group at https://groups.google.com/group/vertx.
To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/d0a888ea-8162-4a5d-aef4-ff3886404f29%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Tim Fox]

On Thursday, 8 June 2017 12:39:04 UTC+1, Julien Viet wrote:

Hi,

I have in mind for the near future (3.5?) to provide a facility to achieve this, it is actually related to enable distributed tracing use case.

Internally, Vert.x would require changes related to allow this (basically now AsyncResult are constructed, timers and runOnContext).

There's also the streaming case to consider as well as one shot results - e.g. getting a HttpClientResponse bodystream or stream from a file -presumably the user would expect the CallerContext to be set in this case too.

 

To unsubscribe from this group and stop receiving emails from it, send an email to vertx+unsubscribe@googlegroups.com.

[Julien Viet]

btw as Tim said, providing support for this might be challenging and bring complexity in Vert.x.

There is an existing discussion about it in a thread related to distributed tracing.

So I’m if favor of this only if the complexity added remains reasonable and the use cases it enables can be fully implemented.

[Sandeep Dugar]

Hi,
Has this been included in the 3.5 release?

[Pratik Panchal]

Is there any update on this topic? I'm looking to greatly help improve logging readability with this exact feature.

Let me know if this conversation has been moved to somewhere else (another threadgithub issue, etc.) which I can follow.

Thanks!

[Julien Viet]

Hi,

the current status is that we have a proto branch for 3.6 but it will rather target 4.0 

Julien

To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/feb601fd-8c67-4dfa-8ba2-2b1efb3cd358%40googlegroups.com.

[Julien Viet]

Hi,

here is the link to the most up to date information

https://github.com/vert-x3/wiki/wiki/RFC:-continuation-instrumentation

Julien

--
You received this message because you are subscribed to the Google Groups "vert.x" group.
To unsubscribe from this group and stop receiving emails from it, send an email to vertx+un...@googlegroups.com.
Visit this group at https://groups.google.com/group/vertx.

To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/1d356f71-12a5-4e55-b5b8-f42e8286844c%40googlegroups.com.

[Yoni Davidson]

Would using coroutins to solve the problem (using Vertx with Kotlin) looks like a valid solution?

package com.tg.core.extenstions

import io.vertx.ext.web.Route
import io.vertx.ext.web.RoutingContext
import io.vertx.kotlin.coroutines.dispatcher
import kotlinx.coroutines.experimental.launch
import kotlinx.coroutines.experimental.slf4j.MDCContext
import kotlinx.coroutines.experimental.withContext
import org.slf4j.MDC

object Route {
    /**
     * Like Vert.x's own [io.vertx.ext.web.Route.handler] but can receive
     * a coroutine lambda.
     */
    fun Route.coroutineHandler(fn: suspend (RoutingContext) -> Unit): Route = handler { ctx ->
        MDC.put("request.id", ctx.request().getHeader("REQUEST-ID"))
        MDC.put("user.id", ctx.request().getHeader("TG-USER-ID"))
        launch(ctx.vertx().dispatcher()) {
            withContext(MDCContext()) {
                try {
                    fn(ctx)
                } catch (e: Exception) {
                    ctx.fail(e)
                }
            }
        }
    }
}

[Julien Viet]

that's a relevant concern.

at first sight I think you would some integration, see this discussion https://github.com/Kotlin/kotlinx.coroutines/issues/119 and https://stackoverflow.com/questions/46227462/how-to-use-code-that-relies-on-threadlocal-with-kotlin-coroutines/46227463

Julien

To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/2990f0bd-713a-499d-96aa-d593a417b6ba%40googlegroups.com.

[samee...@gmail.com]

What are the issues using MDC for vertx. Isn't there a single thread for every event. if yes then I am setting MDC variables inside a service and clearing when processing is done inside service. In my local i am getting correct correlation id. I get the correlation Id as part of object posted rest service.

[Thomas SEGISMONT]

A single thread for your verticle means all requests handled by this thread. So you can't store anything in a thread local variable.

I've been working on a POC for MDC style logging https://groups.google.com/d/msg/vertx-dev/azhHNf9sL7s/N1fQfJgwCwAJ

It may land in Vert.x 4

To view this discussion on the web, visit https://groups.google.com/d/msgid/vertx/fbdd6716-fad9-4030-b76a-531bc838b0f0%40googlegroups.com.