jetty / jetty.project

Eclipse Jetty® - Web Container & Clients - supports HTTP/2, HTTP/1.1, HTTP/1.0, websocket, servlets, and more
https://eclipse.dev/jetty
Other
3.86k stars 1.91k forks source link

Upgrading Jetty Results in EofException Reset no_error being Thrown #7190

Closed FreeGuwop closed 1 year ago

FreeGuwop commented 2 years ago

Jetty version(s)

Upgrading from 9.4.31.v2020072 to 9.4.44.v20210927

Java version/vendor (use: java -version)

Amazon Corretto 11

OS type/version

Amazon Linux 2

How to reproduce?

When upgrading Jetty, we have noticed that this error is being thrown in one of our servlets. This servlet is sending a redirect response to a client. Upon inspection, the client is not terminating the connection properly. However, at this point, this is not our concern and Jetty reflects this by showing the _Reset noerror status on the EofException.

To this point, we have not found anyway to suppress these errors. We are running embedded Jetty with a QosFilter so that all requests are asynchronous. We believe the lack of ability to suppress this error to be a bug, there is actually no_error.

org.eclipse.jetty.io.EofException: Reset no_error
    at org.eclipse.jetty.http2.server.HTTP2ServerConnectionFactory$HTTPServerSessionListener.onReset(HTTP2ServerConnectionFactory.java:159)
    at org.eclipse.jetty.http2.HTTP2Stream.notifyReset(HTTP2Stream.java:666)
    at org.eclipse.jetty.http2.HTTP2Stream.onReset(HTTP2Stream.java:399)
    at org.eclipse.jetty.http2.HTTP2Stream.process(HTTP2Stream.java:311)
    at org.eclipse.jetty.http2.HTTP2Session.onReset(HTTP2Session.java:318)
    at org.eclipse.jetty.http2.parser.Parser$Listener$Wrapper.onReset(Parser.java:372)
    at org.eclipse.jetty.http2.parser.BodyParser.notifyReset(BodyParser.java:144)
    at org.eclipse.jetty.http2.parser.ResetBodyParser.onReset(ResetBodyParser.java:97)
    at org.eclipse.jetty.http2.parser.ResetBodyParser.parse(ResetBodyParser.java:66)
    at org.eclipse.jetty.http2.parser.Parser.parseBody(Parser.java:198)
    at org.eclipse.jetty.http2.parser.Parser.parse(Parser.java:127)
    at org.eclipse.jetty.http2.parser.ServerParser.parse(ServerParser.java:115)
    at org.eclipse.jetty.http2.HTTP2Connection$HTTP2Producer.produce(HTTP2Connection.java:261)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:362)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:186)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:137)
    at org.eclipse.jetty.http2.HTTP2Connection.produce(HTTP2Connection.java:183)
    at org.eclipse.jetty.http2.HTTP2Connection.onFillable(HTTP2Connection.java:138)
    at org.eclipse.jetty.http2.HTTP2Connection$FillableCallback.succeeded(HTTP2Connection.java:361)
    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:338)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
    at java.base/java.lang.Thread.run(Thread.java:829)
    Suppressed: java.lang.Throwable: HttpInput failure
        at org.eclipse.jetty.server.HttpInput.failed(HttpInput.java:895)
        at org.eclipse.jetty.http2.server.HttpChannelOverHTTP2.onFailure(HttpChannelOverHTTP2.java:323)
        at org.eclipse.jetty.http2.server.HTTP2ServerConnection.onStreamFailure(HTTP2ServerConnection.java:203)
        at org.eclipse.jetty.http2.server.HTTP2ServerConnectionFactory$HTTPServerSessionListener.onFailure(HTTP2ServerConnectionFactory.java:173)
        at org.eclipse.jetty.http2.server.HTTP2ServerConnectionFactory$HTTPServerSessionListener.onReset(HTTP2ServerConnectionFactory.java:160)
        ... 29 more
sbordet commented 2 years ago

Can you please add few log lines before and after the line that logs the above stack trace? It will help understanding what part of the code logs this asynchronous exception.

FreeGuwop commented 2 years ago

Interestingly, despite logging the exception and swallowing the exception, it is still thrown somewhere later in the Jetty code. This is all the visibility we have into this error.

Full stack trace:


2471957 [1b694e03-9c0e-494e-b879-26ebb9b40be6] s.g.s.RedirectUrlServlet.logErrorMsg - RedirectUrlServlet error: org.eclipse.jetty.io.EofException: Reset no_error
    at org.eclipse.jetty.http2.server.HTTP2ServerConnectionFactory$HTTPServerSessionListener.onReset(HTTP2ServerConnectionFactory.java:159)
    at org.eclipse.jetty.http2.HTTP2Stream.notifyReset(HTTP2Stream.java:666)
    at org.eclipse.jetty.http2.HTTP2Stream.onReset(HTTP2Stream.java:399)
    at org.eclipse.jetty.http2.HTTP2Stream.process(HTTP2Stream.java:311)
    at org.eclipse.jetty.http2.HTTP2Session.onReset(HTTP2Session.java:318)
    at org.eclipse.jetty.http2.parser.Parser$Listener$Wrapper.onReset(Parser.java:372)
    at org.eclipse.jetty.http2.parser.BodyParser.notifyReset(BodyParser.java:144)
    at org.eclipse.jetty.http2.parser.ResetBodyParser.onReset(ResetBodyParser.java:97)
    at org.eclipse.jetty.http2.parser.ResetBodyParser.parse(ResetBodyParser.java:66)
    at org.eclipse.jetty.http2.parser.Parser.parseBody(Parser.java:198)
    at org.eclipse.jetty.http2.parser.Parser.parse(Parser.java:127)
    at org.eclipse.jetty.http2.parser.ServerParser.parse(ServerParser.java:115)
    at org.eclipse.jetty.http2.HTTP2Connection$HTTP2Producer.produce(HTTP2Connection.java:261)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:362)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:186)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:137)
    at org.eclipse.jetty.http2.HTTP2Connection.produce(HTTP2Connection.java:183)
    at org.eclipse.jetty.http2.HTTP2Connection.onFillable(HTTP2Connection.java:138)
    at org.eclipse.jetty.http2.HTTP2Connection$FillableCallback.succeeded(HTTP2Connection.java:361)
    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:338)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:315)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:173)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:131)
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:409)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:883)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1034)
    at java.base/java.lang.Thread.run(Thread.java:829)
    Suppressed: java.lang.Throwable: HttpInput failure
        at org.eclipse.jetty.server.HttpInput.failed(HttpInput.java:895)
        at org.eclipse.jetty.http2.server.HttpChannelOverHTTP2.onFailure(HttpChannelOverHTTP2.java:323)
        at org.eclipse.jetty.http2.server.HTTP2ServerConnection.onStreamFailure(HTTP2ServerConnection.java:203)
        at org.eclipse.jetty.http2.server.HTTP2ServerConnectionFactory$HTTPServerSessionListener.onFailure(HTTP2ServerConnectionFactory.java:173)
        at org.eclipse.jetty.http2.server.HTTP2ServerConnectionFactory$HTTPServerSessionListener.onReset(HTTP2ServerConnectionFactory.java:160)
        ... 29 more```
sbordet commented 2 years ago

I suspect that server receives a RST_STREAM from the client, it wakes up a blocked read in an application Servlet, and it's the application Servlet that logs the stack trace.

Unfortunately, the information you posted so far is insufficient to determine what code is logging this exception, so I would suggest you debug or trace what code is logging this exception -- my suspect is that it's not Jetty code.

FreeGuwop commented 2 years ago

I suspect that server receives a RST_STREAM from the client, it wakes up a blocked read in an application Servlet, and it's the application Servlet that logs the stack trace.

Unfortunately, the information you posted so far is insufficient to determine what code is logging this exception, so I would suggest you debug or trace what code is logging this exception -- my suspect is that it's not Jetty code.

Sorry, the formatting blocked the right thing from showing. I just edited and fixed it. I agree, the application servlet is logging the stack trace. It is also the one logging the exception above. However, after that log message, we swallow the exception.

That same exception is then rethrown somewhere else in the Jetty code which we cannot control. That is the part which I am escalating. If we could just swallow the exception, I think the above behavior would be okay.

Do you have any recommendations on preventing Jetty from throwing these exceptions or rethrowing them, especially given they are marked as no_error? The behavior changed between Jetty versions.

sbordet commented 2 years ago

That same exception is then rethrown somewhere else in the Jetty code which we cannot control.

Why do you say that? Do you have proof? The stack trace you posted is from application code, so it's not Jetty.

FreeGuwop commented 2 years ago

That same exception is then rethrown somewhere else in the Jetty code which we cannot control.

Why do you say that? Do you have proof? The stack trace you posted is from application code, so it's not Jetty.

Yes, we have proof. The stack trace I posted above is from the exception that Jetty bubbles-up to the servlet. However, that exception is swallowed. This is the code that logs and swallows the exception.

catch (Exception e) {
            LOG.severe(String.format("RedirectUrlServlet error: %s", ExceptionUtils.getFullStackTrace(e)));
            response.sendError(HttpServletResponse.SC_INTERNAL_SERVER_ERROR); //internal service error
            return ;
}

Let me post the one that is re-thrown after this is swallowed.

FreeGuwop commented 2 years ago

After that exception in the Servlet is caught as indicated above, it surfaces again in the filter proceeding the servlet. If the filter was not there, it would be thrown outright. This is a filter we use to log metrics and uncaught exceptions:

Code:

try {
    chain.doFilter(request, response);
    // THE EXCEPTION SHOULD BE SWALLOWED AT THIS POINT
  } catch (Throwable t) {
      // DESPITE BEING SWALLOWED BY THE PREVIOUS CODE, WE MAKE OUR WAY HERE SOMEHOW
      // IN THIS STACK TRACE, THE SERVLET IS NOWHERE TO BE FOUND, INDICATING IT IS BUBBLED UP, SWALLOWED
      // AND SOMEHOW RETHROWN
      final Throwable rootCause = Throwables.getRootCause(t);
      log.log(Level.SEVERE, "Uncaught Exception: " + rootCause.getMessage(), rootCause);
      throw t;
  }

Exception:

"8736883 [82c08408-4ba8-45b1-adee-27ed4110edea] s.a.metrics.BaseMetricsFilter.filterWithProcessed - Uncaught Exception: Reset no_error
    at org.eclipse.jetty.http2.server.HTTP2ServerConnectionFactory$HTTPServerSessionListener.onReset(HTTP2ServerConnectionFactory.java:159)
    at org.eclipse.jetty.http2.HTTP2Stream.notifyReset(HTTP2Stream.java:624)
    at org.eclipse.jetty.http2.HTTP2Stream.onReset(HTTP2Stream.java:382)
    at org.eclipse.jetty.http2.HTTP2Stream.process(HTTP2Stream.java:287)
    at org.eclipse.jetty.http2.HTTP2Session.onReset(HTTP2Session.java:306)
    at org.eclipse.jetty.http2.parser.Parser$Listener$Wrapper.onReset(Parser.java:372)
    at org.eclipse.jetty.http2.parser.BodyParser.notifyReset(BodyParser.java:144)
    at org.eclipse.jetty.http2.parser.ResetBodyParser.onReset(ResetBodyParser.java:97)
    at org.eclipse.jetty.http2.parser.ResetBodyParser.parse(ResetBodyParser.java:66)
    at org.eclipse.jetty.http2.parser.Parser.parseBody(Parser.java:198)
    at org.eclipse.jetty.http2.parser.Parser.parse(Parser.java:127)
    at org.eclipse.jetty.http2.parser.ServerParser.parse(ServerParser.java:115)
    at org.eclipse.jetty.http2.HTTP2Connection$HTTP2Producer.produce(HTTP2Connection.java:247)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produceTask(EatWhatYouKill.java:360)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:184)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:171)
    at org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.produce(EatWhatYouKill.java:135)
    at org.eclipse.jetty.http2.HTTP2Connection.produce(HTTP2Connection.java:169)
    at org.eclipse.jetty.http2.HTTP2Connection.onFillable(HTTP2Connection.java:124)
    at org.eclipse.jetty.http2.HTTP2Connection$FillableCallback.succeeded(HTTP2Connection.java:347)
    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:375)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:806)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:938)
    at java.base/java.lang.Thread.run(Thread.java:829)
    Suppressed: java.lang.Throwable: HttpInput failure
        at org.eclipse.jetty.server.HttpInput.failed(HttpInput.java:830)
        at org.eclipse.jetty.http2.server.HttpChannelOverHTTP2.onFailure(HttpChannelOverHTTP2.java:323)
        at org.eclipse.jetty.http2.server.HTTP2ServerConnection.onStreamFailure(HTTP2ServerConnection.java:218)
        at org.eclipse.jetty.http2.server.HTTP2ServerConnectionFactory$HTTPServerSessionListener.onFailure(HTTP2ServerConnectionFactory.java:173)
        at org.eclipse.jetty.http2.server.HTTP2ServerConnectionFactory$HTTPServerSessionListener.onReset(HTTP2ServerConnectionFactory.java:160)
        ... 29 common frames omitted
FreeGuwop commented 2 years ago

Excuse the caps, no idea why I typed it like that. Really appreciate you engaging with us on this :-) !

sbordet commented 2 years ago

Can you put a try/catch around the sendError() that you have in the catch block in the Servlet? sendError() should not throw, so I still don't understand how the exception is rethrown.

Are you sure it's not caused by 2 different requests, one whose exception is caught, and another whose exception is not caught and logged by the filter?

FreeGuwop commented 2 years ago

Do you have any recommendations on preventing Jetty from throwing these exceptions or rethrowing them, especially given they are marked as no_error? The behavior changed between Jetty versions.

I'll try out this theory by logging a unique request ID in both exceptions. Will get back to you on this by Tuesday.

FreeGuwop commented 2 years ago

It is the same request ID.

Trying to move the conversation in a more helpful direction, is there any way we can suppress on_reset specifically in the case of no_error outright? We do not care to receive any of these exceptions.

FreeGuwop commented 2 years ago

I haven't found an easy way to plugin to HTTPServerSessionListener.onReset...I am by no means a Jetty expert. I think that would be the best resolution for us while this seems like an edge-case that the Jetty team may not want to investigate?

sbordet commented 2 years ago

Can you confirm whether sendError() throws or not?

no_error means that there has been an error, but not a more specific one. So it does not mean that there were no errors; it means that there was a non-specific error.

We have no evidence that it's Jetty code that rethrows this exception. It may be, but you must be hitting a special case or have a special configuration that causes this logging, and if that's the case, we'll fix it.

If you have a reproducer, we'll gladly try it out, so it's not that we don't want to investigate.

If you can reproduce locally, you can use your IDE to trigger a breakpoint when EofException is thrown, so we can catch what code is throwing the exception you see.

github-actions[bot] commented 1 year ago

This issue has been automatically marked as stale because it has been a full year without activity. It will be closed if no further activity occurs. Thank you for your contributions.

github-actions[bot] commented 1 year ago

This issue has been closed due to it having no activity.