Jetty starts consuming CPU that remains high even without any traffic

[dimas]

Jetty version(s)
9.4.41.v20210516
9.4.43.v20210629

Java version/vendor (use: java -version)

$ java -version
openjdk version "1.8.0_292"
OpenJDK Runtime Environment (build 1.8.0_292-8u292-b10-0ubuntu1~18.04-b10)
OpenJDK 64-Bit Server VM (build 25.292-b10, mixed mode)

OS type/version
Ubuntu 18.04

Description
We had an issue with some of the production servers spiking with CPU use.
We do not know what triggered it. When affected servers are removed from load balancer and all traffic to them ceases, the CPU usage still remains high.

About 5 out of 8 servers got affected over a stretch of several hours. The servers belong to different clusters and run different application code on them. The common theme is that they all are Spring apps with embedded Jetty, are on Amazon EC2 and exposed to the internet via load balancers. They are in different AWS accounts, different load balancers and their load pattern is not correlated in any way. Just the AWS region is the same. We saw 9.4.41.v20210516 and 9.4.43.v20210629 affected. Restarting the app (with Jetty) fixes CPU usage.

We tried profiling the running app and building flamegraphs and saw that all the CPU is being eaten by a couple of "qtp" threads with stacktraces similar to:

"qtp708090483-69573" #69573 prio=5 os_prio=0 tid=0x00007f6b1e429000 nid=0x311f in Object.wait() [0x00007f6ac36c8000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        at java.lang.Object.wait(Object.java:502)
        at org.eclipse.jetty.server.HttpInput.blockForContent(HttpInput.java:584)
        at org.eclipse.jetty.server.HttpInput$1.blockForContent(HttpInput.java:1164)
        at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:330)
        - locked <0x00000000c54d9790> (a java.util.ArrayDeque)
        at org.eclipse.jetty.server.HttpInput.read(HttpInput.java:270)
        at org.eclipse.jetty.util.UrlEncoded.decodeUtf8To(UrlEncoded.java:485)
        - locked <0x00000000c54dea40> (a org.eclipse.jetty.util.MultiMap)
        at org.eclipse.jetty.util.UrlEncoded.decodeTo(UrlEncoded.java:572)
        at org.eclipse.jetty.server.Request.extractFormParameters(Request.java:582)
        at org.eclipse.jetty.server.Request.extractContentParameters(Request.java:531)
        at org.eclipse.jetty.server.Request.getParameters(Request.java:435)
        at org.eclipse.jetty.server.Request.getParameterNames(Request.java:1093)
        at ch.qos.logback.access.spi.AccessEvent.buildRequestParameterMap(AccessEvent.java:338)
        at ch.qos.logback.access.spi.AccessEvent.getRequestParameterMap(AccessEvent.java:351)
        at ch.qos.logback.access.spi.AccessEvent.prepareForDeferredProcessing(AccessEvent.java:584)
        #
        # code from https://jira.qos.ch/browse/LOGBACK-1486 here
        #
        at ch.qos.logback.core.AsyncAppenderBase.append(AsyncAppenderBase.java:160)
        at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:84)
        at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:51)
        at ch.qos.logback.access.jetty.RequestLogImpl.log(RequestLogImpl.java:137)
        at org.eclipse.jetty.server.HttpChannel.onCompleted(HttpChannel.java:812)
        at org.eclipse.jetty.server.HttpChannel.onBadMessage(HttpChannel.java:872)
        at org.eclipse.jetty.server.HttpChannelOverHttp.badMessage(HttpChannelOverHttp.java:283)
        at org.eclipse.jetty.http.HttpParser.badMessage(HttpParser.java:1647)
        at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1629)
        at org.eclipse.jetty.server.HttpConnection.parseRequestBuffer(HttpConnection.java:376)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:265)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:311)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:105)
        at org.eclipse.jetty.io.ChannelEndPoint$1.run(ChannelEndPoint.java:104)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:336)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:313)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:129)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:383)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:882)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1036)
        at java.lang.Thread.run(Thread.java:748)

Clearly we are at the end of request trying to log it (with logback-access) and while preparing request for deferred processing it tries to read some of the parameters from it and it all ends up in HttpInput.read().

Which in turn blocks for content. However judging from how much CPU is used, our suspicion is that no actual sleeping happens, the thread just wakes up immediately, re-checks conditions, goes back to waiting and the story repeats.

I do not know anything about Jetty internals but given this code https://github.com/eclipse/jetty.project/blob/jetty-9.4.41.v20210516/jetty-server/src/main/java/org/eclipse/jetty/server/HttpInput.java#L1161-L1166 just calls input.blockForContent() and always returns true (unless throws), then this loop https://github.com/eclipse/jetty.project/blob/jetty-9.4.41.v20210516/jetty-server/src/main/java/org/eclipse/jetty/server/HttpInput.java#L314-L340 reduces to:

            while (true)
            {
                Content item = nextContent();
                if (item != null)
                {
                    l = get(item, b, off, len);
                    if (LOG.isDebugEnabled())
                        LOG.debug("{} read {} from {}", this, l, item);

                    // Consume any following poison pills
                    if (item.isEmpty())
                        nextInterceptedContent();
                    break;
                }

                // No content, so should we block?
                input.blockForContent();
            }

So in theory as long as nextContent() returns null, it just spins input.blockForContent().

We tried verifying it by enabling debug logging with

<logger name="org.eclipse.jetty.server.HttpInput" level="DEBUG"/>

and it resulted in about 10Mb/sec of logs:

-----------------------------------------------------------------------------------------------------------------------------------------------
|       @timestamp        | level |       thread       |                                       message                                        |
|-------------------------|-------|--------------------|--------------------------------------------------------------------------------------|
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-71877 | HttpInputOverHTTP@1202b981[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-71877 | HttpInputOverHTTP@1202b981[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-71877 | HttpInputOverHTTP@1202b981[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-71877 | HttpInputOverHTTP@1202b981[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-71877 | HttpInputOverHTTP@1202b981[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-71877 | HttpInputOverHTTP@1202b981[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-71877 | HttpInputOverHTTP@1202b981[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-71877 | HttpInputOverHTTP@1202b981[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-71877 | HttpInputOverHTTP@1202b981[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-71877 | HttpInputOverHTTP@1202b981[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-71877 | HttpInputOverHTTP@1202b981[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-71877 | HttpInputOverHTTP@1202b981[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-71877 | HttpInputOverHTTP@1202b981[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-71877 | HttpInputOverHTTP@1202b981[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-71877 | HttpInputOverHTTP@1202b981[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-71877 | HttpInputOverHTTP@1202b981[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-71877 | HttpInputOverHTTP@1202b981[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-71877 | HttpInputOverHTTP@1202b981[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
| 2021-10-08 14:54:35.000 | DEBUG | qtp708090483-69573 | HttpInputOverHTTP@72895282[c=0,q=0,[0]=null,s=STREAM] blocking for content timeout=0 |
-----------------------------------------------------------------------------------------------------------------------------------------------

So it does indeed look like read() just spins blockForContent() endlessly which for some reason wakes up every time but there are no data available (or read() would log something on this line https://github.com/eclipse/jetty.project/blob/jetty-9.4.41.v20210516/jetty-server/src/main/java/org/eclipse/jetty/server/HttpInput.java#L321 )

Remember, there is no any load on that server at that moment, no established HTTP connections, just couple of some old requests stuck in this state.

How to reproduce?
Unfortunately I have no idea what triggers it. We just saw several servers ended up in this state. Last time we saw it before today was several months ago. Given all affected servers are on AWS eu-west-1 and behind load balancers, it could be that some region-wide issue with AWS load balancers resulted in some incorrect TCP connection closure or something like that which in turn triggered some edge condition in Jetty.

It also can be the same issue as #5435 although I am not 100% sure

[joakime]

The stacktrace shows the following, which gives hints that you are suffering from an OLD security issue ...

        at org.eclipse.jetty.server.Request.extractFormParameters(Request.java:582)
        at org.eclipse.jetty.server.Request.extractContentParameters(Request.java:531)
        at org.eclipse.jetty.server.Request.getParameters(Request.java:435)
        at org.eclipse.jetty.server.Request.getParameterNames(Request.java:1093)
        at ch.qos.logback.access.spi.AccessEvent.buildRequestParameterMap(AccessEvent.java:338)

This stacktrace is during a POST request parsing of a request with Content-Type: application/x-www-form-urlencoded.

The most important thing you need to check right now.
Make sure you have sane values for the "maxFormContentSize" and "maxFormKeys".

Defaults:

• ContextHandler.maxFormContentSize = 200,000
• ContextHandler.maxFormKeys = 1,000

If you have configured larger values, then you are subject to a exactly the scenario you are experiencing.
See: https://ocert.org/advisories/ocert-2011-003.html

Don't set those value too high, especially the maxFormKeys value.
Each 10% of increase in those values increases exponentially your exposure to ocert-2011-003.

While Java can handle large Map instances in terms of size or key count, it's actually quite trivial to make a set of keys that will just consume extraordinary amounts of CPU.

This was fixed in Jetty 7.6.0 as part of https://bugs.eclipse.org/367638 by adding those limits on maxFormKeys and maxFormContentSize.

[joakime]

Also of note, logback-access was written in the time of Jetty 7.x and Jetty 8.x, and hasn't kept up with Jetty 9.1, 9.2, 9.3, or 9.4 changes.

The Request Logging facilities in Jetty 9.4.44, for example, never trigger request body parsing just to log a request (oh that's a decision in logback-access that has bitten many a user of logback-access. Which is what your stacktrace shows btw.)

Note that with Jetty 9.4.44, you also have access to the wonderful CustomRequestLog with it's own configurable output format (like logback-access).
See: https://javadoc.io/static/org.eclipse.jetty/jetty-server/9.4.44.v20210927/org/eclipse/jetty/server/CustomRequestLog.html

And you can even use CustomRequestLog in combination with any slf4j-api based logger, even logback core (which ships with a nifty SiftingAppender to allow you to have multiple log files being populated from different named loggers, so you can keep a unique request log, with rolling and archiving)

[joakime]

The stacktrace also shows a bug in logback-access ...

        at ch.qos.logback.access.jetty.RequestLogImpl.log(RequestLogImpl.java:137)
        at org.eclipse.jetty.server.HttpChannel.onCompleted(HttpChannel.java:812)
        at org.eclipse.jetty.server.HttpChannel.onBadMessage(HttpChannel.java:872)
        at org.eclipse.jetty.server.HttpChannelOverHttp.badMessage(HttpChannelOverHttp.java:283)
        at org.eclipse.jetty.http.HttpParser.badMessage(HttpParser.java:1647)
        at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1629)

The parser failed, triggered a badMessage, and then logback-access attempted to log the request.
But the first thing it does is attempt to parse the request body content.
Uh, the request is bad, there is no valid request body content.
logback-access should not be attempting to parse the request body content.

[joakime]

@gregw What do you think about flagging the bad Request object so that calls to access the request body also fail early with an IOException?

[joakime]

@gregw Perhaps even have the Request be set to "complete" before the onCompleted() is called, to prevent behavior that can alter the Request after it's complete and before it's recycled. (such as a logging framework attempting to read the request body content after the Request is complete).

[dimas]

@joakime , first of all thanks for a very quick reply.
It will take me some time to dive into your comment regarding the logging stuff but here is a quick reply for the first one. "Some sort of attack" was my second thought (after "Amazon load balancer issue") because these servers are often probed by various scanning tools so it would not surprise me....

However... You are saying it was fixed in 7.6 line and we are using one of the latest 9.4 so it should not have this issue. We are definitely not configuring neither maxFormContentSize nor maxFormKeys explicitly so defaults must be active. If there is a way to get these settings from a running server or start it in a debug mode so these values are printed - I am happy to do it of course. But my money are on the fact we are using these low defaults.

[dimas]

Re logback bug that makes it parse the request body content... I do not think logback knows the request should not be logged - this code

    public void onCompleted()
    {
        if (LOG.isDebugEnabled())
            LOG.debug("onCompleted for {} written={}", getRequest().getRequestURI(), getBytesWritten());

        if (_requestLog != null)
            _requestLog.log(_request, _response);

sends the request to logger like any other request. And I checked Jetty's own CustomRequestLog code and I do not see any special handling for "bad message" there - these requests are treated the same way as any normal ones. Maybe I am missing something.

I believe logback causes body parsing because it attempts to extract body parameters. And the reason it does this is because it prepares the event for background processing - the request thread can quickly queue logging event while it will be written into a file by some async appender.

There was a bug in logback causing it to log random stuff with async appenders because Jetty recycles request objects and by the time logback async thread starts writing the event down, the request can contain completely different data. Few years ago I contributed a fix for logback qos-ch/logback#240 that just made sure that when the event is prepared for background processing - all the important attributes are cloned because at that moment you do not know what of the attributes and parameters your async appender (and formatter) will require.

Obviously this attempt to save request data is what causes Jetty to try parsing the body.

I understand that this parsing probably makes no sense for a completely invalid request (badMessage) but you guys are still sending this request into the log() method so you can not expect each possible implementation knows how to deal with it. Some proprietary implementation can unconditionally try reading some request headers/data for logging purposes. Does not feel like logback issue to me.
It really feels like Jetty should just handle attempts to read parameters/attributes/body/whatever for these bad requests instead of entering high CPU consumption loop.

Cheers

[joakime]

CustomRequestLog will use the committed state of the request/response objects to avoid changes caused by the application after the request/response is committed.
It also does not use APIs that will trigger state changes in the request/response objects.

        at org.eclipse.jetty.server.Request.getParameterNames(Request.java:1093)
        at ch.qos.logback.access.spi.AccessEvent.buildRequestParameterMap(AccessEvent.java:338)

The fact that logback-access calls Request.getParameterNames() is a big no-no for request logging, it should never do that.
That will force a request body read (if it hasn't been read before) per the servlet spec behaviors.

Even on a normal request (one that doesn't cause a parser error), imagine this ...

You have a POST request arrive.
Your servlet (or the authentication layer, or a filter, etc) decides the request isn't useful yet.
It responds with a simple 403 Forbidden, never having read the request body.
Now logback-access wakes up to log the request log entry.
It has now triggered a request body READ, not only that, but it's triggered it at the server level, a context-less Request (one that doesn't have context based configuration to limit form data sizes and whatnot)
This will now consume resources to read the request body content, which could easily be malicious (in size? in keys? etc), even though the application intentionally didn't read the request body.
This is a bug in logback-access, a big one IMO, as it could easily lead to a trivial DOS attack.

[joakime]

Here's another example of where logback-access gets things wrong.

https://github.com/qos-ch/logback/blob/v_1.2.6/logback-access/src/main/java/ch/qos/logback/access/jetty/JettyServerAdapter.java#L49

    public int getStatusCode() {
        return response.getStatus();
    }

That will not have the correct response status code, as the status code is not immutable on the servlet spec.
Eg: It can be sent as one value on the network, and then changed after the fact, before the response has even been fully sent.
Many libraries, such as spring-framework, spring-boot, spring-security, will set different status codes on the way out of the context.
Many error handling routines reset the status code as well.
By the time the request logging occurs, logback-access is logging the wrong status code.

We have special APIs to track the committed state (what was actually sent on the wire).

https://github.com/eclipse/jetty.project/blob/jetty-9.4.44.v20210927/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java#L1159

https://github.com/eclipse/jetty.project/blob/8da83308eeca865e495e53ef315a249d63ba9332/jetty-server/src/main/java/org/eclipse/jetty/server/CustomRequestLog.java#L1157-L1160

You might be thinking, "why not write the request log entry before you exit the context?".

Because the request / response exchange is not complete once the context dispatch is complete.
Application buffers, network buffers, etc all take time, the context dispatch is long gone by the time the real status of the request/response exchange is complete and suitable for being logged in the RequestLog.

This is pretty common as well...

@Override
protected void doGet(HttpServletRequest req, HttpServletResponse resp) throws ServletException, IOException
{
    OutputStream out = resp.getOutputStream();
    out.write(getLargeResponseBuffer());
}

The application told the servlet container to write a big buffer, and then completed the dispatch, but writing that buffer can take time.
If the buffer was 10MB, and only 2MB was written to the network before the connection failed, the request log should show that.

[dimas]

@joakime , I see your point now. Thanks for taking time to explain it.

I agree that logback should not have triggered request reading by trying to access request parameters. Unfortunately it does and I am sure they won't accept a PR to stop it from happening because there is probably a lot of people out there who now rely on it as their logging appenders/formatters are configured to log certain parameters of the request. Logback also seems to attempt grabbing the entire request body among other things in this code https://github.com/dimas/logback/blob/master/logback-access/src/main/java/ch/qos/logback/access/spi/AccessEvent.java#L576-L598 and there can be people relying on it too.

I do not know how to fix the problem without massive rework and breaking backward compatibility with what people may be collecting into their access logs. Does not look practical to me.

We may consider changing logging framework but we can not do it for access logs only - right now logback is used for both application logs as well as access logs, all sent out as JSON. I am not sure what is a good replacement these days - may take a look at log4j2 if you say its support for Jetty access log is correct unlike logback's.

Having said that, isn't it worth fixing Jetty in a way so even if logging framework tries to read bad request, it does not enter some infinite loop? Yes, the logging framework should not be doing it for all the reasons you laid out but if it does - at least it won't not cause a 100% CPU consumption....

(I am working from assumption that our CPU consumption is NOT caused by https://ocert.org/advisories/ocert-2011-003.html - I still believe there may be some edge case handling some bad TCP connection or something)

Thanks

[joakime]

I do not know how to fix the problem without massive rework and breaking backward compatibility with what people may be collecting into their access logs. Does not look practical to me.

We may consider changing logging framework but we can not do it for access logs only - right now logback is used for both application logs as well as access logs, all sent out as JSON. I am not sure what is a good replacement these days - may take a look at log4j2 if you say its support for Jetty access log is correct unlike logback's.

There's absolutely no need to switch from logback to log4j. (We here at Eclipse Jetty are huge fans of slf4j and logback)

Note that logback-access is just a small optional sub-component of logback, you can still use the rest of logback as-is without logback-access, even with CustomRequestLog.

If you decide to look into CustomRequestLog, know that you can set it to use the Slf4jRequestLogWriter, which logback will use happily. You can even have separate log files easily enough with logback (regular logs, and request logs separate)

I'm not ready to close this issue, as there are some possible places we can short-circuit the bad behavior, but it's a delicate thing that might cause ripples elsewhere, which means it will take time.

In any case, this was an enlightening issue, thank you for filing it.

[joakime]

I went ahead and opened 2 issues on the logback side as well ...

• https://jira.qos.ch/browse/LOGBACK-1580 - logback-access uses response.getStatus improperly
• https://jira.qos.ch/browse/LOGBACK-1581 - logback-access should not use Request.getParameterNames

[dimas]

Thank you for reaching out to logback team!

Re CustomRequestLog - I would happily use it but from the code I read it seems like it can only form plaintext strings. We moved to structured text (JSON) everywhere long time ago because it allows us to have these logs nicely indexed in either elasticsearch/logstash/kibana stack or in CloudWatch. Plaintext feels just wrong when the app started with all these separate attributes but bunched them all together into a human-readable string and then you have to create rules to parse that string back into individual attributes. Just some unnecessary conversions back and forth.

I bet we can specify format string as something like { "status": %s, "bytes_received": %I, "method": "%m" } so when thee values are substituted, so our log will look like JSON. But only look like it - should any of the things being logged contain a quotation mark for example - it will render the resulting JSON as invalid. The whole thing becomes too fragile.

However, I understand this conversation has nothing to do with the issue at hands. Just explaining why we use what we use...

[joakime]

Can you share your logback-access configuration?