Support for Contextual Logging / Log Correlation #22724
Comments
|
You added a link to a Zulip discussion, please make sure the description of the issue is comprehensive and doesn't require accessing Zulip.
|
|
@Ladicek FYI |
|
The suggestion on Zulip, which I mostly agree with, is that we should provide MP ConProp There are basically 2 levels on which a context provider could work:
I briefly looked at a couple of those and my impression is that most of these only hand out copies of the backing contextual storage, so while forward propagation would be possible, back-propagation not so much. |
|
The propagation could be enabled as soon as the logging pattern contains a variable referencing the MDC. Using the MDC without having the propagation enabled doesn't really make sense, does it? |
|
Forgive my ignorance but is a handle to the underlying map necessary for back-propagation? Given thread 1 -> 2 -> 1, is it not possible to set the context map (with If it is then probably the only implementation that would support it is logback: |
|
@josephearl A handle to the underlying map would make things more lightweight and easier, but it is not necessary. However, if we are looking only at the lowest common denominator then we'll not come up with a great solution. Often things get possible if you try and convince others (e.g. to adjust their API). Reactive programming does not only exist in Quarkus and I believe that these requirements will become more common. |
|
Agreed, this would be an incredible value add for any cloud logging solution and allow request metadata to be associated with log messages (user identities, request ids etc). Considering the focus on reactive libraries in Quarkus, MDC should be a supported as default. |
|
When trying to solve OTEL MDC log metadata, I did the dmlloyd/jboss-logmanager-embedded#4 PR and now I am waiting for a new version of it to be released... What I planned was to create a Quarkus Vert.x MDC Provider extension, with this extension using MDC as we normally would use works without any code change to existing MDC usage, and It would also make the OTEL feature work as intended. What do you guys think about this approach? |
|
Important to me is that the context does not get lost along its processing chain. E.g. Vert.x request -> blocking call -> back to vert.x thread or vert.x event-loop thread -> managed thread pool - > vert.x thread or scheduler event -> blocking call -> remote call -> finish blocking call. As long as I was only dealing with reactive calls or only with blocking calls, everything was at least somehow working. The problems did arise in mixed environments. I need the context along with an event that is handled (e.g. http request, Kafka message or scheduler event). |
|
#25311 was merged, we should have MDC working with Vert.x now =] |
|
Great! Thanks @luneo7! |
|
Switching between Vertx main threads and worker threads works out of the box, if you use your own worker threads you will need to follow the Quarkus context propagation guide. https://quarkus.io/guides/context-propagation If you check the test here: you will see that we do a log in a Vertx Main loop thread, and later in a blocking thread, that is a worker thread, and they work =] |
|
Thanks a lot @luneo7 for the example. I tried it out with resteasy-reactive and created a reproducer project: Note: The unit tests do not (yet) test the log output. I just use them to invoke the methods. This one works as expected: @GET
@Path("vertx/blocking/new-context")
@Produces(MediaType.TEXT_PLAIN)
public Uni<String> vertxBlockingOnNewContext() {
return Vertx.vertx().executeBlocking(Uni.createFrom().item(service::getBlocking));
}2022-05-22 22:13:18,101 MDC:{} DEBUG [com.git.ren.CorrelationIdFilter] (vert.x-eventloop-thread-1) Created new correlationId: fb414b5f-7cd6-403b-b27d-caa65cd2dbb5.
2022-05-22 22:13:18,101 MDC:{correlationId=fb414b5f-7cd6-403b-b27d-caa65cd2dbb5} INFO [com.git.ren.CorrelationIdFilter] (vert.x-eventloop-thread-1) fb414b5f-7cd6-403b-b27d-caa65cd2dbb5: GET /v1/vertx/blocking/new-context
2022-05-22 22:13:18,103 MDC:{correlationId=fb414b5f-7cd6-403b-b27d-caa65cd2dbb5} WARN [io.ver.cor.imp.VertxImpl] (vert.x-eventloop-thread-1) You're already on a Vert.x context, are you sure you want to create a new Vertx instance?
2022-05-22 22:13:18,357 MDC:{correlationId=fb414b5f-7cd6-403b-b27d-caa65cd2dbb5} INFO [com.git.ren.ExampleService] (vert.x-worker-thread-0) Creating result: 2
2022-05-22 22:13:18,359 MDC:{correlationId=fb414b5f-7cd6-403b-b27d-caa65cd2dbb5} INFO [com.git.ren.CorrelationIdFilter] (vert.x-eventloop-thread-1) fb414b5f-7cd6-403b-b27d-caa65cd2dbb5: 200 OKWhile this version loses the MDC: @GET
@Path("vertx/blocking/new-context")
@Produces(MediaType.TEXT_PLAIN)
public Uni<String> vertxBlockingOnNewContext() {
return Vertx.vertx().executeBlocking(Uni.createFrom().item(service::getBlocking));
}2022-05-22 22:13:17,828 MDC:{} DEBUG [com.git.ren.CorrelationIdFilter] (vert.x-eventloop-thread-0) Created new correlationId: e5c3ee7a-efba-4835-b29e-0a2f308ce3c4.
2022-05-22 22:13:17,828 MDC:{correlationId=e5c3ee7a-efba-4835-b29e-0a2f308ce3c4} INFO [com.git.ren.CorrelationIdFilter] (vert.x-eventloop-thread-0) e5c3ee7a-efba-4835-b29e-0a2f308ce3c4: GET /v1/vertx/blocking
2022-05-22 22:13:18,084 MDC:{} INFO [com.git.ren.ExampleService] (executor-thread-0) Creating result: 1
2022-05-22 22:13:18,085 MDC:{correlationId=e5c3ee7a-efba-4835-b29e-0a2f308ce3c4} INFO [com.git.ren.CorrelationIdFilter] (vert.x-eventloop-thread-0) e5c3ee7a-efba-4835-b29e-0a2f308ce3c4: 200 OKAlso this very simple example loses the MDC: @GET
@Path("hello")
@Produces(MediaType.TEXT_PLAIN)
@Blocking
public String hello() {
logger.info("hello endpoint");
return "Hello from RESTEasy Reactive";
}2022-05-22 22:13:18,372 MDC:{} DEBUG [com.git.ren.CorrelationIdFilter] (vert.x-eventloop-thread-0) Extracted correlationId: MY_CORRELATION_ID from header X-Correlation-ID.
2022-05-22 22:13:18,373 MDC:{correlationId=MY_CORRELATION_ID} INFO [com.git.ren.CorrelationIdFilter] (vert.x-eventloop-thread-0) MY_CORRELATION_ID: GET /v1/hello
2022-05-22 22:13:18,373 MDC:{} INFO [com.git.ren.MyResource] (executor-thread-0) hello endpoint
2022-05-22 22:13:18,375 MDC:{} INFO [com.git.ren.CorrelationIdFilter] (executor-thread-0) MY_CORRELATION_ID: 200 OK-> Here even the Vert.x BodyEndHandler is called on the executor-thread. What am I doing wrong? |
|
@geoand Do you have a hint since I'm using resteasy-reactive? |
|
I do not unfortunately as I haven not followed the MDC stuff in Vert.x |
|
@renegrob you did nothing wrong hahaha You will see that all the tests are passing, the ones using resteasy-reactive, ant the other using vert.x directly. |
|
So, how does the Vert.x MDC works?
|
|
@luneo7 Oh sorry, my bad. Thanks for the information about Vert.x MDC. |
|
@renegrob the It works as expected (as stated in the context propagation guide). The |
|
@cescoffier might be able to explain better why using |
|
@luneo7 Thanks a lot! I will try to fix my tests. We probably should write a guide for this or update existing ones, there are some pitfalls but if it is done correctly, then it works. |
|
I updated the reproducer. The tests are now green and will fail, if the blocking call is done on the eventloop-thread or if the MDC is not logged correctly. |
|
For sure we should document it, but if you follow the context propagation guide exactly as it is it works, there it states to use the |
That's a very good question. Probably a bug. (One is implemented on top of the other one) |
|
For what I see, it is a design flaw, the executor that Quarkus uses is the EnhancedQueueExecutor (https://github.com/jbossas/jboss-threads/blob/main/src/main/java/org/jboss/threads/EnhancedQueueExecutor.java) it has a context handler that is set to get the current Vertx context. But SmallRye |
|
So, that is what happens when you use
|
|
The way that I got package com.luneo7.tests;
import io.vertx.core.Context;
import io.vertx.core.Vertx;
import io.vertx.core.impl.ContextInternal;
import org.eclipse.microprofile.context.spi.ThreadContextProvider;
import org.eclipse.microprofile.context.spi.ThreadContextSnapshot;
import java.util.Map;
public class VertxContextProvider implements ThreadContextProvider {
@Override
public ThreadContextSnapshot currentContext(Map<String, String> props) {
Context context = Vertx.currentContext();
return () -> {
if (context != null) {
final ContextInternal vertxContext = (ContextInternal) context;
vertxContext.beginDispatch();
return () -> vertxContext.endDispatch(null);
}
return () -> {};
};
}
@Override
public ThreadContextSnapshot clearedContext(Map<String, String> props) {
return () -> () -> {};
}
@Override
public String getThreadContextType() {
return "Vertx";
}
}And later create a With this class the Vertx context gets propagated with smallrye context propagation... since the @cescoffier what do you think? should we open a new bug ticket for vertx context propagation with |
|
This also impacts OpenTelemetry, since it has a |
|
Created a new issue (#25818) to track |
|
Any update on this feature? |
|
Both the MDC and the trace propagation have been implemented. If you still see a problem, please re-open an issue with an updated and standalone reproducer. |
cescoffier
added
the
triage/out-of-date
|
@cescoffier how to use Log Correlation? Do you have any example or doc to look at result? |
|
Answering on question, to use it needs to make sure if Quarkus version supports "smallrye-context-propagation" (needs to be printed in logs on startup in "Installed features" block). To make a log correlation needs to put some unique ID into MDC. In my case, I added it to the request filter: Then, to show this ID in logs, added it manually in JsonProvider implementation: Used: |
|
That's not entierely correct - see https://quarkus.io/guides/duplicated-context#duplicated-contexts-and-mapped-diagnostic-context-mdc |
Description
Currently it is very hard if not impossible to enrich log messages related to a request or message with additional context information (e.g. a "correlation-id"). For SREs / operations it is very important to be able to correlate log messages and filter the messages in a log management tool for faster issue analysis. This is often achieved by passing some context attributes along the processing chain that will appear in all logs of related tasks of all involved systems.
JBoss-Logging and slf4j provide an MDC object that allows to set context information that is available in the logger and can be included in the log-format. Since the MDC internally uses a
ThreadLocalobject to associate the context information, this information is lost, if the thread is switched (e.g. due to a blocking execution from avert.x-eventloop-threadto anexecutor-thread).The goal of this ticket is to either make MDC work or offer an alternative solution to be able to include context information in the related log messages - which means passing context information along the execution chain.
Implementation ideas
See also https://quarkusio.zulipchat.com/#narrow/stream/187030-users/topic/Contextual.20Logging.20in.20Quarkus
The text was updated successfully, but these errors were encountered: