jetty.project
jetty.project copied to clipboard
jetty
Cannot invoke "org.eclipse.jetty.client.transport.HttpExchange.getRequest()" because "exchange" is null
Jetty version(s) 12.0.9
Jetty Environment ee9
Java
openjdk version "17.0.11" 2024-04-16
OpenJDK Runtime Environment Temurin-17.0.11+9 (build 17.0.11+9)
OpenJDK 64-Bit Server VM Temurin-17.0.11+9 (build 17.0.11+9, mixed mode, sharing)
Maven
Apache Maven 3.9.6 (bc0240f3c744dd6b6ec2920b3cd08dcc295161ae)
Maven home: C:\java\apache-maven-3.9.6
Java version: 17.0.11, vendor: Eclipse Adoptium, runtime: C:\Program Files\Eclipse Adoptium\jdk-17.0.11.9-hotspot
Default locale: en_US, platform encoding: Cp1252
OS name: "windows 10", version: "10.0", arch: "amd64", family: "windows"
OS type/version
Microsoft Windows [Version 10.0.19045.4291]
Description
java.lang.NullPointerException: Cannot invoke "org.eclipse.jetty.client.transport.HttpExchange.getRequest()" because "exchange" is null
at org.eclipse.jetty.client.transport.HttpSender.abortRequest(HttpSender.java:237)
at org.eclipse.jetty.client.transport.HttpSender.internalAbort(HttpSender.java:389)
at org.eclipse.jetty.client.transport.HttpSender$ContentSender.onCompleteFailure(HttpSender.java:605)
at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:335)
at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:231)
at org.eclipse.jetty.client.transport.HttpSender.send(HttpSender.java:85)
at org.eclipse.jetty.client.transport.internal.HttpChannelOverHTTP.send(HttpChannelOverHTTP.java:86)
at org.eclipse.jetty.client.transport.HttpChannel.send(HttpChannel.java:142)
at org.eclipse.jetty.client.transport.HttpConnection.send(HttpConnection.java:112)
at org.eclipse.jetty.client.transport.internal.HttpConnectionOverHTTP$Delegate.send(HttpConnectionOverHTTP.java:330)
at org.eclipse.jetty.client.transport.internal.HttpConnectionOverHTTP.send(HttpConnectionOverHTTP.java:159)
at org.eclipse.jetty.client.transport.HttpDestination.send(HttpDestination.java:444)
at org.eclipse.jetty.client.transport.HttpDestination.process(HttpDestination.java:420)
at org.eclipse.jetty.client.transport.HttpDestination.process(HttpDestination.java:375)
at org.eclipse.jetty.client.transport.HttpDestination.send(HttpDestination.java:358)
at org.eclipse.jetty.client.transport.HttpDestination.send(HttpDestination.java:352)
at org.eclipse.jetty.client.transport.HttpDestination.send(HttpDestination.java:329)
at org.eclipse.jetty.client.transport.HttpDestination.send(HttpDestination.java:308)
at org.eclipse.jetty.client.transport.HttpRequest.sendAsync(HttpRequest.java:751)
at org.eclipse.jetty.client.transport.HttpDestination.send(HttpDestination.java:303)
at org.eclipse.jetty.client.transport.HttpRequest.send(HttpRequest.java:744)
at org.eclipse.jetty.client.CompletableResponseListener.send(CompletableResponseListener.java:79)
at org.eclipse.jetty.client.transport.HttpRequest.send(HttpRequest.java:707)
at _unit test stack frame_
at java.base/java.lang.reflect.Method.invoke(Method.java:568)
at _test stack frame_
Perhaps, coincidentally, I just saw a similar stack trace with an another test; note that our custom servlet subclasses Jetty's AsyncMiddleManServlet, so I am not sure if the stack traces below are from the client side since the test uses the Jetty client or the server side since the AsyncMiddleManServlet also uses the Jetty client.
2024-05-24 15:39:45,009 WARN [HttpClient@3c1e23ff-24][o.e.j.i.SelectorManager] Exception while notifying connection HttpConnectionOverHTTP@7de18c7::SocketChannelEndPoint@3e19ce4[{l=/127.0.0.1:62969,r=localhost/127.0.0.1:59815,OPEN,fill=FI,flush=-,to=0/30000}{io=1/1,kio=1,kro=1}]->[HttpConnectionOverHTTP@7de18c7(l:/127.0.0.1:62969 <-> r:localhost/127.0.0.1:59815,closed=false)=>HttpChannelOverHTTP@46e312fc(exchange=HttpExchange@e8e3{req=HttpRequest[PATCH /api/abc00.txt HTTP/1.1]@77efd004[TERMINATED/null] res=HttpResponse[HTTP/1.1 100 Continue]@78e674a1[PENDING/null]})[send=HttpSenderOverHTTP@26ccedb3(req=FAILURE,failure=java.lang.NullPointerException: Cannot invoke "org.eclipse.jetty.client.transport.HttpExchange.getRequest()" because "this.exchange" is null)[HttpGenerator@218c4e79{s=START}],recv=HttpReceiverOverHTTP@286ac5bc(ex=HttpExchange@e8e3{req=HttpRequest[PATCH /api/abc00.txt HTTP/1.1]@77efd004[TERMINATED/null] res=HttpResponse[HTTP/1.1 100 Continue]@78e674a1[PENDING/null]},rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]]
java.lang.NullPointerException: Cannot invoke "org.eclipse.jetty.client.transport.HttpExchange.getRequest()" because "exchange" is null
at org.eclipse.jetty.client.transport.HttpSender.abortRequest(HttpSender.java:237) ~[jetty-client-12.0.9.jar:12.0.9]
at org.eclipse.jetty.client.transport.HttpSender.internalAbort(HttpSender.java:389) ~[jetty-client-12.0.9.jar:12.0.9]
at org.eclipse.jetty.client.transport.HttpSender$ContentSender.onCompleteFailure(HttpSender.java:605) ~[jetty-client-12.0.9.jar:12.0.9]
at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:335) ~[jetty-util-12.0.9.jar:12.0.9]
at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:231) ~[jetty-util-12.0.9.jar:12.0.9]
at org.eclipse.jetty.client.transport.HttpSender.send(HttpSender.java:85) ~[jetty-client-12.0.9.jar:12.0.9]
at org.eclipse.jetty.client.transport.internal.HttpChannelOverHTTP.send(HttpChannelOverHTTP.java:86) ~[jetty-client-12.0.9.jar:12.0.9]
at org.eclipse.jetty.client.transport.HttpChannel.send(HttpChannel.java:142) ~[jetty-client-12.0.9.jar:12.0.9]
at org.eclipse.jetty.client.transport.HttpConnection.send(HttpConnection.java:112) ~[jetty-client-12.0.9.jar:12.0.9]
at org.eclipse.jetty.client.transport.internal.HttpConnectionOverHTTP$Delegate.send(HttpConnectionOverHTTP.java:330) ~[jetty-client-12.0.9.jar:12.0.9]
at org.eclipse.jetty.client.transport.internal.HttpConnectionOverHTTP.send(HttpConnectionOverHTTP.java:159) ~[jetty-client-12.0.9.jar:12.0.9]
at org.eclipse.jetty.client.transport.HttpDestination.send(HttpDestination.java:444) ~[jetty-client-12.0.9.jar:12.0.9]
at org.eclipse.jetty.client.transport.HttpDestination.process(HttpDestination.java:420) ~[jetty-client-12.0.9.jar:12.0.9]
at org.eclipse.jetty.client.transport.HttpDestination.process(HttpDestination.java:375) ~[jetty-client-12.0.9.jar:12.0.9]
at org.eclipse.jetty.client.transport.HttpDestination.send(HttpDestination.java:358) ~[jetty-client-12.0.9.jar:12.0.9]
at org.eclipse.jetty.client.transport.HttpDestination.succeeded(HttpDestination.java:291) ~[jetty-client-12.0.9.jar:12.0.9]
at org.eclipse.jetty.client.AbstractConnectionPool.proceed(AbstractConnectionPool.java:315) ~[jetty-client-12.0.9.jar:12.0.9]
at org.eclipse.jetty.client.AbstractConnectionPool$FutureConnection.succeeded(AbstractConnectionPool.java:615) ~[jetty-client-12.0.9.jar:12.0.9]
at org.eclipse.jetty.client.AbstractConnectionPool$FutureConnection.succeeded(AbstractConnectionPool.java:593) ~[jetty-client-12.0.9.jar:12.0.9]
at org.eclipse.jetty.util.Promise$Wrapper.succeeded(Promise.java:195) ~[jetty-util-12.0.9.jar:12.0.9]
at org.eclipse.jetty.client.transport.internal.HttpConnectionOverHTTP.onOpen(HttpConnectionOverHTTP.java:167) ~[jetty-client-12.0.9.jar:12.0.9]
at org.eclipse.jetty.io.SelectorManager.connectionOpened(SelectorManager.java:325) [jetty-io-12.0.9.jar:12.0.9]
at org.eclipse.jetty.io.ClientConnector$ClientSelectorManager.connectionOpened(ClientConnector.java:616) [jetty-io-12.0.9.jar:12.0.9]
at org.eclipse.jetty.io.ManagedSelector.createEndPoint(ManagedSelector.java:401) [jetty-io-12.0.9.jar:12.0.9]
at org.eclipse.jetty.io.ManagedSelector$CreateEndPoint.run(ManagedSelector.java:1056) [jetty-io-12.0.9.jar:12.0.9]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:979) [jetty-util-12.0.9.jar:12.0.9]
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1209) [jetty-util-12.0.9.jar:12.0.9]
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1164) [jetty-util-12.0.9.jar:12.0.9]
at java.base/java.lang.Thread.run(Thread.java:840) [?:?]
2024-05-24 15:39:45,027 WARN [HttpClient@3c1e23ff-18][o.e.j.i.SelectorManager] Exception while notifying connection HttpConnectionOverHTTP@29cf8d83::SocketChannelEndPoint@2d3f260[{l=/[0:0:0:0:0:0:0:1]:62970,r=localhost/[0:0:0:0:0:0:0:1]:59815,OPEN,fill=FI,flush=-,to=2/30000}{io=1/1,kio=1,kro=8}]->[HttpConnectionOverHTTP@29cf8d83(l:/[0:0:0:0:0:0:0:1]:62970 <-> r:localhost/[0:0:0:0:0:0:0:1]:59815,closed=false)=>HttpChannelOverHTTP@565aa3bb(exchange=null)[send=HttpSenderOverHTTP@149f6dee(req=QUEUED,failure=null)[HttpGenerator@41e9496b{s=START}],recv=HttpReceiverOverHTTP@5cb4f3c4(ex=null,rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]]
java.lang.IllegalStateException: Entry already enabled ConcurrentEntry@701b6587{terminated=false,multiplex=0,pooled=HttpConnectionOverHTTP@7de18c7::SocketChannelEndPoint@3e19ce4[{l=/127.0.0.1:62969,r=localhost/127.0.0.1:59815,OPEN,fill=FI,flush=-,to=1/30000}{io=1/1,kio=1,kro=1}]->[HttpConnectionOverHTTP@7de18c7(l:/127.0.0.1:62969 <-> r:localhost/127.0.0.1:59815,closed=false)=>HttpChannelOverHTTP@46e312fc(exchange=null)[send=HttpSenderOverHTTP@26ccedb3(req=FAILURE,failure=java.lang.NullPointerException: Cannot invoke "org.eclipse.jetty.client.transport.HttpExchange.getRequest()" because "this.exchange" is null)[HttpGenerator@218c4e79{s=START}],recv=HttpReceiverOverHTTP@286ac5bc(ex=null,rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]]} for ConcurrentPool@1bf9f49d[strategy=FIRST,inUse=0,size=1,max=64,leaked=0,terminated=false]
at org.eclipse.jetty.util.ConcurrentPool$ConcurrentEntry.enable(ConcurrentPool.java:489) ~[jetty-util-12.0.9.jar:12.0.9]
at org.eclipse.jetty.client.AbstractConnectionPool$FutureConnection.succeeded(AbstractConnectionPool.java:612) ~[jetty-client-12.0.9.jar:12.0.9]
at org.eclipse.jetty.client.AbstractConnectionPool$FutureConnection.succeeded(AbstractConnectionPool.java:593) ~[jetty-client-12.0.9.jar:12.0.9]
at org.eclipse.jetty.util.Promise$Wrapper.succeeded(Promise.java:195) ~[jetty-util-12.0.9.jar:12.0.9]
at org.eclipse.jetty.client.transport.internal.HttpConnectionOverHTTP.onOpen(HttpConnectionOverHTTP.java:167) ~[jetty-client-12.0.9.jar:12.0.9]
at org.eclipse.jetty.io.SelectorManager.connectionOpened(SelectorManager.java:325) [jetty-io-12.0.9.jar:12.0.9]
at org.eclipse.jetty.io.ClientConnector$ClientSelectorManager.connectionOpened(ClientConnector.java:616) [jetty-io-12.0.9.jar:12.0.9]
at org.eclipse.jetty.io.ManagedSelector.createEndPoint(ManagedSelector.java:401) [jetty-io-12.0.9.jar:12.0.9]
at org.eclipse.jetty.io.ManagedSelector$CreateEndPoint.run(ManagedSelector.java:1056) [jetty-io-12.0.9.jar:12.0.9]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:979) [jetty-util-12.0.9.jar:12.0.9]
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1209) [jetty-util-12.0.9.jar:12.0.9]
at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1164) [jetty-util-12.0.9.jar:12.0.9]
at java.base/java.lang.Thread.run(Thread.java:840) [?:?]
Note that the test hangs, perhaps due to the second stack trace in the block above.
How to reproduce?
The reproducer is in PR: https://github.com/jetty/jetty.project/pull/11891, but it is "random", sometimes it happens, sometimes is does not. Using Microsoft's SysInternal's CPU Stres tool helps recreate the issue.
This stack trace is from a test case using a Jetty 12 HTTP Client to a Jetty 12 Server using a custom AsyncMiddleManServlet subclass. I can't share any of it unfortunately.
I am wondering if it is possible that there is some asynchronous bad luck involved here.
@garydgregory I'm looking at this, and I think there is something else going on, and the NPE appears to be a red herring.
I'll keep the issue posted.
@sbordet
The NPE in this issue and the problems in #11894 are in the way to reproduce another more difficult to reproduce issue on the server-side which shows up as an HTTP 502 Bad Gateway in the test below.
java.lang.IllegalStateException: demand pending
at org.eclipse.jetty.io/org.eclipse.jetty.io.content.AsyncContent.demand(AsyncContent.java:222)
(full stack below)
In addition to "fixing" the NPEs with my PR and to workaround the Jetty client hanging problem, I am using (like our actual test suite), Apache HttpClient 5 as the HTTP client, instead of the Jetty Client in a AsyncMiddleManServletTest test:
import java.io.ByteArrayInputStream;
import java.io.ByteArrayOutputStream;
import java.io.IOException;
import java.io.InputStream;
import java.io.InputStreamReader;
import java.io.OutputStream;
import java.lang.management.ManagementFactory;
import java.lang.management.ThreadInfo;
import java.lang.management.ThreadMXBean;
import java.net.URLDecoder;
import java.net.URLEncoder;
import java.nio.ByteBuffer;
import java.nio.charset.StandardCharsets;
import java.nio.file.DirectoryStream;
import java.nio.file.Files;
import java.nio.file.Path;
import java.util.ArrayList;
import java.util.Collections;
import java.util.HashMap;
import java.util.List;
import java.util.Map;
import java.util.Random;
import java.util.concurrent.CompletableFuture;
import java.util.concurrent.CountDownLatch;
import java.util.concurrent.ThreadLocalRandom;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.TimeoutException;
import java.util.concurrent.atomic.AtomicBoolean;
import java.util.concurrent.atomic.AtomicInteger;
import java.util.zip.GZIPInputStream;
import java.util.zip.GZIPOutputStream;
import java.util.zip.ZipEntry;
import java.util.zip.ZipInputStream;
import java.util.zip.ZipOutputStream;
import jakarta.servlet.ServletException;
import jakarta.servlet.ServletInputStream;
import jakarta.servlet.ServletOutputStream;
import jakarta.servlet.http.HttpServlet;
import jakarta.servlet.http.HttpServletRequest;
import jakarta.servlet.http.HttpServletResponse;
import org.apache.hc.client5.http.config.RequestConfig;
import org.apache.hc.client5.http.impl.classic.CloseableHttpClient;
import org.apache.hc.client5.http.impl.classic.HttpClients;
import org.apache.hc.client5.http.impl.routing.DefaultProxyRoutePlanner;
import org.apache.hc.client5.http.routing.HttpRoutePlanner;
import org.apache.hc.core5.http.ClassicHttpRequest;
import org.apache.hc.core5.http.ContentType;
import org.apache.hc.core5.http.HttpEntity;
import org.apache.hc.core5.http.HttpHost;
import org.apache.hc.core5.http.io.entity.ByteArrayEntity;
import org.apache.hc.core5.http.io.entity.EntityUtils;
import org.apache.hc.core5.http.io.support.ClassicRequestBuilder;
import org.apache.hc.core5.util.Timeout;
import org.eclipse.jetty.client.AsyncRequestContent;
import org.eclipse.jetty.client.BytesRequestContent;
import org.eclipse.jetty.client.CompletableResponseListener;
import org.eclipse.jetty.client.ContentResponse;
import org.eclipse.jetty.client.HttpClient;
import org.eclipse.jetty.client.HttpProxy;
import org.eclipse.jetty.client.Request;
import org.eclipse.jetty.client.Response;
import org.eclipse.jetty.ee9.servlet.ServletContextHandler;
import org.eclipse.jetty.ee9.servlet.ServletHolder;
import org.eclipse.jetty.http.HttpFields;
import org.eclipse.jetty.http.HttpHeader;
import org.eclipse.jetty.http.HttpHeaderValue;
import org.eclipse.jetty.http.HttpStatus;
import org.eclipse.jetty.io.RuntimeIOException;
import org.eclipse.jetty.logging.StacklessLogging;
import org.eclipse.jetty.server.HttpConfiguration;
import org.eclipse.jetty.server.HttpConnectionFactory;
import org.eclipse.jetty.server.Server;
import org.eclipse.jetty.server.ServerConnector;
import org.eclipse.jetty.toolchain.test.jupiter.WorkDir;
import org.eclipse.jetty.toolchain.test.jupiter.WorkDirExtension;
import org.eclipse.jetty.util.BufferUtil;
import org.eclipse.jetty.util.Callback;
import org.eclipse.jetty.util.IO;
import org.eclipse.jetty.util.Utf8StringBuilder;
import org.eclipse.jetty.util.ajax.JSON;
import org.eclipse.jetty.util.component.LifeCycle;
import org.eclipse.jetty.util.thread.QueuedThreadPool;
import org.junit.jupiter.api.AfterEach;
import org.junit.jupiter.api.Test;
import org.junit.jupiter.api.condition.OS;
import org.junit.jupiter.api.extension.ExtendWith;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import static org.junit.jupiter.api.Assertions.assertArrayEquals;
import static org.junit.jupiter.api.Assertions.assertEquals;
import static org.junit.jupiter.api.Assertions.assertFalse;
import static org.junit.jupiter.api.Assertions.assertNotNull;
import static org.junit.jupiter.api.Assertions.assertNull;
import static org.junit.jupiter.api.Assertions.assertTrue;
// This is in AsyncMiddleManServletTest ...
@Test
public void testServletExpect100ApacheHttpClient5() throws Exception
{
startServer(new HttpServlet()
{
private AtomicInteger count = new AtomicInteger();
@Override
protected void service(HttpServletRequest request, HttpServletResponse response) throws IOException
{
// Adding logging may slow things down enough to not hang
// System.out.printf("Origin servicing %d%n", count.incrementAndGet());
// Send the 100 Continue.
ServletInputStream input = request.getInputStream();
// Echo the content.
IO.copy(input, response.getOutputStream());
// Slowing down the origin allows the test to not hang sometimes
// try {
// Thread.sleep(50);
// } catch (InterruptedException e) {
// e.printStackTrace();
// }
}
});
startProxy(new AsyncMiddleManServlet()
{
protected void service(HttpServletRequest request, HttpServletResponse response) throws ServletException, IOException
{
// Adding logging may slow things down enough to not hang
// System.out.printf("AsyncMiddleManServlet servicing %n");
super.service(request, response);
}
});
RequestConfig requestConfig = RequestConfig.custom()
.setExpectContinueEnabled(true)
.setResponseTimeout(5, TimeUnit.SECONDS)
.build();
HttpHost proxyHost = new HttpHost("localhost", proxyConnector.getLocalPort());
HttpHost targetHost = new HttpHost("localhost", serverConnector.getLocalPort());
HttpRoutePlanner routePlanner = new DefaultProxyRoutePlanner(proxyHost);
try (CloseableHttpClient httpclient = HttpClients.custom()
.setDefaultRequestConfig(requestConfig)
.setRoutePlanner(routePlanner)
.build()) {
// loop to attempt increase odds of hanging
for (int i = 1; i <= 500; i++) {
long start = System.currentTimeMillis();
System.out.printf("Sending #%d%n", i);
ClassicHttpRequest request = ClassicRequestBuilder.post("http://localhost:" + serverConnector.getLocalPort())
.setHeader(HttpHeader.EXPECT.toString(), HttpHeaderValue.CONTINUE.toString())
.setEntity("a")
.build();
httpclient.execute(targetHost, request, response -> {
System.out.println(response.getCode() + " " + response.getReasonPhrase());
assertEquals(200, response.getCode());
HttpEntity entity = response.getEntity();
EntityUtils.consume(entity);
return null;
});
System.out.printf(" %,d ms%n", System.currentTimeMillis() - start);
}
}
}
Randomly produces (you might have to try a few times and/or stress the CPU):
java.lang.IllegalStateException: demand pending
at org.eclipse.jetty.io/org.eclipse.jetty.io.content.AsyncContent.demand(AsyncContent.java:222)
at org.eclipse.jetty.client/org.eclipse.jetty.client.transport.HttpSender$ContentSender.process(HttpSender.java:525)
at org.eclipse.jetty.util/org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:250)
at org.eclipse.jetty.util/org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:231)
at org.eclipse.jetty.client/org.eclipse.jetty.client.transport.HttpSender.send(HttpSender.java:85)
at org.eclipse.jetty.client/org.eclipse.jetty.client.transport.internal.HttpChannelOverHTTP.send(HttpChannelOverHTTP.java:86)
at org.eclipse.jetty.client/org.eclipse.jetty.client.transport.HttpChannel.send(HttpChannel.java:142)
at org.eclipse.jetty.client/org.eclipse.jetty.client.transport.HttpConnection.send(HttpConnection.java:112)
at org.eclipse.jetty.client/org.eclipse.jetty.client.transport.internal.HttpConnectionOverHTTP$Delegate.send(HttpConnectionOverHTTP.java:330)
at org.eclipse.jetty.client/org.eclipse.jetty.client.transport.internal.HttpConnectionOverHTTP.send(HttpConnectionOverHTTP.java:159)
at org.eclipse.jetty.client/org.eclipse.jetty.client.transport.HttpDestination.send(HttpDestination.java:444)
at org.eclipse.jetty.client/org.eclipse.jetty.client.transport.HttpDestination.process(HttpDestination.java:420)
at org.eclipse.jetty.client/org.eclipse.jetty.client.transport.HttpDestination.process(HttpDestination.java:375)
at org.eclipse.jetty.client/org.eclipse.jetty.client.transport.HttpDestination.send(HttpDestination.java:358)
at org.eclipse.jetty.client/org.eclipse.jetty.client.transport.HttpDestination.send(HttpDestination.java:352)
at org.eclipse.jetty.client/org.eclipse.jetty.client.transport.HttpDestination.send(HttpDestination.java:329)
at org.eclipse.jetty.client/org.eclipse.jetty.client.transport.HttpDestination.send(HttpDestination.java:308)
at org.eclipse.jetty.client/org.eclipse.jetty.client.transport.HttpRequest.sendAsync(HttpRequest.java:751)
at org.eclipse.jetty.client/org.eclipse.jetty.client.transport.HttpDestination.send(HttpDestination.java:303)
at org.eclipse.jetty.client/org.eclipse.jetty.client.transport.HttpRequest.send(HttpRequest.java:744)
at org.eclipse.jetty.ee9.proxy/org.eclipse.jetty.ee9.proxy.AbstractProxyServlet.sendProxyRequest(AbstractProxyServlet.java:637)
at org.eclipse.jetty.ee9.proxy/org.eclipse.jetty.ee9.proxy.AsyncMiddleManServlet.service(AsyncMiddleManServlet.java:128)
at org.eclipse.jetty.ee9.proxy/org.eclipse.jetty.ee9.proxy.AsyncMiddleManServletTest$5.service(AsyncMiddleManServletTest.java:447)
at [email protected]/jakarta.servlet.http.HttpServlet.service(HttpServlet.java:587)
at org.eclipse.jetty.ee9.servlet.ServletHolder.handle(ServletHolder.java:765)
at org.eclipse.jetty.ee9.servlet.ServletHandler.doHandle(ServletHandler.java:528)
at org.eclipse.jetty.ee9.nested.ScopedHandler.nextHandle(ScopedHandler.java:195)
at org.eclipse.jetty.ee9.nested.SessionHandler.doHandle(SessionHandler.java:476)
at org.eclipse.jetty.ee9.nested.ScopedHandler.nextHandle(ScopedHandler.java:195)
at org.eclipse.jetty.ee9.nested.ContextHandler.doHandle(ContextHandler.java:1034)
at org.eclipse.jetty.ee9.nested.ScopedHandler.nextScope(ScopedHandler.java:164)
at org.eclipse.jetty.ee9.servlet.ServletHandler.doScope(ServletHandler.java:483)
at org.eclipse.jetty.ee9.nested.ScopedHandler.nextScope(ScopedHandler.java:162)
at org.eclipse.jetty.ee9.nested.SessionHandler.doScope(SessionHandler.java:470)
at org.eclipse.jetty.ee9.nested.ScopedHandler.nextScope(ScopedHandler.java:162)
at org.eclipse.jetty.ee9.nested.ContextHandler.doScope(ContextHandler.java:955)
at org.eclipse.jetty.ee9.nested.ScopedHandler.handle(ScopedHandler.java:125)
at org.eclipse.jetty.ee9.nested.ContextHandler.handle(ContextHandler.java:1693)
at org.eclipse.jetty.ee9.nested.HttpChannel$RequestDispatchable.dispatch(HttpChannel.java:1575)
at org.eclipse.jetty.ee9.nested.HttpChannel.dispatch(HttpChannel.java:737)
at org.eclipse.jetty.ee9.nested.HttpChannel.handle(HttpChannel.java:510)
at org.eclipse.jetty.ee9.nested.ContextHandler$CoreContextHandler$CoreToNestedHandler.handle(ContextHandler.java:2727)
at org.eclipse.jetty.server/org.eclipse.jetty.server.handler.ContextHandler.handle(ContextHandler.java:851)
at org.eclipse.jetty.server/org.eclipse.jetty.server.Server.handle(Server.java:181)
at org.eclipse.jetty.server/org.eclipse.jetty.server.internal.HttpChannelState$HandlerInvoker.run(HttpChannelState.java:635)
at org.eclipse.jetty.server/org.eclipse.jetty.server.internal.HttpConnection.onFillable(HttpConnection.java:403)
at org.eclipse.jetty.io/org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:322)
at org.eclipse.jetty.io/org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:99)
at org.eclipse.jetty.io/org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
at org.eclipse.jetty.util/org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:478)
at org.eclipse.jetty.util/org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:441)
at org.eclipse.jetty.util/org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293)
at org.eclipse.jetty.util/org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:201)
at org.eclipse.jetty.util/org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:311)
at org.eclipse.jetty.util/org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:979)
at org.eclipse.jetty.util/org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1209)
at org.eclipse.jetty.util/org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1164)
at java.base/java.lang.Thread.run(Thread.java:840)
The most simple way to see this stack trace is to add a call to printStackTrace() call in AbstractProxyServlet.proxyResponseStatus(Throwable) like this:
protected int proxyResponseStatus(Throwable failure)
{
failure.printStackTrace();
return failure instanceof TimeoutException
? HttpStatus.GATEWAY_TIMEOUT_504
: HttpStatus.BAD_GATEWAY_502;
}
Using logging can affect the timing and randomness too much to easily reproduce this.
@garydgregory we can reproduce both exceptions (NPE and demand pending), but still working on a better solution that would avoid both, rather than guarding against.
@garydgregory how sure you are that you are not sending a request with 100-Continue, but Content-Length: 0?
Because I can reproduce the issue with that combination, but as soon as there is a content, it's not reproducible.
We should support that combination, I think, but it's technically not necessary to send expect 100-Continue if there is no content.
Hello @sbordet,
Yes, it is reproducible with and without an HTTP body.
Note that the randomly failing test above uses an HTTP POST with a one-character body.
This showcases the observation that the shorter the body, the easier it might be to reproduce. Reproducing the issue more reliably may require using a CPU stress program like Micorsoft SysInternal’s “CPU Stres” (Windows) app. That’s the case on my laptop: ThinkPad L15; Windows 10 (22H2 build 19045.4412); CPU 11th Gen Intel(R) Core(TM) i7-1165G7 @ 2.80GHz 2.80 GHz; 16 GB RAM.
I agree with your statement that an expect 100 is not needed if there is no body but unfortunately that’s not what we have to support in the real world with actual client apps.
Some of our testing and actual usage reflects what we've seen HTTP clients send our server in the wild. We have instances where the HTTP framework used on the client side which we do not control, enables expect 100, whether it's needed or not. We must deal with it, which means for us that Jetty should allow it without throwing NPEs or “demand pending” exception (albeit random but reproducible).
To recap, there are several issues at play that are likely related, three exceptions: The two NPEs and the “demand pending” exceptions, plus the Jetty client hanging.
Gathering links for record keeping:
- This issue https://github.com/jetty/jetty.project/issues/11841 containing a test for “demand pending” exception.
- PR https://github.com/jetty/jetty.project/pull/11891 to address two NPEs in a simple manner.
- Issue https://github.com/jetty/jetty.project/issues/11894 for the Jetty Client hanging.
TY!
Hello @sbordet Is there anything more I can do to help move solutions (partial, proposed or otherwise) forward?
@garydgregory thanks for the offer, but unfortunately I don't see much you could do to help speeding up the resolution of this bug.
The team is a bit stretched thin at the moment so it's hard to find cycles, but I promise we haven't forgotten about you and will get this fixed ASAP. I'm sorry about having to make you wait.
@garydgregory sorry it took so long, but there were multiple issues, and it took a while to get a grip on all of them.
Can you please try branch fix/jetty-12.0.x/httpsender-proxy-continue-fixes and see if it works for you?
Hello @sbordet
I built and installed (mvn clean install -DskipTests) the branch locally and it does fix the issue 👍 Than you.
Two items of note:
- It looks like using the Jetty HTTP Client for a
GETwithout a body, aContent-Lengthand aContent-Typeheader is now sent, which was not a case in 11.x and causes some of our tests to fail (because we record most HTTP data and assert it):
Accept-Encoding: gzip
User-Agent: Jetty/12.0.13-SNAPSHOT
Host: localhost:50650
Content-Type: application/octet-stream
Content-Length: 0
This is different from the other HTTP clients we test and a difference in behavior from 11.x we'd need to adapt unless it is a mistake. Please let me know.
- It was easy for me to adapt but it should be noted in the release notes that there is a binary incompatible change:
org.eclipse.jetty.ee9.proxy.AsyncMiddleManServlet.onContinue(HttpServletRequest, Request)returns a Runnable in the branch but is avoidmethod in 12.0.12
Well done & thank you!
@garydgregory thanks for the feedback!
The first bullet should be addressed by https://github.com/jetty/jetty.project/pull/12113/commits/4e9755d6f8082a364f68140fa5d96439977aabee, so perhaps you can update to the latest branch code and try again?
The second bullet was necessary, but that method should not be overridden or called by applications. Are you overriding it? If so, may I ask why?
@sbordet
Thank you for the update, I'll pull, build, and test next.
WRT to the onContinue() override, it seems to be no longer needed. In previous versions, we did see random runs where the implementation in AsyncMiddleManServlet called proxyRequest.getAttributes().get(CONTINUE_ACTION_ATTRIBUTE) which returned null and caused an NPE in onContinue(). The current implementation of AsyncMiddleMan seems to make this no longer possible, I hope.
Hello @sbordet The news is mostly good! I only have 9 test failing tests that I am debugging ATM. This is all the same test parameterized with different inputs (HTTP method DELETE, GET, PATCH fail but PUT and POST are OK, different HTTP clients: Apache HttpComponents 4.x, 5.x, and Jetty Client). I'll post back here ASAP with details.
@sbordet
OK, I think we're good with this branch! Thank you!
What are expectations regarding a merge and release? (Do you have a public snapshot Maven repository?)
Details: Our tests made some special allowances for some probably unusual behavior in Jetty 11.0.20 where we saw Jetty return a 417 "Expectation Failed" for DELETE, GET, and PATCH requests without a body but with an Expect 100 header. It's simple enough to update these tests on our end.
OK, I think we're good with this branch! Thank you!
What are expectations regarding a merge and release? (Do you have a public snapshot Maven repository?)
@garydgregory once merged a nightly build will push snapshot to https://oss.sonatype.org/content/repositories/jetty-snapshots
Details: Our tests made some special allowances for some probably unusual behavior in Jetty 11.0.20 where we saw Jetty return a 417 "Expectation Failed" for DELETE, GET, and PATCH requests without a body but with an Expect 100 header. It's simple enough to update these tests on our end.
TY @olamy I will test on the next build now that the PR has been merged.
@garydgregory https://jenkins.webtide.net/job/nightlies/job/jetty-12.0.x-snapshots-deploy/ build 710 will do this for you
Arg, using 12.0.13-SNAPSHOT, I just got a random:
java.lang.NullPointerException: Cannot invoke "org.eclipse.jetty.client.transport.HttpExchange.getRequest()" because "exchange" is null
at org.eclipse.jetty.client.transport.HttpSender.abortRequest(HttpSender.java:237)
at org.eclipse.jetty.client.transport.HttpSender.internalAbort(HttpSender.java:392)
at org.eclipse.jetty.client.transport.HttpSender$ContentSender.onCompleteFailure(HttpSender.java:629)
at org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:354)
at org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:243)
at org.eclipse.jetty.client.transport.HttpSender.send(HttpSender.java:85)
at org.eclipse.jetty.client.transport.internal.HttpChannelOverHTTP.send(HttpChannelOverHTTP.java:86)
at org.eclipse.jetty.client.transport.HttpChannel.send(HttpChannel.java:142)
at org.eclipse.jetty.client.transport.HttpConnection.send(HttpConnection.java:112)
at org.eclipse.jetty.client.transport.internal.HttpConnectionOverHTTP$Delegate.send(HttpConnectionOverHTTP.java:367)
at org.eclipse.jetty.client.transport.internal.HttpConnectionOverHTTP.send(HttpConnectionOverHTTP.java:162)
at org.eclipse.jetty.client.transport.HttpDestination.send(HttpDestination.java:444)
at org.eclipse.jetty.client.transport.HttpDestination.process(HttpDestination.java:420)
at org.eclipse.jetty.client.transport.HttpDestination.process(HttpDestination.java:375)
at org.eclipse.jetty.client.transport.HttpDestination.send(HttpDestination.java:358)
at org.eclipse.jetty.client.transport.HttpDestination.send(HttpDestination.java:352)
at org.eclipse.jetty.client.transport.HttpDestination.send(HttpDestination.java:329)
at org.eclipse.jetty.client.transport.HttpDestination.send(HttpDestination.java:308)
at org.eclipse.jetty.client.transport.HttpRequest.sendAsync(HttpRequest.java:751)
at org.eclipse.jetty.client.transport.HttpDestination.send(HttpDestination.java:303)
at org.eclipse.jetty.client.transport.HttpRequest.send(HttpRequest.java:744)
at org.eclipse.jetty.client.CompletableResponseListener.send(CompletableResponseListener.java:79)
at org.eclipse.jetty.client.transport.HttpRequest.send(HttpRequest.java:707)
<custom code redacted>
Any thoughts?
@lorban
I've updated the test to show the failure still occurs, always, eventually, for me. I would be curious to see what your testing reveals.
The test is in https://github.com/garydgregory/jetty.project/pull/new/12.0.x_issue_11841_NPE
Run mvn test -pl jetty-ee9/jetty-ee9-proxy -Dtest=AsyncMiddleManServletTest#testServletExpect100ApacheHttpClient5 -Dcheckstyle.skip=true
This test shows the NPEs on the console.
Eventually, it will fail the test which checks for replies with status 200, for example:
...
# 7,142 1 ms
java.lang.NullPointerException: Cannot invoke "org.eclipse.jetty.client.transport.HttpExchange.getRequest()" because "exchange" is null
at [email protected]/org.eclipse.jetty.client.transport.HttpSender$ContentSender.process(HttpSender.java:511)
at [email protected]/org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:262)
at [email protected]/org.eclipse.jetty.util.IteratingCallback.succeeded(IteratingCallback.java:401)
at [email protected]/org.eclipse.jetty.io.content.AsyncContent.runDemandCallback(AsyncContent.java:238)
at [email protected]/org.eclipse.jetty.io.content.AsyncContent.invokeDemandCallback(AsyncContent.java:231)
at [email protected]/org.eclipse.jetty.util.thread.SerializedInvoker$Link.run(SerializedInvoker.java:245)
at [email protected]/org.eclipse.jetty.util.thread.SerializedInvoker.run(SerializedInvoker.java:154)
at [email protected]/org.eclipse.jetty.io.content.AsyncContent.offer(AsyncContent.java:117)
at [email protected]/org.eclipse.jetty.io.content.AsyncContent.close(AsyncContent.java:151)
at [email protected]/org.eclipse.jetty.ee9.proxy.AsyncMiddleManServlet$ProxyReader.process(AsyncMiddleManServlet.java:382)
at [email protected]/org.eclipse.jetty.ee9.proxy.AsyncMiddleManServlet$ProxyReader.process(AsyncMiddleManServlet.java:328)
at [email protected]/org.eclipse.jetty.util.IteratingCallback.processing(IteratingCallback.java:262)
at [email protected]/org.eclipse.jetty.util.IteratingCallback.iterate(IteratingCallback.java:243)
at [email protected]/org.eclipse.jetty.ee9.proxy.AsyncMiddleManServlet$ProxyReader.onDataAvailable(AsyncMiddleManServlet.java:280)
at org.eclipse.jetty.ee9.nested.HttpInput.run(HttpInput.java:434)
at org.eclipse.jetty.ee9.nested.ContextHandler.handle(ContextHandler.java:1100)
at org.eclipse.jetty.ee9.nested.HttpChannel.handle(HttpChannel.java:597)
at org.eclipse.jetty.ee9.nested.HttpChannel.lambda$needContent$0(HttpChannel.java:161)
at [email protected]/org.eclipse.jetty.server.handler.ContextHandler$ScopedContext.run(ContextHandler.java:1507)
at [email protected]/org.eclipse.jetty.server.handler.ContextRequest$OnContextDemand.run(ContextRequest.java:74)
at [email protected]/org.eclipse.jetty.util.thread.SerializedInvoker$Link.run(SerializedInvoker.java:245)
at [email protected]/org.eclipse.jetty.server.internal.HttpConnection$DemandContentCallback.succeeded(HttpConnection.java:680)
at [email protected]/org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:99)
at [email protected]/org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
at [email protected]/org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:478)
at [email protected]/org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:441)
at [email protected]/org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293)
at [email protected]/org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:201)
at [email protected]/org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:311)
at [email protected]/org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:979)
at [email protected]/org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1209)
at [email protected]/org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1164)
at java.base/java.lang.Thread.run(Thread.java:840)
# 7,143 5 ms
...
# 7,222 1 ms
# 7,223 1 ms
# 7,224 1 ms
# 7,225 0 ms
java.lang.NullPointerException
2024-08-30 18:35:06.420:INFO :oejs.Server:ForkJoinPool-1-worker-1: Stopped oejs.Server@221f8fd5{STOPPING}[12.0.13-SNAPSHOT,sto=0]
2024-08-30 18:35:06.424:INFO :oejs.AbstractConnector:ForkJoinPool-1-worker-1: Stopped ServerConnector@1b89ab2f{HTTP/1.1, (http/1.1)}{0.0.0.0:0}
[ERROR] Tests run: 1, Failures: 1, Errors: 0, Skipped: 0, Time elapsed: 11.66 s <<< FAILURE! -- in org.eclipse.jetty.ee9.proxy.AsyncMiddleManServletTest
[ERROR] org.eclipse.jetty.ee9.proxy.AsyncMiddleManServletTest.testServletExpect100ApacheHttpClient5 -- Time elapsed: 11.53 s <<< FAILURE!
org.opentest4j.AssertionFailedError: expected: <200> but was: <502>
at org.junit.jupiter.api.AssertionFailureBuilder.build(AssertionFailureBuilder.java:151)
at org.junit.jupiter.api.AssertionFailureBuilder.buildAndThrow(AssertionFailureBuilder.java:132)
at org.junit.jupiter.api.AssertEquals.failNotEqual(AssertEquals.java:197)
at org.junit.jupiter.api.AssertEquals.assertEquals(AssertEquals.java:150)
at org.junit.jupiter.api.AssertEquals.assertEquals(AssertEquals.java:145)
at org.junit.jupiter.api.Assertions.assertEquals(Assertions.java:531)
at [email protected]/org.eclipse.jetty.ee9.proxy.AsyncMiddleManServletTest.lambda$testServletExpect100ApacheHttpClient5$0(AsyncMiddleManServletTest.java:260)
at org.apache.hc.client5.http.impl.classic.CloseableHttpClient.execute(CloseableHttpClient.java:247)
at org.apache.hc.client5.http.impl.classic.CloseableHttpClient.execute(CloseableHttpClient.java:213)
at [email protected]/org.eclipse.jetty.ee9.proxy.AsyncMiddleManServletTest.testServletExpect100ApacheHttpClient5(AsyncMiddleManServletTest.java:258)
at java.base/java.lang.reflect.Method.invoke(Method.java:569)
at java.base/java.util.concurrent.RecursiveAction.exec(RecursiveAction.java:194)
at java.base/java.util.concurrent.ForkJoinTask.doExec(ForkJoinTask.java:373)
at java.base/java.util.concurrent.ForkJoinPool$WorkQueue.topLevelExec(ForkJoinPool.java:1182)
at java.base/java.util.concurrent.ForkJoinPool.scan(ForkJoinPool.java:1655)
at java.base/java.util.concurrent.ForkJoinPool.runWorker(ForkJoinPool.java:1622)
at java.base/java.util.concurrent.ForkJoinWorkerThread.run(ForkJoinWorkerThread.java:165)
[INFO]
[INFO] Results:
[INFO]
[ERROR] Failures:
[ERROR] AsyncMiddleManServletTest.testServletExpect100ApacheHttpClient5:258->lambda$testServletExpect100ApacheHttpClient5$0:260 expected: <200> but was: <502>
[INFO]
[ERROR] Tests run: 1, Failures: 1, Errors: 0, Skipped: 0
[INFO]
[INFO] ------------------------------------------------------------------------
[INFO] BUILD FAILURE
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 39.722 s
[INFO] Finished at: 2024-08-30T18:35:07-04:00
[INFO] ------------------------------------------------------------------------
I am using:
Apache Maven 3.9.9 (8e8579a9e76f7d015ee5ec7bfcdc97d260186937)
Maven home: C:\java\apache-maven-3.9.9
Java version: 17.0.12, vendor: Eclipse Adoptium, runtime: C:\Program Files\Eclipse Adoptium\jdk-17.0.12.7-hotspot
Default locale: en_US, platform encoding: Cp1252
OS name: "windows 10", version: "10.0", arch: "amd64", family: "windows"
Hello @lorban @sbordet This is still a problem in 12.0.13. Shouldn't this issue be reopened?
@garydgregory we're working on it, @lorban will update this and/or open a new issue.
@garydgregory see https://github.com/jetty/jetty.project/pull/12210#issuecomment-2348325466