程序员经验分享-hwhale

间歇性 java.io.IOException：来自 Amazon EC2 内部的 jdk.internal.net.http.HttpClientImpl.send 中的连接重置（不是对等方重置的连接）

2024-01-11

在 Amazon EC2 中使用 openjdk 14.0.1 我遇到间歇性问题java.io.IOException: Connection reset当通过 https 使用 POST 请求访问外部 REST 服务时。在 EC2 之外不会发生这种情况。

它会在短时间不活动后发生一次，并在再次调用 REST 服务后解决。重复冲洗。

使用类似的负载直接通过curl 访问外部REST 服务不会发生该错误，只有在JVM 内部短暂不活动后才会发生该错误。

我一直关注连接池jdk.internal.net.http.Http2ClientImpl。我的理论是从池中拾取一个陈旧的连接，但我没有具体的证据证明这一点。

也许是别的东西。可能是什么原因造成的？

与此同时，我已经将 HTTP 客户端更换为 Apache 产品，到目前为止，效果还不错。

堆栈跟踪：

java.io.IOException: Connection reset
    at java.net.http/jdk.internal.net.http.HttpClientImpl.send(HttpClientImpl.java:576)
    at java.net.http/jdk.internal.net.http.HttpClientFacade.send(HttpClientFacade.java:119)
    at Main.main(Main.java:201)
Caused by: java.net.SocketException: Connection reset
    at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:345)
    at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:376)
    at java.net.http/jdk.internal.net.http.SocketTube.readAvailable(SocketTube.java:1153)
    at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:821)
    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.signalReadable(SocketTube.java:763)
    at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent.signalEvent(SocketTube.java:941)
    at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowEvent.handle(SocketTube.java:245)
    at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.handleEvent(HttpClientImpl.java:968)
    at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.lambda$run$3(HttpClientImpl.java:923)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1510)
    at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:923)
java.io.IOException: Connection reset
    at java.net.http/jdk.internal.net.http.HttpClientImpl.send(HttpClientImpl.java:576)
    at java.net.http/jdk.internal.net.http.HttpClientFacade.send(HttpClientFacade.java:119)
    at Main.main(Main.java:201)
Caused by: java.net.SocketException: Connection reset
    at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:345)
    at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:376)
    at java.net.http/jdk.internal.net.http.SocketTube.readAvailable(SocketTube.java:1153)
    at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:821)
    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.signalReadable(SocketTube.java:763)
    at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent.signalEvent(SocketTube.java:941)
    at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowEvent.handle(SocketTube.java:245)
    at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.handleEvent(HttpClientImpl.java:968)
    at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.lambda$run$3(HttpClientImpl.java:923)
    at java.base/java.util.ArrayList.forEach(ArrayList.java:1510)
    at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:923)

经过大量调试：

DEBUG: [qtp1724731843-13] [1810s 799ms] AsyncSSLConnection(SSLTube(SocketTube(1))) HttpPublisher: sending 1646 bytes (2 buffers) to SSLTube(SocketTube(1))
DEBUG: [qtp1724731843-13] [1810s 800ms] SSLTube(SocketTube(1)) sending 2  buffers to SSL flow delegate
DEBUG: [qtp1724731843-13] [1810s 800ms] SSL Writer(SocketTube(1)) onNext
DEBUG: [qtp1724731843-13] [1810s 800ms] SSL Writer(SocketTube(1)) added 2 (1646 bytes) to the writeList
DEBUG: [qtp1724731843-13] [1810s 800ms] SSL Writer(SocketTube(1)) processData, writeList remaining:1646, hsTriggered:false, needWrap:false
DEBUG: [qtp1724731843-13] [1810s 800ms] SSL Writer(SocketTube(1)) wrapping 1646 bytes
DEBUG: [qtp1724731843-13] [1810s 800ms] SSL Writer(SocketTube(1)) SSLResult: Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 1646 bytesProduced = 1684 sequenceNumber = 20
DEBUG: [qtp1724731843-13] [1810s 800ms] SSL Writer(SocketTube(1)) OK => produced: 1684 bytes into 1688, not wrapped: 0
DEBUG: [qtp1724731843-13] [1810s 800ms] SSL Writer(SocketTube(1)) wrapBuffer returned Status = OK HandshakeStatus = NOT_HANDSHAKING
bytesConsumed = 1646 bytesProduced = 1684 sequenceNumber = 20
DEBUG: [qtp1724731843-13] [1810s 800ms] SSL Writer(SocketTube(1)) Sending 1684 bytes downstream
DEBUG: [qtp1724731843-13] [1810s 800ms] SSL Writer(SocketTube(1)) Adding 1684 to outputQ queue
DEBUG: [qtp1724731843-13] [1810s 800ms] SSL Writer(SocketTube(1)) pushScheduler is alive
DEBUG: [qtp1724731843-13] [1810s 800ms] SSL Writer(SocketTube(1)) DownstreamPusher: queue not empty, downstreamSubscription: SubscriptionBase: window = 1 cancelled = false
DEBUG: [qtp1724731843-13] [1810s 800ms] SSL Writer(SocketTube(1)) DownstreamPusher: Pushing 1684 bytes downstream
DEBUG: [qtp1724731843-13] [1810s 800ms] SocketTube(1) trying to write: 1684
DEBUG: [qtp1724731843-13] [1810s 807ms] SocketTube(1) write error: java.io.IOException: Broken pipe
DEBUG: [qtp1724731843-13] [1810s 808ms] SocketTube(1) error signalled java.io.IOException: Broken pipe
DEBUG: [qtp1724731843-13] [1810s 808ms] SocketTube(1) write: cancel
DEBUG: [qtp1724731843-13] [1810s 808ms] SocketTube(1) write: resetting demand to 0
DEBUG: [qtp1724731843-13] [1810s 808ms] AsyncSSLConnection(SSLTube(SocketTube(1))) HttpPublisher: cancelled by SSLTube(SocketTube(1))
DEBUG: [HttpClient-1-SelectorManager] [1810s 809ms] SocketTube(1) Sending error java.net.SocketException: Connection reset to subscriber READER: SubscriberWrapper: upstreamCompleted: false upstreamWindow: 1 downstreamCompleted: false completionAcknowledged: false outputQ size: 0 cf: jdk.internal.net.http.common.MinimalFuture@e19f43d[Not completed, 4 dependents] (id=21) downstreamSubscription: SubscriptionBase: window = 9223372036854775778 cancelled = false downstreamSubscriber: SSLSubscriberWrapper[SSLTube(SocketTube(1)), delegate: DelegateWrapper[subscribedCalled: true, subscribedDone: true, completed: false, error: null]: jdk.internal.net.http.Http2Connection$Http2TubeSubscriber@6500fba3, getALPN: jdk.internal.net.http.common.MinimalFuture@7dbd5c04[Completed normally] (id=27), onCompleteReceived: false, onError: null], readBuf: java.nio.HeapByteBuffer[pos=1618 lim=1618 cap=4096], count: 14238, scheduler: running, status: OK, handshakeState: 0, engine: NOT_HANDSHAKING
DEBUG: [HttpClient-1-SelectorManager] [1810s 809ms] SocketTube(1) forwarding error to subscriber: java.net.SocketException: Connection reset
DEBUG: [HttpClient-1-SelectorManager] [1810s 809ms] SSL Reader(SocketTube(1)) onError: java.net.SocketException: Connection reset
DEBUG: [HttpClient-1-SelectorManager] [1810s 809ms] SSL Reader(SocketTube(1)) error java.net.SocketException: Connection reset
DEBUG: [qtp1724731843-13] [1810s 810ms] SocketTube(1) leaving w.onNext Reading: [ops=0, demand=0, stopped=false], Writing: [ops=0, demand=0]
DEBUG: [qtp1724731843-13] [1810s 810ms] SSL Writer(SocketTube(1)) upstreamWindowUpdate, downstreamQueueSize:0, upstreamWindow:0
DEBUG: [qtp1724731843-13] [1810s 810ms] SSL Writer(SocketTube(1)) requesting 1
DEBUG: [qtp1724731843-13] [1810s 810ms] SSLTube(SocketTube(1)) request: n=1
DEBUG: [qtp1724731843-13] [1810s 810ms] AsyncSSLConnection(SSLTube(SocketTube(1))) HttpPublisher: got request of 1 from SSLTube(SocketTube(1))
DEBUG: [qtp1724731843-13] [1810s 810ms] Http2Connection(SSLTube(SocketTube(1)))/Stream(19) trySend: request 1
DEBUG: [qtp1724731843-13] [1810s 811ms] Http2Connection(SSLTube(SocketTube(1)))/Stream(19) RequestSubscriber: onComplete
java.net.SocketException: Connection reset
        at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:345)
        at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:376)
        at java.net.http/jdk.internal.net.http.SocketTube.readAvailable(SocketTube.java:1153)
        at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:821)
        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.signalReadable(SocketTube.java:763)
        at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent.signalEvent(SocketTube.java:941)

使用 for 循环我开始发送请求i分钟从 1 分钟开始。这是我在 6 分钟时得到的结果：

Sleeping for 360000
Request sent:2020-08-30T16:20:29.467902
Exception caught:2020-08-30T16:20:29.492103
java.io.IOException: Connection reset
        at java.net.http/jdk.internal.net.http.HttpClientImpl.send(HttpClientImpl.java:576)
        at java.net.http/jdk.internal.net.http.HttpClientFacade.send(HttpClientFacade.java:119)
        at Main.main(Main.java:207)
Caused by: java.net.SocketException: Connection reset
        at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:345)
        at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:376)
        at java.net.http/jdk.internal.net.http.SocketTube.readAvailable(SocketTube.java:1153)
        at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:821)
        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.signalReadable(SocketTube.java:763)
        at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent.signalEvent(SocketTube.java:941)
        at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowEvent.handle(SocketTube.java:245)
        at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.handleEvent(HttpClientImpl.java:968)
        at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.lambda$run$3(HttpClientImpl.java:923)
        at java.base/java.util.ArrayList.forEach(ArrayList.java:1510)
        at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:923)
java.io.IOException: Connection reset
        at java.net.http/jdk.internal.net.http.HttpClientImpl.send(HttpClientImpl.java:576)
        at java.net.http/jdk.internal.net.http.HttpClientFacade.send(HttpClientFacade.java:119)
        at Main.main(Main.java:207)
Caused by: java.net.SocketException: Connection reset
        at java.base/sun.nio.ch.SocketChannelImpl.throwConnectionReset(SocketChannelImpl.java:345)
        at java.base/sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:376)
        at java.net.http/jdk.internal.net.http.SocketTube.readAvailable(SocketTube.java:1153)
        at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$InternalReadSubscription.read(SocketTube.java:821)
        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.signalReadable(SocketTube.java:763)
        at java.net.http/jdk.internal.net.http.SocketTube$InternalReadPublisher$ReadEvent.signalEvent(SocketTube.java:941)
        at java.net.http/jdk.internal.net.http.SocketTube$SocketFlowEvent.handle(SocketTube.java:245)
        at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.handleEvent(HttpClientImpl.java:968)
        at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.lambda$run$3(HttpClientImpl.java:923)
        at java.base/java.util.ArrayList.forEach(ArrayList.java:1510)
        at java.net.http/jdk.internal.net.http.HttpClientImpl$SelectorManager.run(HttpClientImpl.java:923)

这让我发现这个问题 https://github.com/psf/requests/issues/3808这说明该问题是由默认 AWS NAT 网关行为引起的。从the docs https://docs.aws.amazon.com/vpc/latest/userguide/vpc-nat-comparison.html:

超时行为

当连接超时时，NAT网关返回RST报文 NAT 网关后面尝试继续执行的任何资源 连接（它不发送 FIN 数据包）。

我可以将其视为 tcpdump 中的最后一个事件：

IP 111.11.11.11.https > ip-11-111-11-11.eu-west-1.compute.internal.11111: Flags [R], seq 4144024018, win 637, length 0

在 AWS 之外，我收到 FIN 数据包：

IP 111.11.11.11.https > ip-11-111-11-11.eu-west-1.compute.internal.11111: Flags [F.], seq 5972, ack 7484, win 86, length 0

我尝试设置jdk.httpclient.keepalive.timeout基于本文 https://www.programmersought.com/article/2621640094/但这并不能解决问题。阿帕奇就是这样。

Here's 另一个相关线程 https://forums.aws.amazon.com/thread.jspa?threadID=222925时间可以追溯到2016年。

Update

我开始思考，Apache 正在变得干净，因为它没有使用开箱即用的池化。我发现org.apache.http.impl.conn.PoolingHttpClientConnectionManager并开始重现问题。也炸了：

Exception in thread "main" javax.net.ssl.SSLException: Connection reset
        at java.base/sun.security.ssl.Alert.createSSLException(Alert.java:127)
        at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:325)
        at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:268)
        at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:263)
        at java.base/sun.security.ssl.SSLSocketImpl.handleException(SSLSocketImpl.java:1654)
        at java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:1038)
        at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:137)
        at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:153)
        at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:280)
        at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:138)
        at org.apache.http.impl.conn.DefaultHttpResponseParser.parseHead(DefaultHttpResponseParser.java:56)
        at org.apache.http.impl.io.AbstractMessageParser.parse(AbstractMessageParser.java:259)
        at org.apache.http.impl.DefaultBHttpClientConnection.receiveResponseHeader(DefaultBHttpClientConnection.java:163)
        at org.apache.http.impl.conn.CPoolProxy.receiveResponseHeader(CPoolProxy.java:157)
        at org.apache.http.protocol.HttpRequestExecutor.doReceiveResponse(HttpRequestExecutor.java:273)
        at org.apache.http.protocol.HttpRequestExecutor.execute(HttpRequestExecutor.java:125)
        at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:272)
        at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:186)
        at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)
        at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)
        at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)
        at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:108)
        at Main.main(Main.java:226)
        Suppressed: java.net.SocketException: Broken pipe
                at java.base/sun.nio.ch.NioSocketImpl.implWrite(NioSocketImpl.java:420)
                at java.base/sun.nio.ch.NioSocketImpl.write(NioSocketImpl.java:440)
                at java.base/sun.nio.ch.NioSocketImpl$2.write(NioSocketImpl.java:826)
                at java.base/java.net.Socket$SocketOutputStream.write(Socket.java:1052)
                at java.base/sun.security.ssl.SSLSocketOutputRecord.encodeAlert(SSLSocketOutputRecord.java:82)
                at java.base/sun.security.ssl.TransportContext.fatal(TransportContext.java:356)
                ... 22 more
Caused by: java.net.SocketException: Connection reset
        at java.base/sun.nio.ch.NioSocketImpl.implRead(NioSocketImpl.java:323)
        at java.base/sun.nio.ch.NioSocketImpl.read(NioSocketImpl.java:350)
        at java.base/sun.nio.ch.NioSocketImpl$1.read(NioSocketImpl.java:803)
        at java.base/java.net.Socket$SocketInputStream.read(Socket.java:982)
        at java.base/sun.security.ssl.SSLSocketInputRecord.read(SSLSocketInputRecord.java:457)
        at java.base/sun.security.ssl.SSLSocketInputRecord.bytesInCompletePacket(SSLSocketInputRecord.java:68)
        at java.base/sun.security.ssl.SSLSocketImpl.readApplicationRecord(SSLSocketImpl.java:1411)
        at java.base/sun.security.ssl.SSLSocketImpl$AppInputStream.read(SSLSocketImpl.java:1022)
        ... 18 more

我的结论是 AWS NAT 网关做错了事情。

本文内容由网友自发贡献，版权归原作者所有，本站不承担相应法律责任。如您发现有涉嫌抄袭侵权的内容，请联系:hwhale#tublm.com(使用前将#替换为@)

Java

amazonec2

间歇性 java.io.IOException：来自 Amazon EC2 内部的 jdk.internal.net.http.HttpClientImpl.send 中的连接重置（不是对等方重置的连接） 的相关文章

随机推荐

热门标签