New issue
Advanced search Search tips

Issue 784975 link

Starred by 1 user

Issue metadata

Status: Fixed
Owner:
Closed: Nov 2017
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Linux , Android , Windows , iOS , Chrome , Mac , Fuchsia
Pri: 3
Type: Bug



Sign in to add a comment

SpdySession connection detection using PING is unreliable

Project Member Reported by b...@chromium.org, Nov 14 2017

Issue description

It is possible that SpdySession does not detect that a connection is not available for a long time even though it does not receive a PING acknowledgement from the server.  It is also possible that SpdySession incorrectly thinks the connection is not available.  Reported by Tao Yiyuan at https://groups.google.com/a/chromium.org/forum/#!topic/net-dev/ihzrC5c-NnU:

"In file spdy_session.cc, there is a problem if update |last_activity_time_| at SpdySession::DoWriteComplete().
If the connection is not available, while the client continues to send data to the server and update |last_activity_time_| when DoWriteComplete(), SpdySession::CheckPingStatus() will be long delayed. Ping frame can not detect the availability of connection in |hung_interval_| seconds,it may be after 2 minutes, spdy session waits for the TCP socket data read timeout to discover the current connection is not available.

So I propose to delete the code |last_activity_time_ = time_func_();|, but there is another concern here. If set |connection_at_risk_of_loss_time_| and |hung_interval_| to 10 seconds, imagine the scene: we send a ping to server and  instantly receive the ping ack, but CheckPingStatus()  will be executed after 10 seconds. If we happen to send data to sever after 10 seconds, WritePingFrame() will be executed too. If WritePingFrame() comes first, and then CheckPingStatus() flows. In case of the ping ack has not received, the value of |pings_in_flight_| is 1 and the connection is idle more than 10 seconds, CheckPingStatus() will DoDrainSession(), but the connection is still alive.

So I suggest to set |connection_at_risk_of_loss_time_| longer than |hung_interval_| to avoid that problem,  How do folks feel about this?"
 
Project Member

Comment 1 by bugdroid1@chromium.org, Nov 21 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/8381b6e1f7fb5c0cf1245f6bdd0b4d78f00e1a6b

commit 8381b6e1f7fb5c0cf1245f6bdd0b4d78f00e1a6b
Author: Bence Béky <bnc@chromium.org>
Date: Tue Nov 21 17:26:40 2017

Do not update last_activity_time_ in SpdySession::DoWriteComplete().

|last_activity_time_| is used to determine if a PING should be sent out
on an HTTP/2 connection.  The relevant measurement for this is the time
of the last read.  If |last_activity_time_| is also updated on writes,
then it is possible that a connection times out but SpdySession is not
sending any PING frames to check for this for a very long time.

This CL removes the |last_activity_time_| update from
SpdySession::DoWriteComplete(), and renames |last_activity_time_| to
|last_read_time_| to better express its function.

Bug:  784975 
Change-Id: I821cc5145f44557dd3f694833314336bb21f9608
Reviewed-on: https://chromium-review.googlesource.com/779740
Reviewed-by: Ryan Hamilton <rch@chromium.org>
Commit-Queue: Bence Béky <bnc@chromium.org>
Cr-Commit-Position: refs/heads/master@{#518290}
[modify] https://crrev.com/8381b6e1f7fb5c0cf1245f6bdd0b4d78f00e1a6b/net/spdy/chromium/spdy_session.cc
[modify] https://crrev.com/8381b6e1f7fb5c0cf1245f6bdd0b4d78f00e1a6b/net/spdy/chromium/spdy_session.h
[modify] https://crrev.com/8381b6e1f7fb5c0cf1245f6bdd0b4d78f00e1a6b/net/spdy/chromium/spdy_session_unittest.cc

Project Member

Comment 2 by bugdroid1@chromium.org, Nov 29 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromium/src.git/+/f5d8ece50864fc3e7278c33cd1b450bf2cb01128

commit f5d8ece50864fc3e7278c33cd1b450bf2cb01128
Author: Bence Béky <bnc@chromium.org>
Date: Wed Nov 29 16:47:02 2017

Do not send HTTP/2 PING if there is a CheckPingStatus() posted.

Do not send HTTP/2 PING if there is a CheckPingStatus() posted on the
message loop, because it might get confused about which PING to expect a
response to.

Imagine the following scenario:
* SpdySession sends out a preface PING then a request.
* A CheckPingStatus() is posted on the message loop with delay.
* SpdySession receives PING ACK right away.
* Later, SpdySession sends out another preface PING then another
  request.
* CheckPingStatus() gets executed shortly after.  |last_activity_time_|
  is when the first ACK was received.  CheckPingStatus() sees that there
  is an outstanding PING, and thinks that it timed out (even though it
  was just sent), so it tears down the connection.

One could make the argument that this is impossible with the current
values of kDefaultConnectionAtRiskOfLossSeconds and kHungIntervalSeconds
(or at least very unlikely, depending on how much one trusts
PostDelayedTask() timing), but that is not very transparent.

This CL introduces two functional changes.  The first one is that it
returns early from SendPrefacePingIfNoneInFlight() (freshly renamed to
MaybeSendPrefacePing) if |check_ping_status_pending_|.  There is little
harm in not sending another preface PING within kHungIntervalSeconds
(10 seconds) since the last preface PING was sent.

The other functional change is only increment PING opaque data by one
with each PING frame.  "Receivers of a PING frame that does not include
an ACK flag MUST send a PING frame with the ACK flag set in response,
with an identical payload." according to RFC7540 Section 6.7, so this
is acceptable.

This CL also does some cleanup: rename SendPrefacePingIfNoneInFlight()
to MaybeSendPrefacePing(), shuffle around some base::Time and
base::TimeDelta in inequalities for easier readability, improve
comments, inline SendPrefacePing(), and sharpen some expectations in
unit tests.

Bug:  784975 
Change-Id: Ic278ea87041120443fc73304d266b2f7a4eb54a2
Reviewed-on: https://chromium-review.googlesource.com/779670
Reviewed-by: Helen Li <xunjieli@chromium.org>
Commit-Queue: Bence Béky <bnc@chromium.org>
Cr-Commit-Position: refs/heads/master@{#520140}
[modify] https://crrev.com/f5d8ece50864fc3e7278c33cd1b450bf2cb01128/net/spdy/chromium/spdy_session.cc
[modify] https://crrev.com/f5d8ece50864fc3e7278c33cd1b450bf2cb01128/net/spdy/chromium/spdy_session.h
[modify] https://crrev.com/f5d8ece50864fc3e7278c33cd1b450bf2cb01128/net/spdy/chromium/spdy_session_unittest.cc

Comment 3 by b...@chromium.org, Nov 30 2017

Status: Fixed (was: Assigned)

Sign in to add a comment