【发布时间】:2018-01-03 11:42:38
【问题描述】:
我在 HTTP2 上使用 Jersey。当流量变得有点高时,就会引发异常。我让 pcap 发现服务器发送 FIN/ACK 而没有收到 FIN。我不确定从服务器端关闭连接是否是单个 FIN。或单个 FIN 将 ACK 组合到先前的数据包。它看起来是后者,因为客户端没有发送 FIN。所以问题是为什么服务器只在小流量下发送FIN。而且我发现rece_q 和send_q 非常低。 CPU使用率不是那么高。我已经调整了一些 TCP 参数,结果是一样的。这种行为是不稳定的,有时可以,有时不行。当我添加更多请求(具有相同的 TPS)时就不行了。它看起来服务器完成了连接,但不知道确切的原因。它与HTTP2有关吗?我们有什么地方可以看到确切的原因吗?
以下是 pcap 快照。
2017-07-30 更新 调试日志:
Sun Jul 30, 2017 8:31:35.591 PM org.glassfish.grizzly.http2.Http2FrameCodec parse
FINE: Rx [2]: connection=TCPNIOConnection{localSocketAddress={localhost/127.0.0.1:80}, peerSocketAddress={/127.0.0.1:57802}}, frame=DataFrame {streamId=277, type=0, flags=[none], length=42, data=BuffersBuffer (154351355) [pos=0 lim=42 cap=42 bufferSize=1 buffers=[HeapBuffer (165674143) [pos=0 lim=42 cap=8391], null, null, null]]}
Sun Jul 30, 2017 8:31:35.673 PM org.glassfish.grizzly.http2.Http2BaseFilter processFrames
FINE: Http2ConnectionException occurred on connection=TCPNIOConnection{localSocketAddress={localhost/127.0.0.1:80}, peerSocketAddress={/127.0.0.1:57802}} during Http2Frame processing
Sun Jul 30, 2017 8:31:35.684 PM org.glassfish.grizzly.http2.Http2FrameCodec serializeAndRecycle
FINE: Tx: connection=TCPNIOConnection{localSocketAddress={localhost/127.0.0.1:80}, peerSocketAddress={/127.0.0.1:57802}}, frame=GoAwayFrame {streamId=0, type=7, flags=[none], length=64{lastStreamId=199, errorCode=REFUSED_STREAM}
以及 pcap 快照中的流 277
pcap contains stream 277 from No 270,271 and 272
269包中有一个SETTINGS包。运输途中发送SETTINGS是否正常?而在269之后,有3个包270271和272正在使用steam 277。
奇怪的是在 8:31:35.684 左右我没有找到 GOWAY 数据包。但仅在 8:31:36.035 发送 RST/ACK。调试日志如下:
Sun Jul 30, 2017 8:31:36.020 PM org.glassfish.grizzly.http2.Http2FrameCodec parse
FINE: Rx [2]: connection=TCPNIOConnection{localSocketAddress={localhost/127.0.0.1:80}, peerSocketAddress={/127.0.0.1:57802}}, frame=DataFrame {streamId=465, type=0, flags=[END_STREAM], length=0, data=ByteBufferWrapper (1101850112) [visible=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]]]}
Sun Jul 30, 2017 8:31:36.023 PM org.glassfish.grizzly.http2.Http2BaseFilter processDataFrame
FINE: Data frame received for non-existent stream: connection=TCPNIOConnection{localSocketAddress={localhost/127.0.0.1:80}, peerSocketAddress={/127.0.0.1:57802}}, frame=DataFrame {streamId=277, type=0, flags=[END_STREAM], length=0, data=ByteBufferWrapper (1101850112) [visible=[java.nio.HeapByteBuffer[pos=0 lim=0 cap=0]]]}, stream=277
Sun Jul 30, 2017 8:31:36.024 PM org.glassfish.grizzly.http2.Http2BaseFilter processFrames
FINE: Http2StreamException occurred on connection=TCPNIOConnection{localSocketAddress={localhost/127.0.0.1:80}, peerSocketAddress={/127.0.0.1:57802}} during Http2Frame processing
Sun Jul 30, 2017 8:31:36.025 PM org.glassfish.grizzly.http2.Http2BaseFilter processFrames
FINE: Http2ConnectionException occurred on connection=TCPNIOConnection{localSocketAddress={localhost/127.0.0.1:80}, peerSocketAddress={/127.0.0.1:57802}} during Http2Frame processing
日志显示收到一个不存在的流 277。这个流正是第一个日志中记录的流。不确定此蒸汽 277 在接下来的几毫秒内会导致 RST/ACK。我觉得应该是269~272包和277码流有问题。
顺便说一句,这次没有 FIN/ACK。
【问题讨论】:
-
8:31:35.591 处的日志行似乎表明
HEADERS帧以某种方式被解析为流 277,但显然没有成功,导致GOAWAY。您是否尝试过FINEST日志记录级别?也许它有更多的迹象表明出了什么问题。另外,您是否尝试过其他实现,例如 Jetty HTTP/2(免责声明,我是 Jetty HTTP/2 维护者)? -
其实我不知道如何在 Jersey 上注入和配置 Jetty HTTP/2。我只能在 Jersey 上找到非常有限的 HTTP/2 容器使用。如果您能提供更多关于此的信息,我们将不胜感激。谢谢。
-
我已将日志设置为 FINEST,看起来一样,处理错误然后发送 GoAwayFrame。最后在 pcap 处发送 RST/ACK。但是我在今天的 pcap 和昨天的 pcap 中发现了另一件奇怪的事情。服务器产量在发送 RST/ACK 之前没有响应,而且响应很大,但不包括所有预期的响应。昨天的 pcap 甚至除了给客户端的一个 RST/ACK 包外,没有任何响应。
-
@sbordet 看起来这个问题与客户端和服务器的行为有关,当我将请求数增加到 1000(每个请求等待 5ms)时,只有客户端发送请求但没有响应服务器直到 RST。但是当我将请求数减少到100时,客户端和服务器经常ping-pang并没有问题。