Logback-access RequestLog not working

[zUniQueX]

Jetty version(s)
11.0.8

Java version/vendor (use: java -version)
openjdk version "11.0.13" 2021-10-19
OpenJDK Runtime Environment (build 11.0.13+8-Ubuntu-0ubuntu1.20.04)
OpenJDK 64-Bit Server VM (build 11.0.13+8-Ubuntu-0ubuntu1.20.04, mixed mode)

OS type/version
Ubuntu 20.04.3 LTS

Description
After upgrading Jetty from 11.0.7 to 11.0.8 the request logging through logback doesn't work any more. A NullPointerException gets thrown from here. I only see this commit related to this issue. As _contentParamsExtracted = true is set, the extractContentParameters() method of the Request class gets not executed and _contentParameters is null.

java.lang.NullPointerException
        at      at org.eclipse.jetty.server.Request.getParameters(Request.java:478)
        at      at org.eclipse.jetty.server.Request.getParameterNames(Request.java:1058)
        at      at ch.qos.logback.access.spi.AccessEvent.buildRequestParameterMap(AccessEvent.java:356)
        at      at ch.qos.logback.access.spi.AccessEvent.getRequestParameterMap(AccessEvent.java:369)
        at      at ch.qos.logback.access.spi.AccessEvent.prepareForDeferredProcessing(AccessEvent.java:605)
        at      at io.dropwizard.request.logging.async.AsyncAccessEventAppenderFactory$1.preprocess(AsyncAccessEventAppenderFactory.java:22)
        at      at io.dropwizard.request.logging.async.AsyncAccessEventAppenderFactory$1.preprocess(AsyncAccessEventAppenderFactory.java:19)
        at      at ch.qos.logback.core.AsyncAppenderBase.append(AsyncAppenderBase.java:165)
        at      at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:85)
        at      at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
        at      at ch.qos.logback.access.jetty.RequestLogImpl.log(RequestLogImpl.java:149)
        at      at org.eclipse.jetty.server.Request.onCompleted(Request.java:1449)
        at      at org.eclipse.jetty.server.HttpChannel.onCompleted(HttpChannel.java:966)
        at      at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:485)
        at      at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:282)
        at      at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:319)
        at      at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100)
        at      at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
        at      at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:412)
        at      at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:381)
        at      at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:268)
        at      at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.produce(AdaptiveExecutionStrategy.java:190)
        at      at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:894)
        at      at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1038)
        at      at java.base/java.lang.Thread.run(Thread.java:829)

[joakime]

logback-access is doing truly bad things with it's RequestLogImpl. (it hasn't kept up with the changes in the Servlet spec since 3.1.0).

It's incredibly bad for a RequestLog to START reading request body content during the RequestLog.
That's the heart of this issue, you have a scenario where you didn't read the request body, responded to the request, and then the RequestLog attempts to read it.

It was first noticed in Issue #6973

The fix needs to be on the logback side, and we've submitted this PR to them already - qos-ch/logback#532

Your options are to make a fork of logback-access with that PR, convince logback to merge that PR, or use something else (our CustomRequestLog is quite capable configuration wise, look into that)

[zUniQueX]

Thanks for the fast response. I noticed that logback doesn't stay that much up-to-date when trying to upgrade to Jetty 10. There I first hit your PR at their project.

It just seemed odd to me, that a minor Jetty update suddenly broke the logback request logging, but I totally understand your intention there.

I will just stay on Jetty 11.0.7 until this gets fixed on their side.

[joakime]

logback-access as it exists now has many bugs that means you should avoid using it for any release of Jetty 10 (even 10.0.7)

• status code reported by logback-access is often invalid.
• bytes sent are invalid (off by an order of magnitude)
• bytes read are invalid (also off by an order of magnitude)
• response header values are invalid (it reports the last state, not the state when it was committed, so many things especially if you are using Spring/DropWizard change the response headers after commit that renders this feature of logback totally invalid)
• MDC / NDC are often invalid as the Thread that does RequestLog can be different than the thread that did the dispatch.

[joakime]

logback-access issues have existed for the entirety of Jetty 10.0.x, it's not unique for 10.0.8.

I'm surprised you didn't hit the 100% CPU bug with it already.
The fix in 10.0.8 was to fix for that 100% CPU bug.

The scenario: (that exist in Jetty 10.0.0 thru 10.0.7)

1. You receive a request, that has a form.
2. You didn't read the form in your servlet/dispatch.
3. It reaches the LogbackAccessImpl and it attempts to read the form because it used .getParameterNames()
4. But the form wasn't fully sent yet, and the client disconnected, or stopped sending, you now have a context-less read of form content that doesn't belong to anything managing the connection properly - this is being done outside of the handler tree, the dispatch, the scoping, etc (hence a 100% CPU bug).

[zUniQueX]

I was just doing upgrades for Dropwizard after we planned upgrading to Jakarta APIs. We formerly stayed on Jetty 9.x.x quite a long time and would now want to upgrade to Jetty 10 and Jetty 11. Therefore I didn't experience any logback issue with Jetty before.

As we allow customization of the request logging related to logback's APIs, I think we wouldn't want to upgrade to Jetty's request logging mechanism as this could break many implementations.

The third option to use logback-access eith Jetty is to provide a custom RequestLogImpl in logback's namespace to expose the AppenderAttachableImpl, as this is package-private. Then one can manually override the RequestLogImpl.log method and provide a custom JettyServerAdapter. With that workaround, it is possible to use logback-access with Jetty 10.

But I wouldn't want to do this when it's avoidable. Therefore many thanks for your PR at logback and I just hope it gets merged soon.

[joakime]

The 100% CPU issue with logback-access exists in Jetty 9.1.0 thru 9.4.43 as well. (it was fixed in 9.4.44)
(early Jetty 9.0.x releases were using pre-release/alpha/beta Servlet 3.1.0 API jars that are incompatible with all logback-access releases)

Note that if you have any requests that result in a 400 response (Bad Request) you also have a fatal failure in logback-access.
At best, those requests will result in null/empty RequestLog lines in your output.
At worst, it crashes the whole JVM (in various ways, StackOverflowError is the most common).
This is because logback-access makes bad assumptions on what is available on a request or response (400 requests are not uncommon, and need to be handled properly by all RequestLog implementations).
Which result depends on your logback-access configuration.

[joakime]

I opened PR #7618 with more hardening for bad RequestLog implementations. (Once approved it will be merged up into Jetty 11.x and 12.x)

This is not a 100% solution as there's far too many code paths based on configuration to catch all of these bad behaviors.

[zUniQueX]

Many thanks for all the detailed answers. If logback-access is that unstable regarding Jetty, I'll take a look at Jetty's request logging implementation and maybe we could provide a module for that at Dropwizard.

The PR looks good, I think this should fix the current problem from Jetty's end. I hope to see a solution from Logback soon too, but I'm not too optimistic about that yet.