Http 3 Client request timeout not respected

Josiah Noel josiahnoel at gmail.com
Mon Nov 10 13:38:32 UTC 2025 

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.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://mail.openjdk.org/pipermail/net-dev/attachments/20251110/3e6b08d5/attachment.htm>
-------------- next part --------------
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)
-------------- next part --------------
A non-text attachment was scrubbed...
Name: Timeout.java
Type: application/octet-stream
Size: 3839 bytes
Desc: not available
URL: <https://mail.openjdk.org/pipermail/net-dev/attachments/20251110/3e6b08d5/Timeout.java>

More information about the net-dev mailing list