To emulate a few of my worst case latency scenarios that I have seen in production, I have added a sleep with a thirty second timer before I send a 200 status.
Once more I have attached my jbang script as well as the extended logs when I ran with -Djdk.httpclient.HttpClient.log=requests,headers,errors,http3,quic:control:retransmit. -- Cheers, Josiah.
WARNING: Unknown module: io.avaje.jex.test specified to --add-reads WARNING: Unknown module: io.avaje.spi.core specified to --add-reads WARNING: Unknown module: io.avaje.spi specified to --add-reads Nov 10, 2025 8:27:15 AM jdk.internal.net.http.Http3ClientImpl getConnectionFor INFO: HTTP3: getConnectionFor exchange https://localhost:8080 GET #1 Nov 10, 2025 8:27:15 AM jdk.internal.net.http.Http3ClientImpl getConnectionFor INFO: HTTP3: Creating connection for Exchange https://localhost:8080 GET #1 Nov 10, 2025 8:27:15 AM jdk.internal.net.http.HttpQuicConnection logAltSvcFor INFO: ALTSVC: No AltService found for localhost:8080 Nov 10, 2025 8:27:16 AM jdk.internal.net.http.quic.QuicClient chooseEndpoint INFO: QUIC: Adding new endpoint: QuicEndpoint(HttpClientImpl(1)-0) Nov 10, 2025 8:27:16 AM jdk.internal.net.http.quic.QuicEndpoint lambda$create$1 INFO: QUIC: Initial receive buffer size is: 65536 Nov 10, 2025 8:27:16 AM jdk.internal.net.http.quic.QuicEndpoint lambda$create$1 INFO: QUIC: Initial send buffer size is: 65536 Nov 10, 2025 8:27:16 AM jdk.internal.net.http.Http3Connection createAsync INFO: HTTP3: Http3Connection.createAsync: Got HttpQuicConnection for https://localhost:8080 GET #1 is: quic:1 Nov 10, 2025 8:27:16 AM jdk.internal.net.http.quic.QuicConnectionImpl startInitialTimer INFO: QUIC: QuicClientConnection(1): Arming quic initial timer for PT29.999554S Nov 10, 2025 8:27:16 AM jdk.internal.net.http.quic.QuicConnectionImpl sendFirstInitialPacket INFO: QUIC: QuicClientConnection(1): connectionId: ffff4b91840a9a62d8685e, QuicEndpoint(HttpClientImpl(1)-0): QuicEndpoint(HttpClientImpl(1)-0) - /[0:0:0:0:0:0:0:0]:54039 Nov 10, 2025 8:27:16 AM jdk.internal.net.http.quic.IdleTimeoutManager checkUpdateIdleTimeout INFO: QUIC: QuicClientConnection(1) idle connection timeout updated to 30,000 milli seconds Nov 10, 2025 8:27:16 AM jdk.internal.net.http.quic.PacketSpaceManager$PacketTransmissionTask logNoDeadline INFO: QUIC: QuicClientConnection(1): INITIAL no deadline, task unscheduled Nov 10, 2025 8:27:16 AM jdk.internal.net.http.quic.PacketSpaceManager close INFO: QUIC: QuicClientConnection(1) closing packet space INITIAL Nov 10, 2025 8:27:16 AM jdk.internal.net.http.quic.IdleTimeoutManager startIdleTerminationTimer INFO: QUIC: QuicClientConnection(1) started QUIC idle timeout management for connection, idle timeout event: QuicIdleTimeoutEvent-4 deadline: Deadline(2025-11-10T13:27:46.296992600Z) Nov 10, 2025 8:27:16 AM jdk.internal.net.http.quic.IdleTimeoutManager startStreamDataBlockedTimer INFO: QUIC: QuicClientConnection(1) started STREAM_DATA_BLOCKED timer for connection, event: StreamDataBlockedEvent-5 deadline: Deadline(2025-11-10T13:27:38.798481900Z) Nov 10, 2025 8:27:16 AM jdk.internal.net.http.Http3Connection <init> INFO: HTTP3: HTTP/3 connection created for QuicClientConnection(1) - local address: /[0:0:0:0:0:0:0:0]:54039 Nov 10, 2025 8:27:16 AM jdk.internal.net.http.quic.QuicConnectionImpl processDecrypted INFO: QUIC: QuicClientConnection(1) IN: ONERTT(pn:0, size=35, phase:0, spin:0, frames:[HandshakeDoneFrame, StreamFrame(stream=3, offset=0, length=1, fin=false)]) Nov 10, 2025 8:27:16 AM jdk.internal.net.http.quic.QuicConnectionImpl pushDatagram INFO: QUIC: QuicClientConnection(1) OUT: ONERTT(pn:0, size=92, phase:-1, spin:-1, frames:[NewConnectionIDFrame(seqNumber=1, retirePriorTo=0, connIdLength=11), StreamFrame(stream=2, offset=0, length=1, fin=false), StreamFrame(stream=2, offset=1, length=27, fin=false)]) Nov 10, 2025 8:27:16 AM jdk.internal.net.http.AltServicesRegistry registerUnadvertised INFO: ALTSVC: Added unadvertised AltService: Optional[AltSvc: h3="localhost:8080"; origin="https://localhost:8080";; deadline=Deadline(2025-11-11T13:27:16.330910300Z); persist=true; advertised=false; sameAuthorityAsOrigin=true;] Nov 10, 2025 8:27:16 AM jdk.internal.net.http.quic.PacketSpaceManager close INFO: QUIC: QuicClientConnection(1) closing packet space HANDSHAKE Nov 10, 2025 8:27:16 AM jdk.internal.net.http.Http3ClientImpl connectionCompleted INFO: HTTP3: Checking waiters on completed connection quic:1 to https:localhost:8080 created for https://localhost:8080 GET #1 Nov 10, 2025 8:27:16 AM jdk.internal.net.http.quic.PacketSpaceManager$PacketTransmissionTask logNoDeadline INFO: QUIC: QuicClientConnection(1): HANDSHAKE no deadline, task unscheduled Nov 10, 2025 8:27:16 AM jdk.internal.net.http.Http3ClientImpl connectionCompleted0 INFO: HTTP3: Connection creation completed for requests to https:localhost:8080: waiters[0](completed:0, retried:0, errors:0) - originally created for https://localhost:8080 GET #1 Nov 10, 2025 8:27:16 AM jdk.internal.net.http.quic.QuicConnectionImpl processDecrypted INFO: QUIC: QuicClientConnection(1) IN: ONERTT(pn:2, size=102, phase:0, spin:0, frames:[NewConnectionIDFrame(seqNumber=1, retirePriorTo=0, connIdLength=8), CryptoFrame(offset=0, length=42)]) Nov 10, 2025 8:27:16 AM jdk.internal.net.http.Http3Connection createHttp3ExchangeImpl INFO: HTTP3: Creating HTTP/3 exchange for QuicClientConnection(1)/streamId=0 Nov 10, 2025 8:27:16 AM jdk.internal.net.http.Http3ExchangeImpl start INFO: HTTP3: Starting HTTP/3 exchange for QuicClientConnection(1)/streamId=0 (https://localhost:8080 GET #1) Nov 10, 2025 8:27:16 AM jdk.internal.net.http.Http3ExchangeImpl sendHeaders INFO: REQUEST: https://localhost:8080 GET Nov 10, 2025 8:27:16 AM jdk.internal.net.http.Http3ExchangeImpl sendHeaders INFO: HEADERS: H3 HEADERS FRAME (stream=0) :authority: localhost:8080 :method: GET :path: / :scheme: https User-Agent: Java-http-client/26-ea Nov 10, 2025 8:27:16 AM jdk.internal.net.http.quic.QuicConnectionImpl pushDatagram INFO: QUIC: QuicClientConnection(1) OUT: ONERTT(pn:3, size=75, phase:-1, spin:-1, frames:[StreamFrame(stream=0, offset=0, length=2, fin=false), StreamFrame(stream=0, offset=2, length=2, fin=false), StreamFrame(stream=0, offset=4, length=34, fin=true)]) Nov 10, 2025 8:27:16 AM jdk.internal.net.http.quic.PacketSpaceManager$PacketTransmissionTask logNoDeadline INFO: QUIC: QuicClientConnection(1): APPLICATION no deadline, task unscheduled Nov 10, 2025 8:27:46 AM jdk.internal.net.http.quic.IdleTimeoutManager idleTimedOut INFO: QUIC: QuicClientConnection(1) silently terminating connection due to idle timeout (30000 milli seconds): PacketSpace: INITIAL State: closed AckFrame: NextAckFrame[ackFrame=AckFrame(largestAcknowledged=0, ackDelay=0, ackRanges=[0..0]), deadline=Deadline(+1000000000-12-31T23:59:59.999999999Z), lastUpdated=Deadline(2025-11-10T13:27:16.260596800Z), sent=Deadline(2025-11-10T13:27:16.261160100Z)] Pending acks: () Pending retransmit: () PacketSpace: HANDSHAKE State: closed AckFrame: NextAckFrame[ackFrame=AckFrame(largestAcknowledged=3, ackDelay=0, ackRanges=[0..3]), deadline=Deadline(+1000000000-12-31T23:59:59.999999999Z), lastUpdated=Deadline(2025-11-10T13:27:16.296091200Z), sent=Deadline(2025-11-10T13:27:16.296880300Z)] Pending acks: () Pending retransmit: () PacketSpace: APPLICATION State: opened AckFrame: NextAckFrame[ackFrame=AckFrame(largestAcknowledged=4, ackDelay=0, ackRanges=[0..4]), deadline=Deadline(+1000000000-12-31T23:59:59.999999999Z), lastUpdated=Deadline(2025-11-10T13:27:16.391776500Z), sent=Deadline(2025-11-10T13:27:16.401712Z)] Pending acks: () Pending retransmit: () Nov 10, 2025 8:27:46 AM jdk.internal.net.http.quic.ConnectionTerminatorImpl silentTerminate INFO: QUIC: QuicClientConnection(1) silently terminating connection due to: connection idle timed out (30000 milli seconds) Nov 10, 2025 8:27:46 AM jdk.internal.net.http.quic.ConnectionTerminatorImpl silentTerminate INFO: QUIC: QuicClientConnection(1) connection state: sending: {canSend:false, credit: 9999934, sendersReady: false, hasControlFrames: false}, cc: { backoff: 1, duration: PT0.16572S, current deadline: due since 30001ms, prospective deadline: not scheduled (Deadline.MAX)}, streams: [{id:0, available: 0, blocked: false},] Nov 10, 2025 8:27:46 AM jdk.internal.net.http.quic.PacketSpaceManager close INFO: QUIC: QuicClientConnection(1) closing packet space APPLICATION Nov 10, 2025 8:27:46 AM jdk.internal.net.http.Http3ExchangeImpl onPollException INFO: HTTP3: QuicClientConnection(1)/streamId=0 https://localhost:8080 GET #1 (requestSent=true, responseReceived=false, reader=RECV, writer=DATA_RECVD, statusCode=0, finalStream=false, receivedQuicBytes=0, sentQuicBytes=38): java.io.IOException: connection idle timed out (30000 milli seconds) Nov 10, 2025 8:27:46 AM jdk.internal.net.http.Http3ExchangeImpl close INFO: HTTP3: Closed HTTP/3 exchange for QuicClientConnection(1)/streamId=0 with error java.io.IOException: connection idle timed out (30000 milli seconds) Nov 10, 2025 8:27:46 AM jdk.internal.net.http.Http3Connection onExchangeClose INFO: HTTP3: HTTP/3 connection QuicClientConnection(1) left open: exchanged streamId=0 closed; finalStream=false, exchangeStreams=0, reservedStreamCount=0 Exception in thread "main" java.io.IOException: connection idle timed out (30000 milli seconds) at java.net.http/jdk.internal.net.http.HttpClientImpl.send(HttpClientImpl.java:1018) at java.net.http/jdk.internal.net.http.HttpClientFacade.send(HttpClientFacade.java:133) at io.avaje.jex.http3.flupke/io.avaje.jex.http3.flupke.Timeout.main(Timeout.java:99) Caused by: java.io.IOException: connection idle timed out (30000 milli seconds) at java.net.http/jdk.internal.net.http.quic.TerminationCause.toReportedCause(TerminationCause.java:129) at java.net.http/jdk.internal.net.http.quic.TerminationCause.<init>(TerminationCause.java:56) at java.net.http/jdk.internal.net.http.quic.TerminationCause$SilentTermination.<init>(TerminationCause.java:203) at java.net.http/jdk.internal.net.http.quic.TerminationCause.forSilentTermination(TerminationCause.java:96) at java.net.http/jdk.internal.net.http.quic.IdleTimeoutManager.idleTimedOut(IdleTimeoutManager.java:349) at java.net.http/jdk.internal.net.http.quic.IdleTimeoutManager$IdleTimeoutEvent.terminateNow(IdleTimeoutManager.java:437) at java.net.http/jdk.internal.net.http.quic.IdleTimeoutManager$IdleTimeoutEvent.handle(IdleTimeoutManager.java:411) at java.net.http/jdk.internal.net.http.quic.QuicTimerQueue.processDue(QuicTimerQueue.java:298) at java.net.http/jdk.internal.net.http.common.SequentialScheduler$LockingRestartableTask.run(SequentialScheduler.java:182) at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:149) at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:207) at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1090) at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:614) at java.base/java.lang.Thread.run(Thread.java:1474)
Timeout.java
Description: Binary data
