【问题标题】:HTTP2 Server send FIN/ACK and then RST without tremendous trafficHTTP2 服务器发送 FIN/ACK 然后 RST 没有巨大的流量
【发布时间】: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 快照。

pcap snapshot


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并没有问题。

标签: tcp jersey http2


【解决方案1】:

pcap 显示服务器异常终止。

您应该查看服务器日志以了解有关发生这种情况的更多详细信息。

一个可能的原因是服务器错误。

另一个可能的原因是客户端在数据包 14 处发送了无效的HEADERS 帧;不过,服务器应该发送一个GOAWAY 帧,而不仅仅是关闭连接。

17号包的RST是正常的,因为客户端在处理FIN之前在16号包发送了HEADERS帧,所以服务器回复了RST表示发送的数据没有成功到用户代码层。

服务器日志(可能在 DEBUG 级别)应该会告诉您更多关于发生的事情。

【讨论】:

  • 我会试试看,稍后再回复你。
  • 我已经更新了调试日志和一些发现。能不能帮忙看看。谢谢。
猜你喜欢
  • 2012-08-18
  • 1970-01-01
  • 2011-06-16
  • 1970-01-01
  • 2016-09-19
  • 2015-02-26
  • 2019-06-09
  • 2013-08-11
  • 2012-07-27
相关资源
最近更新 更多