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

WebSocket over authenticating proxy fails with NPE

XMLWordPrintable

    • b07
    • x86_64
    • generic

        ADDITIONAL SYSTEM INFORMATION :
        Platform independent, tested on Windows 10, Debian, Centos 8, Fedora 30
        openjdk version "11.0.5" 2019-10-15
        Tested with version 11, 12, 13, 14 EA and and 15 EA

        A DESCRIPTION OF THE PROBLEM :
        When using java.net.httpclient to connect to WebSocket via proxy that requires authentication it fails with NPE when handling 407 (Proxy Authentication Required)

        It looks like problem is in handshake handling code that tries to do debug logging with object that is null.

        Even after patching RawChanelTube.java to prevent NPE, it still fails with different error
        "CheckFailedException: Unexpected HTTP response status code 407"

        STEPS TO FOLLOW TO REPRODUCE THE PROBLEM :
        When you try to connect to websocket via proxy that requires authentication, http client fails to properly handle 407 (proxy auth required) response as result fails to retry with properly set auth headers.

        EXPECTED VERSUS ACTUAL BEHAVIOR :
        EXPECTED -
        Socket is opened and works.
        ACTUAL -
        with debug enabled this is the log

        DEBUG: [HttpClient-1-SelectorManager] [2s 254ms] PlainHttpConnection(SocketTube(4)) ConnectEvent: finishing connect
        DEBUG: [HttpClient-1-SelectorManager] [2s 254ms] PlainHttpConnection(SocketTube(4)) ConnectEvent: connect finished: true Local addr: /192.168.42.39:56565
        DEBUG: [pool-2-thread-3] [2s 255ms] PlainHttpConnection(SocketTube(4)) finishConnect, setting connected=true
        DEBUG: [pool-2-thread-3] [2s 255ms] PlainTunnelingConnection(SocketTube(4)) sending HTTP/1.1 CONNECT
        DEBUG: [pool-2-thread-3] [2s 255ms] Exchange establishing exchange for socket://ws-feed.pro.coinbase.com:443/ CONNECT,
        proxy=null
        DEBUG: [pool-2-thread-3] [2s 255ms] ExchangeImpl get: HTTP/1.1: new Http1Exchange
        DEBUG: [pool-2-thread-3] [2s 255ms] Exchange checkFor407: all clear
        DEBUG: [pool-2-thread-3] [2s 255ms] Http1Exchange Sending headers only
        DEBUG: [pool-2-thread-3] [2s 255ms] Http1AsyncReceiver(SocketTube(4)) Subscribed pending jdk.internal.net.http.Http1Response$HeadersReader@6bc9a6dd queue.isEmpty: true
        DEBUG: [pool-2-thread-3] [2s 255ms] Http1AsyncReceiver(SocketTube(4)) delegate is now jdk.internal.net.http.Http1Response$HeadersReader@6bc9a6dd, demand=1, canRequestMore=true, queue.isEmpty=true
        DEBUG: [pool-2-thread-3] [2s 255ms] Http1AsyncReceiver(SocketTube(4)) downstream subscription demand is 1
        DEBUG: [pool-2-thread-3] [2s 255ms] Http1AsyncReceiver(SocketTube(4)) checkRequestMore: canRequestMore=true, hasDemand=true
        DEBUG: [pool-2-thread-3] [2s 255ms] Http1AsyncReceiver(SocketTube(4)) downstream subscription demand is 1
        DEBUG: [pool-2-thread-3] [2s 255ms] Http1AsyncReceiver(SocketTube(4)) checkRequestMore: canRequestMore=true, hasDemand=true
        DEBUG: [pool-2-thread-3] [2s 255ms] Http1Exchange response created in advance
        DEBUG: [pool-2-thread-3] [2s 255ms] Http1Exchange SocketTube(4) connecting flows
        DEBUG: [pool-2-thread-3] [2s 255ms] SocketTube(4) connecting flows
        DEBUG: [pool-2-thread-3] [2s 255ms] SocketTube(4) read publisher got subscriber
        DEBUG: [pool-2-thread-3] [2s 255ms] SocketTube(4) registering subscribe event
        DEBUG: [pool-2-thread-3] [2s 255ms] SocketTube(4) leaving read.subscribe: Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=0]
        DEBUG: [pool-2-thread-3] [2s 255ms] Http1Publisher(SocketTube(4)) got subscriber: SocketTube(4)
        DEBUG: [HttpClient-1-SelectorManager] [2s 255ms] SocketTube(4) subscribe event raised
        DEBUG: [pool-2-thread-3] [2s 256ms] SocketTube(4) subscribed for writing
        DEBUG: [pool-2-thread-3] [2s 256ms] SocketTube(4) write: registering startSubscription event
        DEBUG: [HttpClient-1-SelectorManager] [2s 256ms] SocketTube(4) handling pending subscription for jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber@58d43ff8
        DEBUG: [HttpClient-1-SelectorManager] [2s 256ms] SocketTube(4) read demand reset to 0
        DEBUG: [pool-2-thread-3] [2s 256ms] Http1Exchange requestAction.headers
        DEBUG: [HttpClient-1-SelectorManager] [2s 256ms] SocketTube(4) calling onSubscribe
        DEBUG: [HttpClient-1-SelectorManager] [2s 256ms] Http1AsyncReceiver(SocketTube(4)) Received onSubscribed from upstream
        DEBUG: [HttpClient-1-SelectorManager] [2s 256ms] SocketTube(4) onSubscribe called
        DEBUG: [HttpClient-1-SelectorManager] [2s 256ms] SocketTube(4) pending subscriber subscribed
        DEBUG: [pool-2-thread-1] [2s 256ms] Http1AsyncReceiver(SocketTube(4)) downstream subscription demand is 1
        DEBUG: [HttpClient-1-SelectorManager] [2s 256ms] SocketTube(4) write: starting subscription
        DEBUG: [pool-2-thread-1] [2s 256ms] Http1AsyncReceiver(SocketTube(4)) checkRequestMore: canRequestMore=true, hasDemand=true
        DEBUG: [pool-2-thread-3] [2s 256ms] Http1Exchange setting outgoing with headers
        DEBUG: [HttpClient-1-SelectorManager] [2s 256ms] SocketTube(4) write: offloading requestMore
        DEBUG: [pool-2-thread-3] [2s 256ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=85 cap=85]], throwable=null]
        DEBUG: [pool-2-thread-1] [2s 256ms] Http1AsyncReceiver(SocketTube(4)) Http1TubeSubscriber: requesting one more from upstream
        DEBUG: [pool-2-thread-3] [2s 256ms] Http1Publisher(SocketTube(4)) WriteTask
        DEBUG: [pool-2-thread-2] [2s 256ms] SocketTube(4) write: requesting more...
        DEBUG: [pool-2-thread-1] [2s 256ms] SocketTube(4) got some demand for reading
        DEBUG: [pool-2-thread-3] [2s 256ms] Http1Publisher(SocketTube(4)) hasOutgoing = true
        DEBUG: [pool-2-thread-1] [2s 256ms] SocketTube(4) resuming read event
        DEBUG: [pool-2-thread-2] [2s 256ms] Http1Publisher(SocketTube(4)) subscription request(1), demand=1
        DEBUG: [pool-2-thread-3] [2s 256ms] Http1Exchange initiating completion of headersSentCF
        DEBUG: [pool-2-thread-1] [2s 256ms] SocketTube(4) leaving request(1): Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
        DEBUG: [pool-2-thread-3] [2s 256ms] Http1Publisher(SocketTube(4)) onNext with 85 bytes
        DEBUG: [pool-2-thread-2] [2s 256ms] SocketTube(4) leaving requestMore: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
        DEBUG: [HttpClient-1-SelectorManager] [2s 256ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@1b4a4034 for 1 (true)
        DEBUG: [pool-2-thread-3] [2s 257ms] SocketTube(4) trying to write: 85
        DEBUG: [pool-2-thread-3] [2s 257ms] SocketTube(4) wrote: 85
        DEBUG: [pool-2-thread-3] [2s 257ms] SocketTube(4) write: requesting more...
        DEBUG: [pool-2-thread-3] [2s 257ms] Http1Publisher(SocketTube(4)) subscription request(1), demand=1
        DEBUG: [pool-2-thread-3] [2s 257ms] SocketTube(4) leaving requestMore: Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
        DEBUG: [pool-2-thread-3] [2s 257ms] SocketTube(4) leaving w.onNext Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
        DEBUG: [pool-2-thread-3] [2s 257ms] Http1Publisher(SocketTube(4)) WriteTask
        DEBUG: [pool-2-thread-3] [2s 257ms] Http1Publisher(SocketTube(4)) hasOutgoing = false
        DEBUG: [pool-2-thread-3] [2s 257ms] Exchange checkFor407: all clear
        DEBUG: [pool-2-thread-3] [2s 257ms] Exchange sendRequestBody
        DEBUG: [pool-2-thread-3] [2s 257ms] Http1Exchange sendBodyAsync
        DEBUG: [pool-2-thread-3] [2s 257ms] Http1Exchange bodySubscriber is null
        DEBUG: [pool-2-thread-3] [2s 257ms] Http1Exchange appending to outgoing DataPair [data=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]], throwable=null]
        DEBUG: [pool-2-thread-3] [2s 257ms] Http1Publisher(SocketTube(4)) WriteTask
        DEBUG: [pool-2-thread-3] [2s 257ms] Http1Publisher(SocketTube(4)) hasOutgoing = true
        DEBUG: [pool-2-thread-3] [2s 257ms] Http1Exchange initiating completion of bodySentCF
        DEBUG: [pool-2-thread-3] [2s 257ms] Http1Publisher(SocketTube(4)) completed, stopping jdk.internal.net.http.common.SequentialScheduler@5dbf8a63
        DEBUG: [pool-2-thread-3] [2s 257ms] Http1Exchange sendBodyAsync completed successfully
        DEBUG: [pool-2-thread-3] [2s 257ms] Http1Exchange reading headers
        DEBUG: [pool-2-thread-3] [2s 257ms] Http1Response(id=8, PlainHttpConnection(SocketTube(4))) Reading Headers: (remaining: 0) READING_HEADERS
        DEBUG: [pool-2-thread-3] [2s 257ms] Http1Response(id=8, PlainHttpConnection(SocketTube(4))) First time around
        DEBUG: [pool-2-thread-3] [2s 257ms] Http1Response(id=8, PlainHttpConnection(SocketTube(4))) headersReader is not yet completed
        DEBUG: [HttpClient-1-SelectorManager] [2s 300ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@1b4a4034 for 0 (false)
        DEBUG: [HttpClient-1-SelectorManager] [2s 300ms] SocketTube(4) read bytes: 3628
        DEBUG: [HttpClient-1-SelectorManager] [2s 300ms] Http1AsyncReceiver(SocketTube(4)) Putting 3628 bytes into the queue
        DEBUG: [HttpClient-1-SelectorManager] [2s 300ms] SocketTube(4) resuming read event
        DEBUG: [HttpClient-1-SelectorManager] [2s 300ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@1b4a4034 for 1 (false)
        DEBUG: [pool-2-thread-1] [2s 300ms] Http1AsyncReceiver(SocketTube(4)) Got 3628 bytes for delegate jdk.internal.net.http.Http1Response$HeadersReader@6bc9a6dd
        DEBUG: [HttpClient-1-SelectorManager] [2s 300ms] SocketTube(4) leaving read() loop after onNext: Reading: [ops=1, demand=0, stopped=false], Writing: [ops=0, demand=1]
        DEBUG: [pool-2-thread-1] [2s 301ms] Http1AsyncReceiver(SocketTube(4)) downstream subscription demand is 1
        DEBUG: [pool-2-thread-1] [2s 301ms] Http1AsyncReceiver(SocketTube(4)) Forwarding 3628 bytes to delegate jdk.internal.net.http.Http1Response$HeadersReader@6bc9a6dd
        DEBUG: [pool-2-thread-1] [2s 301ms] Http1Response(id=8, PlainHttpConnection(SocketTube(4))) Sending 3628/3628 bytes to header parser
        DEBUG: [pool-2-thread-1] [2s 301ms] Http1Response(id=8, PlainHttpConnection(SocketTube(4))) Parsing headers completed. bytes=406
        DEBUG: [pool-2-thread-1] [2s 301ms] Http1AsyncReceiver(SocketTube(4)) Unsubscribed jdk.internal.net.http.Http1Response$HeadersReader@6bc9a6dd
        DEBUG: [pool-2-thread-1] [2s 301ms] Http1Response(id=8, PlainHttpConnection(SocketTube(4))) Reading Headers: creating Response object; state is now READING_BODY
        DEBUG: [pool-2-thread-1] [2s 302ms] Http1Exchange getResponseAsync completed successfully
        DEBUG: [pool-2-thread-1] [2s 302ms] PlainTunnelingConnection(SocketTube(4)) got response: 407
        DEBUG: [pool-2-thread-1] [2s 302ms] PlainHttpConnection(SocketTube(4)) Closing channel: channel registered with selector, key.interestOps=1, sa.interestOps=1
        DEBUG: [pool-2-thread-1] [2s 302ms] SocketTube(4) got read error: java.io.IOException: connection closed locally
        DEBUG: [pool-2-thread-1] [2s 302ms] SocketTube(4) pausing read event
        DEBUG: [pool-2-thread-1] [2s 303ms] SocketTube(4) Sending error java.io.IOException: connection closed locally to subscriber jdk.internal.net.http.Http1AsyncReceiver$Http1TubeSubscriber@58d43ff8
        DEBUG: [pool-2-thread-1] [2s 303ms] SocketTube(4) forwarding error to subscriber: java.io.IOException: connection closed locally
        DEBUG: [pool-2-thread-1] [2s 303ms] Http1AsyncReceiver(SocketTube(4)) onError: java.io.IOException: connection closed locally
        DEBUG: [HttpClient-1-SelectorManager] [2s 303ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@1b4a4034 for 0 (false)
        DEBUG: [HttpClient-1-SelectorManager] [2s 303ms] SocketTube(4) abort: java.nio.channels.ClosedChannelException
        DEBUG: [HttpClient-1-SelectorManager] [2s 303ms] HttpClientImpl(1) Got java.io.IOException while handling registration events
        DEBUG: [pool-2-thread-1] [2s 303ms] Http1AsyncReceiver(SocketTube(4)) recorded java.io.IOException: connection closed locally
        delegate: null queue.isEmpty: false java.io.IOException: connection closed locally
        DEBUG: [HttpClient-1-SelectorManager] [2s 303ms] SocketTube(4) abort: java.io.IOException: Channel closed
        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.Http1Response.ignoreBody(Http1Response.java:264)
        at java.net.http/jdk.internal.net.http.Http1Exchange.ignoreBody(Http1Exchange.java:383)
        at java.net.http/jdk.internal.net.http.Exchange.ignoreBody(Exchange.java:187)
        at java.net.http/jdk.internal.net.http.PlainTunnelingConnection.lambda$connectAsync$2(PlainTunnelingConnection.java:84)
        at java.base/java.util.concurrent.CompletableFuture$UniCompose.tryFire(CompletableFuture.java:1146)
        at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
        at java.base/java.util.concurrent.CompletableFuture.postFire(CompletableFuture.java:610)
        at java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:649)
        at java.base/java.util.concurrent.CompletableFuture$Completion.run(CompletableFuture.java:478)
        at java.net.http/jdk.internal.net.http.HttpClientImpl$DelegatingExecutor.execute(HttpClientImpl.java:155)
        at java.base/java.util.concurrent.CompletableFuture$UniCompletion.claim(CompletableFuture.java:568)
        at java.base/java.util.concurrent.CompletableFuture$UniApply.tryFire(CompletableFuture.java:638)
        at java.base/java.util.concurrent.CompletableFuture.postComplete(CompletableFuture.java:506)
        at java.base/java.util.concurrent.CompletableFuture.complete(CompletableFuture.java:2144)
        at java.net.http/jdk.internal.net.http.Http1Response$HeadersReader.handle(Http1Response.java:686)
        at java.net.http/jdk.internal.net.http.Http1Response$HeadersReader.handle(Http1Response.java:612)
        at java.net.http/jdk.internal.net.http.Http1Response$Receiver.accept(Http1Response.java:603)
        at java.net.http/jdk.internal.net.http.Http1Response$HeadersReader.tryAsyncReceive(Http1Response.java:659)
        at java.net.http/jdk.internal.net.http.Http1AsyncReceiver.flush(Http1AsyncReceiver.java:233)
        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:830)


        ---------- BEGIN SOURCE ----------
        var httpClient = HttpClient.newBuilder()
        .proxy(...) // use proxy that requires auth
        .authenticator(new java.net.Authenticator() {
                    public PasswordAuthentication getPasswordAuthentication() {
                        return this.getRequestorType() == RequestorType.PROXY ? new PasswordAuthentication("proxyUser", "proxyPass".toCharArray()) : null;
                    })
        .build();

        var webSocket = httpClient.newWebSocketBuilder()
        .buildAsync(URI.create("wss://url-to-webSocket"), new WebSocket.Listener() {
        @Override
        public void onOpen(WebSocket webSocket) {
        webSocket.request(1);
        System.out.println("Socket opened");
        }
        })
        .join();
        ---------- END SOURCE ----------

        FREQUENCY : always


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

                Created:
                Updated:
                Resolved: