间歇性java.io.IOException:从Amazon EC2内部的jdk.internal.net.http.H



在AmazonEC2中使用openjdk 14.0.1,当通过https发出POST请求时,我遇到了一个间歇性的java.io.IOException: Connection reset。在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循环,我开始从1分钟开始,每i分钟发送一次请求。这是我在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)

这让我发现了这个问题,解释了这个问题是由默认的AWS NAT网关行为引起的。来自文档:

超时行为

当连接超时时,NAT网关向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,但它并没有解决问题。是Apache。

这是另一个可以追溯到2016年的相关线索。

更新

我开始思考,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网关做了错误的事情。

最新更新