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

HttpClient's client ssl certificate authentication seems to be broken.

    Details

    • Subcomponent:
    • Resolved In Build:
      b19
    • CPU:
      x86_64
    • OS:
      linux
    • Verification:
      Verified

      Description

      ADDITIONAL SYSTEM INFORMATION :
      $ java -version
      openjdk version "11.0.4" 2019-07-16
      OpenJDK Runtime Environment (build 11.0.4+11-post-Ubuntu-1ubuntu219.04)
      OpenJDK 64-Bit Server VM (build 11.0.4+11-post-Ubuntu-1ubuntu219.04, mixed mode, sharing)


      A DESCRIPTION OF THE PROBLEM :
      Being presented with https client certificate authentication handshake it seems that HttpClient hangs instead of emitting errors like other http client implementations. (The bug also occurs of matching ssl context with a real client key and certificate is present).
       If connect timeout is supplied the client hangs internally until that time is achieved and then emits an invalid connect timeout exception instead. If no timeout is supplied it seems to hang forever.

      STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
      Reuse supplied example code to do a request against an ssl client certificate authentication demanding server (or set up an nginx server demanding for an ssl auth and make a request against it).

      EXPECTED VERSUS ACTUAL BEHAVIOR :
      EXPECTED -
      Expecting almost instant 400 error / exception like javax.net.ssl.HttpsURLConnection or curl do.
      ACTUAL -
      Internal timeout from HttpClient. I enabled debug output on jdk to get more details:

      $ java -Djdk.internal.httpclient.debug=true HttpsClientExample
      DEBUG: [main] [212ms] HttpClientImpl(1) proxySelector is sun.net.spi.DefaultProxySelector@2fc14f68 (user-supplied=false)
      DEBUG: [main] [276ms] HttpClientImpl(1) ClientImpl (async) send https://api.fortumo.io GET
      DEBUG: [main] [288ms] Exchange establishing exchange for https://api.fortumo.io GET,
      proxy=null
      DEBUG: [main] [399ms] PlainHttpConnection(?) Initial receive buffer size is: 65536
      DEBUG: [main] [433ms] PlainHttpConnection(SocketTube(1)) registering connect timer: ConnectTimerEvent, TimeoutEvent[id=1, duration=PT10S, deadline=2019-09-21T06:28:31.632113Z]
      DEBUG: [main] [435ms] PlainHttpConnection(SocketTube(1)) registering connect event
      DEBUG: [HttpClient-1-SelectorManager] [439ms] SelectorAttachment Registering jdk.internal.net.http.PlainHttpConnection$ConnectEvent@4416feb8 for 8 (true)
      DEBUG: [main] [443ms] ExchangeImpl get: Trying to get HTTP/2 connection
      DEBUG: [HttpClient-1-SelectorManager] [506ms] PlainHttpConnection(SocketTube(1)) ConnectEvent: finishing connect
      DEBUG: [HttpClient-1-SelectorManager] [507ms] PlainHttpConnection(SocketTube(1)) ConnectEvent: connect finished: true Local addr: /192.168.1.139:45052
      DEBUG: [HttpClient-1-Worker-0] [543ms] SocketTube(1) connecting flows
      DEBUG: [HttpClient-1-Worker-0] [544ms] SocketTube(1) read publisher got subscriber
      DEBUG: [HttpClient-1-Worker-0] [545ms] SocketTube(1) registering subscribe event
      DEBUG: [HttpClient-1-Worker-0] [545ms] SocketTube(1) leaving read.subscribe: Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=0]
      DEBUG: [HttpClient-1-SelectorManager] [545ms] SocketTube(1) subscribe event raised
      DEBUG: [HttpClient-1-Worker-0] [549ms] SSL Writer(SocketTube(1)) requesting 1
      DEBUG: [HttpClient-1-Worker-0] [551ms] SSLTube(SocketTube(1)) request: n=1
      DEBUG: [HttpClient-1-Worker-0] [551ms] SSL Writer(SocketTube(1)) calling downstreamSubscriber::onSubscribe on SocketTube(1)
      DEBUG: [HttpClient-1-Worker-0] [552ms] SocketTube(1) subscribed for writing
      DEBUG: [HttpClient-1-Worker-0] [553ms] SocketTube(1) write: registering startSubscription event
      DEBUG: [HttpClient-1-Worker-0] [553ms] SSL Writer(SocketTube(1)) onSubscribe initiating handshaking
      DEBUG: [HttpClient-1-Worker-0] [565ms] SSL Writer(SocketTube(1)) added 1 (0 bytes) to the writeList
      DEBUG: [HttpClient-1-Worker-0] [579ms] SSL Writer(SocketTube(1)) processData, writeList remaining:0, hsTriggered:true, needWrap:false
      DEBUG: [HttpClient-1-Worker-0] [580ms] SSL Writer(SocketTube(1)) wrapping 0 bytes
      DEBUG: [HttpClient-1-Worker-0] [647ms] SSL Writer(SocketTube(1)) SSLResult: Status = OK HandshakeStatus = NEED_UNWRAP
      bytesConsumed = 0 bytesProduced = 459 sequenceNumber = 0
      DEBUG: [HttpClient-1-Worker-0] [648ms] SSL Writer(SocketTube(1)) OK => produced: 459 bytes into 464, not wrapped: 0
      DEBUG: [HttpClient-1-Worker-0] [648ms] SSL Writer(SocketTube(1)) wrapBuffer returned Status = OK HandshakeStatus = NEED_UNWRAP
      bytesConsumed = 0 bytesProduced = 459 sequenceNumber = 0
      DEBUG: [HttpClient-1-Worker-0] [648ms] SSL Writer(SocketTube(1)) handshaking
      DEBUG: [HttpClient-1-Worker-0] [663ms] SSL Reader(SocketTube(1)) processData: readBuf remaining:0, state: HANDSHAKING , engine handshake status:NEED_UNWRAP
      DEBUG: [HttpClient-1-Worker-0] [664ms] SSL Writer(SocketTube(1)) Sending 459 bytes downstream
      DEBUG: [HttpClient-1-Worker-0] [664ms] SSL Writer(SocketTube(1)) Adding 459 to outputQ queue
      DEBUG: [HttpClient-1-Worker-0] [665ms] SSL Writer(SocketTube(1)) pushScheduler is alive
      DEBUG: [HttpClient-1-Worker-0] [667ms] SSL Writer(SocketTube(1)) DownstreamPusher: queue not empty, downstreamSubscription: SubscriptionBase: window = 0 cancelled = false
      DEBUG: [HttpClient-1-SelectorManager] [682ms] 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@50071922[Not completed, 4 dependents] (id=21) downstreamSubscription: SubscriptionBase: window = 0 cancelled = false downstreamSubscriber: SSLSubscriberWrapper[SSLTube(SocketTube(1)), delegate: null, getALPN: null, onCompleteReceived: false, onError: null], readBuf: java.nio.HeapByteBuffer[pos=0 lim=0 cap=1024], count: 0, scheduler: running, status: null, handshakeState: 0, engine: NEED_UNWRAP
      DEBUG: [HttpClient-1-SelectorManager] [682ms] SocketTube(1) read demand reset to 0
      DEBUG: [HttpClient-1-SelectorManager] [682ms] SocketTube(1) calling onSubscribe
      DEBUG: [HttpClient-1-SelectorManager] [683ms] SSL Reader(SocketTube(1)) requesting 1
      DEBUG: [HttpClient-1-SelectorManager] [683ms] SocketTube(1) got some demand for reading
      DEBUG: [HttpClient-1-SelectorManager] [683ms] SocketTube(1) resuming read event
      DEBUG: [HttpClient-1-SelectorManager] [684ms] SocketTube(1) leaving request(1): Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=0]
      DEBUG: [HttpClient-1-SelectorManager] [684ms] SSL Reader(SocketTube(1)) calling downstreamSubscriber::onSubscribe on SSLSubscriberWrapper[SSLTube(SocketTube(1)), delegate: null, getALPN: jdk.internal.net.http.common.MinimalFuture@6ec950ed[Not completed, 1 dependents] (id=27), onCompleteReceived: false, onError: null]
      DEBUG: [HttpClient-1-SelectorManager] [685ms] SSLTube(SocketTube(1)) SSLSubscriberWrapper (reader) onSubscribe(SubscriptionBase: window = 0 cancelled = false)
      DEBUG: [HttpClient-1-SelectorManager] [685ms] SSLTube(SocketTube(1)) SSLSubscriberWrapper (reader) onSubscribeImpl: no delegate yet
      DEBUG: [HttpClient-1-SelectorManager] [685ms] SocketTube(1) onSubscribe called
      DEBUG: [HttpClient-1-SelectorManager] [685ms] SocketTube(1) pending subscriber subscribed
      DEBUG: [HttpClient-1-SelectorManager] [685ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@5c89b914 for 1 (true)
      DEBUG: [HttpClient-1-SelectorManager] [685ms] SocketTube(1) write: starting subscription
      DEBUG: [HttpClient-1-SelectorManager] [686ms] SocketTube(1) write: offloading requestMore
      DEBUG: [HttpClient-1-Worker-0] [688ms] SocketTube(1) write: requesting more...
      DEBUG: [HttpClient-1-Worker-0] [689ms] SSL Writer(SocketTube(1)) DownstreamPusher: queue not empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
      DEBUG: [HttpClient-1-Worker-0] [689ms] SSL Writer(SocketTube(1)) DownstreamPusher: Pushing 459 bytes downstream
      DEBUG: [HttpClient-1-Worker-0] [690ms] SocketTube(1) trying to write: 459
      DEBUG: [HttpClient-1-Worker-0] [694ms] SocketTube(1) wrote: 459
      DEBUG: [HttpClient-1-Worker-0] [695ms] SocketTube(1) write: requesting more...
      DEBUG: [HttpClient-1-Worker-0] [696ms] SocketTube(1) leaving requestMore: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
      DEBUG: [HttpClient-1-Worker-0] [696ms] SocketTube(1) leaving w.onNext Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
      DEBUG: [HttpClient-1-Worker-0] [696ms] SSL Writer(SocketTube(1)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:1
      DEBUG: [HttpClient-1-Worker-0] [697ms] SSL Writer(SocketTube(1)) DownstreamPusher: queue empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
      DEBUG: [HttpClient-1-Worker-0] [697ms] SocketTube(1) leaving requestMore: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
      DEBUG: [HttpClient-1-SelectorManager] [762ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@5c89b914 for 0 (false)
      DEBUG: [HttpClient-1-SelectorManager] [763ms] HttpClientImpl(1) ByteBuffer.allocateDirect(16384)
      DEBUG: [HttpClient-1-SelectorManager] [766ms] SocketTube(1) read bytes: 1448
      DEBUG: [HttpClient-1-SelectorManager] [766ms] SSL Reader(SocketTube(1)) onNext
      DEBUG: [HttpClient-1-SelectorManager] [766ms] SSL Reader(SocketTube(1)) Adding 1448 bytes to read buffer
      DEBUG: [HttpClient-1-Worker-0] [767ms] SSL Reader(SocketTube(1)) processData: readBuf remaining:1448, state: HANDSHAKING , engine handshake status:NEED_UNWRAP
      DEBUG: [HttpClient-1-SelectorManager] [767ms] SSL Reader(SocketTube(1)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:0
      DEBUG: [HttpClient-1-Worker-0] [767ms] SSL Reader(SocketTube(1)) Unwrapping: 1448
      DEBUG: [HttpClient-1-SelectorManager] [767ms] SSL Reader(SocketTube(1)) requesting 1
      DEBUG: [HttpClient-1-SelectorManager] [767ms] SocketTube(1) got some demand for reading
      DEBUG: [HttpClient-1-SelectorManager] [768ms] SocketTube(1) resuming read event
      DEBUG: [HttpClient-1-SelectorManager] [768ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@5c89b914 for 1 (false)
      DEBUG: [HttpClient-1-SelectorManager] [768ms] SocketTube(1) leaving request(1): Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
      DEBUG: [HttpClient-1-SelectorManager] [768ms] SocketTube(1) resuming read event
      DEBUG: [HttpClient-1-SelectorManager] [769ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@5c89b914 for 1 (false)
      DEBUG: [HttpClient-1-SelectorManager] [769ms] SocketTube(1) leaving read() loop after onNext: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
      DEBUG: [HttpClient-1-SelectorManager] [769ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@5c89b914 for 0 (false)
      DEBUG: [HttpClient-1-SelectorManager] [770ms] SocketTube(1) read bytes: 12784
      DEBUG: [HttpClient-1-SelectorManager] [770ms] SSL Reader(SocketTube(1)) onNext
      DEBUG: [HttpClient-1-SelectorManager] [770ms] SSL Reader(SocketTube(1)) Adding 12784 bytes to read buffer
      DEBUG: [HttpClient-1-Worker-0] [783ms] SSL Reader(SocketTube(1)) Decoded 0 bytes out of 1448 into buffer of 512 remaining to decode: 1350
      DEBUG: [HttpClient-1-Worker-0] [784ms] SSL Reader(SocketTube(1)) Unwrapped: result: Status = OK HandshakeStatus = NEED_TASK
      bytesConsumed = 98 bytesProduced = 0
      DEBUG: [HttpClient-1-Worker-0] [784ms] SSL Reader(SocketTube(1)) Unwrapped: consumed: 98
      DEBUG: [HttpClient-1-Worker-0] [784ms] SSL Reader(SocketTube(1)) handshaking
      DEBUG: [HttpClient-1-SelectorManager] [784ms] SSL Reader(SocketTube(1)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:0
      DEBUG: [HttpClient-1-SelectorManager] [784ms] SSL Reader(SocketTube(1)) requesting 1
      DEBUG: [HttpClient-1-SelectorManager] [785ms] SocketTube(1) got some demand for reading
      DEBUG: [HttpClient-1-SelectorManager] [785ms] SocketTube(1) resuming read event
      DEBUG: [HttpClient-1-Worker-0] [785ms] SSLFlowDelegate(SocketTube(1)) obtaining and initiating task execution
      DEBUG: [HttpClient-1-SelectorManager] [785ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@5c89b914 for 1 (false)
      DEBUG: [HttpClient-1-SelectorManager] [785ms] SocketTube(1) leaving request(1): Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
      DEBUG: [HttpClient-1-SelectorManager] [785ms] SocketTube(1) resuming read event
      DEBUG: [HttpClient-1-SelectorManager] [785ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@5c89b914 for 1 (false)
      DEBUG: [HttpClient-1-SelectorManager] [786ms] SocketTube(1) leaving read() loop after onNext: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
      DEBUG: [HttpClient-1-Worker-0] [786ms] SSLFlowDelegate(SocketTube(1)) #tasks to execute: 1
      DEBUG: [HttpClient-1-Worker-0] [792ms] SSLFlowDelegate(SocketTube(1)) finished task execution
      DEBUG: [HttpClient-1-Worker-0] [792ms] SSL Writer(SocketTube(1)) processData, writeList remaining:0, hsTriggered:false, needWrap:false
      DEBUG: [HttpClient-1-Worker-0] [792ms] SSL Reader(SocketTube(1)) processData: readBuf remaining:14134, state: HANDSHAKING , engine handshake status:NEED_UNWRAP
      DEBUG: [HttpClient-1-Worker-0] [792ms] SSL Reader(SocketTube(1)) Unwrapping: 14134
      DEBUG: [HttpClient-1-Worker-0] [792ms] SSL Reader(SocketTube(1)) Decoded 0 bytes out of 14134 into buffer of 512 remaining to decode: 11248
      DEBUG: [HttpClient-1-Worker-0] [792ms] SSL Reader(SocketTube(1)) Unwrapped: result: Status = OK HandshakeStatus = NEED_TASK
      bytesConsumed = 2886 bytesProduced = 0
      DEBUG: [HttpClient-1-Worker-0] [793ms] SSL Reader(SocketTube(1)) Unwrapped: consumed: 2886
      DEBUG: [HttpClient-1-Worker-0] [793ms] SSL Reader(SocketTube(1)) handshaking
      DEBUG: [HttpClient-1-Worker-0] [793ms] SSLFlowDelegate(SocketTube(1)) obtaining and initiating task execution
      DEBUG: [HttpClient-1-Worker-0] [793ms] SSLFlowDelegate(SocketTube(1)) #tasks to execute: 1
      DEBUG: [HttpClient-1-SelectorManager] [828ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@5c89b914 for 0 (false)
      DEBUG: [HttpClient-1-SelectorManager] [828ms] SocketTube(1) read bytes: 1448
      DEBUG: [HttpClient-1-SelectorManager] [828ms] SSL Reader(SocketTube(1)) onNext
      DEBUG: [HttpClient-1-SelectorManager] [828ms] SSL Reader(SocketTube(1)) Adding 1448 bytes to read buffer
      DEBUG: [HttpClient-1-SelectorManager] [829ms] SSL Reader(SocketTube(1)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:0
      DEBUG: [HttpClient-1-SelectorManager] [829ms] SSL Reader(SocketTube(1)) requesting 1
      DEBUG: [HttpClient-1-SelectorManager] [829ms] SocketTube(1) got some demand for reading
      DEBUG: [HttpClient-1-SelectorManager] [829ms] SocketTube(1) resuming read event
      DEBUG: [HttpClient-1-SelectorManager] [829ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@5c89b914 for 1 (false)
      DEBUG: [HttpClient-1-SelectorManager] [829ms] SocketTube(1) leaving request(1): Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
      DEBUG: [HttpClient-1-SelectorManager] [829ms] SocketTube(1) resuming read event
      DEBUG: [HttpClient-1-SelectorManager] [830ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@5c89b914 for 1 (false)
      DEBUG: [HttpClient-1-SelectorManager] [830ms] SocketTube(1) leaving read() loop after onNext: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
      DEBUG: [HttpClient-1-SelectorManager] [831ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@5c89b914 for 0 (false)
      DEBUG: [HttpClient-1-SelectorManager] [832ms] SocketTube(1) read bytes: 4105
      DEBUG: [HttpClient-1-SelectorManager] [832ms] SSL Reader(SocketTube(1)) onNext
      DEBUG: [HttpClient-1-SelectorManager] [832ms] SSL Reader(SocketTube(1)) Adding 4105 bytes to read buffer
      DEBUG: [HttpClient-1-SelectorManager] [832ms] SSL Reader(SocketTube(1)) readBuf has more than TARGET_BUFSIZE: 16801
      DEBUG: [HttpClient-1-SelectorManager] [832ms] SSL Reader(SocketTube(1)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:0
      DEBUG: [HttpClient-1-SelectorManager] [832ms] SocketTube(1) resuming read event
      DEBUG: [HttpClient-1-SelectorManager] [833ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@5c89b914 for 1 (false)
      DEBUG: [HttpClient-1-SelectorManager] [833ms] SocketTube(1) leaving read() loop after onNext: Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
      DEBUG: [HttpClient-1-Worker-0] [873ms] SSLFlowDelegate(SocketTube(1)) finished task execution
      DEBUG: [HttpClient-1-Worker-0] [873ms] SSL Writer(SocketTube(1)) processData, writeList remaining:0, hsTriggered:false, needWrap:false
      DEBUG: [HttpClient-1-Worker-0] [873ms] SSL Reader(SocketTube(1)) processData: readBuf remaining:16801, state: HANDSHAKING , engine handshake status:NEED_UNWRAP
      DEBUG: [HttpClient-1-Worker-0] [873ms] SSL Reader(SocketTube(1)) Unwrapping: 16801
      DEBUG: [HttpClient-1-Worker-0] [873ms] SSL Reader(SocketTube(1)) Decoded 0 bytes out of 16801 into buffer of 512 remaining to decode: 16463
      DEBUG: [HttpClient-1-Worker-0] [874ms] SSL Reader(SocketTube(1)) Unwrapped: result: Status = OK HandshakeStatus = NEED_TASK
      bytesConsumed = 338 bytesProduced = 0
      DEBUG: [HttpClient-1-Worker-0] [874ms] SSL Reader(SocketTube(1)) Unwrapped: consumed: 338
      DEBUG: [HttpClient-1-Worker-0] [874ms] SSL Reader(SocketTube(1)) handshaking
      DEBUG: [HttpClient-1-Worker-0] [874ms] SSLFlowDelegate(SocketTube(1)) obtaining and initiating task execution
      DEBUG: [HttpClient-1-Worker-0] [874ms] SSLFlowDelegate(SocketTube(1)) #tasks to execute: 1
      DEBUG: [HttpClient-1-Worker-0] [876ms] SSLFlowDelegate(SocketTube(1)) finished task execution
      DEBUG: [HttpClient-1-Worker-0] [876ms] SSL Writer(SocketTube(1)) processData, writeList remaining:0, hsTriggered:false, needWrap:false
      DEBUG: [HttpClient-1-Worker-0] [876ms] SSL Reader(SocketTube(1)) processData: readBuf remaining:16463, state: HANDSHAKING , engine handshake status:NEED_UNWRAP
      DEBUG: [HttpClient-1-Worker-0] [876ms] SSL Reader(SocketTube(1)) Unwrapping: 16463
      DEBUG: [HttpClient-1-Worker-0] [877ms] SSL Reader(SocketTube(1)) Decoded 0 bytes out of 16463 into buffer of 512 remaining to decode: 74
      DEBUG: [HttpClient-1-Worker-0] [877ms] SSL Reader(SocketTube(1)) Unwrapped: result: Status = OK HandshakeStatus = NEED_UNWRAP
      bytesConsumed = 16389 bytesProduced = 0
      DEBUG: [HttpClient-1-Worker-0] [877ms] SSL Reader(SocketTube(1)) Unwrapped: consumed: 16389
      DEBUG: [HttpClient-1-Worker-0] [877ms] SSL Reader(SocketTube(1)) handshaking
      DEBUG: [HttpClient-1-Worker-0] [877ms] SSL Reader(SocketTube(1)) Unwrapping: 74
      DEBUG: [HttpClient-1-Worker-0] [877ms] SSL Reader(SocketTube(1)) Decoded 0 bytes out of 74 into buffer of 512 remaining to decode: 0
      DEBUG: [HttpClient-1-Worker-0] [877ms] SSL Reader(SocketTube(1)) Unwrapped: result: Status = OK HandshakeStatus = NEED_TASK
      bytesConsumed = 74 bytesProduced = 0
      DEBUG: [HttpClient-1-Worker-0] [877ms] SSL Reader(SocketTube(1)) Unwrapped: consumed: 74
      DEBUG: [HttpClient-1-Worker-0] [877ms] SSL Reader(SocketTube(1)) handshaking
      DEBUG: [HttpClient-1-Worker-0] [877ms] SSLFlowDelegate(SocketTube(1)) obtaining and initiating task execution
      DEBUG: [HttpClient-1-Worker-0] [877ms] SSLFlowDelegate(SocketTube(1)) #tasks to execute: 1
      DEBUG: [HttpClient-1-Worker-0] [904ms] SSLFlowDelegate(SocketTube(1)) finished task execution
      DEBUG: [HttpClient-1-Worker-0] [904ms] SSL Writer(SocketTube(1)) processData, writeList remaining:0, hsTriggered:false, needWrap:true
      DEBUG: [HttpClient-1-Worker-0] [904ms] SSL Writer(SocketTube(1)) wrapping 0 bytes
      DEBUG: [HttpClient-1-Worker-0] [904ms] SSL Writer(SocketTube(1)) SSLResult: Status = OK HandshakeStatus = NEED_WRAP
      bytesConsumed = 0 bytesProduced = 82 sequenceNumber = 1
      DEBUG: [HttpClient-1-Worker-0] [904ms] SSL Writer(SocketTube(1)) OK => produced: 82 bytes into 88, not wrapped: 0
      DEBUG: [HttpClient-1-Worker-0] [905ms] SSL Writer(SocketTube(1)) wrapBuffer returned Status = OK HandshakeStatus = NEED_WRAP
      bytesConsumed = 0 bytesProduced = 82 sequenceNumber = 1
      DEBUG: [HttpClient-1-Worker-0] [905ms] SSL Writer(SocketTube(1)) handshaking
      DEBUG: [HttpClient-1-Worker-0] [905ms] SSL Writer(SocketTube(1)) Sending 82 bytes downstream
      DEBUG: [HttpClient-1-Worker-0] [905ms] SSL Writer(SocketTube(1)) Adding 82 to outputQ queue
      DEBUG: [HttpClient-1-Worker-0] [905ms] SSL Writer(SocketTube(1)) pushScheduler is alive
      DEBUG: [HttpClient-1-Worker-0] [905ms] SSL Writer(SocketTube(1)) DownstreamPusher: queue not empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
      DEBUG: [HttpClient-1-Worker-0] [905ms] SSL Writer(SocketTube(1)) DownstreamPusher: Pushing 82 bytes downstream
      DEBUG: [HttpClient-1-Worker-0] [905ms] SocketTube(1) trying to write: 82
      DEBUG: [HttpClient-1-Worker-0] [906ms] SocketTube(1) wrote: 82
      DEBUG: [HttpClient-1-Worker-0] [906ms] SocketTube(1) write: requesting more...
      DEBUG: [HttpClient-1-Worker-0] [906ms] SocketTube(1) leaving requestMore: Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
      DEBUG: [HttpClient-1-Worker-0] [906ms] SocketTube(1) leaving w.onNext Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
      DEBUG: [HttpClient-1-Worker-0] [906ms] SSL Writer(SocketTube(1)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:1
      DEBUG: [HttpClient-1-Worker-0] [906ms] SSL Writer(SocketTube(1)) DownstreamPusher: queue empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
      DEBUG: [HttpClient-1-Worker-0] [906ms] SSL Writer(SocketTube(1)) wrapping 0 bytes
      DEBUG: [HttpClient-1-Worker-0] [906ms] SSL Writer(SocketTube(1)) SSLResult: Status = OK HandshakeStatus = NEED_WRAP
      bytesConsumed = 0 bytesProduced = 6 sequenceNumber = 2
      DEBUG: [HttpClient-1-Worker-0] [906ms] SSL Writer(SocketTube(1)) OK => produced: 6 bytes into 8, not wrapped: 0
      DEBUG: [HttpClient-1-Worker-0] [907ms] SSL Writer(SocketTube(1)) wrapBuffer returned Status = OK HandshakeStatus = NEED_WRAP
      bytesConsumed = 0 bytesProduced = 6 sequenceNumber = 2
      DEBUG: [HttpClient-1-Worker-0] [907ms] SSL Writer(SocketTube(1)) handshaking
      DEBUG: [HttpClient-1-Worker-0] [907ms] SSL Writer(SocketTube(1)) Sending 6 bytes downstream
      DEBUG: [HttpClient-1-Worker-0] [907ms] SSL Writer(SocketTube(1)) Adding 6 to outputQ queue
      DEBUG: [HttpClient-1-Worker-0] [907ms] SSL Writer(SocketTube(1)) pushScheduler is alive
      DEBUG: [HttpClient-1-Worker-0] [907ms] SSL Writer(SocketTube(1)) DownstreamPusher: queue not empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
      DEBUG: [HttpClient-1-Worker-0] [907ms] SSL Writer(SocketTube(1)) DownstreamPusher: Pushing 6 bytes downstream
      DEBUG: [HttpClient-1-Worker-0] [907ms] SocketTube(1) trying to write: 6
      DEBUG: [HttpClient-1-Worker-0] [908ms] SocketTube(1) wrote: 6
      DEBUG: [HttpClient-1-Worker-0] [908ms] SocketTube(1) write: requesting more...
      DEBUG: [HttpClient-1-Worker-0] [908ms] SocketTube(1) leaving requestMore: Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
      DEBUG: [HttpClient-1-Worker-0] [908ms] SocketTube(1) leaving w.onNext Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
      DEBUG: [HttpClient-1-Worker-0] [908ms] SSL Writer(SocketTube(1)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:1
      DEBUG: [HttpClient-1-Worker-0] [908ms] SSL Writer(SocketTube(1)) DownstreamPusher: queue empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
      DEBUG: [HttpClient-1-Worker-0] [908ms] SSL Writer(SocketTube(1)) wrapping 0 bytes
      DEBUG: [HttpClient-1-Worker-0] [918ms] SSL Writer(SocketTube(1)) SSLResult: Status = OK HandshakeStatus = NEED_UNWRAP
      bytesConsumed = 0 bytesProduced = 45 sequenceNumber = 0
      DEBUG: [HttpClient-1-Worker-0] [919ms] SSL Writer(SocketTube(1)) OK => produced: 45 bytes into 48, not wrapped: 0
      DEBUG: [HttpClient-1-Worker-0] [919ms] SSL Writer(SocketTube(1)) wrapBuffer returned Status = OK HandshakeStatus = NEED_UNWRAP
      bytesConsumed = 0 bytesProduced = 45 sequenceNumber = 0
      DEBUG: [HttpClient-1-Worker-0] [919ms] SSL Writer(SocketTube(1)) handshaking
      DEBUG: [HttpClient-1-Worker-0] [919ms] SSL Writer(SocketTube(1)) Sending 45 bytes downstream
      DEBUG: [HttpClient-1-Worker-0] [919ms] SSL Writer(SocketTube(1)) Adding 45 to outputQ queue
      DEBUG: [HttpClient-1-Worker-0] [919ms] SSL Writer(SocketTube(1)) pushScheduler is alive
      DEBUG: [HttpClient-1-Worker-0] [919ms] SSL Writer(SocketTube(1)) DownstreamPusher: queue not empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
      DEBUG: [HttpClient-1-Worker-0] [919ms] SSL Writer(SocketTube(1)) DownstreamPusher: Pushing 45 bytes downstream
      DEBUG: [HttpClient-1-Worker-0] [920ms] SocketTube(1) trying to write: 45
      DEBUG: [HttpClient-1-Worker-0] [920ms] SocketTube(1) wrote: 45
      DEBUG: [HttpClient-1-Worker-0] [920ms] SocketTube(1) write: requesting more...
      DEBUG: [HttpClient-1-Worker-0] [920ms] SocketTube(1) leaving requestMore: Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
      DEBUG: [HttpClient-1-Worker-0] [920ms] SocketTube(1) leaving w.onNext Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
      DEBUG: [HttpClient-1-Worker-0] [920ms] SSL Writer(SocketTube(1)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:1
      DEBUG: [HttpClient-1-Worker-0] [920ms] SSL Writer(SocketTube(1)) DownstreamPusher: queue empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
      DEBUG: [HttpClient-1-Worker-0] [920ms] SSL Reader(SocketTube(1)) processData: readBuf remaining:0, state: HANDSHAKING , engine handshake status:NEED_UNWRAP
      DEBUG: [HttpClient-1-SelectorManager] [985ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@5c89b914 for 0 (false)
      DEBUG: [HttpClient-1-SelectorManager] [985ms] SocketTube(1) no more demand for reading
      DEBUG: [HttpClient-1-SelectorManager] [985ms] SocketTube(1) leaving read() loop with no demand Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=1]
      DEBUG: [HttpClient-1-SelectorManager] [10s 407ms] PlainHttpConnection(SocketTube(1)) HTTP connect timed out
      DEBUG: [HttpClient-1-SelectorManager] [10s 407ms] Exchange cancel exchImpl: null, with "java.net.ConnectException: HTTP connect timed out"
      DEBUG: [HttpClient-1-SelectorManager] [10s 414ms] PlainHttpConnection(SocketTube(1)) Closing channel: channel registered with selector, key.interestOps=0, sa.interestOps=0
      DEBUG: [HttpClient-1-SelectorManager] [10s 415ms] SocketTube(1) got read error: java.io.IOException: connection closed locally
      DEBUG: [HttpClient-1-SelectorManager] [10s 415ms] SocketTube(1) pausing read event
      DEBUG: [HttpClient-1-SelectorManager] [10s 421ms] SocketTube(1) Sending error java.io.IOException: connection closed locally to subscriber READER: SubscriberWrapper: upstreamCompleted: false upstreamWindow: 0 downstreamCompleted: false completionAcknowledged: false outputQ size: 0 cf: jdk.internal.net.http.common.MinimalFuture@50071922[Not completed, 4 dependents] (id=21) downstreamSubscription: SubscriptionBase: window = 0 cancelled = false downstreamSubscriber: SSLSubscriberWrapper[SSLTube(SocketTube(1)), delegate: null, getALPN: jdk.internal.net.http.common.MinimalFuture@6ec950ed[Not completed, 1 dependents] (id=27), onCompleteReceived: false, onError: null], readBuf: java.nio.HeapByteBuffer[pos=16801 lim=16801 cap=32768], count: 0, scheduler: running, status: OK, handshakeState: 1, engine: NEED_UNWRAP
      DEBUG: [HttpClient-1-SelectorManager] [10s 421ms] SocketTube(1) forwarding error to subscriber: java.io.IOException: connection closed locally
      DEBUG: [HttpClient-1-SelectorManager] [10s 422ms] SSL Reader(SocketTube(1)) onError: java.io.IOException: connection closed locally
      DEBUG: [HttpClient-1-SelectorManager] [10s 422ms] SSL Reader(SocketTube(1)) error java.io.IOException: connection closed locally
      java.io.IOException: connection closed locally
      at java.net.http/jdk.internal.net.http.SocketTube.signalClosed(SocketTube.java:157)
      at java.net.http/jdk.internal.net.http.PlainHttpConnection.close(PlainHttpConnection.java:277)
      at java.net.http/jdk.internal.net.http.AsyncSSLConnection.close(AsyncSSLConnection.java:106)
      at java.net.http/jdk.internal.net.http.Exchange$ConnectionAborter.closeConnection(Exchange.java:146)
      at java.net.http/jdk.internal.net.http.Exchange.cancel(Exchange.java:222)
      at java.net.http/jdk.internal.net.http.MultiExchange.cancel(MultiExchange.java:198)
      at java.net.http/jdk.internal.net.http.PlainHttpConnection$ConnectTimerEvent.handle(PlainHttpConnection.java:94)
      at java.net.http/jdk.internal.net.http.HttpClientImpl.purgeTimeoutsAndReturnNextDeadline(HttpClientImpl.java:1248)
      at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:877)
      DEBUG: [HttpClient-1-SelectorManager] [10s 424ms] SSL Reader(SocketTube(1)) DownstreamPusher: forwarding error downstream: java.io.IOException: connection closed locally
      DEBUG: [HttpClient-1-SelectorManager] [10s 425ms] SSLTube(SocketTube(1)) SSLSubscriberWrapper[SSLTube(SocketTube(1)), delegate: null, getALPN: jdk.internal.net.http.common.MinimalFuture@6ec950ed[Not completed, 1 dependents] (id=27), onCompleteReceived: false, onError: java.io.IOException: connection closed locally]: onErrorImpl: java.io.IOException: connection closed locally
      DEBUG: [HttpClient-1-SelectorManager] [10s 425ms] SSLTube(SocketTube(1)) SSLSubscriberWrapper[SSLTube(SocketTube(1)), delegate: null, getALPN: jdk.internal.net.http.common.MinimalFuture@6ec950ed[Not completed, 1 dependents] (id=27), onCompleteReceived: false, onError: java.io.IOException: connection closed locally]: delegate null, stored java.io.IOException: connection closed locally
      DEBUG: [HttpClient-1-SelectorManager] [10s 426ms] ExchangeImpl handling HTTP/2 connection creation result
      DEBUG: [HttpClient-1-SelectorManager] [10s 426ms] ExchangeImpl handling HTTP/2 connection creation failed: java.util.concurrent.CompletionException: java.io.IOException: connection closed locally
      DEBUG: [HttpClient-1-SelectorManager] [10s 427ms] ExchangeImpl HTTP/2 connection creation failed with unexpected exception: java.io.IOException: connection closed locally
      DEBUG: [HttpClient-1-SelectorManager] [10s 427ms] Exchange checkFor407: no response - java.io.IOException: connection closed locally
      DEBUG: [HttpClient-1-SelectorManager] [10s 445ms] HttpClientImpl(1) ClientImpl (async) elapsed 10167 millis for GET to https://api.fortumo.io
      DEBUG: [HttpClient-1-SelectorManager] [10s 445ms] SSL Reader(SocketTube(1)) stop
      DEBUG: [HttpClient-1-SelectorManager] [10s 445ms] SSL Writer(SocketTube(1)) stop
      Exception in thread "main" DEBUG: [HttpClient-1-SelectorManager] [10s 446ms] SocketTube(1) leaving read() loop with error: Reading: [ops=0, demand=0, stopped=true], Writing: [ops=0, demand=1]
      java.net.http.HttpConnectTimeoutException: HTTP connect timed out
      at java.net.http/jdk.internal.net.http.HttpClientImpl.send(HttpClientImpl.java:555)
      at java.net.http/jdk.internal.net.http.HttpClientFacade.send(HttpClientFacade.java:119)
      at HttpsClientExample.main(HttpsClientExample.java:17)
      Caused by: java.net.http.HttpConnectTimeoutException: HTTP connect timed out
      at java.net.http/jdk.internal.net.http.MultiExchange.toTimeoutException(MultiExchange.java:462)
      at java.net.http/jdk.internal.net.http.MultiExchange.getExceptionalCF(MultiExchange.java:412)
      at java.net.http/jdk.internal.net.http.MultiExchange.lambda$responseAsyncImpl$7(MultiExchange.java:339)
      at java.base/java.util.concurrent.CompletableFuture.uniHandle(CompletableFuture.java:930)
      at java.base/java.util.concurrent.CompletableFuture$UniHandle.tryFire(CompletableFuture.java:907)
      at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
      at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2088)
      at java.net.http/jdk.internal.net.http.common.SSLFlowDelegate.stopOnError(SSLFlowDelegate.java:934)
      at java.base/java.util.concurrent.CompletableFuture.uniExceptionally(CompletableFuture.java:986)
      at java.base/java.util.concurrent.CompletableFuture$UniExceptionally.tryFire(CompletableFuture.java:970)
      at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
      at java.base/java.util.concurrent.CompletableFuture.completeExceptionally(CompletableFuture.java:2088)
      at java.net.http/jdk.internal.net.http.common.SubscriberWrapper$DownstreamPusher.run1(SubscriberWrapper.java:297)
      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.errorCommon(SubscriberWrapper.java:390)
      at java.net.http/jdk.internal.net.http.common.SubscriberWrapper.onError(SubscriberWrapper.java:381)
      at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadSubscription.signalCompletion(SocketTube.java:629)
      at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:810)
      at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowTask.run(SocketTube.java:175)
      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.SocketTube$InternalReadPublisher$InternalReadSubscription.signalError(SocketTube.java:759)
      at java.net.http/jdk.internal.net.http.SocketTube.signalClosed(SocketTube.java:157)
      at java.net.http/jdk.internal.net.http.PlainHttpConnection.close(PlainHttpConnection.java:277)
      at java.net.http/jdk.internal.net.http.AsyncSSLConnection.close(AsyncSSLConnection.java:106)
      at java.net.http/jdk.internal.net.http.Exchange$ConnectionAborter.closeConnection(Exchange.java:146)
      at java.net.http/jdk.internal.net.http.Exchange.cancel(Exchange.java:222)
      at java.net.http/jdk.internal.net.http.MultiExchange.cancel(MultiExchange.java:198)
      at java.net.http/jdk.internal.net.http.PlainHttpConnection$ConnectTimerEvent.handle(PlainHttpConnection.java:94)
      at java.net.http/jdk.internal.net.http.HttpClientImpl.purgeTimeoutsAndReturnNextDeadline(HttpClientImpl.java:1248)
      at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:877)
      Caused by: java.net.ConnectException: HTTP connect timed out
      at java.net.http/jdk.internal.net.http.MultiExchange.toTimeoutException(MultiExchange.java:463)
      ... 36 more
      DEBUG: [HttpClient-1-SelectorManager] [10s 446ms] SocketTube(1) Read scheduler stopped


      ---------- BEGIN SOURCE ----------
      /* this code crashes with http client internal timeout */

      import java.net.URI;
      import java.net.http.HttpClient;
      import java.net.http.HttpRequest;
      import java.net.http.HttpResponse;
      import java.time.Duration;

      public class HttpsClientExample {
          public static void main(String[] args) throws Exception {
              HttpClient client = HttpClient.newBuilder()
                      .connectTimeout(Duration.ofSeconds(10))
                      .build();

              HttpRequest reqest = HttpRequest.newBuilder()
                      .uri(new URI("https://api.fortumo.io"))
                      .build();

              HttpResponse<String> result = client.send(reqest, HttpResponse.BodyHandlers.ofString());

              System.out.println(result.toString());
          }
      }

      /* this is the old way of java8 , works as expected, i get error code 400 */

      import javax.net.ssl.HttpsURLConnection;
      import java.net.URL;

      public class HttpsConnectionExample {

          public static void main(String[] args) throws Exception {
              final HttpsURLConnection con = (HttpsURLConnection) new URL("https://api.fortumo.io").openConnection();
              System.out.println("Response code " + con.getResponseCode());
              byte[] response = new byte[16 * 1024];
              int len = con.getErrorStream().read(response);
              System.out.println("Response data " + new String(response, 0, len));
          }
      }

      /* this is curl command line example, doing the same operation , emits error 400 from server */
      /*
      curl -v https://api.fortumo.io/
      */
      ---------- END SOURCE ----------

      CUSTOMER SUBMITTED WORKAROUND :
      None.

      FREQUENCY : always


        Attachments

          Activity

            People

            • Assignee:
              dfuchs Daniel Fuchs
              Reporter:
              webbuggrp Webbug Group
            • Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: