Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

High CPU in qtp HttpInput.nextInterceptedContent() #7712

Closed
boekhold opened this issue Mar 9, 2022 · 10 comments
Closed

High CPU in qtp HttpInput.nextInterceptedContent() #7712

boekhold opened this issue Mar 9, 2022 · 10 comments
Labels
Bug For general bugs on Jetty side

Comments

@boekhold
Copy link

boekhold commented Mar 9, 2022

Jetty version(s)
9.4.7.v20170914, embedded

Java version/vendor (use: java -version)
java version "1.8.0_162"
Java(TM) SE Runtime Environment (build 1.8.0_162-b12)
Java HotSpot(TM) 64-Bit Server VM (build 25.162-b12, mixed mode)

OS type/version
Windows Server 2012, Version 6.2 build 9200

Description
We have an internal application running, for which I observed high CPU usage while idle. Upon inspecting with JVisualVM/JMC, I noticed that a single "qtp" thread is consuming most CPU. The application is otherwise idle, no requests are currently coming in.

image

This thread seems to be looping inside org.eclipse.jetty.server.HttpInput.nextInterceptedContent():

image

The stacktrace of this thread is:

"qtp1393325366-3623" #3623 prio=5 os_prio=0 tid=0x0000000026640000 nid=0x3bb8 runnable [0x0000000028e5e000]
   java.lang.Thread.State: RUNNABLE
        at org.eclipse.jetty.server.HttpInput.nextInterceptedContent(HttpInput.java:467)
        at org.eclipse.jetty.server.HttpInput.addContent(HttpInput.java:609)
        - locked <0x00000000922b5c30> (a java.util.ArrayDeque)
        at org.eclipse.jetty.server.HttpChannel.onContent(HttpChannel.java:615)
        at org.eclipse.jetty.server.HttpChannelOverHttp.content(HttpChannelOverHttp.java:247)
        at org.eclipse.jetty.http.HttpParser.parseContent(HttpParser.java:1614)
        at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1385)
        at org.eclipse.jetty.server.HttpConnection.parseRequestBuffer(HttpConnection.java:351)
        at org.eclipse.jetty.server.HttpConnection.fillAndParseForContent(HttpConnection.java:286)
        at org.eclipse.jetty.server.HttpInputOverHTTP.produceContent(HttpInputOverHTTP.java:33)
        at org.eclipse.jetty.server.HttpInput.nextContent(HttpInput.java:359)
        at org.eclipse.jetty.server.HttpInput.consumeAll(HttpInput.java:671)
        - locked <0x00000000922b5c30> (a java.util.ArrayDeque)
        at org.eclipse.jetty.server.HttpConnection.onCompleted(HttpConnection.java:413)
        at org.eclipse.jetty.server.HttpChannel.onCompleted(HttpChannel.java:651)
        at org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:459)
        at org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:251)
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:279)
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:104)
        at org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:124)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:247)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:140)
        at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
        at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:243)
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:679)
        at org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:597)
        at java.lang.Thread.run(Thread.java:748)

   Locked ownable synchronizers:
        - None

Line 467 is a call to _content = _inputQ.poll();, so it appears that nextInterceptedContent() never exits the while loop started at Line 434.

The only way to recover from this is to shutdown and restart the application.

Upon further research, I have discovered that this issue is triggered during an automated PAN test that our internal security team is running nightly against "all open ports on all servers" inside our data center. The access.log file unfortunately does not provide enough detail to identify the exact test that is triggering this issue. Some possible candidates are:

[2022-03-07 11:27:01.474] WARN |qtp1393325366-3623          |org.eclipse.jetty.http.HttpParser                                Illegal character 0x20 in state=HEADER for buffer HeapByteBuffer@17dce847[p=180,l=239,c=8192,r=59]={GET / HTTP/1.0\r\nH...-Forwarded-For <<<header: ${jndi:co...QUALYSTEST}\r\n\r\n>>>ST}\r\n\r\n\n\r\n0%80%ae...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}
[2022-03-07 11:29:30.046] WARN |qtp1393325366-3623          |org.eclipse.jetty.http.HttpParser                                Illegal character 0x20 in state=HEADER for buffer HeapByteBuffer@17dce847[p=228,l=286,c=8192,r=58]={GET /websso/SAML2...-Forwarded-For <<<header: ${jndi:ht...QUALYSTEST}\r\n\r\n>>>e/%f8%80%80%80%ae...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00} 
[2022-03-07 11:29:43.050] WARN |qtp1393325366-3623          |org.eclipse.jetty.util.URIUtil                                   /%c0%ae%c0%ae/%c0%ae%c0%ae/%c0%ae%c0%ae/%c0%ae%c0%ae/%c0%ae%c0%ae/%c0%ae%c0%ae/%c0%ae%c0%ae/%c0%ae%c0%ae/%c0%ae%c0%ae/%c0%ae%c0%ae/%c0%ae%c0%ae/%c0%ae%c0%ae/boot.ini org.eclipse.jetty.util.Utf8Appendable$NotUtf8Exception: Not valid UTF8! byte C0 in state 0  

These are the only messages in our log files related to this specific thread, listed in order. The last line therefore seems to be the most likely cause for this issue.

The only other issue logged against Jetty that references nextInterceptedContent() is #6973, however my issue does not seem to match the description of #6973.

I'm trying to find evidence that this issue is fixed in newer (>9.4.7.v20170914) releases of Jetty, so that I can try to convince the team owning this application to upgrade to a newer version of the (internal) framework on which this application has been built (the latest version of this framework includes Jetty 9.4.43).

How to reproduce?

@boekhold boekhold added the Bug For general bugs on Jetty side label Mar 9, 2022
@joakime
Copy link
Contributor

joakime commented Mar 9, 2022

Are you using logback, or logback access perhaps? Or something similar that doesn't do access.log properly (you should see the 400 responses for those 3 example requests in your access.log if you are using a proper RequestLog setup in Jetty).

Improper RequestLog usage is the most common reason for your high CPU.
Where the RequestLog access the request body content (a giant no-no) either directly with things like Request.getInputStream() or indirectly via things like Request.getParameters(), this is because RequestLog is outside of the scope of the Servlet layer, and usage of HttpInput in that realm is undefined.

@joakime
Copy link
Contributor

joakime commented Mar 9, 2022

Note that a consumeAll fix was implemented in Jetty 9.4.40.v20210413 as part of Issue #6168

Also note that Java 1.8.0_162 expired in January 16, 2018 and should not be used in production right now.
See: https://www.oracle.com/java/technologies/javase/8u162-relnotes.html
The expiration dates of Java are vitally important in production, especially so if you use SSL/TLS anywhere (even used as an HTTP client within that JVM).

btw ...

[2022-03-07 11:27:01.474] WARN |qtp1393325366-3623          |org.eclipse.jetty.http.HttpParser                                Illegal character 0x20 in state=HEADER for buffer HeapByteBuffer@17dce847[p=180,l=239,c=8192,r=59]={GET / HTTP/1.0\r\nH...-Forwarded-For <<<header: ${jndi:co...QUALYSTEST}\r\n\r\n>>>ST}\r\n\r\n\n\r\n0%80%ae...\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00}

... that is your security system testing for the Log4Shell bug.

@joakime
Copy link
Contributor

joakime commented Mar 9, 2022

The latest release, 9.4.45.v20220203 has fixes for logback access and bad request log implementations as well (specifically to address high CPU issues)

@joakime
Copy link
Contributor

joakime commented Mar 9, 2022

Since Jetty 9.4.7, several bugs were fixed in multiple code area whose impact could solve your reported issue.

Upgrading to the latest 9.4 release and try again.
If that fails, the investigation should be resumed.

@boekhold
Copy link
Author

boekhold commented Mar 9, 2022

Hi Joachim, thank you very much for all your comments and details. Indeed this application seems to write access.log via Logback through a Filter class. I don't see any references however to getInputStream() or getParameters() however:

@WebFilter(filterName = "RequestLogFilter", urlPatterns = { "/*" })
final class RequestLogFilter implements Filter {
    private static final Logger LOG = getLogger(RequestLogFilter.class);
    private static final Logger LOG_ERROR = getLogger(RequestLogFilter.class.getPackage().getName());

    private static final String USER_SECURITY = "user";
    private static final String USER_NOT_SET = "UserNotSet";
    private static final String NO_USER_AGENT = "UserAgentNotSet";
    private static final String ACCESS_LOGGED = "AccessLogged";

    @Override
    public void doFilter(ServletRequest request, ServletResponse response, FilterChain chain)
            throws IOException, ServletException {

        if (response instanceof HttpServletResponse && request instanceof HttpServletRequest) {
            Stopwatch timer = Stopwatch.createStarted();
            try {
                chain.doFilter(request, response);
            } catch (Exception e) {
                LOG_ERROR.error("Error occurred on: {}", ((HttpServletRequest)request).getRequestURI(), e);
                throw e;
            } finally {
                HttpServletRequest httpRequest = (HttpServletRequest) request;
                String user = firstNonNull((String)httpRequest.getAttribute(USER_SECURITY), USER_NOT_SET);
                httpRequest.removeAttribute(USER_SECURITY);
                if (httpRequest.getAttribute(ACCESS_LOGGED) == null && (LOG.isTraceEnabled() || LOG.isInfoEnabled())) {
                    // In case the incoming request has NOT been matched to a particular resource by JAX-RS runtime
                    // the access logging falls into responsibility of the web filter.
                    String remoteAddress = httpRequest.getRemoteAddr();
                    String protocol = httpRequest.getProtocol();
                    String httpMethod = httpRequest.getMethod();
                    if (LOG.isTraceEnabled()) {
                        LOG.trace("Received {} - \"{} {} {}\"", remoteAddress, user, protocol, httpMethod);
                    }
                    if (LOG.isInfoEnabled()) {
                        String requestURI = httpRequest.getQueryString() == null
                                            ? httpRequest.getRequestURI()
                                            : httpRequest.getRequestURI() + "?" + httpRequest.getQueryString();
                        LOG.info("{}-{} - \"{} {} {}\" {} \"{}\" {} ms",
                                remoteAddress, user,
                                protocol, httpMethod, requestURI,
                                ((HttpServletResponse)response).getStatus(),
                                firstNonNull(httpRequest.getHeader(USER_AGENT), NO_USER_AGENT),
                                timer.stop().elapsed(MILLISECONDS));
                    }
                }
            }

        } else {
            throw new ServletException(
                    format("Servlet error occurred in the filter: %s",
                            RequestLogFilter.class.getCanonicalName()));
        }
    }

    @Override
    public void init(FilterConfig filterConfig) {
        // Do nothing init not a necessity
    }

    @Override
    public void destroy() {
        // Do nothing destroy not a necessity
    }
}

Can you see anything wrong in the above? In the mean time I will study the issues you linked to, in the hope I can use them to convince our development team to upgrade.

Btw. I'm aware of the Java version. Fortunately this isn't a production system, however I'll investigate if we have any production systems still running with outdated java versions.

@joakime
Copy link
Contributor

joakime commented Mar 9, 2022

Does your configured logback pattern include references to request parameters?

Also note that a Filter based approach for RequestLog is not going to work reliably.
You also wont get RequestLog events for things that don't match your servlet context / webapp. (example, bad requests, 400, requests that trigger an unhandled exception, etc. there's several dozen edge cases)
You also will get what the request/response look like at the time when the Filter is executed, which is often not what the values were when the response was committed. (many libraries will reset the response object after the response is committed, rendering all sorts bad behaviors for a Filter based RequestLog). A proper RequestLog gives you what the state of the request/response was at the time the response was committed, ignoring all changes that have happened after commit.
There's a reason that all servlet containers offer their own Request/Access log features, because a Filter cannot see all of the requests, nor see the true values of the request/response at the time of response commit.

Please look into using Server.setRequestLog(RequestLog) properly.
Based on your output format ...

LOG.info("{}-{} - \"{} {} {}\" {} \"{}\" {} ms",
                                remoteAddress, user,
                                protocol, httpMethod, requestURI,
                                ((HttpServletResponse)response).getStatus(),
                                firstNonNull(httpRequest.getHeader(USER_AGENT), NO_USER_AGENT),
                                timer.stop().elapsed(MILLISECONDS));

You would have the following configuration ...

// Output request log events to a slf4j logger (you can route slf4j to log4j2 or even log4j1 easily)
Slf4jRequestLogWriter logRequestLogWriter = new Slf4jRequestLogWriter();
// The name of the logger to write the events to, you can use a logger configuration to sift/split the events for this named logger
// into a separate file easily enough
logRequestLogWriter.setLoggerName("com.boekhold.accesslog");

// The output format string
String requestLogFormat = "%{client}a-%u - \"%r\" %s \"%{User-Agent}i\" %D";
// Tie together the output/writer and the format string together
CustomRequestLog customRequestLog = new CustomRequestLog(logRequestLogWriter, requestLogFormat);
// Set the RequestLog behavior on the server level (so that all requests/responses can be seen, regardless of servlet rules or errors)
server.setRequestLog(customRequestLog);

See javadoc for CustomRequestLog for format string options.
https://javadoc.io/doc/org.eclipse.jetty/jetty-server/9.4.45.v20220203/org/eclipse/jetty/server/CustomRequestLog.html

@boekhold
Copy link
Author

boekhold commented Mar 9, 2022

Does your configured logback pattern include references to request parameters?

I've searched our code base for any filters used, and cannot find any direct references to request body and/or parameters. However, a few of the filters delegate to 3rd-party libraries, and I cannot be sure what's happening inside those.

Your point on Filters not being suitable for implementing an access.log is taken. I'll bring this info to the development team and hopefully they'll agree to migrate to the CustomRequestLog method.

Thanks Joakim for all the explanations, details and suggestions. Since I don't control the code of this application, I won't be able to try out all of your suggestions immediately, but I'll try my hardest to convince the dev team to take action. I'll close this issue for now, but will update in a comment once/if we've confirmed the fix.

@boekhold boekhold closed this as completed Mar 9, 2022
@joakime
Copy link
Contributor

joakime commented Mar 9, 2022

Does your configured logback pattern include references to request parameters?

I've searched our code base for any filters used, and cannot find any direct references to request body and/or parameters. However, a few of the filters delegate to 3rd-party libraries, and I cannot be sure what's happening inside those.

The question was about your logback configuration, usually in the form of a logback.xml.
Do any of the format strings in there, attempt to look up a request parameter?
This kind of configuration is typically not present in code, but I don't know your app well enough to say for sure.

@boekhold
Copy link
Author

boekhold commented Mar 9, 2022

Joakim, although "access logging" is done through logback, I don't think logback is involved in any way except to just write a string. The logic is fully contained inside that RequestLogFilter for which I included the code above.

Here are the relevant bits of our logback.xml:

<configuration scan="true" scanPeriod="5 seconds">
    <appender name="ACCESS_LOG" class="ch.qos.logback.core.rolling.RollingFileAppender">
        <file>${app.log}/http/access.log</file>
        <rollingPolicy class="ch.qos.logback.core.rolling.FixedWindowRollingPolicy">
            <FileNamePattern>${app.log}/http/access_%i.log</FileNamePattern>
            <MinIndex>1</MinIndex>
            <MaxIndex>10</MaxIndex>
        </rollingPolicy>
        <triggeringPolicy class="ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy">
            <MaxFileSize>20MB</MaxFileSize>
        </triggeringPolicy>
        <encoder class="ch.qos.logback.classic.encoder.PatternLayoutEncoder">
            <Pattern>[%d{yyyy-MM-dd HH:mm:ss.SSS}]  %msg%n</Pattern>
        </encoder>
    </appender>

    <logger level="INFO" additivity="false" name="package.path.to.RequestLogFilter">
        <appender-ref ref="ACCESS_LOG" />
    </logger>
</configuration>

@joakime
Copy link
Contributor

joakime commented May 4, 2022

logback-access has several bugs surrounding the assumptions of what is valid from the HttpServletRequest and HttpServletResponse.
It also attempts to load request body content at the wrong time.

See:

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Bug For general bugs on Jetty side
Projects
None yet
Development

No branches or pull requests

2 participants