AsyncProxyServlet calls onProxyResponseSuccess() when internally it throws "Response header too large" exception

[arshadwkhan]

Jetty version
9.4.30

Java version
8

OS type/version
Mac

Description
I am using embedded jetty version 9.4.30 and use AsyncProxyServlet to reverse proxy request to the server. When the server returns a very large header, AsyncProxyServlet calls onProxyResponseSuccess() with proxyResponse.status=200 even though the servlet sends http status 500 to the client. Is it possible to detect "Response header too large" error in AsyncProxyServlet ?

[gregw]

@arshadwkhan can you attach any stack traces that you have, as that will make it easier to replicate.

[arshadwkhan]

@gregw Attaching logs
jetty.log

[arshadwkhan]

@gregw @joakime Did you get a chance to look into this issue ? Will apprreciate your guidance on this ?

[gregw]

@arshadwkhan not yet. Other priorities sorry.

But just to clarify the scenario:

1. request received client->proxy
2. request sent proxy->server
3. response received server-> proxy with large header
4. 200 response fails to be sent proxy->server because of header too large. 500 actually sent, but onProxyResponseSuccess is called with 200

I think this is because onProxyResponseSuccess is an event to say the proxy has successfully received the 200 from the server and probably happens prior to the forwarding of the response to the client.

How big is the response body? Would it likely overflow a buffer and cause the response to the client to be committed during transfer of the body, or is it smallish, and thus we'd only discover the too large header once the handling is over and we try to commit?

So if I'm reading this right, the code in onProxyResponseSuccess actually does an AsyncContext.complete(), so it is after that that any problem with the size of the headers in the response will be detected. Moreover that complete call does not give any mechanism to report errors... Hmmm or does it... maybe an onError could get called on the AsyncContext...

Eitherway, it is a difficult case where there error happens after the proxy app says it is finished with the request/response. We'll have to do some experiments to see.
At the very least, you should be able to install a HttpChannel.Listener and see all events, including this 500 - but it would be a little separate from the proxy.

I probably wont have time to look at this in detail until next week.

[arshadwkhan]

I think OnProxyResponseSuccess() is called after a response is committed to the client. It sends http status 500 to the client.
This problem started happening after we upgraded from 9.4.27 to 9.4.30. Before the upgrade to 9.4.30 it used to call onProxyResponseFailure().

Here is the call stack when header overflow is detected.

HttpConnection:761 ==>case HEADER_OVERFLOW:
                    {
                        if (_header.capacity() >= _config.getResponseHeaderSize())
                            throw new BadMessageException(INTERNAL_SERVER_ERROR_500, "Response header too large");
                        releaseHeader();
                        _header = _bufferPool.acquire(_config.getResponseHeaderSize(), HEADER_BUFFER_DIRECT);
                        continue;
                    }

process:761, HttpConnection$SendCallback (org.eclipse.jetty.server)
processing:241, IteratingCallback (org.eclipse.jetty.util)
iterate:223, IteratingCallback (org.eclipse.jetty.util)
send:543, HttpConnection (org.eclipse.jetty.server)
sendResponse:833, HttpChannel (org.eclipse.jetty.server)
write:910, HttpChannel (org.eclipse.jetty.server)
channelWrite:283, HttpOutput (org.eclipse.jetty.server)
access$400:60, HttpOutput (org.eclipse.jetty.server)
process:1668, HttpOutput$AsyncWrite (org.eclipse.jetty.server)
processing:241, IteratingCallback (org.eclipse.jetty.util)
iterate:223, IteratingCallback (org.eclipse.jetty.util)
write:818, HttpOutput (org.eclipse.jetty.server)
onWritePossible:246, AsyncProxyServlet$StreamWriter (org.eclipse.jetty.proxy)
onResponseContent:90, AsyncProxyServlet (org.eclipse.jetty.proxy)
onContent:220, ProxyServlet$ProxyResponseListener (org.eclipse.jetty.proxy)
onContent:189, Response$AsyncContentListener (org.eclipse.jetty.client.api)
notifyContent:155, ResponseNotifier (org.eclipse.jetty.client)
notifyContent:139, ResponseNotifier (org.eclipse.jetty.client)
notifyContent:726, HttpReceiver$ContentListeners (org.eclipse.jetty.client)
access$500:688, HttpReceiver$ContentListeners (org.eclipse.jetty.client)
responseContent:409, HttpReceiver (org.eclipse.jetty.client)
content:295, HttpReceiverOverHTTP (org.eclipse.jetty.client.http)
parseContent:1691, HttpParser (org.eclipse.jetty.http)
parseNext:1526, HttpParser (org.eclipse.jetty.http)
parse:200, HttpReceiverOverHTTP (org.eclipse.jetty.client.http)
process:141, HttpReceiverOverHTTP (org.eclipse.jetty.client.http)
receive:75, HttpReceiverOverHTTP (org.eclipse.jetty.client.http)
demand:118, HttpReceiver (org.eclipse.jetty.client)
accept:-1, 342518151 (org.eclipse.jetty.client.HttpReceiver$ContentListeners$$Lambda$137)
demand:734, HttpReceiver$ContentListeners (org.eclipse.jetty.client)
accept:-1, 1711914035 (org.eclipse.jetty.client.HttpReceiver$ContentListeners$$Lambda$147)
lambda$notifyContent$1:139, ResponseNotifier (org.eclipse.jetty.client)
accept:-1, 1473556966 (org.eclipse.jetty.client.ResponseNotifier$$Lambda$148)
lambda$onContent$0:192, Response$AsyncContentListener (org.eclipse.jetty.client.api)
run:-1, 859920362 (org.eclipse.jetty.client.api.Response$AsyncContentListener$$Lambda$149)
succeeded:129, Callback$3 (org.eclipse.jetty.util)
succeeded:266, Callback$Nested (org.eclipse.jetty.util)
complete:284, AsyncProxyServlet$StreamWriter (org.eclipse.jetty.proxy)
onWritePossible:252, AsyncProxyServlet$StreamWriter (org.eclipse.jetty.proxy)
run:1492, HttpOutput (org.eclipse.jetty.server)
handle:1454, ContextHandler (org.eclipse.jetty.server.handler)
handle:487, HttpChannel (org.eclipse.jetty.server)
run:335, HttpChannel (org.eclipse.jetty.server)
runJob:806, QueuedThreadPool (org.eclipse.jetty.util.thread)
run:938, QueuedThreadPool$Runner (org.eclipse.jetty.util.thread)
run:748, Thread (java.lang)

[arshadwkhan]

@gregw any update on this issue ? This looks like a defect. Can you please confirm ?

[arshadwkhan]

@gregw @joakime is there a way I can escalate this ? This is definitely a bug.

[arshadwkhan]

@gregw @joakime any update on this issue. I have provided all the stack trace and logs. Let me know if you need anything else ?

[joakime]

Sorry, we've not looked at this as we have other priorities.

[arshadwkhan]

@joakime thanks for the update. Can you please convert this to defect ? The underlying layer eats up the error and sends http status 500 to the client but reports http status 200 to asyncservlet.

[github-actions]

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]

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]

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.

[sbordet]

FTR, the behavior reported is expected (in Jetty 12).

The logs show that the server generator is not able to generate a response due to the response headers being too large.

This failure is detected and handled, and since the response has not been committed, an error response is generated, which results in a 500.

The response 500 is a perfectly valid HTTP response, and that's why onProxyResponseSuccess() is called, and this response is then relayed to the client.

However, this issue uncovered a few glitches in Jetty 12, which have been addressed in #12351.

Sorry for the long time to get this issue looked at!