Contextual logging in Vert.x
One of the widely used practices to improve logging in your system (be it just one application or multiple communicating with one another) is the usage of contextual logging. In case of a single application some request ID could be generated and then with the usage of tools such as MDC/ThreadContext the value would be present in each log message related to that particular request which makes tracing with tools like Kibana so much easier.
But the problem arises when you want to use similar approach with Vert.x. Applications written in Vert.x are asynchronous in nature but standard MDC is based on ThreadLocal. Consider following router:
helloRouter
.get("/hello")
.handler { req ->
val reqId = requestIdProvider()
MDC.put("requestId", reqId) // put request ID
val name: String = req.request().getParam("name") ?: "anonymous"
log.info("Hello $name.")
vertx.executeBlocking<Unit>(
{ promise ->
Thread.sleep(100)
log.info("Finished waiting for $name")
promise.complete()
},
{
log.info("Bye $name.")
MDC.remove("requestId") // remove when handling ends
req.response().end()
}
)
}And logging config for log4j2 (similar can be configured for other logging backends):
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
<Appenders>
<Console name="console" target="SYSTEM_OUT">
<PatternLayout>
<Pattern>%p [%t] requestId=%X{requestId} %m%n</Pattern>
</PatternLayout>
</Console>
</Appenders>
<Loggers>
<Root level="WARN">
<AppenderRef ref="console"/>
</Root>
<Logger name="ib.example" level="DEBUG" additivity="false">
<AppenderRef ref="console"/>
</Logger>
</Loggers>
</Configuration>Expectedly we get following output when executing multiple requests:
INFO [vert.x-eventloop-thread-0] requestId=58387d4d0efbb192 Hello 1.
INFO [vert.x-eventloop-thread-0] requestId=589114d99e88a5e3 Hello 2.
INFO [vert.x-eventloop-thread-0] requestId=17db5856563a07d8 Hello 3.
INFO [vert.x-worker-thread-0] requestId= Finished waiting for 1
INFO [vert.x-eventloop-thread-0] requestId=17db5856563a07d8 Bye 1.
INFO [vert.x-worker-thread-0] requestId= Finished waiting for 2
INFO [vert.x-eventloop-thread-0] requestId= Bye 2.
INFO [vert.x-worker-thread-0] requestId= Finished waiting for 3
INFO [vert.x-eventloop-thread-0] requestId= Bye 3.Request ID was lost as soon as we have switched threads and actually we even have incorrect request ID when we are saying good bye to the last person. That’s not helpful at all.
Vert.x 4 tracing SPI
In Vert.x 4 tracing SPI which introduces new localContext which is attached to standard and worker contexts (more on this here https://vertx.io/blog/eclipse-vert-x-4-milestone-1-released/). And there is already a library that provides us MDC-like capabilities — https://github.com/tsegismont/vertx-contextual-logging.
Let’s tweak our code a little to to start using ContextualData instead of MDC. ContextualData is a convenience wrapped for Vert.x Context. It provides API similar to the familiar MDC. After substitution our code would look like this:
val helloRouter = Router.router(vertx)
helloRouter
.get("/hello")
.handler { req ->
val reqId = createRequestId()
ContextualData.put("requestId", reqId)
val name: String = req.request().getParam("name") ?: "anonymous"
log.info("Hello $name.")
vertx.executeBlocking<Unit>(
{ promise ->
Thread.sleep(ThreadLocalRandom.current().nextLong(100, 1000))
log.info("Finished waiting for $name")
promise.complete()
},
{
log.info("Bye $name.")
req.response().end()
}
)
}
vertx.createHttpServer()
.requestHandler(helloRouter)
.listenAwait(8080)
log.info("Listening on port 8080")An changing %X to %vcl is logs configuration:
<?xml version="1.0" encoding="UTF-8"?>
<Configuration status="WARN">
<Appenders>
<Console name="console" target="SYSTEM_OUT">
<PatternLayout>
<Pattern>%p [%t] requestId=%vcl{requestId} %m%n</Pattern>
</PatternLayout>
</Console>
</Appenders>
<Loggers>
<Root level="WARN">
<AppenderRef ref="console"/>
</Root>
<Logger name="ib.example" level="DEBUG" additivity="false">
<AppenderRef ref="console"/>
</Logger>
</Loggers>
</Configuration>We get:
INFO [vert.x-eventloop-thread-0] requestId=c39087e0d9a7209 Hello 1.
INFO [vert.x-eventloop-thread-0] requestId=1c793da71eea8e57 Hello 2.
INFO [vert.x-eventloop-thread-0] requestId=6615f5c73a5c710c Hello 3.
INFO [vert.x-worker-thread-0] requestId=c39087e0d9a7209 Finished waiting for 1
INFO [vert.x-eventloop-thread-0] requestId=c39087e0d9a7209 Bye 1.
INFO [vert.x-worker-thread-2] requestId=6615f5c73a5c710c Finished waiting for 3
INFO [vert.x-eventloop-thread-0] requestId=6615f5c73a5c710c Bye 3.
INFO [vert.x-worker-thread-1] requestId=1c793da71eea8e57 Finished waiting for 2
INFO [vert.x-eventloop-thread-0] requestId=1c793da71eea8e57 Bye 2.Great, that’s exactly what we wanted to achieve! Only problem that at the moment Vert.x 4 is not released yet and the mentioned above library is in alpha stage…
Kotlin for the rescue
There is still a way to achieve similar results with Vert.x 3 if you are using Kotlin and coroutines. We would need to add kotlinx-coroutines-slf4j dependency to our project. For maven:
<dependency>
<groupId>org.jetbrains.kotlinx</groupId>
<artifactId>kotlinx-coroutines-slf4j</artifactId>
<version>${kotlinMdcIntegrationVersion}</version>
</dependency>And for gradle:
implementation "org.jetbrains.kotlinx:kotlinx-coroutines-slf4j:$kotlinMdcIntegrationVersion"With this approach we would need to launch processing of the request passing MDCContext as context:
val helloRouter = Router.router(vertx)
helloRouter.get("/hello")
.handler { req ->
val reqId = generateRequestId()
MDC.put("requestId", reqId)
launch(context = MDCContext()) {
val name: String = req.request().getParam("name") ?: "anonymous"
log.info("Hello $name.")
delay(ThreadLocalRandom.current().nextLong(100, 1000))
log.info("Finished waiting for $name")
log.info("Bye $name.")
req.response().end()
}
MDC.remove("requestId")
}
vertx.createHttpServer()
.requestHandler(helloRouter)
.listenAwait(8080)
log.info("Listening on port 8080")
}The log output:
INFO [vert.x-eventloop-thread-0 @coroutine#3] requestId=7c57c1618e1b3ff8 Hello 1.
INFO [vert.x-eventloop-thread-0 @coroutine#4] requestId=3da09e18e00493bb Hello 2.
INFO [vert.x-eventloop-thread-0 @coroutine#5] requestId=7e209696c876f886 Hello 3.
INFO [vert.x-eventloop-thread-0 @coroutine#4] requestId=3da09e18e00493bb Finished waiting for 2
INFO [vert.x-eventloop-thread-0 @coroutine#4] requestId=3da09e18e00493bb Bye 2.
INFO [vert.x-eventloop-thread-0 @coroutine#5] requestId=7e209696c876f886 Finished waiting for 3
INFO [vert.x-eventloop-thread-0 @coroutine#5] requestId=7e209696c876f886 Bye 3.
INFO [vert.x-eventloop-thread-0 @coroutine#3] requestId=7c57c1618e1b3ff8 Finished waiting for 1
INFO [vert.x-eventloop-thread-0 @coroutine#3] requestId=7c57c1618e1b3ff8 Bye 1.
It works just as with Vert.x 4. Now we can easily trace that pesky bug on production environment that kept you up at night.
Conclusion
Contextual logging is a great tool to improve tracing of workflow in your application. It makes investigation of unexpected behaviour easier especially if you have multiple services involved in processing of the same request. It is often problematic to use it in asynchronous environment but as shown above it is still possible and can make your life and life of your fellow colleagues just a little bit easier.
Examples are available at https://github.com/silh/vertx-contextual-logging
