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.83k stars 1.91k forks source link

InvalidArgumentExceptions due to invalid status codes are not handled properly #11749

Open kilianke opened 4 months ago

kilianke commented 4 months ago

Jetty version(s) Jetty 11.0.20 Jetty ReactiveStream HttpClient 1.1.13

Java version/vendor (use: java -version) openjdk 17.0.10

OS type/version Windows

Description If an http response contains an invalid status code <100, an IllegalArgumentException is thrown by Spring's HttpStatusCode interface, when the ResponseNotifier tries to execute the onHeaders method. The onHeaders method of Jetty ReactiveStream Client's ResponseListenerProcessor class, which is one of the registered listeners that are notified, applies the content function, which calls the constructor of JettyClientHttpResponse. The problem only surfaced after this commit was introduce to Spring, which introduced a HttpStatusCode.valueOf method call in the JettyClientHttpResponse constructor to create a status code object, which then throws the exception mentioned above.

The problem is, that the ResponseNotifier catches all exceptions, logs them and doesn't terminate the exchange nor propagates the exception to the caller. Therefore http calls with status codes <100 run into a timeout resulting in a TimeoutException, with no indication of the real cause.

The following Exception is logged (see log excerpt for further details incl. timeout exception):

2024-05-03 15:20:09,977 INFO  - [org.eclipse.jetty.client.ResponseNotifier] - Exception while notifying listener ResponseListenerProcessor@58601e7a[Reactive[HttpRequest[GET / HTTP/1.1]@62735b13]]
java.lang.IllegalArgumentException: Status code '50' should be a three-digit positive integer
    at org.springframework.util.Assert.isTrue(Assert.java:140)
    at org.springframework.http.HttpStatusCode.valueOf(HttpStatusCode.java:99)
    at org.springframework.http.client.reactive.JettyClientHttpResponse.<init>(JettyClientHttpResponse.java:52)
    at org.springframework.http.client.reactive.JettyClientHttpConnector.lambda$execute$0(JettyClientHttpConnector.java:132)
    at org.eclipse.jetty.reactive.client.internal.ResponseListenerProcessor.onHeaders(ResponseListenerProcessor.java:93)
    at org.eclipse.jetty.client.ResponseNotifier.notifyHeaders(ResponseNotifier.java:95)
    at org.eclipse.jetty.client.ResponseNotifier.notifyHeaders(ResponseNotifier.java:87)
    at org.eclipse.jetty.client.HttpReceiver.responseHeaders(HttpReceiver.java:327)
    at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.headerComplete(HttpReceiverOverHTTP.java:331)
    at org.eclipse.jetty.http.HttpParser.parseFields(HttpParser.java:1256)
    at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1542)
    at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.parse(HttpReceiverOverHTTP.java:221)
    at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:160)
    at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:91)
    at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:97)
    at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:207)
    at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:314)
    at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100)
    at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53)
    at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:969)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1194)
    at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1149)
    at java.base/java.lang.Thread.run(Thread.java:840)
How to reproduce? ``` import java.time.Duration; import org.eclipse.jetty.client.HttpClient; import org.eclipse.jetty.client.http.HttpClientTransportOverHTTP; import org.springframework.boot.SpringApplication; import org.springframework.boot.autoconfigure.SpringBootApplication; import org.springframework.http.ResponseEntity; import org.springframework.http.client.reactive.JettyClientHttpConnector; import org.springframework.web.reactive.function.client.WebClient; import okhttp3.mockwebserver.MockResponse; import okhttp3.mockwebserver.MockWebServer; @SpringBootApplication public class JettyBugReproductionExampleApplication { public static void main(String[] args) throws Exception { SpringApplication.run(JettyBugReproductionExampleApplication.class, args); HttpClient httpClient = new HttpClient(new HttpClientTransportOverHTTP()); JettyClientHttpConnector jettyClientHttpConnector = new JettyClientHttpConnector(httpClient); WebClient webClient = WebClient.builder() .clientConnector(jettyClientHttpConnector) .build(); MockWebServer mockWebServer = new MockWebServer(); mockWebServer.start(1337); MockResponse mockResponse = new MockResponse().setResponseCode(50); mockWebServer.enqueue(mockResponse); try { ResponseEntity responseEntity = webClient.get() .uri("http://localhost:1337/") .retrieve() .toEntity(String.class) .timeout(Duration.ofSeconds(15)) .block(); } catch (Exception e) { System.out.println(e.getMessage()); } } } ```
Log excerpt ``` 2024-05-03 15:20:09,953 DEBUG - [org.eclipse.jetty.client.HttpSender] - Request headers HttpRequest[GET / HTTP/1.1]@62735b13 Accept-Encoding: gzip User-Agent: Jetty/11.0.20 Accept: */* Host: localhost:1337 2024-05-03 15:20:09,953 DEBUG - [org.eclipse.jetty.client.util.AbstractRequestContent] - Content demand, producing true for BytesRequestContent.SubscriptionImpl@1f39be57[demand=1,stalled=false,committed=false,emitInitial=true] 2024-05-03 15:20:09,954 DEBUG - [org.eclipse.jetty.client.util.AbstractRequestContent] - Notifying content last=true HeapByteBuffer@12c7d102[p=0,l=0,c=0,r=0]={<<<>>>} for BytesRequestContent.SubscriptionImpl@1f39be57[demand=0,stalled=false,committed=true,emitInitial=true] 2024-05-03 15:20:09,954 DEBUG - [org.eclipse.jetty.client.HttpSender] - Content HeapByteBuffer@12c7d102[p=0,l=0,c=0,r=0]={<<<>>>} last=true for HttpRequest[GET / HTTP/1.1]@62735b13 2024-05-03 15:20:09,955 DEBUG - [org.eclipse.jetty.client.http.HttpSenderOverHTTP] - Sending headers with content HeapByteBuffer@12c7d102[p=0,l=0,c=0,r=0]={<<<>>>} last=true for HttpRequest[GET / HTTP/1.1]@62735b13 2024-05-03 15:20:09,956 DEBUG - [org.eclipse.jetty.client.http.HttpSenderOverHTTP] - Generated headers (-1 bytes), chunk (-1 bytes), content (0 bytes) - NEED_HEADER/HttpGenerator@4dad3475{s=START} for HttpRequest[GET / HTTP/1.1]@62735b13 2024-05-03 15:20:09,957 DEBUG - [org.eclipse.jetty.http.HttpGenerator] - generateHeaders GET{u=/,HTTP/1.1,h=4,cl=0,p=null} last=true content=HeapByteBuffer@12c7d102[p=0,l=0,c=0,r=0]={<<<>>>} 2024-05-03 15:20:09,957 DEBUG - [org.eclipse.jetty.http.HttpGenerator] - Accept-Encoding: gzip User-Agent: Jetty/11.0.20 Accept: */* Host: localhost:1337 2024-05-03 15:20:09,957 DEBUG - [org.eclipse.jetty.http.HttpGenerator] - NO_CONTENT 2024-05-03 15:20:09,957 DEBUG - [org.eclipse.jetty.client.http.HttpSenderOverHTTP] - Generated headers (103 bytes), chunk (-1 bytes), content (0 bytes) - FLUSH/HttpGenerator@4dad3475{s=COMPLETING} for HttpRequest[GET / HTTP/1.1]@62735b13 2024-05-03 15:20:09,957 DEBUG - [org.eclipse.jetty.io.WriteFlusher] - write: WriteFlusher@2e9619a6{IDLE}->null [DirectByteBuffer@7535878b[p=0,l=103,c=4096,r=103]={<<>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00},HeapByteBuffer@12c7d102[p=0,l=0,c=0,r=0]={<<<>>>},HeapByteBuffer@12c7d102[p=0,l=0,c=0,r=0]={<<<>>>}] 2024-05-03 15:20:09,957 DEBUG - [org.eclipse.jetty.io.WriteFlusher] - update WriteFlusher@2e9619a6{WRITING}->null:IDLE-->WRITING 2024-05-03 15:20:09,958 DEBUG - [org.eclipse.jetty.io.SocketChannelEndPoint] - flushed 103 SocketChannelEndPoint@61d85b7e[{l=/127.0.0.1:55910,r=localhost/127.0.0.1:1337,OPEN,fill=FI,flush=W,to=8/30000}{io=1/1,kio=1,kro=8}]->[HttpConnectionOverHTTP@71045497(l:/127.0.0.1:55910 <-> r:localhost/127.0.0.1:1337,closed=false)=>HttpChannelOverHTTP@55ef7c4d(exchange=HttpExchange@1ea7a937{req=HttpRequest[GET / HTTP/1.1]@62735b13[PENDING/null] res=HttpResponse[null 0 null]@1277d590[PENDING/null]})[send=HttpSenderOverHTTP@61c3a8b(req=HEADERS,failure=null)[HttpGenerator@4dad3475{s=COMPLETING}],recv=HttpReceiverOverHTTP@35da9039(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]] 2024-05-03 15:20:09,958 DEBUG - [org.eclipse.jetty.io.WriteFlusher] - Flushed=true written=103 remaining=0 WriteFlusher@2e9619a6{WRITING}->null 2024-05-03 15:20:09,958 DEBUG - [org.eclipse.jetty.io.WriteFlusher] - update WriteFlusher@2e9619a6{IDLE}->null:WRITING-->IDLE 2024-05-03 15:20:09,959 DEBUG - [org.eclipse.jetty.client.http.HttpSenderOverHTTP] - Generated headers (-1 bytes), chunk (-1 bytes), content (-1 bytes) - DONE/HttpGenerator@4dad3475{s=END} for HttpRequest[GET / HTTP/1.1]@62735b13 2024-05-03 15:20:09,959 DEBUG - [org.eclipse.jetty.client.HttpSender] - Request committed HttpRequest[GET / HTTP/1.1]@62735b13 2024-05-03 15:20:09,959 DEBUG - [org.eclipse.jetty.client.HttpSender] - Request success HttpRequest[GET / HTTP/1.1]@62735b13 2024-05-03 15:20:09,959 DEBUG - [org.eclipse.jetty.client.HttpExchange] - Terminated request for HttpExchange@1ea7a937{req=HttpRequest[GET / HTTP/1.1]@62735b13[TERMINATED/null] res=HttpResponse[null 0 null]@1277d590[PENDING/null]}, result: null 2024-05-03 15:20:09,959 DEBUG - [org.eclipse.jetty.client.HttpSender] - Terminating request HttpRequest[GET / HTTP/1.1]@62735b13 2024-05-03 15:20:09,959 DEBUG - [org.eclipse.jetty.client.util.AbstractRequestContent] - No demand, processing stalled for BytesRequestContent.SubscriptionImpl@1f39be57[demand=0,stalled=true,committed=true,emitInitial=true] 2024-05-03 15:20:09,959 DEBUG - [org.eclipse.jetty.io.ManagedSelector] - Created SocketChannelEndPoint@61d85b7e[{l=/127.0.0.1:55910,r=localhost/127.0.0.1:1337,OPEN,fill=FI,flush=-,to=1/30000}{io=1/1,kio=1,kro=8}]->[HttpConnectionOverHTTP@71045497(l:/127.0.0.1:55910 <-> r:localhost/127.0.0.1:1337,closed=false)=>HttpChannelOverHTTP@55ef7c4d(exchange=HttpExchange@1ea7a937{req=HttpRequest[GET / HTTP/1.1]@62735b13[TERMINATED/null] res=HttpResponse[null 0 null]@1277d590[PENDING/null]})[send=HttpSenderOverHTTP@61c3a8b(req=QUEUED,failure=null)[HttpGenerator@4dad3475{s=START}],recv=HttpReceiverOverHTTP@35da9039(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]] 2024-05-03 15:20:09,959 DEBUG - [org.eclipse.jetty.util.thread.QueuedThreadPool] - ran CreateEndPoint@5bba6a92{Connect@634d8287{java.nio.channels.SocketChannel[connected local=/127.0.0.1:55910 remote=localhost/127.0.0.1:1337],{org.eclipse.jetty.client.connector.remoteSocketAddress=localhost/127.0.0.1:1337, org.eclipse.jetty.client.connector.clientConnectionFactory=HttpClientTransportOverHTTP@5f395ce1{STARTED}, org.eclipse.jetty.client.destination=HttpDestination[Origin@db1e424a[http://localhost:1337,tag=null,protocol=Protocol@7f4624a[proto=[http/1.1],nego=false]]]@38f617f4,state=STARTED,queue=0,pool=DuplexConnectionPool@3407aa4f[s=STARTED,c=0/1/64,a=1,i=0,q=0,p=Pool@22ae905f[inUse=1,size=1,max=64,closed=false]],stale=false,idle=-1, org.eclipse.jetty.client.connector=ClientConnector@5b2b8d86{STARTED}, org.eclipse.jetty.client.connector.applicationProtocols=[http/1.1], org.eclipse.jetty.client=HttpClient@3554bdc0{STARTED}, org.eclipse.jetty.client.connection.promise=org.eclipse.jetty.client.HttpClient$1$1@196e4b8c, org.eclipse.jetty.client.connector.connectionPromise=org.eclipse.jetty.util.Promise$1@5d13c55b}}} in QueuedThreadPool[HttpClient@3554bdc0]@56a05324{STARTED,8<=9<=200,i=0,r=-1,t=59951ms,q=0}[ReservedThreadExecutor@36510e73{reserved=0/16,pending=0}] 2024-05-03 15:20:09,959 DEBUG - [org.eclipse.jetty.util.thread.QueuedThreadPool] - Evict check, period=60000ms QueuedThreadPool[HttpClient@3554bdc0]@56a05324{STARTED,8<=9<=200,i=1,r=-1,t=59950ms,q=0}[ReservedThreadExecutor@36510e73{reserved=0/16,pending=0}] 2024-05-03 15:20:09,959 DEBUG - [org.eclipse.jetty.util.thread.QueuedThreadPool] - Evict skipped, threshold=119950ms in the future QueuedThreadPool[HttpClient@3554bdc0]@56a05324{STARTED,8<=9<=200,i=1,r=-1,t=59950ms,q=0}[ReservedThreadExecutor@36510e73{reserved=0/16,pending=0}] 2024-05-03 15:20:09,971 DEBUG - [org.eclipse.jetty.io.ManagedSelector] - Selector sun.nio.ch.WEPollSelectorImpl@702154cf woken up from select, 1/1/1 selected 2024-05-03 15:20:09,971 DEBUG - [org.eclipse.jetty.io.ManagedSelector] - Selector sun.nio.ch.WEPollSelectorImpl@702154cf processing 1 keys, 0 updates 2024-05-03 15:20:09,971 DEBUG - [org.eclipse.jetty.io.ManagedSelector] - selected 1 channel=java.nio.channels.SocketChannel[connected local=/127.0.0.1:55910 remote=localhost/127.0.0.1:1337], selector=sun.nio.ch.WEPollSelectorImpl@702154cf, interestOps=1, readyOps=1 SocketChannelEndPoint@61d85b7e[{l=/127.0.0.1:55910,r=localhost/127.0.0.1:1337,OPEN,fill=FI,flush=-,to=13/30000}{io=1/1,kio=1,kro=1}]->[HttpConnectionOverHTTP@71045497(l:/127.0.0.1:55910 <-> r:localhost/127.0.0.1:1337,closed=false)=>HttpChannelOverHTTP@55ef7c4d(exchange=HttpExchange@1ea7a937{req=HttpRequest[GET / HTTP/1.1]@62735b13[TERMINATED/null] res=HttpResponse[null 0 null]@1277d590[PENDING/null]})[send=HttpSenderOverHTTP@61c3a8b(req=QUEUED,failure=null)[HttpGenerator@4dad3475{s=START}],recv=HttpReceiverOverHTTP@35da9039(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]] 2024-05-03 15:20:09,971 DEBUG - [org.eclipse.jetty.io.SelectableChannelEndPoint] - onSelected 1->0 r=true w=false for SocketChannelEndPoint@61d85b7e[{l=/127.0.0.1:55910,r=localhost/127.0.0.1:1337,OPEN,fill=FI,flush=-,to=13/30000}{io=1/0,kio=1,kro=1}]->[HttpConnectionOverHTTP@71045497(l:/127.0.0.1:55910 <-> r:localhost/127.0.0.1:1337,closed=false)=>HttpChannelOverHTTP@55ef7c4d(exchange=HttpExchange@1ea7a937{req=HttpRequest[GET / HTTP/1.1]@62735b13[TERMINATED/null] res=HttpResponse[null 0 null]@1277d590[PENDING/null]})[send=HttpSenderOverHTTP@61c3a8b(req=QUEUED,failure=null)[HttpGenerator@4dad3475{s=START}],recv=HttpReceiverOverHTTP@35da9039(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]] 2024-05-03 15:20:09,971 DEBUG - [org.eclipse.jetty.io.SelectableChannelEndPoint] - task SocketChannelEndPoint@61d85b7e[{l=/127.0.0.1:55910,r=localhost/127.0.0.1:1337,OPEN,fill=FI,flush=-,to=13/30000}{io=1/0,kio=1,kro=1}]->[HttpConnectionOverHTTP@71045497(l:/127.0.0.1:55910 <-> r:localhost/127.0.0.1:1337,closed=false)=>HttpChannelOverHTTP@55ef7c4d(exchange=HttpExchange@1ea7a937{req=HttpRequest[GET / HTTP/1.1]@62735b13[TERMINATED/null] res=HttpResponse[null 0 null]@1277d590[PENDING/null]})[send=HttpSenderOverHTTP@61c3a8b(req=QUEUED,failure=null)[HttpGenerator@4dad3475{s=START}],recv=HttpReceiverOverHTTP@35da9039(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]]:runFillable:BLOCKING 2024-05-03 15:20:09,972 DEBUG - [org.eclipse.jetty.util.thread.ReservedThreadExecutor] - ReservedThreadExecutor@36510e73{reserved=0/16,pending=0} tryExecute AdaptiveExecutionStrategy@30036a18/SelectorProducer@537b3b2e/PRODUCING/p=false/QueuedThreadPool[HttpClient@3554bdc0]@56a05324{STARTED,8<=9<=200,i=1,r=-1,t=59938ms,q=0}[ReservedThreadExecutor@36510e73{reserved=0/16,pending=0}][pc=0,pic=0,pec=0,epc=0]@2024-05-03T15:20:09.9722294+02:00 2024-05-03 15:20:09,972 DEBUG - [org.eclipse.jetty.util.thread.ReservedThreadExecutor] - ReservedThreadExecutor@36510e73{reserved=0/16,pending=1} startReservedThread p=1 2024-05-03 15:20:09,972 DEBUG - [org.eclipse.jetty.util.thread.QueuedThreadPool] - queue ReservedThread@22f71d6d{PENDING,thread=null} startThread=0 2024-05-03 15:20:09,972 DEBUG - [org.eclipse.jetty.util.thread.QueuedThreadPool] - run ReservedThread@22f71d6d{PENDING,thread=null} in QueuedThreadPool[HttpClient@3554bdc0]@56a05324{STARTED,8<=9<=200,i=0,r=-1,t=59937ms,q=0}[ReservedThreadExecutor@36510e73{reserved=0/16,pending=1}] 2024-05-03 15:20:09,972 DEBUG - [org.eclipse.jetty.util.thread.ReservedThreadExecutor] - ReservedThread@22f71d6d{PENDING,thread=Thread[HttpClient@3554bdc0-70,5,main]} was=PENDING next=RESERVED size=0+1 capacity=16 2024-05-03 15:20:09,972 DEBUG - [org.eclipse.jetty.util.thread.ReservedThreadExecutor] - ReservedThread@22f71d6d{RESERVED,thread=Thread[HttpClient@3554bdc0-70,5,main]} waiting ReservedThreadExecutor@36510e73{reserved=1/16,pending=0} 2024-05-03 15:20:09,972 DEBUG - [org.eclipse.jetty.util.thread.strategy.AdaptiveExecutionStrategy] - ss=PRODUCE_EXECUTE_CONSUME t=SocketChannelEndPoint@61d85b7e[{l=/127.0.0.1:55910,r=localhost/127.0.0.1:1337,OPEN,fill=FI,flush=-,to=14/30000}{io=1/0,kio=1,kro=1}]->[HttpConnectionOverHTTP@71045497(l:/127.0.0.1:55910 <-> r:localhost/127.0.0.1:1337,closed=false)=>HttpChannelOverHTTP@55ef7c4d(exchange=HttpExchange@1ea7a937{req=HttpRequest[GET / HTTP/1.1]@62735b13[TERMINATED/null] res=HttpResponse[null 0 null]@1277d590[PENDING/null]})[send=HttpSenderOverHTTP@61c3a8b(req=QUEUED,failure=null)[HttpGenerator@4dad3475{s=START}],recv=HttpReceiverOverHTTP@35da9039(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]]:runFillable:BLOCKING/BLOCKING AdaptiveExecutionStrategy@30036a18/SelectorProducer@537b3b2e/PRODUCING/p=false/QueuedThreadPool[HttpClient@3554bdc0]@56a05324{STARTED,8<=9<=200,i=0,r=-1,t=59937ms,q=0}[ReservedThreadExecutor@36510e73{reserved=1/16,pending=0}][pc=0,pic=0,pec=0,epc=0]@2024-05-03T15:20:09.9722294+02:00 2024-05-03 15:20:09,973 DEBUG - [org.eclipse.jetty.util.thread.QueuedThreadPool] - queue SocketChannelEndPoint@61d85b7e[{l=/127.0.0.1:55910,r=localhost/127.0.0.1:1337,OPEN,fill=FI,flush=-,to=14/30000}{io=1/0,kio=1,kro=1}]->[HttpConnectionOverHTTP@71045497(l:/127.0.0.1:55910 <-> r:localhost/127.0.0.1:1337,closed=false)=>HttpChannelOverHTTP@55ef7c4d(exchange=HttpExchange@1ea7a937{req=HttpRequest[GET / HTTP/1.1]@62735b13[TERMINATED/null] res=HttpResponse[null 0 null]@1277d590[PENDING/null]})[send=HttpSenderOverHTTP@61c3a8b(req=QUEUED,failure=null)[HttpGenerator@4dad3475{s=START}],recv=HttpReceiverOverHTTP@35da9039(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]]:runFillable:BLOCKING startThread=1 2024-05-03 15:20:09,973 DEBUG - [org.eclipse.jetty.util.thread.QueuedThreadPool] - Starting Thread[HttpClient@3554bdc0-73,5,main] 2024-05-03 15:20:09,973 DEBUG - [org.eclipse.jetty.io.ManagedSelector] - updateable 0 2024-05-03 15:20:09,973 DEBUG - [org.eclipse.jetty.io.ManagedSelector] - updates 0 2024-05-03 15:20:09,973 DEBUG - [org.eclipse.jetty.io.SelectableChannelEndPoint] - Key interests updated 1 -> 0 on SocketChannelEndPoint@61d85b7e[{l=/127.0.0.1:55910,r=localhost/127.0.0.1:1337,OPEN,fill=FI,flush=-,to=15/30000}{io=0/0,kio=0,kro=1}]->[HttpConnectionOverHTTP@71045497(l:/127.0.0.1:55910 <-> r:localhost/127.0.0.1:1337,closed=false)=>HttpChannelOverHTTP@55ef7c4d(exchange=HttpExchange@1ea7a937{req=HttpRequest[GET / HTTP/1.1]@62735b13[TERMINATED/null] res=HttpResponse[null 0 null]@1277d590[PENDING/null]})[send=HttpSenderOverHTTP@61c3a8b(req=QUEUED,failure=null)[HttpGenerator@4dad3475{s=START}],recv=HttpReceiverOverHTTP@35da9039(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]] 2024-05-03 15:20:09,973 DEBUG - [org.eclipse.jetty.io.ManagedSelector] - Selector sun.nio.ch.WEPollSelectorImpl@702154cf waiting with 1 keys 2024-05-03 15:20:09,973 DEBUG - [org.eclipse.jetty.util.thread.QueuedThreadPool] - Runner started for QueuedThreadPool[HttpClient@3554bdc0]@56a05324{STARTED,8<=10<=200,i=0,r=-1,t=59999ms,q=0}[ReservedThreadExecutor@36510e73{reserved=1/16,pending=0}] 2024-05-03 15:20:09,973 DEBUG - [org.eclipse.jetty.util.thread.QueuedThreadPool] - run SocketChannelEndPoint@61d85b7e[{l=/127.0.0.1:55910,r=localhost/127.0.0.1:1337,OPEN,fill=FI,flush=-,to=15/30000}{io=0/0,kio=0,kro=1}]->[HttpConnectionOverHTTP@71045497(l:/127.0.0.1:55910 <-> r:localhost/127.0.0.1:1337,closed=false)=>HttpChannelOverHTTP@55ef7c4d(exchange=HttpExchange@1ea7a937{req=HttpRequest[GET / HTTP/1.1]@62735b13[TERMINATED/null] res=HttpResponse[null 0 null]@1277d590[PENDING/null]})[send=HttpSenderOverHTTP@61c3a8b(req=QUEUED,failure=null)[HttpGenerator@4dad3475{s=START}],recv=HttpReceiverOverHTTP@35da9039(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]]:runFillable:BLOCKING in QueuedThreadPool[HttpClient@3554bdc0]@56a05324{STARTED,8<=10<=200,i=0,r=-1,t=59999ms,q=0}[ReservedThreadExecutor@36510e73{reserved=1/16,pending=0}] 2024-05-03 15:20:09,973 DEBUG - [org.eclipse.jetty.io.FillInterest] - fillable FillInterest@1bf99fdb{ReadCallback@7cd6264d{HttpConnectionOverHTTP@71045497::SocketChannelEndPoint@61d85b7e[{l=/127.0.0.1:55910,r=localhost/127.0.0.1:1337,OPEN,fill=FI,flush=-,to=15/30000}{io=0/0,kio=0,kro=1}]->[HttpConnectionOverHTTP@71045497(l:/127.0.0.1:55910 <-> r:localhost/127.0.0.1:1337,closed=false)=>HttpChannelOverHTTP@55ef7c4d(exchange=HttpExchange@1ea7a937{req=HttpRequest[GET / HTTP/1.1]@62735b13[TERMINATED/null] res=HttpResponse[null 0 null]@1277d590[PENDING/null]})[send=HttpSenderOverHTTP@61c3a8b(req=QUEUED,failure=null)[HttpGenerator@4dad3475{s=START}],recv=HttpReceiverOverHTTP@35da9039(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]]}} 2024-05-03 15:20:09,973 DEBUG - [org.eclipse.jetty.util.Pool] - RetainedBucket@2d9f5da1[inUse=0,size=1,max=100,closed=false]{capacity=16384,inuse=0(0%)} returning new reserved entry MonoEntry@29a0ccca{PENDING,pooled=null} 2024-05-03 15:20:09,974 DEBUG - [org.eclipse.jetty.client.http.HttpReceiverOverHTTP] - Acquired RetainableByteBuffer@8c3d0f9{DirectByteBuffer@5483eb10[p=0,l=0,c=16384,r=0]={<<<>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00},r=1} 2024-05-03 15:20:09,974 DEBUG - [org.eclipse.jetty.http.HttpParser] - parseNext s=START DirectByteBuffer@5483eb10[p=0,l=0,c=16384,r=0]={<<<>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00} 2024-05-03 15:20:09,974 DEBUG - [org.eclipse.jetty.client.http.HttpReceiverOverHTTP] - Parse result=false, failed=false 2024-05-03 15:20:09,974 DEBUG - [org.eclipse.jetty.client.http.HttpReceiverOverHTTP] - Parse complete=false, RetainableByteBuffer@8c3d0f9{DirectByteBuffer@5483eb10[p=0,l=0,c=16384,r=0]={<<<>>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00},r=1} HttpParser{s=START,0 of -1} 2024-05-03 15:20:09,974 DEBUG - [org.eclipse.jetty.io.SocketChannelEndPoint] - filled 48 DirectByteBuffer@5483eb10[p=0,l=48,c=16384,r=48]={<<>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00} 2024-05-03 15:20:09,974 DEBUG - [org.eclipse.jetty.client.http.HttpReceiverOverHTTP] - Read 48 bytes in RetainableByteBuffer@8c3d0f9{DirectByteBuffer@5483eb10[p=0,l=48,c=16384,r=48]={<<>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00},r=1} from SocketChannelEndPoint@61d85b7e[{l=/127.0.0.1:55910,r=localhost/127.0.0.1:1337,OPEN,fill=-,flush=-,to=0/30000}{io=0/0,kio=0,kro=1}]->[HttpConnectionOverHTTP@71045497(l:/127.0.0.1:55910 <-> r:localhost/127.0.0.1:1337,closed=false)=>HttpChannelOverHTTP@55ef7c4d(exchange=HttpExchange@1ea7a937{req=HttpRequest[GET / HTTP/1.1]@62735b13[TERMINATED/null] res=HttpResponse[null 0 null]@1277d590[PENDING/null]})[send=HttpSenderOverHTTP@61c3a8b(req=QUEUED,failure=null)[HttpGenerator@4dad3475{s=START}],recv=HttpReceiverOverHTTP@35da9039(rsp=IDLE,failure=null)[HttpParser{s=START,0 of -1}]]] 2024-05-03 15:20:09,974 DEBUG - [org.eclipse.jetty.http.HttpParser] - parseNext s=START DirectByteBuffer@5483eb10[p=0,l=48,c=16384,r=48]={<<>>\x00\x00\x00\x00\x00\x00\x00\x00\x00...\x00\x00\x00\x00\x00\x00\x00} 2024-05-03 15:20:09,975 DEBUG - [org.eclipse.jetty.http.HttpParser] - START --> RESPONSE_VERSION 2024-05-03 15:20:09,975 DEBUG - [org.eclipse.jetty.http.HttpParser] - RESPONSE_VERSION --> SPACE1 2024-05-03 15:20:09,975 DEBUG - [org.eclipse.jetty.http.HttpParser] - SPACE1 --> STATUS 2024-05-03 15:20:09,975 DEBUG - [org.eclipse.jetty.http.HttpParser] - STATUS --> SPACE2 2024-05-03 15:20:09,975 DEBUG - [org.eclipse.jetty.http.HttpParser] - SPACE2 --> REASON 2024-05-03 15:20:09,975 DEBUG - [org.eclipse.jetty.http.HttpParser] - REASON --> HEADER 2024-05-03 15:20:09,975 DEBUG - [org.eclipse.jetty.client.HttpConversation] - Exchanges in conversation 1, override=null, listeners=[org.eclipse.jetty.client.HttpRequest$8@586843bc, org.eclipse.jetty.client.HttpRequest$8@17134190, org.eclipse.jetty.client.HttpRequest$10@7d8b66d9, org.eclipse.jetty.client.HttpRequest$13@5599b5bb, org.eclipse.jetty.client.HttpRequest$14@4ff66917, org.eclipse.jetty.client.HttpRequest$15@4264beb8, org.eclipse.jetty.client.HttpRequest$16@647fb583, ResponseListenerProcessor@58601e7a[Reactive[HttpRequest[GET / HTTP/1.1]@62735b13]]] 2024-05-03 15:20:09,975 DEBUG - [org.eclipse.jetty.client.HttpReceiver] - Response begin HttpResponse[HTTP/1.1 50 Mock Response]@1277d590 2024-05-03 15:20:09,975 DEBUG - [org.eclipse.jetty.http.HttpParser] - HEADER:Content-Length: 0 --> IN_VALUE 2024-05-03 15:20:09,975 DEBUG - [org.eclipse.jetty.http.HttpParser] - HEADER:Content-Length: 0 --> FIELD 2024-05-03 15:20:09,975 DEBUG - [org.eclipse.jetty.http.HttpParser] - parsedHeader(Content-Length: 0) header=Content-Length, headerString=[Content-Length], valueString=[0] 2024-05-03 15:20:09,976 DEBUG - [org.eclipse.jetty.http.HttpParser] - HEADER --> CONTENT 2024-05-03 15:20:09,976 DEBUG - [org.eclipse.jetty.client.HttpReceiver] - Response headers HttpResponse[HTTP/1.1 50 Mock Response]@1277d590 Content-Length: 0 2024-05-03 15:20:09,976 DEBUG - [org.eclipse.jetty.reactive.client.internal.ResponseListenerProcessor] - received response headers HttpResponse[HTTP/1.1 50 Mock Response]@1277d590 on ResponseListenerProcessor@58601e7a[Reactive[HttpRequest[GET / HTTP/1.1]@62735b13]] 2024-05-03 15:20:09,977 INFO - [org.eclipse.jetty.client.ResponseNotifier] - Exception while notifying listener ResponseListenerProcessor@58601e7a[Reactive[HttpRequest[GET / HTTP/1.1]@62735b13]] java.lang.IllegalArgumentException: Status code '50' should be a three-digit positive integer at org.springframework.util.Assert.isTrue(Assert.java:140) at org.springframework.http.HttpStatusCode.valueOf(HttpStatusCode.java:99) at org.springframework.http.client.reactive.JettyClientHttpResponse.(JettyClientHttpResponse.java:52) at org.springframework.http.client.reactive.JettyClientHttpConnector.lambda$execute$0(JettyClientHttpConnector.java:132) at org.eclipse.jetty.reactive.client.internal.ResponseListenerProcessor.onHeaders(ResponseListenerProcessor.java:93) at org.eclipse.jetty.client.ResponseNotifier.notifyHeaders(ResponseNotifier.java:95) at org.eclipse.jetty.client.ResponseNotifier.notifyHeaders(ResponseNotifier.java:87) at org.eclipse.jetty.client.HttpReceiver.responseHeaders(HttpReceiver.java:327) at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.headerComplete(HttpReceiverOverHTTP.java:331) at org.eclipse.jetty.http.HttpParser.parseFields(HttpParser.java:1256) at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:1542) at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.parse(HttpReceiverOverHTTP.java:221) at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.process(HttpReceiverOverHTTP.java:160) at org.eclipse.jetty.client.http.HttpReceiverOverHTTP.receive(HttpReceiverOverHTTP.java:91) at org.eclipse.jetty.client.http.HttpChannelOverHTTP.receive(HttpChannelOverHTTP.java:97) at org.eclipse.jetty.client.http.HttpConnectionOverHTTP.onFillable(HttpConnectionOverHTTP.java:207) at org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:314) at org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100) at org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53) at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:969) at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1194) at org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1149) at java.base/java.lang.Thread.run(Thread.java:840) 2024-05-03 15:20:09,979 DEBUG - [org.eclipse.jetty.client.HttpReceiver] - Response headers hasDemand=false HttpResponse[HTTP/1.1 50 Mock Response]@1277d590 2024-05-03 15:20:09,979 DEBUG - [org.eclipse.jetty.client.http.HttpReceiverOverHTTP] - Parse result=true, failed=false 2024-05-03 15:20:09,979 DEBUG - [org.eclipse.jetty.util.thread.QueuedThreadPool] - ran SocketChannelEndPoint@61d85b7e[{l=/127.0.0.1:55910,r=localhost/127.0.0.1:1337,OPEN,fill=-,flush=-,to=4/30000}{io=0/0,kio=0,kro=1}]->[HttpConnectionOverHTTP@71045497(l:/127.0.0.1:55910 <-> r:localhost/127.0.0.1:1337,closed=false)=>HttpChannelOverHTTP@55ef7c4d(exchange=HttpExchange@1ea7a937{req=HttpRequest[GET / HTTP/1.1]@62735b13[TERMINATED/null] res=HttpResponse[HTTP/1.1 50 Mock Response]@1277d590[PENDING/null]})[send=HttpSenderOverHTTP@61c3a8b(req=QUEUED,failure=null)[HttpGenerator@4dad3475{s=START}],recv=HttpReceiverOverHTTP@35da9039(rsp=HEADERS,failure=null)[HttpParser{s=CONTENT,0 of 0}]]]:runFillable:BLOCKING in QueuedThreadPool[HttpClient@3554bdc0]@56a05324{STARTED,8<=10<=200,i=0,r=-1,t=59993ms,q=0}[ReservedThreadExecutor@36510e73{reserved=1/16,pending=0}] 2024-05-03 15:20:09,979 DEBUG - [org.eclipse.jetty.util.thread.QueuedThreadPool] - Evict check, period=60000ms QueuedThreadPool[HttpClient@3554bdc0]@56a05324{STARTED,8<=10<=200,i=1,r=-1,t=59993ms,q=0}[ReservedThreadExecutor@36510e73{reserved=1/16,pending=0}] 2024-05-03 15:20:09,979 DEBUG - [org.eclipse.jetty.util.thread.QueuedThreadPool] - Evict skipped, threshold=119993ms in the future QueuedThreadPool[HttpClient@3554bdc0]@56a05324{STARTED,8<=10<=200,i=1,r=-1,t=59993ms,q=0}[ReservedThreadExecutor@36510e73{reserved=1/16,pending=0}] 2024-05-03 15:20:24,900 DEBUG - [org.springframework.web.reactive.function.client.ExchangeFunctions] - [34009349] Cancel signal (to close connection) 2024-05-03 15:20:24,900 DEBUG - [org.eclipse.jetty.client.HttpExchange] - Failed HttpExchange@1ea7a937{req=HttpRequest[GET / HTTP/1.1]@62735b13[TERMINATED/null] res=HttpResponse[HTTP/1.1 50 Mock Response]@1277d590[COMPLETED/java.util.concurrent.CancellationException]}: req=false/rsp=true {} java.util.concurrent.CancellationException: null at org.eclipse.jetty.reactive.client.internal.ResponseListenerProcessor.cancel(ResponseListenerProcessor.java:174) at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.cancel(MonoIgnoreThen.java:143) at reactor.core.publisher.FluxPeek$PeekSubscriber.cancel(FluxPeek.java:153) at reactor.core.publisher.FluxPeek$PeekSubscriber.cancel(FluxPeek.java:153) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drainLoop(Operators.java:2399) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drain(Operators.java:2367) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.cancel(Operators.java:2179) at reactor.core.publisher.FluxMap$MapSubscriber.cancel(FluxMap.java:169) at reactor.core.publisher.FluxPeek$PeekSubscriber.cancel(FluxPeek.java:153) at reactor.core.publisher.FluxOnAssembly$OnAssemblySubscriber.cancel(FluxOnAssembly.java:654) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drainLoop(Operators.java:2399) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drain(Operators.java:2367) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.cancel(Operators.java:2179) at reactor.core.publisher.FluxPeekFuseable$PeekConditionalSubscriber.cancel(FluxPeekFuseable.java:798) at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.cancel(MonoPeekTerminal.java:144) at reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.cancel(FluxDoFinally.java:134) at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.cancel(FluxContextWrite.java:141) at reactor.core.publisher.MonoFlatMap$FlatMapMain.cancel(MonoFlatMap.java:199) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drainLoop(Operators.java:2399) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drain(Operators.java:2367) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.cancel(Operators.java:2179) at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.handleTimeout(FluxTimeout.java:294) at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.doTimeout(FluxTimeout.java:280) at reactor.core.publisher.FluxTimeout$TimeoutTimeoutSubscriber.onNext(FluxTimeout.java:419) at reactor.core.publisher.FluxOnErrorReturn$ReturnSubscriber.onNext(FluxOnErrorReturn.java:162) at reactor.core.publisher.MonoDelay$MonoDelayRunnable.propagateDelay(MonoDelay.java:271) at reactor.core.publisher.MonoDelay$MonoDelayRunnable.run(MonoDelay.java:286) at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:68) at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:28) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) at java.base/java.lang.Thread.run(Thread.java:840) 2024-05-03 15:20:24,901 DEBUG - [org.eclipse.jetty.client.HttpReceiver] - Response abort HttpResponse[HTTP/1.1 50 Mock Response]@1277d590 HttpExchange@1ea7a937{req=HttpRequest[GET / HTTP/1.1]@62735b13[TERMINATED/null] res=HttpResponse[HTTP/1.1 50 Mock Response]@1277d590[COMPLETED/java.util.concurrent.CancellationException]} on HttpChannelOverHTTP@55ef7c4d(exchange=HttpExchange@1ea7a937{req=HttpRequest[GET / HTTP/1.1]@62735b13[TERMINATED/null] res=HttpResponse[HTTP/1.1 50 Mock Response]@1277d590[COMPLETED/java.util.concurrent.CancellationException]})[send=HttpSenderOverHTTP@61c3a8b(req=QUEUED,failure=null)[HttpGenerator@4dad3475{s=START}],recv=HttpReceiverOverHTTP@35da9039(rsp=FAILURE,failure=java.util.concurrent.CancellationException)[HttpParser{s=CONTENT,0 of 0}]]: {} java.util.concurrent.CancellationException: null at org.eclipse.jetty.reactive.client.internal.ResponseListenerProcessor.cancel(ResponseListenerProcessor.java:174) at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.cancel(MonoIgnoreThen.java:143) at reactor.core.publisher.FluxPeek$PeekSubscriber.cancel(FluxPeek.java:153) at reactor.core.publisher.FluxPeek$PeekSubscriber.cancel(FluxPeek.java:153) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drainLoop(Operators.java:2399) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drain(Operators.java:2367) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.cancel(Operators.java:2179) at reactor.core.publisher.FluxMap$MapSubscriber.cancel(FluxMap.java:169) at reactor.core.publisher.FluxPeek$PeekSubscriber.cancel(FluxPeek.java:153) at reactor.core.publisher.FluxOnAssembly$OnAssemblySubscriber.cancel(FluxOnAssembly.java:654) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drainLoop(Operators.java:2399) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drain(Operators.java:2367) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.cancel(Operators.java:2179) at reactor.core.publisher.FluxPeekFuseable$PeekConditionalSubscriber.cancel(FluxPeekFuseable.java:798) at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.cancel(MonoPeekTerminal.java:144) at reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.cancel(FluxDoFinally.java:134) at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.cancel(FluxContextWrite.java:141) at reactor.core.publisher.MonoFlatMap$FlatMapMain.cancel(MonoFlatMap.java:199) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drainLoop(Operators.java:2399) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drain(Operators.java:2367) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.cancel(Operators.java:2179) at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.handleTimeout(FluxTimeout.java:294) at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.doTimeout(FluxTimeout.java:280) at reactor.core.publisher.FluxTimeout$TimeoutTimeoutSubscriber.onNext(FluxTimeout.java:419) at reactor.core.publisher.FluxOnErrorReturn$ReturnSubscriber.onNext(FluxOnErrorReturn.java:162) at reactor.core.publisher.MonoDelay$MonoDelayRunnable.propagateDelay(MonoDelay.java:271) at reactor.core.publisher.MonoDelay$MonoDelayRunnable.run(MonoDelay.java:286) at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:68) at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:28) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) at java.base/java.lang.Thread.run(Thread.java:840) 2024-05-03 15:20:24,902 DEBUG - [org.eclipse.jetty.reactive.client.internal.ResponseListenerProcessor] - response failure HttpResponse[HTTP/1.1 50 Mock Response]@1277d590 on ResponseListenerProcessor@58601e7a[Reactive[HttpRequest[GET / HTTP/1.1]@62735b13]] java.util.concurrent.CancellationException: null at org.eclipse.jetty.reactive.client.internal.ResponseListenerProcessor.cancel(ResponseListenerProcessor.java:174) at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.cancel(MonoIgnoreThen.java:143) at reactor.core.publisher.FluxPeek$PeekSubscriber.cancel(FluxPeek.java:153) at reactor.core.publisher.FluxPeek$PeekSubscriber.cancel(FluxPeek.java:153) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drainLoop(Operators.java:2399) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drain(Operators.java:2367) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.cancel(Operators.java:2179) at reactor.core.publisher.FluxMap$MapSubscriber.cancel(FluxMap.java:169) at reactor.core.publisher.FluxPeek$PeekSubscriber.cancel(FluxPeek.java:153) at reactor.core.publisher.FluxOnAssembly$OnAssemblySubscriber.cancel(FluxOnAssembly.java:654) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drainLoop(Operators.java:2399) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drain(Operators.java:2367) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.cancel(Operators.java:2179) at reactor.core.publisher.FluxPeekFuseable$PeekConditionalSubscriber.cancel(FluxPeekFuseable.java:798) at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.cancel(MonoPeekTerminal.java:144) at reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.cancel(FluxDoFinally.java:134) at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.cancel(FluxContextWrite.java:141) at reactor.core.publisher.MonoFlatMap$FlatMapMain.cancel(MonoFlatMap.java:199) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drainLoop(Operators.java:2399) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drain(Operators.java:2367) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.cancel(Operators.java:2179) at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.handleTimeout(FluxTimeout.java:294) at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.doTimeout(FluxTimeout.java:280) at reactor.core.publisher.FluxTimeout$TimeoutTimeoutSubscriber.onNext(FluxTimeout.java:419) at reactor.core.publisher.FluxOnErrorReturn$ReturnSubscriber.onNext(FluxOnErrorReturn.java:162) at reactor.core.publisher.MonoDelay$MonoDelayRunnable.propagateDelay(MonoDelay.java:271) at reactor.core.publisher.MonoDelay$MonoDelayRunnable.run(MonoDelay.java:286) at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:68) at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:28) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) at java.base/java.lang.Thread.run(Thread.java:840) 2024-05-03 15:20:24,903 DEBUG - [org.eclipse.jetty.client.HttpExchange] - Terminated response for HttpExchange@1ea7a937{req=HttpRequest[GET / HTTP/1.1]@62735b13[TERMINATED/null] res=HttpResponse[HTTP/1.1 50 Mock Response]@1277d590[TERMINATED/java.util.concurrent.CancellationException]}, result: Result[HttpRequest[GET / HTTP/1.1]@62735b13 > HttpResponse[HTTP/1.1 50 Mock Response]@1277d590] java.util.concurrent.CancellationException 2024-05-03 15:20:24,903 DEBUG - [org.eclipse.jetty.client.HttpReceiver] - Response complete HttpResponse[HTTP/1.1 50 Mock Response]@1277d590, result: Result[HttpRequest[GET / HTTP/1.1]@62735b13 > HttpResponse[HTTP/1.1 50 Mock Response]@1277d590] java.util.concurrent.CancellationException 2024-05-03 15:20:24,904 DEBUG - [org.eclipse.jetty.client.HttpChannel] - HttpExchange@1ea7a937{req=HttpRequest[GET / HTTP/1.1]@62735b13[TERMINATED/null] res=HttpResponse[HTTP/1.1 50 Mock Response]@1277d590[TERMINATED/java.util.concurrent.CancellationException]} disassociated true from HttpChannelOverHTTP@55ef7c4d(exchange=null)[send=HttpSenderOverHTTP@61c3a8b(req=QUEUED,failure=null)[HttpGenerator@4dad3475{s=START}],recv=HttpReceiverOverHTTP@35da9039(rsp=FAILURE,failure=java.util.concurrent.CancellationException)[HttpParser{s=CONTENT,0 of 0}]] 2024-05-03 15:20:24,904 DEBUG - [org.eclipse.jetty.client.http.HttpChannelOverHTTP] - Closing, reason: failure - HttpConnectionOverHTTP@71045497::SocketChannelEndPoint@61d85b7e[{l=/127.0.0.1:55910,r=localhost/127.0.0.1:1337,OPEN,fill=-,flush=-,to=14929/30000}{io=0/0,kio=0,kro=1}]->[HttpConnectionOverHTTP@71045497(l:/127.0.0.1:55910 <-> r:localhost/127.0.0.1:1337,closed=false)=>HttpChannelOverHTTP@55ef7c4d(exchange=null)[send=HttpSenderOverHTTP@61c3a8b(req=QUEUED,failure=null)[HttpGenerator@4dad3475{s=START}],recv=HttpReceiverOverHTTP@35da9039(rsp=FAILURE,failure=java.util.concurrent.CancellationException)[HttpParser{s=CONTENT,0 of 0}]]] 2024-05-03 15:20:24,904 DEBUG - [org.eclipse.jetty.client.AbstractConnectionPool] - Removed (true) MultiEntry@5b14f482{CLOSED,usage=0,multiplex=0,pooled=HttpConnectionOverHTTP@71045497::SocketChannelEndPoint@61d85b7e[{l=/127.0.0.1:55910,r=localhost/127.0.0.1:1337,OPEN,fill=-,flush=-,to=14930/30000}{io=0/0,kio=0,kro=1}]->[HttpConnectionOverHTTP@71045497(l:/127.0.0.1:55910 <-> r:localhost/127.0.0.1:1337,closed=true)=>HttpChannelOverHTTP@55ef7c4d(exchange=null)[send=HttpSenderOverHTTP@61c3a8b(req=QUEUED,failure=null)[HttpGenerator@4dad3475{s=START}],recv=HttpReceiverOverHTTP@35da9039(rsp=FAILURE,failure=java.util.concurrent.CancellationException)[HttpParser{s=CONTENT,0 of 0}]]]} Pool@22ae905f[inUse=0,size=0,max=64,closed=false] 2024-05-03 15:20:24,904 DEBUG - [org.eclipse.jetty.io.AbstractEndPoint] - shutdownOutput SocketChannelEndPoint@61d85b7e[{l=/127.0.0.1:55910,r=localhost/127.0.0.1:1337,OPEN,fill=-,flush=-,to=14930/30000}{io=0/0,kio=0,kro=1}]->[HttpConnectionOverHTTP@71045497(l:/127.0.0.1:55910 <-> r:localhost/127.0.0.1:1337,closed=true)=>HttpChannelOverHTTP@55ef7c4d(exchange=null)[send=HttpSenderOverHTTP@61c3a8b(req=QUEUED,failure=null)[HttpGenerator@4dad3475{s=START}],recv=HttpReceiverOverHTTP@35da9039(rsp=FAILURE,failure=java.util.concurrent.CancellationException)[HttpParser{s=CONTENT,0 of 0}]]] 2024-05-03 15:20:24,905 DEBUG - [org.eclipse.jetty.client.http.HttpConnectionOverHTTP] - Shutdown HttpConnectionOverHTTP@71045497::SocketChannelEndPoint@61d85b7e[{l=/127.0.0.1:55910,r=localhost/127.0.0.1:1337,OSHUT,fill=-,flush=-,to=14930/30000}{io=0/0,kio=0,kro=1}]->[HttpConnectionOverHTTP@71045497(l:/127.0.0.1:55910 <-> r:localhost/127.0.0.1:1337,closed=true)=>HttpChannelOverHTTP@55ef7c4d(exchange=null)[send=HttpSenderOverHTTP@61c3a8b(req=QUEUED,failure=null)[HttpGenerator@4dad3475{s=START}],recv=HttpReceiverOverHTTP@35da9039(rsp=FAILURE,failure=java.util.concurrent.CancellationException)[HttpParser{s=CONTENT,0 of 0}]]] 2024-05-03 15:20:24,905 DEBUG - [org.eclipse.jetty.io.AbstractEndPoint] - close SocketChannelEndPoint@61d85b7e[{l=/127.0.0.1:55910,r=localhost/127.0.0.1:1337,OSHUT,fill=-,flush=-,to=14931/30000}{io=0/0,kio=0,kro=1}]->[HttpConnectionOverHTTP@71045497(l:/127.0.0.1:55910 <-> r:localhost/127.0.0.1:1337,closed=true)=>HttpChannelOverHTTP@55ef7c4d(exchange=null)[send=HttpSenderOverHTTP@61c3a8b(req=QUEUED,failure=null)[HttpGenerator@4dad3475{s=START}],recv=HttpReceiverOverHTTP@35da9039(rsp=FAILURE,failure=java.util.concurrent.CancellationException)[HttpParser{s=CONTENT,0 of 0}]]] 2024-05-03 15:20:24,905 DEBUG - [org.eclipse.jetty.io.AbstractEndPoint] - close(null) SocketChannelEndPoint@61d85b7e[{l=/127.0.0.1:55910,r=localhost/127.0.0.1:1337,OSHUT,fill=-,flush=-,to=14931/30000}{io=0/0,kio=0,kro=1}]->[HttpConnectionOverHTTP@71045497(l:/127.0.0.1:55910 <-> r:localhost/127.0.0.1:1337,closed=true)=>HttpChannelOverHTTP@55ef7c4d(exchange=null)[send=HttpSenderOverHTTP@61c3a8b(req=QUEUED,failure=null)[HttpGenerator@4dad3475{s=START}],recv=HttpReceiverOverHTTP@35da9039(rsp=FAILURE,failure=java.util.concurrent.CancellationException)[HttpParser{s=CONTENT,0 of 0}]]] 2024-05-03 15:20:24,905 DEBUG - [org.eclipse.jetty.io.SelectableChannelEndPoint] - doClose SocketChannelEndPoint@61d85b7e[{l=/127.0.0.1:55910,r=localhost/127.0.0.1:1337,CLOSED,fill=-,flush=-,to=14931/30000}{io=0/0,kio=0,kro=1}]->[HttpConnectionOverHTTP@71045497(l:/127.0.0.1:55910 <-> r:localhost/127.0.0.1:1337,closed=true)=>HttpChannelOverHTTP@55ef7c4d(exchange=null)[send=HttpSenderOverHTTP@61c3a8b(req=QUEUED,failure=null)[HttpGenerator@4dad3475{s=START}],recv=HttpReceiverOverHTTP@35da9039(rsp=FAILURE,failure=java.util.concurrent.CancellationException)[HttpParser{s=CONTENT,0 of 0}]]] 2024-05-03 15:20:24,907 DEBUG - [org.eclipse.jetty.io.FillInterest] - onClose FillInterest@1bf99fdb{null} 2024-05-03 15:20:24,907 DEBUG - [org.eclipse.jetty.io.ManagedSelector] - Wakeup ManagedSelector@1544ded3{STARTED} id=1 keys=1 selected=0 updates=0 2024-05-03 15:20:24,907 DEBUG - [org.eclipse.jetty.io.ManagedSelector] - Selector sun.nio.ch.WEPollSelectorImpl@702154cf woken with none selected 2024-05-03 15:20:24,907 DEBUG - [org.eclipse.jetty.io.ManagedSelector] - Selector sun.nio.ch.WEPollSelectorImpl@702154cf woken up from select, 0/0/0 selected 2024-05-03 15:20:24,907 DEBUG - [org.eclipse.jetty.io.ManagedSelector] - Selector sun.nio.ch.WEPollSelectorImpl@702154cf processing 0 keys, 0 updates 2024-05-03 15:20:24,908 DEBUG - [org.eclipse.jetty.io.ManagedSelector] - updateable 0 2024-05-03 15:20:24,908 DEBUG - [org.eclipse.jetty.io.ManagedSelector] - updates 0 2024-05-03 15:20:24,908 DEBUG - [org.eclipse.jetty.io.ManagedSelector] - Selector sun.nio.ch.WEPollSelectorImpl@702154cf waiting with 0 keys 2024-05-03 15:20:24,908 DEBUG - [org.eclipse.jetty.util.thread.QueuedThreadPool] - queue org.eclipse.jetty.io.ManagedSelector$DestroyEndPoint@6a2013c8 startThread=0 2024-05-03 15:20:24,908 DEBUG - [org.eclipse.jetty.client.http.HttpConnectionOverHTTP] - Closed HttpConnectionOverHTTP@71045497::SocketChannelEndPoint@61d85b7e[{l=null,r=null,CLOSED,fill=-,flush=-,to=14933/30000}{io=0/0,kio=-1,kro=-1}]->[HttpConnectionOverHTTP@71045497(l:null <-> r:null,closed=true)=>HttpChannelOverHTTP@55ef7c4d(exchange=null)[send=HttpSenderOverHTTP@61c3a8b(req=QUEUED,failure=null)[HttpGenerator@4dad3475{s=START}],recv=HttpReceiverOverHTTP@35da9039(rsp=FAILURE,failure=java.util.concurrent.CancellationException)[HttpParser{s=CONTENT,0 of 0}]]] 2024-05-03 15:20:24,908 DEBUG - [org.eclipse.jetty.util.thread.QueuedThreadPool] - run org.eclipse.jetty.io.ManagedSelector$DestroyEndPoint@6a2013c8 in QueuedThreadPool[HttpClient@3554bdc0]@56a05324{STARTED,8<=10<=200,i=0,r=-1,t=45064ms,q=0}[ReservedThreadExecutor@36510e73{reserved=1/16,pending=0}] 2024-05-03 15:20:24,908 DEBUG - [org.eclipse.jetty.client.HttpReceiver] - Request/Response failed: Result[HttpRequest[GET / HTTP/1.1]@62735b13 > HttpResponse[HTTP/1.1 50 Mock Response]@1277d590] java.util.concurrent.CancellationException, notifying [org.eclipse.jetty.client.HttpRequest$8@586843bc, org.eclipse.jetty.client.HttpRequest$8@17134190, org.eclipse.jetty.client.HttpRequest$10@7d8b66d9, org.eclipse.jetty.client.HttpRequest$13@5599b5bb, org.eclipse.jetty.client.HttpRequest$14@4ff66917, org.eclipse.jetty.client.HttpRequest$15@4264beb8, org.eclipse.jetty.client.HttpRequest$16@647fb583, ResponseListenerProcessor@58601e7a[Reactive[HttpRequest[GET / HTTP/1.1]@62735b13]]] 2024-05-03 15:20:24,908 DEBUG - [org.eclipse.jetty.io.ManagedSelector] - Destroyed SocketChannelEndPoint@61d85b7e[{l=null,r=null,CLOSED,fill=-,flush=-,to=14933/30000}{io=0/0,kio=-1,kro=-1}]->[HttpConnectionOverHTTP@71045497(l:null <-> r:null,closed=true)=>HttpChannelOverHTTP@55ef7c4d(exchange=null)[send=HttpSenderOverHTTP@61c3a8b(req=QUEUED,failure=null)[HttpGenerator@4dad3475{s=START}],recv=HttpReceiverOverHTTP@35da9039(rsp=FAILURE,failure=java.util.concurrent.CancellationException)[HttpParser{s=CONTENT,0 of 0}]]] 2024-05-03 15:20:24,908 DEBUG - [org.eclipse.jetty.io.AbstractConnection] - onClose HttpConnectionOverHTTP@71045497::SocketChannelEndPoint@61d85b7e[{l=null,r=null,CLOSED,fill=-,flush=-,to=14933/30000}{io=0/0,kio=-1,kro=-1}]->[HttpConnectionOverHTTP@71045497(l:null <-> r:null,closed=true)=>HttpChannelOverHTTP@55ef7c4d(exchange=null)[send=HttpSenderOverHTTP@61c3a8b(req=QUEUED,failure=null)[HttpGenerator@4dad3475{s=START}],recv=HttpReceiverOverHTTP@35da9039(rsp=FAILURE,failure=java.util.concurrent.CancellationException)[HttpParser{s=CONTENT,0 of 0}]]] 2024-05-03 15:20:24,908 DEBUG - [org.eclipse.jetty.reactive.client.internal.QueuedSinglePublisher] - failed ContentPublisher@282b52d java.util.concurrent.CancellationException: null at org.eclipse.jetty.reactive.client.internal.ResponseListenerProcessor.cancel(ResponseListenerProcessor.java:174) at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.cancel(MonoIgnoreThen.java:143) at reactor.core.publisher.FluxPeek$PeekSubscriber.cancel(FluxPeek.java:153) at reactor.core.publisher.FluxPeek$PeekSubscriber.cancel(FluxPeek.java:153) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drainLoop(Operators.java:2399) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drain(Operators.java:2367) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.cancel(Operators.java:2179) at reactor.core.publisher.FluxMap$MapSubscriber.cancel(FluxMap.java:169) at reactor.core.publisher.FluxPeek$PeekSubscriber.cancel(FluxPeek.java:153) at reactor.core.publisher.FluxOnAssembly$OnAssemblySubscriber.cancel(FluxOnAssembly.java:654) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drainLoop(Operators.java:2399) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drain(Operators.java:2367) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.cancel(Operators.java:2179) at reactor.core.publisher.FluxPeekFuseable$PeekConditionalSubscriber.cancel(FluxPeekFuseable.java:798) at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.cancel(MonoPeekTerminal.java:144) at reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.cancel(FluxDoFinally.java:134) at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.cancel(FluxContextWrite.java:141) at reactor.core.publisher.MonoFlatMap$FlatMapMain.cancel(MonoFlatMap.java:199) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drainLoop(Operators.java:2399) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drain(Operators.java:2367) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.cancel(Operators.java:2179) at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.handleTimeout(FluxTimeout.java:294) at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.doTimeout(FluxTimeout.java:280) at reactor.core.publisher.FluxTimeout$TimeoutTimeoutSubscriber.onNext(FluxTimeout.java:419) at reactor.core.publisher.FluxOnErrorReturn$ReturnSubscriber.onNext(FluxOnErrorReturn.java:162) at reactor.core.publisher.MonoDelay$MonoDelayRunnable.propagateDelay(MonoDelay.java:271) at reactor.core.publisher.MonoDelay$MonoDelayRunnable.run(MonoDelay.java:286) at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:68) at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:28) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) at java.base/java.lang.Thread.run(Thread.java:840) 2024-05-03 15:20:24,908 DEBUG - [org.eclipse.jetty.util.thread.QueuedThreadPool] - ran org.eclipse.jetty.io.ManagedSelector$DestroyEndPoint@6a2013c8 in QueuedThreadPool[HttpClient@3554bdc0]@56a05324{STARTED,8<=10<=200,i=0,r=-1,t=45064ms,q=0}[ReservedThreadExecutor@36510e73{reserved=1/16,pending=0}] 2024-05-03 15:20:24,908 DEBUG - [org.eclipse.jetty.util.thread.QueuedThreadPool] - Evict check, period=60000ms QueuedThreadPool[HttpClient@3554bdc0]@56a05324{STARTED,8<=10<=200,i=1,r=-1,t=45064ms,q=0}[ReservedThreadExecutor@36510e73{reserved=1/16,pending=0}] 2024-05-03 15:20:24,908 DEBUG - [org.eclipse.jetty.util.thread.QueuedThreadPool] - Evict skipped, threshold=105064ms in the future QueuedThreadPool[HttpClient@3554bdc0]@56a05324{STARTED,8<=10<=200,i=1,r=-1,t=45064ms,q=0}[ReservedThreadExecutor@36510e73{reserved=1/16,pending=0}] 2024-05-03 15:20:24,908 DEBUG - [org.eclipse.jetty.client.HttpExchange] - Aborted (true) while active HttpExchange@1ea7a937{req=HttpRequest[GET / HTTP/1.1]@62735b13[TERMINATED/null] res=HttpResponse[HTTP/1.1 50 Mock Response]@1277d590[TERMINATED/java.util.concurrent.CancellationException]}: {} java.util.concurrent.CancellationException: null at org.eclipse.jetty.reactive.client.internal.ResponseListenerProcessor.cancel(ResponseListenerProcessor.java:174) at reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain.cancel(MonoIgnoreThen.java:143) at reactor.core.publisher.FluxPeek$PeekSubscriber.cancel(FluxPeek.java:153) at reactor.core.publisher.FluxPeek$PeekSubscriber.cancel(FluxPeek.java:153) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drainLoop(Operators.java:2399) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drain(Operators.java:2367) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.cancel(Operators.java:2179) at reactor.core.publisher.FluxMap$MapSubscriber.cancel(FluxMap.java:169) at reactor.core.publisher.FluxPeek$PeekSubscriber.cancel(FluxPeek.java:153) at reactor.core.publisher.FluxOnAssembly$OnAssemblySubscriber.cancel(FluxOnAssembly.java:654) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drainLoop(Operators.java:2399) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drain(Operators.java:2367) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.cancel(Operators.java:2179) at reactor.core.publisher.FluxPeekFuseable$PeekConditionalSubscriber.cancel(FluxPeekFuseable.java:798) at reactor.core.publisher.MonoPeekTerminal$MonoTerminalPeekSubscriber.cancel(MonoPeekTerminal.java:144) at reactor.core.publisher.FluxDoFinally$DoFinallySubscriber.cancel(FluxDoFinally.java:134) at reactor.core.publisher.FluxContextWrite$ContextWriteSubscriber.cancel(FluxContextWrite.java:141) at reactor.core.publisher.MonoFlatMap$FlatMapMain.cancel(MonoFlatMap.java:199) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drainLoop(Operators.java:2399) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.drain(Operators.java:2367) at reactor.core.publisher.Operators$MultiSubscriptionSubscriber.cancel(Operators.java:2179) at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.handleTimeout(FluxTimeout.java:294) at reactor.core.publisher.FluxTimeout$TimeoutMainSubscriber.doTimeout(FluxTimeout.java:280) at reactor.core.publisher.FluxTimeout$TimeoutTimeoutSubscriber.onNext(FluxTimeout.java:419) at reactor.core.publisher.FluxOnErrorReturn$ReturnSubscriber.onNext(FluxOnErrorReturn.java:162) at reactor.core.publisher.MonoDelay$MonoDelayRunnable.propagateDelay(MonoDelay.java:271) at reactor.core.publisher.MonoDelay$MonoDelayRunnable.run(MonoDelay.java:286) at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:68) at reactor.core.scheduler.SchedulerTask.call(SchedulerTask.java:28) at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) at java.base/java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:304) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) at java.base/java.lang.Thread.run(Thread.java:840) 2024-05-03 15:20:24,908 DEBUG - [org.eclipse.jetty.reactive.client.internal.AbstractSinglePublisher] - ResponseListenerProcessor@58601e7a[Reactive[HttpRequest[GET / HTTP/1.1]@62735b13]] cancelled subscription from reactor.core.publisher.MonoIgnoreThen$ThenIgnoreMain@7aae1170 java.util.concurrent.TimeoutException: Did not observe any item or terminal signal within 15000ms in 'flatMap' (and no fallback has been configured) ```
sbordet commented 4 months ago

HttpClient event listeners implementations are not supposed to throw.

In this example, HttpClient's Response.HeadersListener calls the implementation in the reactive client, which calls Spring, so Spring should not throw.

From the point of view of HttpClient the event was delivered, but it cannot know if the listener implementation did enough to continue with the processing of the request/response or not. That's why it was decided to catch and log rather than catch and abort.

Consider a valid response (e.g. with a valid status code), and listener implementation such as:

public void onHeaders(Response response) {
    System.err.println("HEADERS");
    throw new NullPointerException();
}

From the point of view of HttpClient the response is still valid; HttpClient can read and notify content events until the whole response is properly processed. The fact that an application listener threw does not affect, in general, the processing of the response. It was deemed too harsh to abort, because the response has arrived, it is valid, and can be processed further.

There is an explicit API to abort a request or a response, so applications should use that.

What we can do is to be more aggressive at parsing a response with a status code < 100 or >= 600, as per RFC 9110, and generate a parser error. In this way, HttpClient would catch the bad message earlier, fail early, and Spring would not fail (because it would not be called for the "headers" event, but only for a "bad response" event).

@gregw WDYT? Should we be more strict at parsing status codes?

However, in general, if an event listener implementation can throw, it should catch and decide what to do: sometimes the error is recoverable, other times it is fatal and the abort APIs should be used.

joakime commented 4 months ago

Probably a good idea to be extra strict on the response line.

After all, what would happen if the HttpClient decided to connect to something that isn't HTTP? (eg: an SMTP server - http://example.org:25/test) You would want to know pretty quick if you should continue to parse the response, no?