JDK-8221395 : HttpClient leaving connections in CLOSE_WAIT state until Java process ends
  • Type: Bug
  • Component: core-libs
  • Sub-Component: java.net
  • Affected Version: 11,12,13
  • Priority: P3
  • Status: Closed
  • Resolution: Fixed
  • OS: linux
  • CPU: x86_64
  • Submitted: 2019-03-22
  • Updated: 2019-10-24
  • Resolved: 2019-03-28
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 11 JDK 13
11.0.6-oracleFixed 13 b15Fixed
Description
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.
Comments
Fix Request (OpenJDK 11u): Please approve backporting this to OpenJDK 11u. The jdk/jdk patch applies cleanly and fails/passes the test case prior/after. It's an Oracle JDK 11.0.6 parity patch. Testing: tier1 on x86_64 and :jdk_net.
23-10-2019
Review thread: http://mail.openjdk.java.net/pipermail/net-dev/2019-March/012310.html
28-03-2019
The issue is the proxy - I guess. We are tunelling. Would be worth trying without a proxy in the picture. The log submitted hints that there is no proxy.
26-03-2019
Can reproduce using supplied testcase. Will investigate. Response status code is 500 with a JSON document body
25-03-2019
Reproduced the issue in Windows 7 by following the steps provided in the bug report. JDK 11.0.2 - Fail JDK 12 GA - Fail JDK 13-ea+12 - Fail C:\>netstat -an 1 | find "200.186.62.89" TCP 192.168.1.3:58153 200.186.62.89:443 CLOSE_WAIT TCP 192.168.1.3:58153 200.186.62.89:443 CLOSE_WAIT TCP 192.168.1.3:58153 200.186.62.89:443 CLOSE_WAIT TCP 192.168.1.3:58153 200.186.62.89:443 CLOSE_WAIT TCP 192.168.1.3:58153 200.186.62.89:443 CLOSE_WAIT TCP 192.168.1.3:58153 200.186.62.89:443 CLOSE_WAIT TCP 192.168.1.3:58153 200.186.62.89:443 CLOSE_WAIT TCP 192.168.1.3:58153 200.186.62.89:443 CLOSE_WAIT TCP 192.168.1.3:58153 200.186.62.89:443 CLOSE_WAIT TCP 192.168.1.3:58153 200.186.62.89:443 CLOSE_WAIT TCP 192.168.1.3:58153 200.186.62.89:443 CLOSE_WAIT TCP 192.168.1.3:58153 200.186.62.89:443 CLOSE_WAIT ............... ................
25-03-2019