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

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

    XMLWordPrintable

Details

    • b19
    • x86_64
    • linux
    • Verified

    Backports

      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

          Issue Links

            Activity

              People

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

                Dates

                  Created:
                  Updated:
                  Resolved: