search

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

RuntimeIOException: Parser is terminated when doing lots of requests with Connection: Keep-Alive #12356

Closed gg-dt closed 1 month ago

gg-dt commented 1 month ago

Jetty version(s) 12.0.13

Jetty Environment core

Java version/vendor (use: java -version) openjdk 21.0.2 2024-01-16 LTS

OS type/version Windows 11

Description When running Apache HTTP's ab tool the -k option (keep the connection alive), after a couple of requests (usually some hundred), ab logs apr_socket_recv: Software caused connection abort (113). When enabling debug logging in Jetty you can see these exceptions:

2024-10-09T13:39:48.325+02:00 DEBUG 8208 --- [qtp274426173-59] o.e.j.server.internal.HttpConnection     : caught exception HttpConnection@16c7d92b::SocketChannelEndPoint@384e5d4f[{l=/[0:0:0:0:0:0:0:1]:8080,r=/[0:0:0:0:0:0:0:1]:55422,OSHUT,fill=-,flush=-,to=0/30000}{io=0/0,kio=0,kro=1}]->[HttpConnection@16c7d92b[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@6a092a24{s=START}]=>HttpChannelState@20e7b60f{handling=null, handled=false, send=SENDING, completed=false, request=null}] HttpChannelState@20e7b60f{handling=null, handled=false, send=SENDING, completed=false, request=null}

org.eclipse.jetty.io.RuntimeIOException: Parser is terminated
    at org.eclipse.jetty.server.internal.HttpConnection.parseRequestBuffer(HttpConnection.java:561) ~[jetty-server-12.0.13.jar:12.0.13]
    at org.eclipse.jetty.server.internal.HttpConnection.onFillable(HttpConnection.java:386) ~[jetty-server-12.0.13.jar:12.0.13]
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:322) ~[jetty-io-12.0.13.jar:12.0.13]
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:99) ~[jetty-io-12.0.13.jar:12.0.13]
    at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53) ~[jetty-io-12.0.13.jar:12.0.13]
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.runTask(AdaptiveExecutionStrategy.java:478) ~[jetty-util-12.0.13.jar:12.0.13]
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.consumeTask(AdaptiveExecutionStrategy.java:441) ~[jetty-util-12.0.13.jar:12.0.13]
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.tryProduce(AdaptiveExecutionStrategy.java:293) ~[jetty-util-12.0.13.jar:12.0.13]
    at org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy.run(AdaptiveExecutionStrategy.java:201) ~[jetty-util-12.0.13.jar:12.0.13]
    at org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:311) ~[jetty-util-12.0.13.jar:12.0.13]
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:979) ~[jetty-util-12.0.13.jar:12.0.13]
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1209) ~[jetty-util-12.0.13.jar:12.0.13]
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1164) ~[jetty-util-12.0.13.jar:12.0.13]
    at java.base/java.lang.Thread.run(Thread.java:1583) ~[na:na]

How to reproduce? I attached a reproducer Java application with spring boot and jetty. ~reproducer.zip~ (UNSAFE, DO NOT DOWNLOAD OR USE AS-IS)

joakime commented 1 month ago

@gregw don't trust the binaries and jar files in the reproducer.zip

Start with a fresh copy of gradle from a known source, or convert the project to maven.

joakime commented 1 month ago

The safer code / example can be found here -> https://github.com/joakime/issue-12356-reproducer

It's a maven build, but the Spring Application doesn't stay running. (it's not setup properly) build.txt

The Spring Application starts/runs, but then is immediately closed/stopped. There's no opportunity to test it. Literally zero time.

joakime commented 1 month ago

Testing an empty non-spring Jetty 12.0.14, using embedded Jetty.

https://github.com/jetty/jetty-examples/blob/12.0.x/embedded/simple-server/src/main/java/examples/SimplestServer.java

And testing it using ab results in ...

$ ab -n 100000 -k "http://localhost:9090/"
This is ApacheBench, Version 2.3 <$Revision: 1879490 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 10000 requests
Completed 20000 requests
Completed 30000 requests
Completed 40000 requests
Completed 50000 requests
Completed 60000 requests
Completed 70000 requests
Completed 80000 requests
Completed 90000 requests
Completed 100000 requests
Finished 100000 requests

Server Software:        Jetty(12.0.14)
Server Hostname:        localhost
Server Port:            9090

Document Path:          /
Document Length:        413 bytes

Concurrency Level:      1
Time taken for tests:   6.540 seconds
Complete requests:      100000
Failed requests:        0
Non-2xx responses:      100000
Keep-Alive requests:    100000
Total transferred:      63900000 bytes
HTML transferred:       41300000 bytes
Requests per second:    15291.34 [#/sec] (mean)
Time per request:       0.065 [ms] (mean)
Time per request:       0.065 [ms] (mean, across all concurrent requests)
Transfer rate:          9542.15 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:     0    0   0.3      0      91
Waiting:        0    0   0.3      0      91
Total:          0    0   0.3      0      91

Percentage of the requests served within a certain time (ms)
  50%      0
  66%      0
  75%      0
  80%      0
  90%      0
  95%      0
  98%      0
  99%      0
 100%     91 (longest request)

Unable to reproduce using Jetty (without Spring Boot)

Server side shows ...

2024-10-09 17:00:16.025:INFO :oejs.Server:main: jetty-12.0.14; built: 2024-09-30T14:22:54.197Z; git: e77516598a07cca826d27fa8a4f7c70e953921a6; jvm 17.0.11+9
2024-10-09 17:00:16.068:INFO :oejs.AbstractConnector:main: Started ServerConnector@29774679{HTTP/1.1, (http/1.1)}{0.0.0.0:9090}
2024-10-09 17:00:16.078:INFO :oejs.Server:main: Started oejs.Server@2d6e8792{STARTING}[12.0.14,sto=0] @337ms
Hint: Hit Ctrl+C to stop Jetty.
gregw commented 1 month ago

@gg-dt Can you comment on why your reproducing code is existing immediately when run?

I also can't see in the source code that it is actually doing anything?

gg-dt commented 1 month ago

@joakime I adapted your maven-based reproducer to actually use Jetty instead of Tomcat, and I added a RestController to it which accepts GET requests on /get/param. The newer version can be found here: https://github.com/gg-dt/issue-12356-reproducer/tree/main

I then started it using mvn spring-boot:run. Now comes the interesting part: When I run ab against the existing endpoint there are no errors: ab -n 100000 -k "http://localhost:8080/get/param" But when running it against an inexisting endpoint (it will get 404s) then after some time it stops. You can see the stacktraces I posted above earlier in the logs:

$ ab -n 100000 -k "http://localhost:8080/inexistent"
This is ApacheBench, Version 2.3 <$Revision: 1843412 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 10000 requests
Completed 20000 requests
Completed 30000 requests
Completed 40000 requests
apr_socket_recv: Software caused connection abort (113)
Total of 47769 requests completed

So it seems to me the error (only?) occurs when a non-200 response like 404 occurs. @joakime can you please run ab against an inexistant endpoint like localhost:9090/inexistant on a plain Jetty? I don't know how to run a plain Jetty... If this does not appear in a plain Jetty then I will take this issue to Spring Boot - maybe their error handler uses Jetty wrong or so.

gregw commented 1 month ago

Good info, thanks!

joakime commented 1 month ago

So it seems to me the error (only?) occurs when a non-200 response like 404 occurs. @joakime can you please run ab against an inexistant endpoint like localhost:9090/inexistant on a plain Jetty? I don't know how to run a plain Jetty... If this does not appear in a plain Jetty then I will take this issue to Spring Boot - maybe their error handler uses Jetty wrong or so.

The test you saw in https://github.com/jetty/jetty.project/issues/12356#issuecomment-2403506895 was done against a standard Jetty server where 100% of requests result in a 404. There's no handler/endpoint installed on the server it used.

Basically this code.

package examples;

import org.eclipse.jetty.server.Server;

public class SimplestServer
{
    public static void main(String[] args) throws Exception
    {
        Server server = new Server(9090);
        // This has a connector listening on port 9090
        // and no handlers, meaning all requests will result
        // in a 404 response
        server.start();
        System.err.println("Hint: Hit Ctrl+C to stop Jetty.");
        server.join();
    }
}

Let me give your spring example project a test too.

gregw commented 1 month ago

@joakime I've tested the latest spring-boot reproducer and I am definitely getting RuntimeIOException: Parser is terminated exceptions, although the server has not yet become unresponsive to me, but it does slow down. It should not do either.

This is most likely an issue in the new spring-boot integration code of jetty-12, as that was refactored very recently. But I'll do some hammering on a raw jetty as well just to triple check our error paths.

joakime commented 1 month ago

@gregw the ab tests against the spring-boot reproducer show the following output on ab ...

$ ab -n 100000 -k "http://localhost:8080/nothere"
This is ApacheBench, Version 2.3 <$Revision: 1879490 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 10000 requests
Completed 20000 requests
Completed 30000 requests
Completed 40000 requests
Completed 50000 requests
Completed 60000 requests
Completed 70000 requests
Completed 80000 requests
Completed 90000 requests
Completed 100000 requests
Finished 100000 requests

Server Software:        
Server Hostname:        localhost
Server Port:            8080

Document Path:          /nothere
Document Length:        96 bytes

Concurrency Level:      1
Time taken for tests:   48.927 seconds
Complete requests:      100000
Failed requests:        50009
   (Connect: 0, Receive: 0, Length: 50000, Exceptions: 9)
Non-2xx responses:      50000
Keep-Alive requests:    50000
Total transferred:      13250000 bytes
HTML transferred:       4800000 bytes
Requests per second:    2043.86 [#/sec] (mean)
Time per request:       0.489 [ms] (mean)
Time per request:       0.489 [ms] (mean, across all concurrent requests)
Transfer rate:          264.46 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:     0    0   0.6      0     139
Waiting:        0    0   0.6      0     139
Total:          0    0   0.6      0     139

Percentage of the requests served within a certain time (ms)
  50%      0
  66%      1
  75%      1
  80%      1
  90%      1
  95%      1
  98%      1
  99%      1
 100%    139 (longest request)

The interesting bits would be ...

Complete requests:      100000
Failed requests:        50009
   (Connect: 0, Receive: 0, Length: 50000, Exceptions: 9)
Non-2xx responses:      50000
Keep-Alive requests:    50000

Why are half failed? (that's a strange coincidence) And where did those extra 9 "Exceptions" come from? I'll have to see if I can get details out of ab to see how it reports those.

Also, that output looks different than what the Embedded Jetty direct output produces ...

Complete requests:      100000
Failed requests:        0
Non-2xx responses:      100000
Keep-Alive requests:    100000

Meanwhile, I'll leave it in your hands to review the Spring integration on the spring side (as you have some experience there).

gregw commented 1 month ago

@gg-dt whilst we debug this.... I'll just say my usual rant against ab..... it is really a bad way to benchmark a server (see my ancient blog: https://webtide.com/lies-damned-lies-and-benchmarks-2/). When a benchmaking tool reports throughput, it is typically measuring latency. You need to measure latency in order to truly measure throughput.

Having said that, tools like ab are good at finding bugs like this one :)

gregw commented 1 month ago

@joakime just confirming that your spring-boot server didn't lock up either? @gg-dt can you confirm/deny if you are always seeing a lockup?

joakime commented 1 month ago

@gregw not sure if this means anything, but if you run ab without keep-alive it works without failure.

Complete requests:      100000
Failed requests:        0
Non-2xx responses:      100000

So, ab uses HTTP/1.0, not HTTP/1.1. Rant: That's just so stupid, nothing in the real world still uses HTTP/1.0.

You can verify the behavior of your ab configuration this way (with a low -n and high verbosity -v 4)

$ ab -n 2 -v 4 "http://localhost:8080/nothere"
This is ApacheBench, Version 2.3 <$Revision: 1879490 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)...INFO: GET header == 
---
GET /nothere HTTP/1.0
Host: localhost:8080
User-Agent: ApacheBench/2.3
Accept: */*

---
LOG: header received:
HTTP/1.1 404 Not Found
Date: Thu, 10 Oct 2024 21:53:56 GMT
Cache-Control: must-revalidate,no-cache,no-store
Content-Type: application/json

{"timestamp":"2024-10-10T21:53:56.890+00:00","status":404,"error":"Not Found","path":"/nothere"}
WARNING: Response code not 2xx (404)
LOG: header received:
HTTP/1.1 404 Not Found
Date: Thu, 10 Oct 2024 21:53:56 GMT
Cache-Control: must-revalidate,no-cache,no-store
Content-Type: application/json

{"timestamp":"2024-10-10T21:53:56.891+00:00","status":404,"error":"Not Found","path":"/nothere"}
WARNING: Response code not 2xx (404)
..done

Server Software:        
Server Hostname:        localhost
Server Port:            8080

Document Path:          /nothere
Document Length:        96 bytes

Concurrency Level:      1
Time taken for tests:   0.003 seconds
Complete requests:      2
Failed requests:        0
Non-2xx responses:      2
Total transferred:      482 bytes
HTML transferred:       192 bytes
Requests per second:    593.65 [#/sec] (mean)
Time per request:       1.685 [ms] (mean)
Time per request:       1.685 [ms] (mean, across all concurrent requests)
Transfer rate:          139.72 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:     1    2   0.1      2       2
Waiting:        1    1   0.1      2       2
Total:          2    2   0.2      2       2
ERROR: The median and mean for the waiting time are more than twice the standard
       deviation apart. These results are NOT reliable.

Percentage of the requests served within a certain time (ms)
  50%      2
  66%      2
  75%      2
  80%      2
  90%      2
  95%      2
  98%      2
  99%      2
 100%      2 (longest request)
joakime commented 1 month ago

@joakime just confirming that your spring-boot server didn't lock up either? @gg-dt can you confirm/deny if you are always seeing a lockup?

No lockup on my machine, at any configuration yet.

joakime commented 1 month ago

Including my spring-reproducer output here, in case it matters to someone. (You can see the versions of spring, Jetty, and the JVM in this output)

[INFO] --- spring-boot:3.3.4:run (default-cli) @ issue-12356-reproducer ---
[INFO] Attaching agents: []

  .   ____          _            __ _ _
 /\\ / ___'_ __ _ _(_)_ __  __ _ \ \ \ \
( ( )\___ | '_ | '_| | '_ \/ _` | \ \ \ \
 \\/  ___)| |_)| | | | | || (_| |  ) ) ) )
  '  |____| .__|_| |_|_| |_\__, | / / / /
 =========|_|==============|___/=/_/_/_/

 :: Spring Boot ::                (v3.3.4)

2024-10-10T16:42:01.981-05:00  INFO 126661 --- [           main] r.reproducer.ReproducerApplication       : Starting ReproducerApplication using Java 17.0.11 with PID 126661 (/home/joakim/code/jetty/github/issue-12356/reproducer/target/classes started by joakim in /home/joakim/code/jetty/github/issue-12356/reproducer)
2024-10-10T16:42:01.984-05:00  INFO 126661 --- [           main] r.reproducer.ReproducerApplication       : No active profile set, falling back to 1 default profile: "default"
2024-10-10T16:42:02.725-05:00  INFO 126661 --- [           main] o.s.b.w.e.j.JettyServletWebServerFactory : Server initialized with port: 8080
2024-10-10T16:42:02.728-05:00  INFO 126661 --- [           main] org.eclipse.jetty.server.Server          : jetty-12.0.13; built: 2024-09-03T03:04:05.240Z; git: 816018a420329c1cacd4116799cda8c8c60a57cd; jvm 17.0.11+9
2024-10-10T16:42:02.756-05:00  INFO 126661 --- [           main] o.e.j.s.h.ContextHandler.application     : Initializing Spring embedded WebApplicationContext
2024-10-10T16:42:02.757-05:00  INFO 126661 --- [           main] w.s.c.ServletWebServerApplicationContext : Root WebApplicationContext: initialization completed in 735 ms
2024-10-10T16:42:02.798-05:00  INFO 126661 --- [           main] o.e.j.session.DefaultSessionIdManager    : Session workerName=node0
2024-10-10T16:42:02.803-05:00  INFO 126661 --- [           main] o.e.jetty.server.handler.ContextHandler  : Started osbwej.JettyEmbeddedWebAppContext@73c9e8e8{application,/,b=file:/tmp/jetty-docbase.8080.9751945002466047585/,a=AVAILABLE,h=oeje10s.SessionHandler@de8039f{STARTED}}
2024-10-10T16:42:02.804-05:00  INFO 126661 --- [           main] o.e.j.e.servlet.ServletContextHandler    : Started osbwej.JettyEmbeddedWebAppContext@73c9e8e8{application,/,b=file:/tmp/jetty-docbase.8080.9751945002466047585/,a=AVAILABLE,h=oeje10s.SessionHandler@de8039f{STARTED}}
2024-10-10T16:42:02.806-05:00  INFO 126661 --- [           main] org.eclipse.jetty.server.Server          : Started oejs.Server@129bd55d{STARTING}[12.0.13,sto=0] @1376ms
2024-10-10T16:42:03.022-05:00  INFO 126661 --- [           main] o.e.j.s.h.ContextHandler.application     : Initializing Spring DispatcherServlet 'dispatcherServlet'
2024-10-10T16:42:03.022-05:00  INFO 126661 --- [           main] o.s.web.servlet.DispatcherServlet        : Initializing Servlet 'dispatcherServlet'
2024-10-10T16:42:03.023-05:00  INFO 126661 --- [           main] o.s.web.servlet.DispatcherServlet        : Completed initialization in 1 ms
2024-10-10T16:42:03.037-05:00  INFO 126661 --- [           main] o.e.jetty.server.AbstractConnector       : Started ServerConnector@5d1e0fbb{HTTP/1.1, (http/1.1)}{0.0.0.0:8080}
2024-10-10T16:42:03.038-05:00  INFO 126661 --- [           main] o.s.b.web.embedded.jetty.JettyWebServer  : Jetty started on port 8080 (http/1.1) with context path '/'
2024-10-10T16:42:03.046-05:00  INFO 126661 --- [           main] r.reproducer.ReproducerApplication       : Started ReproducerApplication in 1.385 seconds (process running for 1.617)
gregw commented 1 month ago

@gregw not sure if this means anything, but if you run ab without keep-alive it works without failure.

That most definitely means something. The parser instance is reused on a persistent connection, so it is subsequent requests on the same connection that are seeing the Parser is terminated exception. This is either because the parser was not correctly reset from the last request... or worse yet, perhaps an async handler resets it after the handling of the next request starts.

In the case of non persistent requests, the parser is thrown away after every request, so no chance of getting this failure.

gregw commented 1 month ago

So I have tried several variations of: 

public class TestServer
{
    public static void main(String[] args) throws Exception
    {
        Server server = new Server();
        ServerConnector connector = new ServerConnector(server);
        connector.setPort(8080);
        server.addConnector(connector);
        server.setHandler(new Handler.Abstract()
        {
            @Override
            public boolean handle(Request request, Response response, Callback callback)
            {
                request.getContext().execute(() -> Response.writeError(request, response, callback, 404));
                return true;
            }
        });
        server.start();
        server.join();
    }
}

With 404 sent from another thread, with no handler, 404 from the handling thread etc.

All of them, in pure jetty 12.0 run without an issue with output like:

[2005] ab -n 100000 -k "http://localhost:8080/inexistent"
This is ApacheBench, Version 2.3 <$Revision: 1903618 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)
Completed 10000 requests
Completed 20000 requests
Completed 30000 requests
Completed 40000 requests
Completed 50000 requests
Completed 60000 requests
Completed 70000 requests
Completed 80000 requests
Completed 90000 requests
Completed 100000 requests
Finished 100000 requests

Server Software:        Jetty(12.0.15-SNAPSHOT)
Server Hostname:        localhost
Server Port:            8080

Document Path:          /inexistent
Document Length:        432 bytes

Concurrency Level:      1
Time taken for tests:   1.602 seconds
Complete requests:      100000
Failed requests:        0
Non-2xx responses:      100000
Keep-Alive requests:    100000
Total transferred:      66700000 bytes
HTML transferred:       43200000 bytes
Requests per second:    62415.62 [#/sec] (mean)
Time per request:       0.016 [ms] (mean)
Time per request:       0.016 [ms] (mean, across all concurrent requests)
Transfer rate:          40655.49 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:     0    0   0.0      0       2
Waiting:        0    0   0.0      0       2
Total:          0    0   0.0      0       2

Percentage of the requests served within a certain time (ms)
  50%      0
  66%      0
  75%      0
  80%      0
  90%      0
  95%      0
  98%      0
  99%      0
 100%      2 (longest request)

So it is almost certainly an aspect of the spring integration..... but the mystery is: what could the spring integration code possibly be doing to core jetty to make it fail like it does. I.e. if I want to get that error, what must I do??? I'm going to keep on trying to reproduce the error directly in jetty for an hour or two before diving into spring integration... because even if the spring integration is buggy, and application should not be able to trick jetty into this state.

gregw commented 1 month ago

I've tried all sorts of evil things to reproduce.. writing twice, completing then writing... but I get 'already completed' ISE.

However, switching back to testing the spring-boot reproducer, I get the exception with only 2 requests:

ab -c 1 -n 2 -k "http://localhost:8080/inexistent"
...
Concurrency Level:      1
Time taken for tests:   0.118 seconds
Complete requests:      2
Failed requests:        1
...

So this should be easier to debug. standby...

gregw commented 1 month ago

Ah - This is not the latest spring integration code, as it is still using servlets rather than direct jetty-12 handlers. The sequence of events is as follows:

The first request is received and parsed:

2024-10-11T10:57:19.457+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.j.server.internal.HttpConnection     : onFillable filled 116 HttpConnection@c826039::SocketChannelEndPoint@39f0bd1d[{l=/127.0.0.1:8080,r=/127.0.0.1:55626,OPEN,fill=-,flush=-,to=0/30000}{io=0/0,kio=0,kro=1}]->[HttpConnection@c826039[p=HttpParser{s=START,0 of -1},g=HttpGenerator@7ffc9024{s=START}]=>HttpChannelState@d9dc517{handling=null, handled=false, send=SENDING, completed=false, request=null}] HttpChannelState@d9dc517{handling=null, handled=false, send=SENDING, completed=false, request=null} ReservedBuffer@68161bd1[rc=1,DirectByteBuffer@2b56626a[p=0,l=116,c=8192,r=116]={<<<GET /inexistent HTTP/1.0\r...ch/2.3\r\nAccept: */*\r\n\r\n>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00}]
2024-10-11T10:57:19.457+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.j.server.internal.HttpConnection     : HttpConnection@c826039::SocketChannelEndPoint@39f0bd1d[{l=/127.0.0.1:8080,r=/127.0.0.1:55626,OPEN,fill=-,flush=-,to=0/30000}{io=0/0,kio=0,kro=1}]->[HttpConnection@c826039[p=HttpParser{s=START,0 of -1},g=HttpGenerator@7ffc9024{s=START}]=>HttpChannelState@d9dc517{handling=null, handled=false, send=SENDING, completed=false, request=null}] parse ReservedBuffer@68161bd1[rc=1,DirectByteBuffer@2b56626a[p=0,l=116,c=8192,r=116]={<<<GET /inexistent HTTP/1.0\r...ch/2.3\r\nAccept: */*\r\n\r\n>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00}]
2024-10-11T10:57:19.457+11:00 DEBUG 791759 --- [qtp105663489-65] org.eclipse.jetty.http.HttpParser        : parseNext s=START DirectByteBuffer@2b56626a[p=0,l=116,c=8192,r=116]={<<<GET /inexistent HTTP/1.0\r...ch/2.3\r\nAccept: */*\r\n\r\n>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00}
2024-10-11T10:57:19.458+11:00 DEBUG 791759 --- [qtp105663489-65] org.eclipse.jetty.http.HttpParser        : START --> SPACE1(GET)
2024-10-11T10:57:19.458+11:00 DEBUG 791759 --- [qtp105663489-65] org.eclipse.jetty.http.HttpParser        : SPACE1 --> URI
2024-10-11T10:57:19.458+11:00 DEBUG 791759 --- [qtp105663489-65] org.eclipse.jetty.http.HttpParser        : URI --> HEADER
2024-10-11T10:57:19.460+11:00 DEBUG 791759 --- [qtp105663489-65] org.eclipse.jetty.http.HttpParser        : HEADER:FIELD --> IN_VALUE
2024-10-11T10:57:19.460+11:00 DEBUG 791759 --- [qtp105663489-65] org.eclipse.jetty.http.HttpParser        : HEADER:IN_VALUE --> FIELD(Connection: keep-alive: keep-alive)
2024-10-11T10:57:19.461+11:00 DEBUG 791759 --- [qtp105663489-65] org.eclipse.jetty.http.HttpParser        : parsedHeader(Connection: keep-alive) header=Connection, headerString=[Connection], valueString=[keep-alive]
2024-10-11T10:57:19.461+11:00 DEBUG 791759 --- [qtp105663489-65] org.eclipse.jetty.http.HttpParser        : HEADER:FIELD --> IN_VALUE
2024-10-11T10:57:19.461+11:00 DEBUG 791759 --- [qtp105663489-65] org.eclipse.jetty.http.HttpParser        : HEADER:IN_VALUE --> FIELD(Host: localhost:8080)
2024-10-11T10:57:19.461+11:00 DEBUG 791759 --- [qtp105663489-65] org.eclipse.jetty.http.HttpParser        : parsedHeader(Host: localhost:8080) header=Host, headerString=[Host], valueString=[localhost:8080]
2024-10-11T10:57:19.461+11:00 DEBUG 791759 --- [qtp105663489-65] org.eclipse.jetty.http.HttpParser        : HEADER:FIELD --> VALUE
2024-10-11T10:57:19.461+11:00 DEBUG 791759 --- [qtp105663489-65] org.eclipse.jetty.http.HttpParser        : HEADER:VALUE --> IN_VALUE
2024-10-11T10:57:19.461+11:00 DEBUG 791759 --- [qtp105663489-65] org.eclipse.jetty.http.HttpParser        : HEADER:IN_VALUE --> FIELD(User-Agent: ApacheBench/2.3)
2024-10-11T10:57:19.461+11:00 DEBUG 791759 --- [qtp105663489-65] org.eclipse.jetty.http.HttpParser        : parsedHeader(User-Agent: ApacheBench/2.3) header=User-Agent, headerString=[User-Agent], valueString=[ApacheBench/2.3]
2024-10-11T10:57:19.461+11:00 DEBUG 791759 --- [qtp105663489-65] org.eclipse.jetty.http.HttpParser        : HEADER:FIELD --> IN_VALUE
2024-10-11T10:57:19.461+11:00 DEBUG 791759 --- [qtp105663489-65] org.eclipse.jetty.http.HttpParser        : HEADER:IN_VALUE --> FIELD(Accept: */*: */*)
2024-10-11T10:57:19.461+11:00 DEBUG 791759 --- [qtp105663489-65] org.eclipse.jetty.http.HttpParser        : parsedHeader(Accept: */*) header=Accept, headerString=[Accept], valueString=[*/*]
2024-10-11T10:57:19.462+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.j.server.internal.HttpChannelState   : onRequest GET{u=http://localhost:8080/inexistent,HTTP/1.0,h=4,cl=-1,p=null} HttpChannelState@d9dc517{handling=null, handled=false, send=SENDING, completed=false, request=null}
2024-10-11T10:57:19.465+11:00 DEBUG 791759 --- [qtp105663489-65] org.eclipse.jetty.http.HttpParser        : HEADER --> CONTENT
2024-10-11T10:57:19.465+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.j.server.internal.HttpConnection     : HttpConnection@c826039::SocketChannelEndPoint@39f0bd1d[{l=/127.0.0.1:8080,r=/127.0.0.1:55626,OPEN,fill=-,flush=-,to=7/30000}{io=0/0,kio=0,kro=1}]->[HttpConnection@c826039[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@7ffc9024{s=START}]=>HttpChannelState@d9dc517{handling=null, handled=false, send=SENDING, completed=false, request=GET@376bc966 http://localhost:8080/inexistent HTTP/1.0}] parsed true HttpParser{s=CONTENT,0 of -1}
2024-10-11T10:57:19.465+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.j.server.internal.HttpConnection     : releaseRequestBuffer HttpConnection@c826039::SocketChannelEndPoint@39f0bd1d[{l=/127.0.0.1:8080,r=/127.0.0.1:55626,OPEN,fill=-,flush=-,to=7/30000}{io=0/0,kio=0,kro=1}]->[HttpConnection@c826039[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@7ffc9024{s=START}]=>HttpChannelState@d9dc517{handling=null, handled=false, send=SENDING, completed=false, request=GET@376bc966 http://localhost:8080/inexistent HTTP/1.0}]
2024-10-11T10:57:19.465+11:00 DEBUG 791759 --- [qtp105663489-65] org.eclipse.jetty.util.ConcurrentPool    : returning reserved entry ConcurrentEntry@152fd87e{terminated=false,multiplex=-1,pooled=null} for ConcurrentPool@4f3cdf15[strategy=THREAD_ID,inUse=0,size=1,max=256,leaked=0,terminated=false]
2024-10-11T10:57:19.466+11:00 DEBUG 791759 --- [qtp105663489-65] org.eclipse.jetty.util.ConcurrentPool    : enabled ConcurrentEntry@152fd87e{terminated=false,multiplex=0,pooled=Buffer@7cd80c28[rc=0,DirectByteBuffer@2b56626a[p=0,l=0,c=8192,r=0]={<<<>>>GET /inex...\x00\x00\x00\x00\x00\x00\x00}]} for ConcurrentPool@4f3cdf15[strategy=THREAD_ID,inUse=0,size=1,max=256,leaked=0,terminated=false]
2024-10-11T10:57:19.466+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.j.server.internal.HttpConnection     : HANDLE GET@376bc966 http://localhost:8080/inexistent HTTP/1.0 HttpConnection@c826039::SocketChannelEndPoint@39f0bd1d[{l=/127.0.0.1:8080,r=/127.0.0.1:55626,OPEN,fill=-,flush=-,to=8/30000}{io=0/0,kio=0,kro=1}]->[HttpConnection@c826039[p=HttpParser{s=CONTENT,0 of -1},g=HttpGenerator@7ffc9024{s=START}]=>HttpChannelState@d9dc517{handling=null, handled=false, send=SENDING, completed=false, request=GET@376bc966 http://localhost:8080/inexistent HTTP/1.0}]

This fails to find a matching resource and exits handling after something calls sendError

2024-10-11T10:57:19.493+11:00 DEBUG 791759 --- [qtp105663489-65] o.s.w.s.handler.SimpleUrlHandlerMapping  : Mapped to ResourceHttpRequestHandler [classpath [META-INF/resources/], classpath [resources/], classpath [static/], classpath [public/], ServletContext [/]]
2024-10-11T10:57:19.497+11:00 DEBUG 791759 --- [qtp105663489-65] o.s.w.s.r.ResourceHttpRequestHandler     : Resource not found
2024-10-11T10:57:19.500+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.j.ee10.servlet.ServletChannelState   : sendError ServletChannelState@3028e2fc{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=true al=0}
2024-10-11T10:57:19.501+11:00 DEBUG 791759 --- [qtp105663489-65] .w.s.m.s.DefaultHandlerExceptionResolver : Resolved [org.springframework.web.servlet.resource.NoResourceFoundException: No static resource inexistent.]
2024-10-11T10:57:19.501+11:00 DEBUG 791759 --- [qtp105663489-65] o.s.web.servlet.DispatcherServlet        : Completed 404 NOT_FOUND
2024-10-11T10:57:19.501+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.j.ee10.servlet.ServletChannelState   : unhandle ServletChannelState@3028e2fc{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=true i=true al=0}
2024-10-11T10:57:19.501+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.j.ee10.servlet.ServletChannelState   : nextAction(false) SEND_ERROR ServletChannelState@3028e2fc{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=false al=0}
2024-10-11T10:57:19.501+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.jetty.ee10.servlet.ServletChannel    : action SEND_ERROR ServletChannel@6794f72c{s=ServletChannelState@3028e2fc{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=false al=0},r=0,c=false/false,a=HANDLING,uri=http://localhost:8080/inexistent,age=38}

The sendError handling looks for an finds an error page:

2024-10-11T10:57:19.502+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.j.ee10.servlet.ServletChannelState   : errorHandling ServletChannelState@3028e2fc{s=HANDLING rs=BLOCKING os=OPEN is=IDLE awp=false se=false i=false al=0}
2024-10-11T10:57:19.502+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.j.e.servlet.ErrorPageErrorHandler    : getErrorPage(GET /inexistent) => error_page=/error (from global default)

which is dispatched with an error dispatch, which writes the error page:

2024-10-11T10:57:19.503+11:00 DEBUG 791759 --- [qtp105663489-65] o.s.web.servlet.DispatcherServlet        : "ERROR" dispatch for GET "/error", parameters={}
2024-10-11T10:57:19.505+11:00 DEBUG 791759 --- [qtp105663489-65] s.w.s.m.m.a.RequestMappingHandlerMapping : Mapped to org.springframework.boot.autoconfigure.web.servlet.error.BasicErrorController#error(HttpServletRequest)
2024-10-11T10:57:19.518+11:00 DEBUG 791759 --- [qtp105663489-65] o.s.w.s.m.m.a.HttpEntityMethodProcessor  : Using 'application/json', given [*/*] and supported [application/json, application/*+json]
2024-10-11T10:57:19.521+11:00 DEBUG 791759 --- [qtp105663489-65] o.s.w.s.m.m.a.HttpEntityMethodProcessor  : Writing [{timestamp=Fri Oct 11 10:57:19 AEDT 2024, status=404, error=Not Found, path=/inexistent}]
2024-10-11T10:57:19.537+11:00 DEBUG 791759 --- [qtp105663489-65] o.eclipse.jetty.ee10.servlet.HttpOutput  : write(array HeapByteBuffer@7a304468[p=0,l=99,c=8000,r=99]={<<<{"timestamp":"2024-10-10T...","path":"/inexistent"}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00})
2024-10-11T10:57:19.537+11:00 DEBUG 791759 --- [qtp105663489-65] o.eclipse.jetty.ee10.servlet.HttpOutput  : write(array) s=OPEN,api=BLOCKING,sc=false,e=null aggregated !flush ReservedBuffer@233ee306[rc=1,DirectByteBuffer@46a68e5f[p=0,l=99,c=32768,r=99]={<<<{"timestamp":"2024-10-10T...","path":"/inexistent"}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00}]
2024-10-11T10:57:19.537+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.j.s.internal.ResponseHttpFields      : Date: Thu, 10 Oct 2024 23:57:19 GMT
Cache-Control: must-revalidate,no-cache,no-store
Content-Type: application/json

which when generated is seen as a persistent connection and Connection: keep-alive:

2024-10-11T10:57:19.538+11:00 DEBUG 791759 --- [qtp105663489-65] org.eclipse.jetty.http.HttpGenerator     : generateHeaders HTTP/1.0{s=404,h=4,cl=-1} last=false content=DirectByteBuffer@46a68e5f[p=0,l=99,c=32768,r=99]={<<<{"timestamp":"2024-10-10T...","path":"/inexistent"}>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00}
2024-10-11T10:57:19.538+11:00 DEBUG 791759 --- [qtp105663489-65] org.eclipse.jetty.http.HttpGenerator     : Date: Thu, 10 Oct 2024 23:57:19 GMT
Cache-Control: must-revalidate,no-cache,no-store
Content-Type: application/json
Connection: keep-alive

BUT when this is actually generated, a SHUTDOWN_OUT is done, as if the connection was not persistent?!?!? 

2024-10-11T10:57:19.558+11:00 DEBUG 791759 --- [qtp105663489-65] o.s.web.servlet.DispatcherServlet        : Exiting from "ERROR" dispatch, status 404
2024-10-11T10:57:19.558+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.j.ee10.servlet.ServletChannelState   : errorHandlingComplete ServletChannelState@3028e2fc{s=HANDLING rs=ERRORING os=OPEN is=IDLE awp=false se=false i=false al=0}
2024-10-11T10:57:19.558+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.j.ee10.servlet.ServletChannelState   : unhandle ServletChannelState@3028e2fc{s=HANDLING rs=COMPLETE os=OPEN is=IDLE awp=false se=false i=false al=0}
2024-10-11T10:57:19.558+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.j.ee10.servlet.ServletChannelState   : nextAction(false) COMPLETE ServletChannelState@3028e2fc{s=HANDLING rs=COMPLETING os=OPEN is=IDLE awp=false se=false i=false al=0}
2024-10-11T10:57:19.558+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.jetty.ee10.servlet.ServletChannel    : action COMPLETE ServletChannel@6794f72c{s=ServletChannelState@3028e2fc{s=HANDLING rs=COMPLETING os=OPEN is=IDLE awp=false se=false i=false al=0},r=0,c=false/false,a=HANDLING,uri=http://localhost:8080/inexistent,age=95}
2024-10-11T10:57:19.559+11:00 DEBUG 791759 --- [qtp105663489-65] o.eclipse.jetty.ee10.servlet.HttpOutput  : complete(Callback@12e5a0a3{NON_BLOCKING, org.eclipse.jetty.ee10.servlet.ServletChannel$$Lambda/0x000072c57745c000@68c923a0,org.eclipse.jetty.ee10.servlet.ServletChannel$$Lambda/0x000072c57745c220@1d9e2392}) s=CLOSING,api=BLOCKED,sc=false,e=null s=false e=null, c=HeapByteBuffer@5a3c12d0[p=0,l=0,c=0,r=0]={<<<>>>}
2024-10-11T10:57:19.559+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.j.server.internal.HttpChannelState   : writing last=true HeapByteBuffer@5a3c12d0[p=0,l=0,c=0,r=0]={<<<>>>} ChannelResponse@7317fc22{404,GET@376bc966 http://localhost:8080/inexistent HTTP/1.0}
2024-10-11T10:57:19.559+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.j.server.internal.HttpConnection     : generate: CONTINUE for SendCallback@7de0f359[PROCESSING][i=null,cb=ChannelResponse@7317fc22{404,GET@376bc966 http://localhost:8080/inexistent HTTP/1.0}] (null,[p=0,l=0,c=0,r=0],true)@COMPLETING
2024-10-11T10:57:19.559+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.j.server.internal.HttpConnection     : generate: SHUTDOWN_OUT for SendCallback@7de0f359[PROCESSING][i=null,cb=ChannelResponse@7317fc22{404,GET@376bc966 http://localhost:8080/inexistent HTTP/1.0}] (null,[p=0,l=0,c=0,r=0],true)@END
2024-10-11T10:57:19.559+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.j.server.internal.HttpConnection     : generate: DONE for SendCallback@7de0f359[PROCESSING][i=null,cb=ChannelResponse@7317fc22{404,GET@376bc966 http://localhost:8080/inexistent HTTP/1.0}] (null,[p=0,l=0,c=0,r=0],true)@END
2024-10-11T10:57:19.559+11:00 DEBUG 791759 --- [qtp105663489-65] org.eclipse.jetty.io.AbstractEndPoint    : shutdownOutput SocketChannelEndPoint@39f0bd1d[{l=/127.0.0.1:8080,r=/127.0.0.1:55626,OPEN,fill=-,flush=-,to=20/30000}{io=0/0,kio=0,kro=1}]->[HttpConnection@c826039[p=HttpParser{s=END,0 of -1},g=HttpGenerator@7ffc9024{s=END}]=>HttpChannelState@d9dc517{handling=Thread[#65,qtp105663489-65,5,main], handled=false, send=LAST_SENDING, completed=false, request=GET@376bc966 http://localhost:8080/inexistent HTTP/1.0}]
2024-10-11T10:57:19.560+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.j.server.internal.HttpChannelState   : write succeeded ChannelResponse@7317fc22{404,GET@376bc966 http://localhost:8080/inexistent HTTP/1.0}

The connection is now half closed and the parser CLOSED. We read seeking EOF, but see the second request, which "correctly" fails as the parser is CLOSED: 

2024-10-11T10:57:19.584+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.j.server.internal.HttpConnection     : onFillable filled 116 HttpConnection@c826039::SocketChannelEndPoint@39f0bd1d[{l=/127.0.0.1:8080,r=/127.0.0.1:55626,OSHUT,fill=-,flush=-,to=0/30000}{io=0/0,kio=0,kro=1}]->[HttpConnection@c826039[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@7ffc9024{s=START}]=>HttpChannelState@d9dc517{handling=null, handled=false, send=SENDING, completed=false, request=null}] HttpChannelState@d9dc517{handling=null, handled=false, send=SENDING, completed=false, request=null} Buffer@7cd80c28[rc=1,DirectByteBuffer@2b56626a[p=0,l=116,c=8192,r=116]={<<<GET /inexistent HTTP/1.0\r...ch/2.3\r\nAccept: */*\r\n\r\n>>>nt-Type: ...\x00\x00\x00\x00\x00\x00\x00}]
2024-10-11T10:57:19.584+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.j.server.internal.HttpConnection     : HttpConnection@c826039::SocketChannelEndPoint@39f0bd1d[{l=/127.0.0.1:8080,r=/127.0.0.1:55626,OSHUT,fill=-,flush=-,to=0/30000}{io=0/0,kio=0,kro=1}]->[HttpConnection@c826039[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@7ffc9024{s=START}]=>HttpChannelState@d9dc517{handling=null, handled=false, send=SENDING, completed=false, request=null}] parse Buffer@7cd80c28[rc=1,DirectByteBuffer@2b56626a[p=0,l=116,c=8192,r=116]={<<<GET /inexistent HTTP/1.0\r...ch/2.3\r\nAccept: */*\r\n\r\n>>>nt-Type: ...\x00\x00\x00\x00\x00\x00\x00}]
2024-10-11T10:57:19.584+11:00 DEBUG 791759 --- [qtp105663489-65] o.e.j.server.internal.HttpConnection     : caught exception HttpConnection@c826039::SocketChannelEndPoint@39f0bd1d[{l=/127.0.0.1:8080,r=/127.0.0.1:55626,OSHUT,fill=-,flush=-,to=1/30000}{io=0/0,kio=0,kro=1}]->[HttpConnection@c826039[p=HttpParser{s=CLOSE,0 of -1},g=HttpGenerator@7ffc9024{s=START}]=>HttpChannelState@d9dc517{handling=null, handled=false, send=SENDING, completed=false, request=null}] HttpChannelState@d9dc517{handling=null, handled=false, send=SENDING, completed=false, request=null}

org.eclipse.jetty.io.RuntimeIOException: Parser is terminated
        at org.eclipse.jetty.server.internal.HttpConnection.parseRequestBuffer(HttpConnection.java:561) ~[jetty-server-12.0.13.jar:12.0.13]
        at org.eclipse.jetty.server.internal.HttpConnection.onFillable(HttpConnection.java:386) ~[jetty-server-12.0.13.jar:12.0.13]
        at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:322) ~[jetty-io-12.0.13.jar:12.0.13]
        at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:99) ~[jetty-io-12.0.13.jar:12.0.13]
        at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53) ~[jetty-io-12.0.13.jar:12.0.13]
        at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:979) ~[jetty-util-12.0.13.jar:12.0.13]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1209) ~[jetty-util-12.0.13.jar:12.0.13]
        at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1164) ~[jetty-util-12.0.13.jar:12.0.13]
        at java.base/java.lang.Thread.run(Thread.java:1570) ~[na:na]

So the issue is: Why is an EE10 servlet sending a persistent 404 response, but then closing the connection???

Switching back to pure jetty EE10 to try to reproduce...

gregw commented 1 month ago

Still no reproduction with:

public class TestWebAppServer
{
    public static void main(String[] args) throws Exception
    {
        Server server = new Server();
        WebAppContext webapp = new WebAppContext();
        webapp.setContextPath("/");
        webapp.setBaseResourceAsString(".");
        ErrorPageErrorHandler errorHandler = new ErrorPageErrorHandler();
        errorHandler.addErrorPage(404, "/error404");
        webapp.setErrorHandler(errorHandler);
        webapp.addServlet(new HttpServlet() {
            @Override
            protected void doGet(HttpServletRequest req, HttpServletResponse resp) throws IOException
            {
                resp.setStatus(404);
                resp.getOutputStream().write("404 Not Found".getBytes());
            }
        }, "/error404");

        server.setHandler(webapp);

        ServerConnector connector = new ServerConnector(server);
        connector.setPort(8080);
        server.addConnector(connector);
        server.start();
        server.join();
    }
}
joakime commented 1 month ago

I was able to, sort of, reproduce with the minimal ab test of only 2 requests ...

$ ab -n 2 -k -v 5 "http://localhost:8080/inexistent" 
This is ApacheBench, Version 2.3 <$Revision: 1879490 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/

Benchmarking localhost (be patient)...INFO: GET header == 
---
GET /inexistent HTTP/1.0
Connection: Keep-Alive
Host: localhost:8080
User-Agent: ApacheBench/2.3
Accept: */*

---
LOG: header received:
HTTP/1.1 404 Not Found
Date: Fri, 11 Oct 2024 00:40:35 GMT
Cache-Control: must-revalidate,no-cache,no-store
Content-Type: application/json
Connection: keep-alive

{"timestamp":"2024-10-11T00:40:35.164+00:00","status":404,"error":"Not Found","path":"/inexistent"}
WARNING: Response code not 2xx (404)
..done

Server Software:        
Server Hostname:        localhost
Server Port:            8080

Document Path:          /inexistent
Document Length:        99 bytes

Concurrency Level:      1
Time taken for tests:   0.002 seconds
Complete requests:      2
Failed requests:        1
   (Connect: 0, Receive: 0, Length: 1, Exceptions: 0)
Non-2xx responses:      1
Keep-Alive requests:    1
Total transferred:      268 bytes
HTML transferred:       99 bytes
Requests per second:    858.37 [#/sec] (mean)
Time per request:       1.165 [ms] (mean)
Time per request:       1.165 [ms] (mean, across all concurrent requests)
Transfer rate:          112.33 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.1      0       0
Processing:     0    1   1.5      2       2
Waiting:        0    1   1.5      2       2
Total:          0    1   1.5      2       2

Percentage of the requests served within a certain time (ms)
  50%      2
  66%      2
  75%      2
  80%      2
  90%      2
  95%      2
  98%      2
  99%      2
 100%      2 (longest request)

Got a pcapng of it as well (doesn't tell us much that we don't already know)

spring-boot-ab-testing.pcapng.gz

gregw commented 1 month ago

OK, I know what the issue is, and it is in normal jetty, the HttpGenerator!!!

The following server will fail in exactly the same way:

public class TestServer
{
    public static void main(String[] args) throws Exception
    {
        Server server = new Server();
        ServerConnector connector = new ServerConnector(server);
        connector.setPort(8080);
        server.addConnector(connector);
        server.setHandler(new Handler.Abstract()
        {
            @Override
            public boolean handle(Request request, Response response, Callback callback)
            {
                try
                {
                    Callback.Completable writeCB = new Callback.Completable();
                    response.write(false, BufferUtil.toBuffer("Not Found!!!!"), writeCB);
                    writeCB.get();

                    callback.succeeded();
                }
                catch (Throwable t)
                {
                    callback.failed(t);
                }

                return true;
            }
        });
        server.start();
        server.join();
    }
}

The issue is that the way that response is written, the content-length is unknown and there is no chunking available. So with HTTP/1.0, jetty has no other option but to use EOF termination to mark the end of the response body. However, the "bug" is that we are leaving the Connection: keep-alive header in the response, when that should be removed!

Now, as a server, jetty is actually entitled to close the connection at any time between requests, even after sending a keep-alive, so this is really a "bug" rather than a bug.

But ab is also entitled to try to send another request on that connection if it sees keep-alive. As it is an idempotent request (GET), a normal browser would just retry on a new connection, but ab is counting it as a failure... which I guess is OK too.

This is never triggered normally as we are careful to always write our error pages in such a way that the content-length is known and thus even with HTTP/1.0 we can be persistent. But spring-boot obviously has an error handler that is forcing a commit before the response is closed, thus we have no other choice but to close the connection. This is an inefficient way to generate error pages, as you throw away a perfectly good connection.

So to fix/improve this we need to: a) not add the keep-alive (or remove it) if we are EOF body limited. b) find where/how springboot are generating their error pages and encourage them to do so in a way that can be persisted (just not flushing would probably be sufficient).

gregw commented 1 month ago

@gg-dt I have opened #12375 with a fix for this.

Note that for real deployments, this is not really an issue. Either the response is written is a way that is really persistent (and we don't trigger this issue); OR the response is written in a way that cannot use persistent connections for HTTP/1.0 so it is a little more inefficient as the client may try the connection for another request, but a) the inefficiency is mostly on the client side; b) any app that closes connections like that is not going to be efficient anyway.

If you were getting this error for real request (not 404s), then it is kind of pointless benchmarking it until you fix the response generation so that it can persist connection in HTTP/1.0 or avoid chunking in HTTP/1.1. Doing that will give you huge performance improvements.

gg-dt commented 1 month ago

@joakime just confirming that your spring-boot server didn't lock up either? @gg-dt can you confirm/deny if you are always seeing a lockup?

I don't always see a lockup. As shown in my example output - sometimes some 40000 requests go good. Looked like some race condition to me.

@gg-dt I have opened #12375 with a fix for this.

Note that for real deployments, this is not really an issue. Either the response is written is a way that is really persistent (and we don't trigger this issue); OR the response is written in a way that cannot use persistent connections for HTTP/1.0 so it is a little more inefficient as the client may try the connection for another request, but a) the inefficiency is mostly on the client side; b) any app that closes connections like that is not going to be efficient anyway.

If you were getting this error for real request (not 404s), then it is kind of pointless benchmarking it until you fix the response generation so that it can persist connection in HTTP/1.0 or avoid chunking in HTTP/1.1. Doing that will give you huge performance improvements.

Ok, thanks for the analysis. Are you in contact with the Spring project regarding the flushing in the error page generation or should I tell them?

And just for my understanding: Why does Jetty not close the TCP connection if the error handler flushes?