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.8k stars 1.9k forks source link

Jetty12 ee9 request recycling #8024

Open gregw opened 2 years ago

gregw commented 2 years ago

Jetty version(s)

jetty-12 ee9

Description

If AsyncContext.complete is called from a random thread, then the context exit listeners see a recycled request. For example when running: org.eclipse.jetty.ee9.servlet.AsyncServletTest#testStartWaitComplete I get:

java.lang.IllegalStateException: channel already completed
    at org.eclipse.jetty.server@12.0.0-SNAPSHOT/org.eclipse.jetty.server.internal.HttpChannelState$ChannelRequest.lockedGetHttpChannel(HttpChannelState.java:880)
    at org.eclipse.jetty.server@12.0.0-SNAPSHOT/org.eclipse.jetty.server.internal.HttpChannelState$ChannelRequest.getHttpChannel(HttpChannelState.java:873)
    at org.eclipse.jetty.server@12.0.0-SNAPSHOT/org.eclipse.jetty.server.internal.HttpChannelState$ChannelRequest.getAttribute(HttpChannelState.java:809)
    at org.eclipse.jetty.util@12.0.0-SNAPSHOT/org.eclipse.jetty.util.Attributes$Wrapper.getAttribute(Attributes.java:135)
    at org.eclipse.jetty.server@12.0.0-SNAPSHOT/org.eclipse.jetty.server.handler.ContextRequest.getAttribute(ContextRequest.java:131)
    at org.eclipse.jetty.util@12.0.0-SNAPSHOT/org.eclipse.jetty.util.Attributes$Wrapper.getAttribute(Attributes.java:135)
    at org.eclipse.jetty.ee9.nested@12.0.0-SNAPSHOT/org.eclipse.jetty.ee9.nested.AsyncAttributes.getAttribute(AsyncAttributes.java:61)
    at org.eclipse.jetty.ee9.nested@12.0.0-SNAPSHOT/org.eclipse.jetty.ee9.nested.ServletAttributes.getAttribute(ServletAttributes.java:63)
    at org.eclipse.jetty.ee9.nested@12.0.0-SNAPSHOT/org.eclipse.jetty.ee9.nested.Request.getAttribute(Request.java:587)
    at org.eclipse.jetty.ee9.nested@12.0.0-SNAPSHOT/org.eclipse.jetty.ee9.nested.DebugListener.findRequestName(DebugListener.java:166)
    at org.eclipse.jetty.ee9.nested@12.0.0-SNAPSHOT/org.eclipse.jetty.ee9.nested.DebugListener$3.exitScope(DebugListener.java:315)
    at org.eclipse.jetty.ee9.nested@12.0.0-SNAPSHOT/org.eclipse.jetty.ee9.nested.ContextHandler.exitScope(ContextHandler.java:909)
    at org.eclipse.jetty.ee9.nested@12.0.0-SNAPSHOT/org.eclipse.jetty.ee9.nested.ContextHandler$CoreContextHandler.exitScope(ContextHandler.java:2547)
    at org.eclipse.jetty.server@12.0.0-SNAPSHOT/org.eclipse.jetty.server.handler.ContextHandler$Context.run(ContextHandler.java:898)
    at org.eclipse.jetty.ee9.nested@12.0.0-SNAPSHOT/org.eclipse.jetty.ee9.nested.ContextHandler.handle(ContextHandler.java:942)
    at org.eclipse.jetty.ee9.nested@12.0.0-SNAPSHOT/org.eclipse.jetty.ee9.nested.HttpChannelState.runInContext(HttpChannelState.java:1205)
    at org.eclipse.jetty.ee9.nested@12.0.0-SNAPSHOT/org.eclipse.jetty.ee9.nested.HttpChannelState.complete(HttpChannelState.java:724)
    at org.eclipse.jetty.ee9.nested@12.0.0-SNAPSHOT/org.eclipse.jetty.ee9.nested.AsyncContextState.complete(AsyncContextState.java:66)
    at org.eclipse.jetty.ee9.servlet@12.0.0-SNAPSHOT/org.eclipse.jetty.ee9.servlet.AsyncServletTest$AsyncServlet$2.run(AsyncServletTest.java:815)
    at java.base/java.util.TimerThread.mainLoop(Timer.java:566)
    at java.base/java.util.TimerThread.run(Timer.java:516)
gregw commented 2 years ago

@sbordet @lorban @lachlan-roberts Do we think this is a problem? I lean to yes, as these listeners are part of our Debugging handler and have worked before. There are probably similar problems with servlet-spec listeners as well.

Not sure how we can fix this? how to delay the recycling until all our API calls have returned. Note that in this case we are still within the scope of a complete call.

gregw commented 2 years ago

I've put in a work around for the DebugListener, so it now catches this exception and handles it correctly. Still not a perfect fix as there is still the cost of creating the exception, but at least that is only in some circumstances.

lorban commented 2 years ago

I'm tempted to consider this a bug: the request should not be recycled before AsyncContext.complete() returned. But what do we do with timeouts? Do we keep the resources around hoping for a AsyncContext.complete() call to eventually come?

gregw commented 2 years ago

@lorban The simple solution is to move the attributes map from the channel to the request. This would mean that after recycling a request could still be accessed, but the cost is that a ConcurrentHashMap may be constructed for every request (if arbitrary attributes are used). Previous testing has shown that this is a measurable cost, but we can mitigate by including specific handling for most known attributes used by our code.

Note that this is probably a problem in previous versions of jetty, but we have not notices as the attribute map has been accessed and found to be empty rather than getting an ISE indicating that the connection to the attribute map has been severed. I guess an alternate solution might be to return null rather than throw ISE?

lorban commented 2 years ago

Returning a null map sounds like a sure way to get a NPE instead of the current ISE. I don't think that would improve anything.

gregw commented 2 years ago

@lorban not a null map, a null value from the attribute get. Would be same behaviour as jetty-9,10,11. Still not entirely correct behavior.... but the same. Ultimately we need to re-benchmark the cost of creating a ConcurrentHashMap per request with the four options:

  1. always create the map in the HttpChannel and reuse in each request
  2. lazily create the map in the HttpChannel and reuse in each request (extra atomic dereference)
  3. always create the map in the Request
  4. lazily create the map in the Request

Can you run some benchmarks?

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.

gregw commented 1 year ago

Touch

github-actions[bot] commented 2 months 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.

eugene-sadovsky commented 2 weeks ago

Hello, I would like to share another case where this manifests itself now, starting from jetty 12.0.1

We have a SpringBoot 3 application, with REST controller. HTTP request kicks-off an async operation and returns HTTP response to the client right away.

The @Async operation, running on a different thread, needs to make few HTTP calls to other services. It also needs to propagate some of the HTTP headers from the original HTTP request. There's a fairly common way to do this in SpringWeb, using org.springframework.web.context.request.RequestContextHolder, here's an example from spring-cloud-openfeign on how it's used

We do it the same way, copy the request attributes from the parent thread, the one that served the HTTP request, i.e.

import org.springframework.core.task.TaskDecorator;
import org.springframework.web.context.request.RequestAttributes;
import org.springframework.web.context.request.RequestContextHolder;

public class AsyncRequestAttributesPropagator implements TaskDecorator {

    @Override
    public Runnable decorate(Runnable runnable) {
        RequestAttributes parentRequestAttributes = RequestContextHolder.getRequestAttributes();
        return () -> {
            try {
                RequestContextHolder.setRequestAttributes(parentRequestAttributes);
                runnable.run();
            } finally {
                RequestContextHolder.resetRequestAttributes();
            }
        };
    }

}

RequestAttributes holds a refference to org.eclipse.jetty.ee10.servlet.ServletApiRequest which might be recycled at the point when we try to access request headers or request attributes. So we started to see this kind of errors

java.lang.RuntimeException: java.lang.NullPointerException: Cannot invoke "org.eclipse.jetty.server.Request.getHeaders()" because the return value of "org.eclipse.jetty.ee10.servlet.ServletApiRequest.getRequest()" is null
    at a.b.c.feign.AuthorizationHeaderInterceptor.getAuthorizationHeader(AuthorizationHeaderInterceptor.java:30)
    at a.b.c.feign.AuthorizationHeaderInterceptor.apply(AuthorizationHeaderInterceptor.java:19)

My investigation led me to this commit in Jetty https://github.com/jetty/jetty.project/commit/cdf5035ab22f695af3084c5184abbe065c8c77ae#diff-08a987495c36d6ed1f41979826c3e93113157535428e3f9b0887704654001271R449 particularly changes in ServletChannel::recycle() method after which behavior has changed. I'm able to confirm this against previous commit.

I may be wrong, but this looks to me more like a Spring issue, from jetty standpoint request-response loop has finished and internal objects can be recycled. We shouldn't hold on to them outside the original http request without utilizing some wrappers around the original request

eugene-sadovsky commented 2 weeks ago

after the discussion in spring-framework, this seems to be an miss-use on my side. In any case, this has nothing to do with this issue in jetty