Issue while logging MDC values with Jetty 12

[narharim]

Jetty version(s)

Jetty 12.0.8

Jetty Environment

core

Java version/vendor (use: java -version) Amazon Corretto 17.0.9

OS type/version Ubuntu 22.04.4 LTS

Description

We have a service A that initiates an API call to another service B. In response service B transfers zip file in chunk to service A. We have written a custom response listener which transfer chunk from service A to its client without storing it in buffer.

while doing so when ever connection is aborted from client of service A, key-value pair which we are inserting into MDC map are getting cleared out and we are unable to log those key-value.

for example MDC.put(ABORTED, "true") is not printed in log

logback-access version 2.0.2

Note: we are using kotlin as our programming language

How to reproduce? Attached code for ref logging.txt handler.txt

[sbordet]

This does not seem a Jetty issue.

Jetty will (possibly) use different threads to invoke handle(), onContent() and onComplete(), but you seem to take care of this by passing the MDC map around.

If these 3 consecutive lines do not work, then Jetty is out of the picture:

MDC.setContextMap(mdc)
MDC.put(ABORTED, "true")
log.debug("aborted")

Do you have a Java reproducer that we can try?

[narharim]

Hi @sbordet, apologies for the delay, was caught up in other tasks.

Please Find Attached zip for all three services written in java Please change the static path to your liking. (static path is contains string - "narhari")

service.zip

[joakime]

Your code is using MDC in a bad way. MDC in Logback Core isn't live when being passed around as a copy of the map like that. Only the MDC threadlocal is live, all other maps are not.

You seem to want to pass the MDC into HttpClient handling. But that will use different threads, so MDC is not a good choice for all logging events in that HttpClient. Only the thread that is initiating the send will have those MDC values (it's the same thread).

Your issue mentioned logback-access. That will not work on the server side, as by the time the logging of the event is kicked off, the threadlocal is no longer holding the MDC values you think (it could be an entirely different thread).

Also, because of the Jetty ThreadPool, and MDC you attach to a thread, will remain with that thread, even in the threadpool, contaminating the thread for other MDC use cases.

Like Simone said, MDC will work, but it has the same limits as any other ThreadLocal, and will only from the same thread.

[narharim]

Also, because of the Jetty ThreadPool, and MDC you attach to a thread, will remain with that thread, even in the threadpool, contaminating the thread for other MDC use cases.

We can handled this adding MDC.clear() as first statement in handle function

@joakime If MDC is not a good choice or rather an incorrect one, what are the better suited options for this requirement

[joakime]

Your description of how you use MDC is to pass some kind of values between services, not for the intended purpose of MDC which is to capture logging level details to output from logging events related to the same thread execution.

You shouldn't use / rely on the ThreadLocal to pass this information between services.

If it's the same HttpServletRequest, use the request attributes. Otherwise use a custom class (or record) that you pass between services via a method call.

[narharim]

As mentioned earlier in the description, we are using MDC for its intended purpose of capturing logging level details from logging events. However, when a client of Service A drops the connection abruptly, we are unable to log values for that specific API event. If everything follows the happy path, it logs the values for that API event correctly.

while doing so when ever connection is aborted from client of service A, key-value pair which we are inserting into MDC map are getting cleared out and we are unable to log those key-value.

[joakime]

@narharim you are assuming a model where 1 thread is used for 1 request / response exchange.

For MDC (which is a ThreadLocal) to make sense, that assumption has to be true.

But that assumption is false, Jetty will use 1...n threads for a request / response exchange. The number of threads depends on many factors, from the technology (APIs) you choose to use, to the protocols in use (HTTP/1, HTTP/2, WebSocket, etc), the handling / dispatching, and even the error handling. (to name just a few of the more common things that use multiple threads, there are more scenarios)

Just a reminder, javax.servlet.SingleThreadModel was deprecated in Servlet 2.4 (November 2003), and completely removed in Servlet 6.0, there is no expectation of a single thread handling a request in Servlet.

If you want to carry over something through the life of the HttpServletRequest (and not worry about the threading), use the HttpServletRequest attributes, those will still be available at the point in time when the Jetty RequestLog kicks in.