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

[11u REDO] - WebSocket over authenticating proxy fails with NPE

XMLWordPrintable

    • b01
    • 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


            inakonechnyy Ilarion Nakonechnyy
            inakonechnyy Ilarion Nakonechnyy
            Votes:
            0 Vote for this issue
            Watchers:
            2 Start watching this issue

              Created:
              Updated:
              Resolved: