Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8221395

HttpClient leaving connections in CLOSE_WAIT state until Java process ends

XMLWordPrintable

    • b15
    • x86_64
    • linux
    • Verified

        ADDITIONAL SYSTEM INFORMATION :
        Simulated in both Linux and Windows. Using JDK12, but it happens with JDK 11 as well.

        openjdk version "12" 2019-03-19
        OpenJDK Runtime Environment (build 12+33)
        OpenJDK 64-Bit Server VM (build 12+33, mixed mode, sharing)

        A DESCRIPTION OF THE PROBLEM :
        We've been noticing that our HTTP connections are staying in a CLOSE_WAIT state, requiring us to shutdown the Java process in order to release them when using the new API.

        In our actual application we run the code in WildFly 16, but I was able to reproduce in standalone code, completely isolated from our source to guarantee there's no interference.

        The server host we are calling (IP: 200.186.62.89) seems to be the one that triggers the problem in the client, however the API Impl seems to be unable to terminate the CLOSE_WAIT connections regardless, so I consider it to be an API problem. I don't understand why.

        After enabling the debug with "-Djdk.internal.httpclient.debug=true" I found out an "java.io.EOFException: EOF reached while reading". The complete debug log is attached, also with the source code.

        If it helps theres this thread I've created in SO: https://stackoverflow.com/q/55271192/3231778

        STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
        1) Start the socket server I've pasted in the source code
        2) Connect to the socket server with any client (telnet localhost 59090)
        3) Server will build an HttpClient instance and send a request to "https://xxxxx.com.br/grb/sb/incidentes/listar" (the IP is xxx.xxx.62.89) and respond with the status code. Client and server will terminate the session.
        4) Check operating system for active connections: netstat -an 1 | find "xxxx.xxx.62.89"
        5) Every connection established will remain in a CLOSE_WAIT state until the Java process is terminated.

        EXPECTED VERSUS ACTUAL BEHAVIOR :
        EXPECTED -
        Connections should be released after being in the TCP CLOSE_WAIT state. This state means that the server will end the connection, and the client must do it too. However client is not releasing the connection.
        ACTUAL -
        Any connection that we start stays on CLOSE_WAIT until the Java process ends.

        D:\Users\TECBMEPI>netstat -an 1 | find "xxx.xxx.62.89"
          TCP 192.168.9.200:62836 xxx.xxx.62.89:443 CLOSE_WAIT
          TCP 192.168.9.200:62836 xxx.xxx.62.89:443 CLOSE_WAIT
          TCP 192.168.9.200:62836 xxx.xxx.62.89:443 CLOSE_WAIT
          TCP 192.168.9.200:62836 xxx.xxx.62.89:443 CLOSE_WAIT
          TCP 192.168.9.200:62836 xxx.xxx.62.89:443 CLOSE_WAIT
          TCP 192.168.9.200:62836 xxx.xxx.62.89:443 CLOSE_WAIT
          TCP 192.168.9.200:62836 xxx.xxx.62.89:443 CLOSE_WAIT
          TCP 192.168.9.200:62836 xxx.xxx.62.89:443 CLOSE_WAIT
          TCP 192.168.9.200:62836 xxx.xxx.62.89:443 CLOSE_WAIT
          TCP 192.168.9.200:62836 xxx.xxx.62.89:443 CLOSE_WAIT
          TCP 192.168.9.200:62836 xxx.xxx.62.89:443 CLOSE_WAIT
          TCP 192.168.9.200:62836 xxx.xxx.62.89:443 CLOSE_WAIT
          TCP 192.168.9.200:62836 xxx.xxx.62.89:443 CLOSE_WAIT


        The debug output is the following:


        DEBUG: [main] [339ms] HttpClientImpl(1) proxySelector is sun.net.spi.DefaultProxySelector@17695df3 (user-supplied=false)
        DEBUG: [main] [434ms] HttpClientImpl(1) ClientImpl (async) send https://xxxx.com.br/grb/sb/incidentes/listar GET
        DEBUG: [main] [447ms] Exchange establishing exchange for https://xxxx.com.br/grb/sb/incidentes/listar GET,
        proxy=null
        DEBUG: [main] [449ms] ExchangeImpl get: HTTP/1.1: new Http1Exchange
        DEBUG: [main] [594ms] PlainHttpConnection(?) Initial receive buffer size is: 65536
        DEBUG: [main] [607ms] Exchange checkFor407: all clear
        DEBUG: [main] [608ms] Http1Exchange Sending headers only
        DEBUG: [main] [630ms] Http1AsyncReceiver(?) Subscribed pending jdk.internal.net.http.Http1Response$HeadersReader@7f010382 queue.isEmpty: true
        DEBUG: [main] [649ms] Http1AsyncReceiver(?) delegate is now jdk.internal.net.http.Http1Response$HeadersReader@7f010382, demand=1, canRequestMore=true, queue.isEmpty=true
        DEBUG: [main] [649ms] Http1AsyncReceiver(?) downstream subscription demand is 1
        DEBUG: [main] [663ms] Http1AsyncReceiver(?) checkRequestMore: canRequestMore=true, hasDemand=true
        DEBUG: [main] [663ms] Http1AsyncReceiver(?) downstream subscription demand is 1
        DEBUG: [main] [663ms] Http1AsyncReceiver(?) checkRequestMore: canRequestMore=true, hasDemand=true
        DEBUG: [main] [663ms] Http1Exchange response created in advance
        DEBUG: [main] [663ms] Http1Exchange initiating connect async
        DEBUG: [main] [669ms] PlainHttpConnection(SocketTube(1)) registering connect event
        DEBUG: [HttpClient-1-SelectorManager] [671ms] SelectorAttachment Registering jdk.internal.net.http.PlainHttpConnection$ConnectEvent@25f3efa9 for 8 (true)
        DEBUG: [HttpClient-1-SelectorManager] [730ms] PlainHttpConnection(SocketTube(1)) ConnectEvent: finishing connect
        DEBUG: [HttpClient-1-SelectorManager] [731ms] PlainHttpConnection(SocketTube(1)) ConnectEvent: connect finished: true Local addr: /192.168.9.200:62065
        DEBUG: [HttpClient-1-Worker-0] [762ms] SocketTube(1) connecting flows
        DEBUG: [HttpClient-1-Worker-0] [763ms] SocketTube(1) read publisher got subscriber
        DEBUG: [HttpClient-1-Worker-0] [763ms] SocketTube(1) registering subscribe event
        DEBUG: [HttpClient-1-SelectorManager] [763ms] SocketTube(1) subscribe event raised
        DEBUG: [HttpClient-1-Worker-0] [767ms] SocketTube(1) leaving read.subscribe: Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=0]
        DEBUG: [HttpClient-1-Worker-0] [802ms] SSL Writer(SocketTube(1)) requesting 1
        DEBUG: [HttpClient-1-SelectorManager] [804ms] SocketTube(1) handling pending subscription for READER: SubscriberWrapper: upstreamCompleted: false upstreamWindow: 0 downstreamCompleted: false completionAcknowledged: false outputQ size: 0 cf: jdk.internal.net.http.common.MinimalFuture@5c25e85b[Not completed, 4 dependents] (id=26) downstreamSubscription: SubscriptionBase: window = 0 cancelled = false, readBuf: java.nio.HeapByteBuffer[pos=0 lim=0 cap=1024], count: 0, scheduler: running, status: null
        DEBUG: [HttpClient-1-SelectorManager] [804ms] SocketTube(1) read demand reset to 0
        DEBUG: [HttpClient-1-SelectorManager] [804ms] SocketTube(1) calling onSubscribe
        DEBUG: [HttpClient-1-Worker-0] [804ms] SSLTube(SocketTube(1)) request: n=1
        DEBUG: [HttpClient-1-Worker-0] [805ms] SSL Writer(SocketTube(1)) calling downstreamSubscriber::onSubscribe on SocketTube(1)
        DEBUG: [HttpClient-1-Worker-0] [805ms] SocketTube(1) subscribed for writing
        DEBUG: [HttpClient-1-Worker-0] [806ms] SocketTube(1) write: registering startSubscription event
        DEBUG: [HttpClient-1-Worker-0] [807ms] SSL Writer(SocketTube(1)) onSubscribe initiating handshaking
        DEBUG: [HttpClient-1-SelectorManager] [804ms] SSL Reader(SocketTube(1)) requesting 1
        DEBUG: [HttpClient-1-SelectorManager] [819ms] SocketTube(1) got some demand for reading
        DEBUG: [HttpClient-1-SelectorManager] [820ms] SocketTube(1) resuming read event
        DEBUG: [HttpClient-1-SelectorManager] [821ms] SocketTube(1) leaving request(1): Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=0]
        DEBUG: [HttpClient-1-SelectorManager] [822ms] SSL Reader(SocketTube(1)) calling downstreamSubscriber::onSubscribe on jdk.internal.net.http.common.SSLTube$SSLSubscriberWrapper@3590506
        DEBUG: [HttpClient-1-SelectorManager] [822ms] SSLTube(SocketTube(1)) SSLSubscriberWrapper (reader) onSubscribe(SubscriptionBase: window = 0 cancelled = false)
        DEBUG: [HttpClient-1-SelectorManager] [822ms] SSLTube(SocketTube(1)) SSLSubscriberWrapper (reader) onSubscribeImpl: no delegate yet
        DEBUG: [HttpClient-1-SelectorManager] [822ms] SocketTube(1) onSubscribe called
        DEBUG: [HttpClient-1-SelectorManager] [822ms] SocketTube(1) pending subscriber subscribed
        DEBUG: [HttpClient-1-SelectorManager] [823ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@2e414b42 for 1 (true)
        DEBUG: [HttpClient-1-SelectorManager] [823ms] SocketTube(1) write: starting subscription
        DEBUG: [HttpClient-1-SelectorManager] [823ms] SocketTube(1) write: offloading requestMore
        DEBUG: [HttpClient-1-Worker-1] [824ms] SocketTube(1) write: requesting more...
        DEBUG: [HttpClient-1-Worker-1] [826ms] SSL Writer(SocketTube(1)) DownstreamPusher: queue empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
        DEBUG: [HttpClient-1-Worker-1] [826ms] SocketTube(1) leaving requestMore: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
        DEBUG: [HttpClient-1-Worker-0] [829ms] SSL Writer(SocketTube(1)) added 1 (0 bytes) to the writeList
        DEBUG: [HttpClient-1-Worker-0] [844ms] SSL Writer(SocketTube(1)) processData, writeList remaining:0, hsTriggered:true, needWrap:false
        DEBUG: [HttpClient-1-Worker-0] [845ms] SSL Writer(SocketTube(1)) wrapping 0 bytes
        DEBUG: [HttpClient-1-Worker-0] [935ms] SSL Writer(SocketTube(1)) SSLResult: Status = OK HandshakeStatus = NEED_UNWRAP
        bytesConsumed = 0 bytesProduced = 473 sequenceNumber = 0
        DEBUG: [HttpClient-1-Worker-0] [936ms] SSL Writer(SocketTube(1)) OK => produced: 473 bytes into 480, not wrapped: 0
        DEBUG: [HttpClient-1-Worker-0] [937ms] SSL Writer(SocketTube(1)) wrapBuffer returned Status = OK HandshakeStatus = NEED_UNWRAP
        bytesConsumed = 0 bytesProduced = 473 sequenceNumber = 0
        DEBUG: [HttpClient-1-Worker-0] [937ms] SSL Writer(SocketTube(1)) handshaking
        DEBUG: [HttpClient-1-Worker-0] [951ms] SSL Reader(SocketTube(1)) processData: readBuf remaining:0, state: HANDSHAKING , engine handshake status:NEED_UNWRAP
        DEBUG: [HttpClient-1-Worker-0] [952ms] SSL Writer(SocketTube(1)) Sending 473 bytes downstream
        DEBUG: [HttpClient-1-Worker-0] [952ms] SSL Writer(SocketTube(1)) Adding 473 to outputQ queue
        DEBUG: [HttpClient-1-Worker-0] [952ms] SSL Writer(SocketTube(1)) pushScheduler is alive
        DEBUG: [HttpClient-1-Worker-0] [953ms] SSL Writer(SocketTube(1)) DownstreamPusher: queue not empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
        DEBUG: [HttpClient-1-Worker-0] [954ms] SSL Writer(SocketTube(1)) DownstreamPusher: Pushing 473 bytes downstream
        DEBUG: [HttpClient-1-Worker-0] [954ms] SocketTube(1) trying to write: 473
        DEBUG: [HttpClient-1-Worker-0] [956ms] SocketTube(1) wrote: 473
        DEBUG: [HttpClient-1-Worker-0] [957ms] SocketTube(1) write: requesting more...
        DEBUG: [HttpClient-1-Worker-0] [957ms] SocketTube(1) leaving requestMore: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
        DEBUG: [HttpClient-1-Worker-0] [958ms] SocketTube(1) leaving w.onNext Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
        DEBUG: [HttpClient-1-Worker-0] [958ms] SSL Writer(SocketTube(1)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:1
        DEBUG: [HttpClient-1-Worker-0] [958ms] SSL Writer(SocketTube(1)) DownstreamPusher: queue empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
        DEBUG: [HttpClient-1-SelectorManager] [1s 68ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@2e414b42 for 0 (false)
        DEBUG: [HttpClient-1-SelectorManager] [1s 69ms] HttpClientImpl(1) ByteBuffer.allocateDirect(16384)
        DEBUG: [HttpClient-1-SelectorManager] [1s 71ms] SocketTube(1) read bytes: 6100
        DEBUG: [HttpClient-1-SelectorManager] [1s 71ms] SSL Reader(SocketTube(1)) onNext
        DEBUG: [HttpClient-1-SelectorManager] [1s 71ms] SSL Reader(SocketTube(1)) Adding 6100 bytes to read buffer
        DEBUG: [HttpClient-1-SelectorManager] [1s 72ms] SSL Reader(SocketTube(1)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:0
        DEBUG: [HttpClient-1-SelectorManager] [1s 72ms] SSL Reader(SocketTube(1)) requesting 1
        DEBUG: [HttpClient-1-SelectorManager] [1s 72ms] SocketTube(1) got some demand for reading
        DEBUG: [HttpClient-1-SelectorManager] [1s 73ms] SocketTube(1) resuming read event
        DEBUG: [HttpClient-1-SelectorManager] [1s 73ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@2e414b42 for 1 (false)
        DEBUG: [HttpClient-1-SelectorManager] [1s 73ms] SocketTube(1) leaving request(1): Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
        DEBUG: [HttpClient-1-SelectorManager] [1s 73ms] SocketTube(1) resuming read event
        DEBUG: [HttpClient-1-SelectorManager] [1s 73ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@2e414b42 for 1 (false)
        DEBUG: [HttpClient-1-SelectorManager] [1s 73ms] SocketTube(1) leaving read() loop after onNext: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
        DEBUG: [HttpClient-1-Worker-0] [1s 74ms] SSL Reader(SocketTube(1)) processData: readBuf remaining:6100, state: HANDSHAKING , engine handshake status:NEED_UNWRAP
        DEBUG: [HttpClient-1-Worker-0] [1s 74ms] SSL Reader(SocketTube(1)) Unwrapping: 6100
        DEBUG: [HttpClient-1-Worker-0] [1s 85ms] SSL Reader(SocketTube(1)) Decoded 0 bytes out of 6100 into buffer of 512 remaining to decode: 6004
        DEBUG: [HttpClient-1-Worker-0] [1s 85ms] SSL Reader(SocketTube(1)) Unwrapped: result: Status = OK HandshakeStatus = NEED_TASK
        bytesConsumed = 96 bytesProduced = 0
        DEBUG: [HttpClient-1-Worker-0] [1s 86ms] SSL Reader(SocketTube(1)) Unwrapped: consumed: 96
        DEBUG: [HttpClient-1-Worker-0] [1s 86ms] SSL Reader(SocketTube(1)) handshaking
        DEBUG: [HttpClient-1-Worker-0] [1s 86ms] SSLFlowDelegate(SocketTube(1)) obtaining and initiating task execution
        DEBUG: [HttpClient-1-Worker-0] [1s 88ms] SSLFlowDelegate(SocketTube(1)) #tasks to execute: 1
        DEBUG: [HttpClient-1-Worker-0] [1s 93ms] SSLFlowDelegate(SocketTube(1)) finished task execution
        DEBUG: [HttpClient-1-Worker-0] [1s 93ms] SSL Writer(SocketTube(1)) processData, writeList remaining:0, hsTriggered:false, needWrap:false
        DEBUG: [HttpClient-1-Worker-0] [1s 93ms] SSL Reader(SocketTube(1)) processData: readBuf remaining:6004, state: HANDSHAKING , engine handshake status:NEED_UNWRAP
        DEBUG: [HttpClient-1-Worker-0] [1s 93ms] SSL Reader(SocketTube(1)) Unwrapping: 6004
        DEBUG: [HttpClient-1-Worker-0] [1s 93ms] SSL Reader(SocketTube(1)) Decoded 0 bytes out of 6004 into buffer of 512 remaining to decode: 347
        DEBUG: [HttpClient-1-Worker-0] [1s 93ms] SSL Reader(SocketTube(1)) Unwrapped: result: Status = OK HandshakeStatus = NEED_TASK
        bytesConsumed = 5657 bytesProduced = 0
        DEBUG: [HttpClient-1-Worker-0] [1s 94ms] SSL Reader(SocketTube(1)) Unwrapped: consumed: 5657
        DEBUG: [HttpClient-1-Worker-0] [1s 94ms] SSL Reader(SocketTube(1)) handshaking
        DEBUG: [HttpClient-1-Worker-0] [1s 94ms] SSLFlowDelegate(SocketTube(1)) obtaining and initiating task execution
        DEBUG: [HttpClient-1-Worker-0] [1s 94ms] SSLFlowDelegate(SocketTube(1)) #tasks to execute: 1
        DEBUG: [HttpClient-1-Worker-0] [1s 215ms] SSLFlowDelegate(SocketTube(1)) finished task execution
        DEBUG: [HttpClient-1-Worker-0] [1s 215ms] SSL Writer(SocketTube(1)) processData, writeList remaining:0, hsTriggered:false, needWrap:false
        DEBUG: [HttpClient-1-Worker-0] [1s 216ms] SSL Reader(SocketTube(1)) processData: readBuf remaining:347, state: HANDSHAKING , engine handshake status:NEED_UNWRAP
        DEBUG: [HttpClient-1-Worker-0] [1s 217ms] SSL Reader(SocketTube(1)) Unwrapping: 347
        DEBUG: [HttpClient-1-Worker-0] [1s 217ms] SSL Reader(SocketTube(1)) Decoded 0 bytes out of 347 into buffer of 512 remaining to decode: 9
        DEBUG: [HttpClient-1-Worker-0] [1s 217ms] SSL Reader(SocketTube(1)) Unwrapped: result: Status = OK HandshakeStatus = NEED_TASK
        bytesConsumed = 338 bytesProduced = 0
        DEBUG: [HttpClient-1-Worker-0] [1s 217ms] SSL Reader(SocketTube(1)) Unwrapped: consumed: 338
        DEBUG: [HttpClient-1-Worker-0] [1s 217ms] SSL Reader(SocketTube(1)) handshaking
        DEBUG: [HttpClient-1-Worker-0] [1s 218ms] SSLFlowDelegate(SocketTube(1)) obtaining and initiating task execution
        DEBUG: [HttpClient-1-Worker-0] [1s 218ms] SSLFlowDelegate(SocketTube(1)) #tasks to execute: 1
        DEBUG: [HttpClient-1-Worker-0] [1s 223ms] SSLFlowDelegate(SocketTube(1)) finished task execution
        DEBUG: [HttpClient-1-Worker-0] [1s 224ms] SSL Writer(SocketTube(1)) processData, writeList remaining:0, hsTriggered:false, needWrap:false
        DEBUG: [HttpClient-1-Worker-0] [1s 224ms] SSL Reader(SocketTube(1)) processData: readBuf remaining:9, state: HANDSHAKING , engine handshake status:NEED_UNWRAP
        DEBUG: [HttpClient-1-Worker-0] [1s 226ms] SSL Reader(SocketTube(1)) Unwrapping: 9
        DEBUG: [HttpClient-1-Worker-0] [1s 226ms] SSL Reader(SocketTube(1)) Decoded 0 bytes out of 9 into buffer of 512 remaining to decode: 0
        DEBUG: [HttpClient-1-Worker-0] [1s 226ms] SSL Reader(SocketTube(1)) Unwrapped: result: Status = OK HandshakeStatus = NEED_TASK
        bytesConsumed = 9 bytesProduced = 0
        DEBUG: [HttpClient-1-Worker-0] [1s 228ms] SSL Reader(SocketTube(1)) Unwrapped: consumed: 9
        DEBUG: [HttpClient-1-Worker-0] [1s 228ms] SSL Reader(SocketTube(1)) handshaking
        DEBUG: [HttpClient-1-Worker-0] [1s 228ms] SSLFlowDelegate(SocketTube(1)) obtaining and initiating task execution
        DEBUG: [HttpClient-1-Worker-0] [1s 228ms] SSLFlowDelegate(SocketTube(1)) #tasks to execute: 1
        DEBUG: [HttpClient-1-Worker-0] [1s 247ms] SSLFlowDelegate(SocketTube(1)) finished task execution
        DEBUG: [HttpClient-1-Worker-0] [1s 247ms] SSL Writer(SocketTube(1)) processData, writeList remaining:0, hsTriggered:false, needWrap:true
        DEBUG: [HttpClient-1-Worker-0] [1s 247ms] SSL Writer(SocketTube(1)) wrapping 0 bytes
        DEBUG: [HttpClient-1-Worker-0] [1s 247ms] SSL Writer(SocketTube(1)) SSLResult: Status = OK HandshakeStatus = NEED_WRAP
        bytesConsumed = 0 bytesProduced = 75 sequenceNumber = 1
        DEBUG: [HttpClient-1-Worker-0] [1s 248ms] SSL Writer(SocketTube(1)) OK => produced: 75 bytes into 80, not wrapped: 0
        DEBUG: [HttpClient-1-Worker-0] [1s 248ms] SSL Writer(SocketTube(1)) wrapBuffer returned Status = OK HandshakeStatus = NEED_WRAP
        bytesConsumed = 0 bytesProduced = 75 sequenceNumber = 1
        DEBUG: [HttpClient-1-Worker-0] [1s 248ms] SSL Writer(SocketTube(1)) handshaking
        DEBUG: [HttpClient-1-Worker-0] [1s 249ms] SSL Writer(SocketTube(1)) Sending 75 bytes downstream
        DEBUG: [HttpClient-1-Worker-0] [1s 250ms] SSL Writer(SocketTube(1)) Adding 75 to outputQ queue
        DEBUG: [HttpClient-1-Worker-0] [1s 250ms] SSL Writer(SocketTube(1)) pushScheduler is alive
        DEBUG: [HttpClient-1-Worker-0] [1s 250ms] SSL Writer(SocketTube(1)) DownstreamPusher: queue not empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
        DEBUG: [HttpClient-1-Worker-0] [1s 250ms] SSL Writer(SocketTube(1)) DownstreamPusher: Pushing 75 bytes downstream
        DEBUG: [HttpClient-1-Worker-0] [1s 250ms] SocketTube(1) trying to write: 75
        DEBUG: [HttpClient-1-Worker-0] [1s 251ms] SocketTube(1) wrote: 75
        DEBUG: [HttpClient-1-Worker-0] [1s 251ms] SocketTube(1) write: requesting more...
        DEBUG: [HttpClient-1-Worker-0] [1s 251ms] SocketTube(1) leaving requestMore: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
        DEBUG: [HttpClient-1-Worker-0] [1s 251ms] SocketTube(1) leaving w.onNext Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
        DEBUG: [HttpClient-1-Worker-0] [1s 251ms] SSL Writer(SocketTube(1)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:1
        DEBUG: [HttpClient-1-Worker-0] [1s 251ms] SSL Writer(SocketTube(1)) DownstreamPusher: queue empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
        DEBUG: [HttpClient-1-Worker-0] [1s 251ms] SSL Writer(SocketTube(1)) wrapping 0 bytes
        DEBUG: [HttpClient-1-Worker-0] [1s 252ms] SSL Writer(SocketTube(1)) SSLResult: Status = OK HandshakeStatus = NEED_WRAP
        bytesConsumed = 0 bytesProduced = 6 sequenceNumber = 2
        DEBUG: [HttpClient-1-Worker-0] [1s 252ms] SSL Writer(SocketTube(1)) OK => produced: 6 bytes into 8, not wrapped: 0
        DEBUG: [HttpClient-1-Worker-0] [1s 252ms] SSL Writer(SocketTube(1)) wrapBuffer returned Status = OK HandshakeStatus = NEED_WRAP
        bytesConsumed = 0 bytesProduced = 6 sequenceNumber = 2
        DEBUG: [HttpClient-1-Worker-0] [1s 252ms] SSL Writer(SocketTube(1)) handshaking
        DEBUG: [HttpClient-1-Worker-0] [1s 252ms] SSL Writer(SocketTube(1)) Sending 6 bytes downstream
        DEBUG: [HttpClient-1-Worker-0] [1s 252ms] SSL Writer(SocketTube(1)) Adding 6 to outputQ queue
        DEBUG: [HttpClient-1-Worker-0] [1s 252ms] SSL Writer(SocketTube(1)) pushScheduler is alive
        DEBUG: [HttpClient-1-Worker-0] [1s 252ms] SSL Writer(SocketTube(1)) DownstreamPusher: queue not empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
        DEBUG: [HttpClient-1-Worker-0] [1s 253ms] SSL Writer(SocketTube(1)) DownstreamPusher: Pushing 6 bytes downstream
        DEBUG: [HttpClient-1-Worker-0] [1s 253ms] SocketTube(1) trying to write: 6
        DEBUG: [HttpClient-1-Worker-0] [1s 254ms] SocketTube(1) wrote: 6
        DEBUG: [HttpClient-1-Worker-0] [1s 254ms] SocketTube(1) write: requesting more...
        DEBUG: [HttpClient-1-Worker-0] [1s 254ms] SocketTube(1) leaving requestMore: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
        DEBUG: [HttpClient-1-Worker-0] [1s 254ms] SocketTube(1) leaving w.onNext Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
        DEBUG: [HttpClient-1-Worker-0] [1s 254ms] SSL Writer(SocketTube(1)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:1
        DEBUG: [HttpClient-1-Worker-0] [1s 255ms] SSL Writer(SocketTube(1)) DownstreamPusher: queue empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
        DEBUG: [HttpClient-1-Worker-0] [1s 255ms] SSL Writer(SocketTube(1)) wrapping 0 bytes
        DEBUG: [HttpClient-1-Worker-0] [1s 269ms] SSL Writer(SocketTube(1)) SSLResult: Status = OK HandshakeStatus = NEED_UNWRAP
        bytesConsumed = 0 bytesProduced = 45 sequenceNumber = 0
        DEBUG: [HttpClient-1-Worker-0] [1s 269ms] SSL Writer(SocketTube(1)) OK => produced: 45 bytes into 48, not wrapped: 0
        DEBUG: [HttpClient-1-Worker-0] [1s 269ms] SSL Writer(SocketTube(1)) wrapBuffer returned Status = OK HandshakeStatus = NEED_UNWRAP
        bytesConsumed = 0 bytesProduced = 45 sequenceNumber = 0
        DEBUG: [HttpClient-1-Worker-0] [1s 269ms] SSL Writer(SocketTube(1)) handshaking
        DEBUG: [HttpClient-1-Worker-0] [1s 270ms] SSL Writer(SocketTube(1)) Sending 45 bytes downstream
        DEBUG: [HttpClient-1-Worker-0] [1s 270ms] SSL Writer(SocketTube(1)) Adding 45 to outputQ queue
        DEBUG: [HttpClient-1-Worker-0] [1s 270ms] SSL Writer(SocketTube(1)) pushScheduler is alive
        DEBUG: [HttpClient-1-Worker-0] [1s 270ms] SSL Writer(SocketTube(1)) DownstreamPusher: queue not empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
        DEBUG: [HttpClient-1-Worker-0] [1s 270ms] SSL Writer(SocketTube(1)) DownstreamPusher: Pushing 45 bytes downstream
        DEBUG: [HttpClient-1-Worker-0] [1s 270ms] SocketTube(1) trying to write: 45
        DEBUG: [HttpClient-1-Worker-0] [1s 271ms] SocketTube(1) wrote: 45
        DEBUG: [HttpClient-1-Worker-0] [1s 271ms] SocketTube(1) write: requesting more...
        DEBUG: [HttpClient-1-Worker-0] [1s 271ms] SocketTube(1) leaving requestMore: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
        DEBUG: [HttpClient-1-Worker-0] [1s 271ms] SocketTube(1) leaving w.onNext Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
        DEBUG: [HttpClient-1-Worker-0] [1s 271ms] SSL Writer(SocketTube(1)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:1
        DEBUG: [HttpClient-1-Worker-0] [1s 271ms] SSL Writer(SocketTube(1)) DownstreamPusher: queue empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
        DEBUG: [HttpClient-1-Worker-0] [1s 271ms] SSL Reader(SocketTube(1)) processData: readBuf remaining:0, state: HANDSHAKING , engine handshake status:NEED_UNWRAP
        DEBUG: [HttpClient-1-SelectorManager] [1s 329ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@2e414b42 for 0 (false)
        DEBUG: [HttpClient-1-SelectorManager] [1s 330ms] SocketTube(1) read bytes: 51
        DEBUG: [HttpClient-1-SelectorManager] [1s 330ms] SSL Reader(SocketTube(1)) onNext
        DEBUG: [HttpClient-1-SelectorManager] [1s 330ms] SSL Reader(SocketTube(1)) Adding 51 bytes to read buffer
        DEBUG: [HttpClient-1-Worker-0] [1s 330ms] SSL Reader(SocketTube(1)) processData: readBuf remaining:51, state: HANDSHAKING , engine handshake status:NEED_UNWRAP
        DEBUG: [HttpClient-1-SelectorManager] [1s 330ms] SSL Reader(SocketTube(1)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:0
        DEBUG: [HttpClient-1-Worker-0] [1s 330ms] SSL Reader(SocketTube(1)) Unwrapping: 51
        DEBUG: [HttpClient-1-SelectorManager] [1s 330ms] SSL Reader(SocketTube(1)) requesting 1
        DEBUG: [HttpClient-1-SelectorManager] [1s 330ms] SocketTube(1) got some demand for reading
        DEBUG: [HttpClient-1-SelectorManager] [1s 330ms] SocketTube(1) resuming read event
        DEBUG: [HttpClient-1-SelectorManager] [1s 330ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@2e414b42 for 1 (false)
        DEBUG: [HttpClient-1-SelectorManager] [1s 330ms] SocketTube(1) leaving request(1): Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
        DEBUG: [HttpClient-1-SelectorManager] [1s 331ms] SocketTube(1) resuming read event
        DEBUG: [HttpClient-1-SelectorManager] [1s 331ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@2e414b42 for 1 (false)
        DEBUG: [HttpClient-1-SelectorManager] [1s 331ms] SocketTube(1) leaving read() loop after onNext: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
        DEBUG: [HttpClient-1-Worker-0] [1s 331ms] SSL Reader(SocketTube(1)) Decoded 0 bytes out of 51 into buffer of 512 remaining to decode: 45
        DEBUG: [HttpClient-1-Worker-0] [1s 331ms] SSL Reader(SocketTube(1)) Unwrapped: result: Status = OK HandshakeStatus = NEED_UNWRAP
        bytesConsumed = 6 bytesProduced = 0
        DEBUG: [HttpClient-1-Worker-0] [1s 331ms] SSL Reader(SocketTube(1)) Unwrapped: consumed: 6
        DEBUG: [HttpClient-1-Worker-0] [1s 331ms] SSL Reader(SocketTube(1)) handshaking
        DEBUG: [HttpClient-1-Worker-0] [1s 331ms] SSL Reader(SocketTube(1)) Unwrapping: 45
        DEBUG: [HttpClient-1-Worker-0] [1s 332ms] SSL Reader(SocketTube(1)) Decoded 0 bytes out of 45 into buffer of 512 remaining to decode: 0
        DEBUG: [HttpClient-1-Worker-0] [1s 333ms] SSL Reader(SocketTube(1)) Unwrapped: result: Status = OK HandshakeStatus = FINISHED
        bytesConsumed = 45 bytesProduced = 0
        DEBUG: [HttpClient-1-Worker-0] [1s 333ms] SSL Reader(SocketTube(1)) Unwrapped: consumed: 45
        DEBUG: [HttpClient-1-Worker-0] [1s 333ms] SSLFlowDelegate(SocketTube(1)) setALPN =
        DEBUG: [HttpClient-1-Worker-0] [1s 333ms] PlainHttpConnection(SocketTube(1)) finishConnect, setting connected=true
        DEBUG: [HttpClient-1-Worker-0] [1s 333ms] Http1Exchange SSLTube(SocketTube(1)) connecting flows
        DEBUG: [HttpClient-1-Worker-0] [1s 333ms] SSLTube(SocketTube(1)) connecting flows
        DEBUG: [HttpClient-1-Worker-0] [1s 334ms] SSLTube(SocketTube(1)) SSLSubscriberWrapper (reader) got delegate: jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber@350ee240
        DEBUG: [HttpClient-1-Worker-0] [1s 335ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) Received onSubscribed from upstream
        DEBUG: [HttpClient-1-Worker-0] [1s 335ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) downstream subscription demand is 1
        DEBUG: [HttpClient-1-Worker-0] [1s 335ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) checkRequestMore: canRequestMore=true, hasDemand=true
        DEBUG: [HttpClient-1-Worker-0] [1s 335ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) Http1TubeSubscriber: requesting one more from upstream
        DEBUG: [HttpClient-1-Worker-0] [1s 335ms] SSL Reader(SocketTube(1)) DownstreamPusher: queue empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
        DEBUG: [HttpClient-1-Worker-0] [1s 335ms] SSL Reader(SocketTube(1)) DownstreamPusher: queue empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
        DEBUG: [HttpClient-1-Worker-0] [1s 336ms] Http1Publisher(SSLTube(SocketTube(1))) got subscriber: SSLTube(SocketTube(1))
        DEBUG: [HttpClient-1-Worker-0] [1s 336ms] SSLTube(SocketTube(1)) setSubscription: demand=1, cancelled:false
        DEBUG: [HttpClient-1-Worker-0] [1s 336ms] Http1Publisher(SSLTube(SocketTube(1))) subscription request(1), demand=1
        DEBUG: [HttpClient-1-Worker-0] [1s 336ms] Http1Publisher(SSLTube(SocketTube(1))) WriteTask
        DEBUG: [HttpClient-1-Worker-0] [1s 338ms] Http1Publisher(SSLTube(SocketTube(1))) hasOutgoing = false
        DEBUG: [HttpClient-1-Worker-0] [1s 338ms] Http1Exchange requestAction.headers
        DEBUG: [HttpClient-1-Worker-0] [1s 340ms] Http1Exchange setting outgoing with headers
        DEBUG: [HttpClient-1-Worker-0] [1s 346ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=239 cap=239]], throwable=null]
        DEBUG: [HttpClient-1-Worker-0] [1s 346ms] Http1Publisher(SSLTube(SocketTube(1))) WriteTask
        DEBUG: [HttpClient-1-Worker-0] [1s 346ms] Http1Publisher(SSLTube(SocketTube(1))) hasOutgoing = true
        DEBUG: [HttpClient-1-Worker-0] [1s 346ms] Http1Exchange initiating completion of headersSentCF
        DEBUG: [HttpClient-1-Worker-0] [1s 347ms] Http1Publisher(SSLTube(SocketTube(1))) onNext with 239 bytes
        DEBUG: [HttpClient-1-Worker-0] [1s 348ms] SSLTube(SocketTube(1)) sending 1 buffers to SSL flow delegate
        DEBUG: [HttpClient-1-Worker-0] [1s 348ms] SSL Writer(SocketTube(1)) onNext
        DEBUG: [HttpClient-1-Worker-0] [1s 348ms] SSL Writer(SocketTube(1)) added 1 (239 bytes) to the writeList
        DEBUG: [HttpClient-1-Worker-0] [1s 348ms] SSL Writer(SocketTube(1)) processData, writeList remaining:239, hsTriggered:false, needWrap:false
        DEBUG: [HttpClient-1-Worker-0] [1s 348ms] SSL Writer(SocketTube(1)) wrapping 239 bytes
        DEBUG: [HttpClient-1-Worker-0] [1s 348ms] SSL Writer(SocketTube(1)) SSLResult: Status = OK HandshakeStatus = NOT_HANDSHAKING
        bytesConsumed = 239 bytesProduced = 268 sequenceNumber = 1
        DEBUG: [HttpClient-1-Worker-0] [1s 349ms] SSL Writer(SocketTube(1)) OK => produced: 268 bytes into 272, not wrapped: 0
        DEBUG: [HttpClient-1-Worker-0] [1s 349ms] SSL Writer(SocketTube(1)) wrapBuffer returned Status = OK HandshakeStatus = NOT_HANDSHAKING
        bytesConsumed = 239 bytesProduced = 268 sequenceNumber = 1
        DEBUG: [HttpClient-1-Worker-0] [1s 349ms] SSL Writer(SocketTube(1)) Sending 268 bytes downstream
        DEBUG: [HttpClient-1-Worker-0] [1s 350ms] SSL Writer(SocketTube(1)) Adding 268 to outputQ queue
        DEBUG: [HttpClient-1-Worker-0] [1s 350ms] SSL Writer(SocketTube(1)) pushScheduler is alive
        DEBUG: [HttpClient-1-Worker-0] [1s 350ms] SSL Writer(SocketTube(1)) DownstreamPusher: queue not empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
        DEBUG: [HttpClient-1-Worker-0] [1s 350ms] SSL Writer(SocketTube(1)) DownstreamPusher: Pushing 268 bytes downstream
        DEBUG: [HttpClient-1-Worker-0] [1s 350ms] SocketTube(1) trying to write: 268
        DEBUG: [HttpClient-1-Worker-0] [1s 350ms] SocketTube(1) wrote: 268
        DEBUG: [HttpClient-1-Worker-0] [1s 350ms] SocketTube(1) write: requesting more...
        DEBUG: [HttpClient-1-Worker-0] [1s 350ms] SocketTube(1) leaving requestMore: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
        DEBUG: [HttpClient-1-Worker-0] [1s 350ms] SocketTube(1) leaving w.onNext Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
        DEBUG: [HttpClient-1-Worker-0] [1s 350ms] SSL Writer(SocketTube(1)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:0
        DEBUG: [HttpClient-1-Worker-0] [1s 350ms] SSL Writer(SocketTube(1)) requesting 1
        DEBUG: [HttpClient-1-Worker-0] [1s 351ms] SSLTube(SocketTube(1)) request: n=1
        DEBUG: [HttpClient-1-Worker-0] [1s 351ms] Http1Publisher(SSLTube(SocketTube(1))) subscription request(1), demand=1
        DEBUG: [HttpClient-1-Worker-0] [1s 351ms] SSL Writer(SocketTube(1)) DownstreamPusher: queue empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
        DEBUG: [HttpClient-1-Worker-0] [1s 351ms] SSL Writer(SocketTube(1)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:1
        DEBUG: [HttpClient-1-Worker-0] [1s 351ms] Http1Publisher(SSLTube(SocketTube(1))) WriteTask
        DEBUG: [HttpClient-1-Worker-0] [1s 351ms] Http1Publisher(SSLTube(SocketTube(1))) hasOutgoing = false
        DEBUG: [HttpClient-1-Worker-0] [1s 351ms] Exchange checkFor407: all clear
        DEBUG: [HttpClient-1-Worker-0] [1s 351ms] Exchange sendRequestBody
        DEBUG: [HttpClient-1-Worker-0] [1s 351ms] Http1Exchange sendBodyAsync
        DEBUG: [HttpClient-1-Worker-0] [1s 351ms] Http1Exchange bodySubscriber is null
        DEBUG: [HttpClient-1-Worker-0] [1s 352ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]], throwable=null]
        DEBUG: [HttpClient-1-Worker-0] [1s 352ms] Http1Publisher(SSLTube(SocketTube(1))) WriteTask
        DEBUG: [HttpClient-1-Worker-0] [1s 352ms] Http1Publisher(SSLTube(SocketTube(1))) hasOutgoing = true
        DEBUG: [HttpClient-1-Worker-0] [1s 352ms] Http1Exchange initiating completion of bodySentCF
        DEBUG: [HttpClient-1-Worker-0] [1s 353ms] Http1Publisher(SSLTube(SocketTube(1))) completed, stopping jdk.internal.net.http.common.SequentialScheduler@58b73dd0
        DEBUG: [HttpClient-1-Worker-0] [1s 354ms] Http1Exchange sendBodyAsync completed successfully
        DEBUG: [HttpClient-1-Worker-0] [1s 358ms] Http1Exchange reading headers
        DEBUG: [HttpClient-1-Worker-0] [1s 359ms] Http1Response(id=1) Reading Headers: (remaining: 0) READING_HEADERS
        DEBUG: [HttpClient-1-Worker-0] [1s 360ms] Http1Response(id=1) First time around
        DEBUG: [HttpClient-1-Worker-0] [1s 360ms] Http1Response(id=1) headersReader is not yet completed
        DEBUG: [HttpClient-1-Worker-0] [1s 361ms] SSL Writer(SocketTube(1)) processData, writeList remaining:0, hsTriggered:false, needWrap:false
        DEBUG: [HttpClient-1-Worker-0] [1s 361ms] SSL Reader(SocketTube(1)) processData: readBuf remaining:0, state: NOT_HANDSHAKING , engine handshake status:NOT_HANDSHAKING
        DEBUG: [HttpClient-1-SelectorManager] [1s 548ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@2e414b42 for 0 (false)
        DEBUG: [HttpClient-1-SelectorManager] [1s 548ms] SocketTube(1) read bytes: 561
        DEBUG: [HttpClient-1-SelectorManager] [1s 548ms] SSL Reader(SocketTube(1)) onNext
        DEBUG: [HttpClient-1-SelectorManager] [1s 548ms] SSL Reader(SocketTube(1)) Adding 561 bytes to read buffer
        DEBUG: [HttpClient-1-SelectorManager] [1s 548ms] SSL Reader(SocketTube(1)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:0
        DEBUG: [HttpClient-1-Worker-0] [1s 548ms] SSL Reader(SocketTube(1)) processData: readBuf remaining:561, state: NOT_HANDSHAKING , engine handshake status:NOT_HANDSHAKING
        DEBUG: [HttpClient-1-SelectorManager] [1s 548ms] SSL Reader(SocketTube(1)) requesting 1
        DEBUG: [HttpClient-1-SelectorManager] [1s 548ms] SocketTube(1) got some demand for reading
        DEBUG: [HttpClient-1-SelectorManager] [1s 548ms] SocketTube(1) resuming read event
        DEBUG: [HttpClient-1-Worker-0] [1s 548ms] SSL Reader(SocketTube(1)) Unwrapping: 561
        DEBUG: [HttpClient-1-SelectorManager] [1s 549ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@2e414b42 for 1 (false)
        DEBUG: [HttpClient-1-SelectorManager] [1s 549ms] SocketTube(1) leaving request(1): Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
        DEBUG: [HttpClient-1-SelectorManager] [1s 549ms] SocketTube(1) resuming read event
        DEBUG: [HttpClient-1-SelectorManager] [1s 549ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@2e414b42 for 1 (false)
        DEBUG: [HttpClient-1-SelectorManager] [1s 549ms] SocketTube(1) leaving read() loop after onNext: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
        DEBUG: [HttpClient-1-SelectorManager] [1s 549ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@2e414b42 for 0 (false)
        DEBUG: [HttpClient-1-SelectorManager] [1s 549ms] SocketTube(1) got read EOF
        DEBUG: [HttpClient-1-SelectorManager] [1s 549ms] SocketTube(1) pausing read event
        DEBUG: [HttpClient-1-Worker-0] [1s 550ms] SSL Reader(SocketTube(1)) Decoded 315 bytes out of 561 into buffer of 512 remaining to decode: 217
        DEBUG: [HttpClient-1-Worker-0] [1s 550ms] SSL Reader(SocketTube(1)) Unwrapped: result: Status = OK HandshakeStatus = NOT_HANDSHAKING
        bytesConsumed = 344 bytesProduced = 315
        DEBUG: [HttpClient-1-Worker-0] [1s 550ms] SSL Reader(SocketTube(1)) Unwrapped: consumed: 344
        DEBUG: [HttpClient-1-Worker-0] [1s 550ms] SSL Reader(SocketTube(1)) sending 315
        DEBUG: [HttpClient-1-SelectorManager] [1s 550ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@2e414b42 for 0 (false)
        DEBUG: [HttpClient-1-SelectorManager] [1s 550ms] SocketTube(1) completing subscriber
        DEBUG: [HttpClient-1-Worker-0] [1s 550ms] SSL Reader(SocketTube(1)) Adding 315 to outputQ queue
        DEBUG: [HttpClient-1-Worker-0] [1s 550ms] SSL Reader(SocketTube(1)) pushScheduler is alive
        DEBUG: [HttpClient-1-Worker-0] [1s 550ms] SSL Reader(SocketTube(1)) DownstreamPusher: queue not empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
        DEBUG: [HttpClient-1-Worker-0] [1s 550ms] SSL Reader(SocketTube(1)) DownstreamPusher: Pushing 315 bytes downstream
        DEBUG: [HttpClient-1-SelectorManager] [1s 550ms] SSL Reader(SocketTube(1)) upstream completed: READER: SubscriberWrapper: upstreamCompleted: false upstreamWindow: 1 downstreamCompleted: false completionAcknowledged: false outputQ size: 0 cf: jdk.internal.net.http.common.MinimalFuture@5c25e85b[Not completed, 4 dependents] (id=26) downstreamSubscription: SubscriptionBase: window = 1 cancelled = false, readBuf: java.nio.HeapByteBuffer[pos=344 lim=561 cap=8192], count: 315, scheduler: running, status: OK
        DEBUG: [HttpClient-1-SelectorManager] [1s 551ms] SSL Reader(SocketTube(1)) Adding 0 bytes to read buffer
        DEBUG: [HttpClient-1-SelectorManager] [1s 551ms] SocketTube(1) leaving read() loop after EOF: Reading: [ops=0, demand=0, stopped=true], Writing: [ops=0, demand=1]
        DEBUG: [HttpClient-1-SelectorManager] [1s 551ms] SocketTube(1) Read scheduler stopped
        DEBUG: [HttpClient-1-Worker-0] [1s 551ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) Putting 315 bytes into the queue
        DEBUG: [HttpClient-1-Worker-0] [1s 551ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) Got 315 bytes for delegate jdk.internal.net.http.Http1Response$HeadersReader@7f010382
        DEBUG: [HttpClient-1-Worker-0] [1s 551ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) downstream subscription demand is 1
        DEBUG: [HttpClient-1-Worker-0] [1s 551ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) Forwarding 315 bytes to delegate jdk.internal.net.http.Http1Response$HeadersReader@7f010382
        DEBUG: [HttpClient-1-Worker-0] [1s 555ms] Http1Response(id=1) Sending 315/512 bytes to header parser
        DEBUG: [HttpClient-1-Worker-0] [1s 556ms] Http1Response(id=1) Parsing headers completed. bytes=315
        DEBUG: [HttpClient-1-Worker-0] [1s 556ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) Unsubscribed jdk.internal.net.http.Http1Response$HeadersReader@7f010382
        DEBUG: [HttpClient-1-Worker-0] [1s 557ms] Http1Response(id=1) Reading Headers: creating Response object; state is now READING_BODY
        DEBUG: [HttpClient-1-Worker-0] [1s 557ms] Http1Exchange getResponseAsync completed successfully
        DEBUG: [HttpClient-1-Worker-0] [1s 572ms] Http1Response(id=1, AsyncSSLConnection(SSLTube(SocketTube(1)))) Operation started: incrementing ref count for jdk.internal.net.http.HttpClientImpl@13acb0d1(1)
        DEBUG: [HttpClient-1-Worker-0] [1s 575ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) Subscribed pending jdk.internal.net.http.Http1Response$BodyReader@2238a23c/parser=jdk.internal.net.http.ResponseContent$UnknownLengthBodyParser@62d4e0c3 queue.isEmpty: false
        DEBUG: [HttpClient-1-Worker-0] [1s 587ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) Delegate done: 0
        DEBUG: [HttpClient-1-Worker-0] [1s 587ms] AsyncSSLConnection(SSLTube(SocketTube(1)))/ResponseContent/UnknownLengthBodyParser onSubscribe: jdk.internal.net.http.Http1Response$Http1BodySubscriber
        DEBUG: [HttpClient-1-Worker-0] [1s 587ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) delegate is now jdk.internal.net.http.Http1Response$BodyReader@2238a23c/parser=jdk.internal.net.http.ResponseContent$UnknownLengthBodyParser@62d4e0c3, demand=9223372036854775807, canRequestMore=false, queue.isEmpty=false
        DEBUG: [HttpClient-1-Worker-0] [1s 587ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) Got 0 bytes for delegate jdk.internal.net.http.Http1Response$BodyReader@2238a23c/parser=jdk.internal.net.http.ResponseContent$UnknownLengthBodyParser@62d4e0c3
        DEBUG: [HttpClient-1-Worker-0] [1s 587ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) downstream subscription demand is 9223372036854775807
        DEBUG: [HttpClient-1-Worker-0] [1s 587ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) Forwarding 0 bytes to delegate jdk.internal.net.http.Http1Response$BodyReader@2238a23c/parser=jdk.internal.net.http.ResponseContent$UnknownLengthBodyParser@62d4e0c3
        DEBUG: [HttpClient-1-Worker-0] [1s 588ms] Http1Response(id=1, AsyncSSLConnection(SSLTube(SocketTube(1)))) Sending 0/512 bytes to body parser
        DEBUG: [HttpClient-1-Worker-0] [1s 588ms] AsyncSSLConnection(SSLTube(SocketTube(1)))/ResponseContent/UnknownLengthBodyParser Parser got 0 bytes
        DEBUG: [HttpClient-1-Worker-0] [1s 588ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) downstream subscription demand is 9223372036854775807
        DEBUG: [HttpClient-1-Worker-0] [1s 588ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) checkRequestMore: canRequestMore=true, hasDemand=true
        DEBUG: [HttpClient-1-Worker-0] [1s 588ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) Http1TubeSubscriber: requesting one more from upstream
        DEBUG: [HttpClient-1-Worker-0] [1s 588ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) downstream subscription demand is 9223372036854775807
        DEBUG: [HttpClient-1-Worker-0] [1s 588ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) checkRequestMore: canRequestMore=false, hasDemand=true
        DEBUG: [HttpClient-1-Worker-0] [1s 588ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) Http1TubeSubscriber: no need to request more
        DEBUG: [HttpClient-1-Worker-0] [1s 589ms] SSL Reader(SocketTube(1)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:1
        DEBUG: [HttpClient-1-Worker-0] [1s 589ms] SSL Reader(SocketTube(1)) DownstreamPusher: queue empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
        DEBUG: [HttpClient-1-Worker-0] [1s 589ms] SSL Reader(SocketTube(1)) Unwrapping: 217
        DEBUG: [HttpClient-1-Worker-0] [1s 590ms] SSL Reader(SocketTube(1)) Decoded 188 bytes out of 217 into buffer of 320 remaining to decode: 0
        DEBUG: [HttpClient-1-Worker-0] [1s 590ms] SSL Reader(SocketTube(1)) Unwrapped: result: Status = OK HandshakeStatus = NOT_HANDSHAKING
        bytesConsumed = 217 bytesProduced = 188
        DEBUG: [HttpClient-1-Worker-0] [1s 590ms] SSL Reader(SocketTube(1)) Unwrapped: consumed: 217
        DEBUG: [HttpClient-1-Worker-0] [1s 590ms] SSL Reader(SocketTube(1)) sending 188
        DEBUG: [HttpClient-1-Worker-0] [1s 590ms] SSL Reader(SocketTube(1)) Adding 188 to outputQ queue
        DEBUG: [HttpClient-1-Worker-0] [1s 590ms] SSL Reader(SocketTube(1)) pushScheduler is alive
        DEBUG: [HttpClient-1-Worker-0] [1s 590ms] SSL Reader(SocketTube(1)) DownstreamPusher: queue not empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
        DEBUG: [HttpClient-1-Worker-0] [1s 590ms] SSL Reader(SocketTube(1)) DownstreamPusher: Pushing 188 bytes downstream
        DEBUG: [HttpClient-1-Worker-0] [1s 590ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) Putting 188 bytes into the queue
        DEBUG: [HttpClient-1-Worker-0] [1s 590ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) Got 188 bytes for delegate jdk.internal.net.http.Http1Response$BodyReader@2238a23c/parser=jdk.internal.net.http.ResponseContent$UnknownLengthBodyParser@62d4e0c3
        DEBUG: [HttpClient-1-Worker-0] [1s 590ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) downstream subscription demand is 9223372036854775807
        DEBUG: [HttpClient-1-Worker-0] [1s 591ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) Forwarding 188 bytes to delegate jdk.internal.net.http.Http1Response$BodyReader@2238a23c/parser=jdk.internal.net.http.ResponseContent$UnknownLengthBodyParser@62d4e0c3
        DEBUG: [HttpClient-1-Worker-0] [1s 591ms] Http1Response(id=1, AsyncSSLConnection(SSLTube(SocketTube(1)))) Sending 188/320 bytes to body parser
        DEBUG: [HttpClient-1-Worker-0] [1s 591ms] AsyncSSLConnection(SSLTube(SocketTube(1)))/ResponseContent/UnknownLengthBodyParser Parser got 188 bytes
        DEBUG: [HttpClient-1-Worker-0] [1s 592ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) downstream subscription demand is 9223372036854775806
        DEBUG: [HttpClient-1-Worker-0] [1s 592ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) checkRequestMore: canRequestMore=true, hasDemand=true
        DEBUG: [HttpClient-1-Worker-0] [1s 592ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) Http1TubeSubscriber: requesting one more from upstream
        DEBUG: [HttpClient-1-Worker-0] [1s 592ms] SSL Reader(SocketTube(1)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:1
        DEBUG: [HttpClient-1-Worker-0] [1s 592ms] SSL Reader(SocketTube(1)) DownstreamPusher: queue empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
        DEBUG: [HttpClient-1-Worker-0] [1s 592ms] SSL Reader(SocketTube(1)) completing
        DEBUG: [HttpClient-1-Worker-0] [1s 592ms] SSL Reader(SocketTube(1)) completionAcknowledged upstreamCompleted:true, downstreamCompleted:false, closing:false
        DEBUG: [HttpClient-1-Worker-0] [1s 592ms] SSL Reader(SocketTube(1)) pushScheduler is alive
        DEBUG: [HttpClient-1-Worker-0] [1s 592ms] SSL Reader(SocketTube(1)) DownstreamPusher: queue empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
        DEBUG: [HttpClient-1-Worker-0] [1s 592ms] SSL Reader(SocketTube(1)) calling downstreamSubscriber.onComplete()
        DEBUG: [HttpClient-1-Worker-0] [1s 592ms] SSLTube(SocketTube(1)) DelegateWrapper: completing subscriber
        DEBUG: [HttpClient-1-Worker-0] [1s 592ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) onError: java.io.EOFException: EOF reached while reading
        DEBUG: [HttpClient-1-Worker-0] [1s 597ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) recorded java.io.EOFException: EOF reached while reading
        delegate: jdk.internal.net.http.Http1Response$BodyReader@2238a23c/parser=jdk.internal.net.http.ResponseContent$UnknownLengthBodyParser@62d4e0c3 queue.isEmpty: true java.io.EOFException: EOF reached while reading
        java.io.EOFException: EOF reached while reading
        at java.net.http/jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber.onComplete(Http1AsyncReceiver.java:591)
        at java.net.http/jdk.internal.net.http.common.SSLTube$DelegateWrapper.onComplete(SSLTube.java:268)
        at java.net.http/jdk.internal.net.http.common.SSLTube$SSLSubscriberWrapper.complete(SSLTube.java:411)
        at java.net.http/jdk.internal.net.http.common.SSLTube$SSLSubscriberWrapper.onComplete(SSLTube.java:540)
        at java.net.http/jdk.internal.net.http.common.SubscriberWrapper.checkCompletion(SubscriberWrapper.java:443)
        at java.net.http/jdk.internal.net.http.common.SubscriberWrapper$DownstreamPusher.run1(SubscriberWrapper.java:322)
        at java.net.http/jdk.internal.net.http.common.SubscriberWrapper$DownstreamPusher.run(SubscriberWrapper.java:261)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SynchronizedRestartableTask.run(SequentialScheduler.java:175)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:147)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:271)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler.runOrSchedule(SequentialScheduler.java:224)
        at java.net.http/jdk.internal.net.http.common.SubscriberWrapper.outgoing(SubscriberWrapper.java:234)
        at java.net.http/jdk.internal.net.http.common.SSLFlowDelegate$Reader.processData(SSLFlowDelegate.java:467)
        at java.net.http/jdk.internal.net.http.common.SSLFlowDelegate$Reader$ReaderDownstreamPusher.run(SSLFlowDelegate.java:263)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SynchronizedRestartableTask.run(SequentialScheduler.java:175)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$CompleteRestartableTask.run(SequentialScheduler.java:147)
        at java.net.http/jdk.internal.net.http.common.SequentialScheduler$SchedulableTask.run(SequentialScheduler.java:198)
        at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128)
        at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628)
        at java.base/java.lang.Thread.run(Thread.java:834)
        DEBUG: [HttpClient-1-Worker-0] [1s 600ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) downstream subscription demand is 9223372036854775806
        DEBUG: [HttpClient-1-Worker-0] [1s 600ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) checkRequestMore: canRequestMore=false, hasDemand=true
        DEBUG: [HttpClient-1-Worker-0] [1s 601ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) Http1TubeSubscriber: no need to request more
        DEBUG: [HttpClient-1-Worker-0] [1s 602ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) flushing java.io.EOFException: EOF reached while reading
        delegate: jdk.internal.net.http.Http1Response$BodyReader@2238a23c/parser=jdk.internal.net.http.ResponseContent$UnknownLengthBodyParser@62d4e0c3 queue.isEmpty: true
        DEBUG: [HttpClient-1-Worker-0] [1s 603ms] AsyncSSLConnection(SSLTube(SocketTube(1)))/ResponseContent/UnknownLengthBodyParser Parser got all expected bytes: completing
        DEBUG: [HttpClient-1-Worker-0] [1s 604ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) cleared
        DEBUG: [HttpClient-1-Worker-0] [1s 604ms] Http1Response(id=1, AsyncSSLConnection(SSLTube(SocketTube(1)))) SSLTube(SocketTube(1)): return to HTTP/1.1 pool
        DEBUG: [HttpClient-1-Worker-0] [1s 621ms] HttpClientImpl(1) ClientImpl (async) elapsed 1186 millis for GET to https://hapi.grupoboticario.com.br/grb/sb/incidentes/listar
        DEBUG: [HttpClient-1-Worker-0] [1s 621ms] Http1Response(id=1, AsyncSSLConnection(SSLTube(SocketTube(1)))) Finished reading body: READING_BODY
        DEBUG: [HttpClient-1-Worker-0] [1s 621ms] Http1Response(id=1, AsyncSSLConnection(SSLTube(SocketTube(1)))) Operation finished: decrementing ref count for jdk.internal.net.http.HttpClientImpl@13acb0d1(1)
        DEBUG: [HttpClient-1-Worker-0] [1s 621ms] Http1Exchange asyncReceiver finished (failed=java.io.EOFException: EOF reached while reading)
        DEBUG: [HttpClient-1-Worker-0] [1s 622ms] SSLTube(SocketTube(1)) subscriber completed %snormally
        DEBUG: [HttpClient-1-Worker-0] [1s 622ms] Http1Publisher(SSLTube(SocketTube(1))) subscription cancelled
        DEBUG: [HttpClient-1-Worker-0] [1s 622ms] SSL Reader(SocketTube(1)) processData: readBuf remaining:0, state: NOT_HANDSHAKING , engine handshake status:NOT_HANDSHAKING
        DEBUG: [HttpClient-1-Worker-0] [1s 622ms] SSL Reader(SocketTube(1)) completing
        DEBUG: [HttpClient-1-Worker-0] [1s 622ms] SSL Reader(SocketTube(1)) completionAcknowledged upstreamCompleted:true, downstreamCompleted:true, closing:false
        DEBUG: [HttpClient-1-Worker-0] [1s 622ms] SSL Reader(SocketTube(1)) pushScheduler is alive
        DEBUG: [HttpClient-1-Worker-0] [1s 622ms] SSL Reader(SocketTube(1)) DownstreamPusher: downstream is already completed


        ---------- BEGIN SOURCE ----------
        Start the socket server and connect to the port with telnet or anything. The client socket will end.
        After that, check for leaked connections: netstat -an 1 | find "xxx.xxx.62.89"

        import java.io.PrintWriter;
        import java.net.ServerSocket;
        import java.net.URI;
        import java.net.http.HttpClient;
        import java.net.http.HttpClient.Version;
        import java.net.http.HttpRequest;
        import java.net.http.HttpResponse;
        import java.net.http.HttpResponse.BodyHandlers;

        public class SocketSandbox {

        public static void main(String[] args) throws Exception {
        HttpClient client = HttpClient.newBuilder().version(Version.HTTP_1_1).build();
        try (var listener = new ServerSocket(59090)) {
        System.out.println("Server is running...");
        while (true) {
        try (var socket = listener.accept()) {
        HttpRequest request = HttpRequest
        .newBuilder(URI.create("https://xxx.com.br/grb/sb/incidentes/listar"))
        .header("X-IBM-Client-Id", "5ee56396-8062-4f38-8ed3-0d16c38fdec4")
        .header("unidadeNegocio", "GB").header("content-type", "application/json").build();
        HttpResponse<String> response = client.send(request, BodyHandlers.ofString());
        var out = new PrintWriter(socket.getOutputStream(), true);
        out.println(String.format("Response HTTP status: %s", response.statusCode()));
        }
        }
        }
        }

        }
        ---------- END SOURCE ----------

        CUSTOMER SUBMITTED WORKAROUND :
        Apache HttpClient and OkHttp libraries are not leaking connections so we are considering to refactor the code and use one of them.

              dfuchs Daniel Fuchs
              webbuggrp Webbug Group
              Votes:
              0 Vote for this issue
              Watchers:
              7 Start watching this issue

                Created:
                Updated:
                Resolved: