java. net .http HttpClient переходит в l oop wrapBuffer возвращается Status = OK HandshakeStatus = NEED_WRAP - PullRequest
0 голосов
/ 28 мая 2020

Я не могу опубликовать это в отчете об ошибках JDK, потому что я не могу воспроизвести его за пределами моей корпоративной инфраструктуры, но, возможно, кто-то сталкивался с чем-то похожим. 6

Код для сборки HttpClient:

return HttpClient.newBuilder()
        .version(HttpClient.Version.HTTP_1_1)
        .connectTimeout(Duration.ofSeconds(30))
        .proxy(ProxySelector.of(new InetSocketAddress(host, port)))
        .build();

Мой запрос выглядит так:

HttpRequest request = HttpRequest.newBuilder()
        .uri(URI.create(URL))
        .timeout(Duration.ofSeconds(10))
        .GET()
        .header("Content-Type", "application/json")
        .header("x-auth-identifier", "<credential_username>")
        .header("x-auth-key", "<credentials_password>")
        .header("Accept", "application/json")
        .build();

Использование: -Djdk.internal.httpclient.debug=true

Интересное Часть состоит в том, что данные удаляются в первый раз, а затем они попадают в l oop и просто вращаются бесконечно (?). Во второй половине журнала все происходит.

Кто-нибудь сталкивался с этим? Я знаю, что его Java HttpClient виноват, потому что, когда я меняю реализации на что-то вроде RestTemplate (который внутренне использует Apache HttpClient), он работает нормально.

DEBUG: [HttpClient-1-Worker-1] [177s 223ms] SSL Reader(SocketTube(1)) Unwrapped: consumed: 848
DEBUG: [HttpClient-1-Worker-1] [177s 223ms] SSL Reader(SocketTube(1)) sending 826
DEBUG: [HttpClient-1-Worker-1] [177s 223ms] SSL Reader(SocketTube(1)) Adding 826 to outputQ queue
DEBUG: [HttpClient-1-Worker-1] [177s 223ms] SSL Reader(SocketTube(1)) pushScheduler is alive
DEBUG: [HttpClient-1-Worker-1] [177s 223ms] SSL Reader(SocketTube(1)) DownstreamPusher: queue not empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
DEBUG: [HttpClient-1-Worker-1] [177s 223ms] SSL Reader(SocketTube(1)) DownstreamPusher: Pushing 826 bytes downstream
DEBUG: [HttpClient-1-Worker-1] [177s 223ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) Putting 826 bytes into the queue
DEBUG: [HttpClient-1-Worker-1] [177s 223ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) Got 826 bytes for delegate jdk.internal.net.http.Http1Response$BodyReader@558115d0/parser=jdk.internal.net.http.ResponseContent$ChunkedBodyParser@57db3286
DEBUG: [HttpClient-1-Worker-1] [177s 223ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) downstream subscription demand is 9223372036854775806
DEBUG: [HttpClient-1-Worker-1] [177s 223ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) Forwarding 826 bytes to delegate jdk.internal.net.http.Http1Response$BodyReader@558115d0/parser=jdk.internal.net.http.ResponseContent$ChunkedBodyParser@57db3286
DEBUG: [HttpClient-1-Worker-1] [177s 223ms] Http1Response(id=1, AsyncSSLTunnelConnection(SSLTube(SocketTube(1)))) Sending 826/1376 bytes to body parser
DEBUG: [HttpClient-1-Worker-1] [177s 223ms] AsyncSSLTunnelConnection(SSLTube(SocketTube(1)))/ResponseContent/ChunkedBodyParser Reading chunk: available 826, needed 819
DEBUG: [HttpClient-1-Worker-1] [177s 223ms] AsyncSSLTunnelConnection(SSLTube(SocketTube(1)))/ResponseContent/ChunkedBodyParser Returning chunk bytes: 819
DEBUG: [HttpClient-1-Worker-1] [177s 223ms] AsyncSSLTunnelConnection(SSLTube(SocketTube(1)))/ResponseContent/ChunkedBodyParser No more bytes to read - 0 yet to consume.
DEBUG: [HttpClient-1-Worker-1] [177s 223ms] AsyncSSLTunnelConnection(SSLTube(SocketTube(1)))/ResponseContent/ChunkedBodyParser Ready to read next chunk
DEBUG: [HttpClient-1-Worker-1] [177s 223ms] AsyncSSLTunnelConnection(SSLTube(SocketTube(1)))/ResponseContent/ChunkedBodyParser Sending chunk to consumer (819)
DEBUG: [HttpClient-1-Worker-1] [177s 223ms] AsyncSSLTunnelConnection(SSLTube(SocketTube(1)))/ResponseContent/ChunkedBodyParser Trying to read chunk len (remaining in buffer:5)
DEBUG: [HttpClient-1-Worker-1] [177s 223ms] AsyncSSLTunnelConnection(SSLTube(SocketTube(1)))/ResponseContent/ChunkedBodyParser Got chunk len 0
DEBUG: [HttpClient-1-Worker-1] [177s 223ms] AsyncSSLTunnelConnection(SSLTube(SocketTube(1)))/ResponseContent/ChunkedBodyParser Trying to consume bytes: 2 (remaining in buffer: 2)
DEBUG: [HttpClient-1-Worker-1] [177s 223ms] AsyncSSLTunnelConnection(SSLTube(SocketTube(1)))/ResponseContent/ChunkedBodyParser No more chunks: 0
DEBUG: [HttpClient-1-Worker-1] [177s 223ms] AsyncSSLTunnelConnection(SSLTube(SocketTube(1)))/ResponseContent/ChunkedBodyParser Chunks sent
DEBUG: [HttpClient-1-Worker-1] [177s 223ms] AsyncSSLTunnelConnection(SSLTube(SocketTube(1)))/ResponseContent/ChunkedBodyParser done!
DEBUG: [HttpClient-1-Worker-1] [177s 223ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) cleared
DEBUG: [HttpClient-1-Worker-1] [177s 223ms] Http1Response(id=1, AsyncSSLTunnelConnection(SSLTube(SocketTube(1)))) SSLTube(SocketTube(1)): return to HTTP/1.1 pool
DEBUG: [HttpClient-1-Worker-1] [177s 225ms] ConnectionPool(1) registering CleanupTrigger(SSLTube(SocketTube(1)))
DEBUG: [HttpClient-1-Worker-1] [177s 225ms] SSLTube(SocketTube(1)) connecting flows
DEBUG: [HttpClient-1-Worker-1] [177s 225ms] SSLTube(SocketTube(1)) SSLSubscriberWrapper (reader) got delegate: CleanupTrigger(SSLTube(SocketTube(1)))
DEBUG: [HttpClient-1-Worker-1] [177s 225ms] Http1Publisher(SSLTube(SocketTube(1))) subscription cancelled
DEBUG: [HttpClient-1-Worker-1] [177s 225ms] SSLTube(SocketTube(1)) setSubscription: demand=1, cancelled:false
DEBUG: [HttpClient-1-Worker-1] [177s 297ms] HttpClientImpl(1) ClientImpl (async) elapsed 1005 millis for GET to <URL is Hidden> 
DEBUG: [HttpClient-1-Worker-1] [177s 298ms] AsyncSSLTunnelConnection(SSLTube(SocketTube(1)))/ResponseContent/ChunkedBodyParser subscriber completed
DEBUG: [HttpClient-1-Worker-1] [177s 298ms] Http1Response(id=1, AsyncSSLTunnelConnection(SSLTube(SocketTube(1)))) Finished reading body: READING_BODY
DEBUG: [HttpClient-1-Worker-1] [177s 298ms] Http1Response(id=1, AsyncSSLTunnelConnection(SSLTube(SocketTube(1)))) Operation finished: decrementing ref count for jdk.internal.net.http.HttpClientImpl@41659a39(1)
DEBUG: [HttpClient-1-Worker-1] [177s 298ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) Delegate done: 0
DEBUG: [HttpClient-1-Worker-1] [177s 298ms] SSL Reader(SocketTube(1)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:1
DEBUG: [HttpClient-1-Worker-1] [177s 298ms] Http1AsyncReceiver(SSLTube(SocketTube(1))) Http1TubeSubscriber: dropSubscription
2020-05-28 09:28:03.525  WARN 1 --- [nio-4000-exec-4] l.n.proxy.handlers.ProxyRequestHandler   : RESPONSE OUT #65f3e430-525e-4546-86dc-20eb23f399f5
DEBUG: [HttpClient-1-Worker-1] [177s 298ms] SSL Reader(SocketTube(1)) DownstreamPusher: queue empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
DEBUG: [HttpClient-1-Worker-1] [177s 298ms] SSL Reader(SocketTube(1)) DownstreamPusher: queue empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
2020-05-28 09:28:03.529  WARN 1 --- [nio-4000-exec-4] l.n.proxy.handlers.PutToCacheHandler     : Adding to cache #65f3e430-525e-4546-86dc-20eb23f399f5
2020-05-28 09:28:03.533  WARN 1 --- [nio-4000-exec-4] l.n.proxy.handlers.PutToCacheHandler     : Save conditions passed for #65f3e430-525e-4546-86dc-20eb23f399f5
2020-05-28 09:28:03.559  WARN 1 --- [nio-4000-exec-4] lt.northstar.proxy.Endpoint              : Returning GET '<URL is Hidden>' with 200 OK #65f3e430-525e-4546-86dc-20eb23f399f5

--------------------------------------------------------------------------------------------------------------------------------------
----------------------------------------------GOES INTO LOOP--------------------------------------------------------------------------
--------------------------------------------------------------------------------------------------------------------------------------

DEBUG: [HttpClient-1-SelectorManager] [192s 155ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@2bf8cf41 for 0 (false)
DEBUG: [HttpClient-1-SelectorManager] [192s 155ms] SocketTube(1) read bytes: 24
DEBUG: [HttpClient-1-SelectorManager] [192s 155ms] SSL Reader(SocketTube(1)) onNext
DEBUG: [HttpClient-1-SelectorManager] [192s 155ms] SSL Reader(SocketTube(1)) Adding 24 bytes to read buffer
DEBUG: [HttpClient-1-SelectorManager] [192s 155ms] SSL Reader(SocketTube(1)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:0
DEBUG: [HttpClient-1-SelectorManager] [192s 155ms] SSL Reader(SocketTube(1)) requesting 1
DEBUG: [HttpClient-1-SelectorManager] [192s 155ms] SocketTube(1) got some demand for reading
DEBUG: [HttpClient-1-SelectorManager] [192s 155ms] SocketTube(1) resuming read event
DEBUG: [HttpClient-1-SelectorManager] [192s 155ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@2bf8cf41 for 1 (false)
DEBUG: [HttpClient-1-SelectorManager] [192s 155ms] SocketTube(1) leaving request(1):  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
DEBUG: [HttpClient-1-SelectorManager] [192s 156ms] SocketTube(1) resuming read event
DEBUG: [HttpClient-1-SelectorManager] [192s 156ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@2bf8cf41 for 1 (false)
DEBUG: [HttpClient-1-SelectorManager] [192s 156ms] SocketTube(1) leaving read() loop after onNext:  Reading: [ops=1, demand=1, stopped=false], Writing: [ops=0, demand=1]
DEBUG: [HttpClient-1-SelectorManager] [192s 156ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@2bf8cf41 for 0 (false)
DEBUG: [HttpClient-1-SelectorManager] [192s 156ms] SocketTube(1) got read EOF
DEBUG: [HttpClient-1-SelectorManager] [192s 156ms] SocketTube(1) pausing read event
DEBUG: [HttpClient-1-Worker-1] [192s 159ms] SSL Reader(SocketTube(1)) processData: readBuf remaining:24, state: NOT_HANDSHAKING , engine handshake status:NOT_HANDSHAKING
DEBUG: [HttpClient-1-Worker-1] [192s 159ms] SSL Reader(SocketTube(1)) Unwrapping: 24
DEBUG: [HttpClient-1-SelectorManager] [192s 159ms] SelectorAttachment Registering jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent@2bf8cf41 for 0 (false)
DEBUG: [HttpClient-1-SelectorManager] [192s 159ms] SocketTube(1) completing subscriber
DEBUG: [HttpClient-1-Worker-1] [192s 162ms] SSLFlowDelegate(SocketTube(1)) doClosure(Status = CLOSED HandshakeStatus = NEED_WRAP
bytesConsumed = 24 bytesProduced = 0): NEED_WRAP [isOutboundDone: false, isInboundDone: true]
DEBUG: [HttpClient-1-Worker-1] [192s 162ms] SSLFlowDelegate(SocketTube(1)) doClosure: close_notify received
DEBUG: [HttpClient-1-Worker-1] [192s 162ms] SSL Writer(SocketTube(1)) processData, writeList remaining:0, hsTriggered:true, needWrap:true
DEBUG: [HttpClient-1-Worker-1] [192s 162ms] SSL Writer(SocketTube(1)) wrapping 0 bytes
DEBUG: [HttpClient-1-Worker-1] [192s 162ms] SSL Writer(SocketTube(1)) SSLResult: Status = OK HandshakeStatus = NEED_WRAP
bytesConsumed = 0 bytesProduced = 0
DEBUG: [HttpClient-1-Worker-1] [192s 162ms] SSL Writer(SocketTube(1)) OK => produced: 0 bytes into 0, not wrapped: 0
DEBUG: [HttpClient-1-Worker-1] [192s 162ms] SSL Writer(SocketTube(1)) wrapBuffer returned Status = OK HandshakeStatus = NEED_WRAP
bytesConsumed = 0 bytesProduced = 0
DEBUG: [HttpClient-1-Worker-1] [192s 162ms] SSL Writer(SocketTube(1)) handshaking
DEBUG: [HttpClient-1-Worker-1] [192s 162ms] SSL Writer(SocketTube(1)) wrapping 0 bytes
DEBUG: [HttpClient-1-Worker-1] [192s 162ms] SSL Writer(SocketTube(1)) SSLResult: Status = OK HandshakeStatus = NEED_WRAP
bytesConsumed = 0 bytesProduced = 0
DEBUG: [HttpClient-1-Worker-1] [192s 162ms] SSL Writer(SocketTube(1)) OK => produced: 0 bytes into 0, not wrapped: 0
DEBUG: [HttpClient-1-Worker-1] [192s 162ms] SSL Writer(SocketTube(1)) wrapBuffer returned Status = OK HandshakeStatus = NEED_WRAP
bytesConsumed = 0 bytesProduced = 0
DEBUG: [HttpClient-1-Worker-1] [192s 162ms] SSL Writer(SocketTube(1)) handshaking
DEBUG: [HttpClient-1-Worker-1] [192s 162ms] SSL Writer(SocketTube(1)) wrapping 0 bytes
DEBUG: [HttpClient-1-Worker-1] [192s 162ms] SSL Writer(SocketTube(1)) SSLResult: Status = OK HandshakeStatus = NEED_WRAP
bytesConsumed = 0 bytesProduced = 0
DEBUG: [HttpClient-1-Worker-1] [192s 162ms] SSL Writer(SocketTube(1)) OK => produced: 0 bytes into 0, not wrapped: 0
DEBUG: [HttpClient-1-Worker-1] [192s 162ms] SSL Writer(SocketTube(1)) wrapBuffer returned Status = OK HandshakeStatus = NEED_WRAP
bytesConsumed = 0 bytesProduced = 0
DEBUG: [HttpClient-1-Worker-1] [192s 162ms] SSL Writer(SocketTube(1)) handshaking
DEBUG: [HttpClient-1-Worker-1] [192s 162ms] SSL Writer(SocketTube(1)) wrapping 0 bytes
DEBUG: [HttpClient-1-Worker-1] [192s 162ms] SSL Writer(SocketTube(1)) SSLResult: Status = OK HandshakeStatus = NEED_WRAP
bytesConsumed = 0 bytesProduced = 0
.........................

1 Ответ

1 голос
/ 28 мая 2020

Скорее всего, это JDK-8214418, который был исправлен в JDK 12. Он также был перенесен на Oracle JDK 11.0.4. Проблема не видна напрямую, но вы должны найти всю информацию в ветке обзора publi c здесь: http://mail.openjdk.java.net/pipermail/security-dev/2019-January/019142.html

...