Bug 1426366 - Detect http transaction stalls with TFO. r=hurley

modules/libpref/init/all.js

@@ -4784,6 +4784,16 @@ pref("network.tcp.keepalive.probe_count", 4);
 
 pref("network.tcp.tcp_fastopen_enable", false);
 pref("network.tcp.tcp_fastopen_consecutive_failure_limit", 5);
+// We are trying to detect stalled tcp connections that use TFO and TLS
+// (bug 1395494).
+// This is only happening if a connection is idle for more than 10s, but we
+// will make this a pref. If tcp_fastopen_http_stalls_limit of stalls are
+// detected the TCP fast open will be disabled.
+// If tcp_fastopen_http_check_for_stalls_only_if_idle_for is set to 0 the
+// check will not be performed.
+pref("network.tcp.tcp_fastopen_http_check_for_stalls_only_if_idle_for", 10);
+pref("network.tcp.tcp_fastopen_http_stalls_limit", 3);
+pref("network.tcp.tcp_fastopen_http_stalls_timeout", 20);
 
 // Whether to disable acceleration for all widgets.
 pref("layers.acceleration.disabled", false);

netwerk/protocol/http/Http2Session.cpp

@@ -42,6 +42,7 @@
 #include "nsICacheStorage.h"
 #include "CacheControlParser.h"
 #include "LoadContextInfo.h"
+#include "TCPFastOpenLayer.h"
 
 namespace mozilla {
 namespace net {
@@ -119,6 +120,8 @@ Http2Session::Http2Session(nsISocketTransport *aSocketTransport, uint32_t versio
   , mAttemptingEarlyData(attemptingEarlyData)
   , mOriginFrameActivated(false)
   , mTlsHandshakeFinished(false)
+  , mCheckNetworkStallsWithTFO(false)
+  , mLastRequestBytesSentTime(0)
 {
   MOZ_ASSERT(OnSocketThread(), "not on socket thread");
 
@@ -269,8 +272,19 @@ Http2Session::ReadTimeoutTick(PRIntervalTime now)
   LOG3(("Http2Session::ReadTimeoutTick %p delta since last read %ds\n",
        this, PR_IntervalToSeconds(now - mLastReadEpoch)));
 
+  uint32_t nextTick = UINT32_MAX;
+  if (mCheckNetworkStallsWithTFO && mLastRequestBytesSentTime) {
+    PRIntervalTime initialResponseDelta = now - mLastRequestBytesSentTime;
+    if (initialResponseDelta >= gHttpHandler->FastOpenStallsTimeout()) {
+      gHttpHandler->IncrementFastOpenStallsCounter();
+      mCheckNetworkStallsWithTFO = false;
+    } else {
+      nextTick = PR_IntervalToSeconds(gHttpHandler->FastOpenStallsTimeout()) -
+                 PR_IntervalToSeconds(initialResponseDelta);
+    }
+  }
   if (!mPingThreshold)
-    return UINT32_MAX;
+    return nextTick;
 
   if ((now - mLastReadEpoch) < mPingThreshold) {
     // recent activity means ping is not an issue
@@ -283,8 +297,8 @@ Http2Session::ReadTimeoutTick(PRIntervalTime now)
       }
     }
 
-    return PR_IntervalToSeconds(mPingThreshold) -
-      PR_IntervalToSeconds(now - mLastReadEpoch);
+    return std::min(nextTick, PR_IntervalToSeconds(mPingThreshold) -
+                              PR_IntervalToSeconds(now - mLastReadEpoch));
   }
 
   if (mPingSentEpoch) {
@@ -373,6 +387,20 @@ Http2Session::RegisterStreamID(Http2Stream *stream, uint32_t aNewID)
   }
 
   mStreamIDHash.Put(aNewID, stream);
+
+  // If TCP fast Open has been used and conection was idle for some time
+  // we will be cautious and watch out for bug 1395494.
+  if (!mCheckNetworkStallsWithTFO && mConnection) {
+    RefPtr<nsHttpConnection> conn = mConnection->HttpConnection();
+    if (conn && (conn->GetFastOpenStatus() == TFO_DATA_SENT) &&
+        gHttpHandler->CheckIfConnectionIsStalledOnlyIfIdleForThisAmountOfSeconds() &&
+        IdleTime() >= gHttpHandler->CheckIfConnectionIsStalledOnlyIfIdleForThisAmountOfSeconds()) {
+      // If a connection was using the TCP FastOpen and it was idle for a
+      // long time we should check for stalls like bug 1395494.
+      mCheckNetworkStallsWithTFO = true;
+      mLastRequestBytesSentTime = PR_IntervalNow();
+    }
+  }
   return aNewID;
 }
 
@@ -512,8 +540,10 @@ Http2Session::NetworkRead(nsAHttpSegmentWriter *writer, char *buf,
   }
 
   nsresult rv = writer->OnWriteSegment(buf, count, countWritten);
-  if (NS_SUCCEEDED(rv) && *countWritten > 0)
+  if (NS_SUCCEEDED(rv) && *countWritten > 0) {
     mLastReadEpoch = PR_IntervalNow();
+    mCheckNetworkStallsWithTFO = false;
+  }
   return rv;
 }
 

netwerk/protocol/http/Http2Session.h

@@ -563,6 +563,9 @@ private:
   // We should propagate this events to the first nsHttpTransaction.
   RefPtr<nsHttpTransaction> mFirstHttpTransaction;
   bool mTlsHandshakeFinished;
+
+  bool mCheckNetworkStallsWithTFO;
+  PRIntervalTime mLastRequestBytesSentTime;
 private:
 /// connect tunnels
   void DispatchOnTunnel(nsAHttpTransaction *, nsIInterfaceRequestor *);

netwerk/protocol/http/nsHttpConnection.cpp

@@ -90,6 +90,8 @@ nsHttpConnection::nsHttpConnection()
     , mFastOpenStatus(TFO_NOT_SET)
     , mForceSendDuringFastOpenPending(false)
     , mReceivedSocketWouldBlockDuringFastOpen(false)
+    , mCheckNetworkStallsWithTFO(false)
+    , mLastRequestBytesSentTime(0)
 {
     LOG(("Creating nsHttpConnection @%p\n", this));
 
@@ -641,6 +643,18 @@ nsHttpConnection::Activate(nsAHttpTransaction *trans, uint32_t caps, int32_t pri
     NS_ENSURE_ARG_POINTER(trans);
     NS_ENSURE_TRUE(!mTransaction, NS_ERROR_IN_PROGRESS);
 
+    // If TCP fast Open has been used and conection was idle for some time
+    // we will be cautious and watch out for bug 1395494.
+    if (mNPNComplete && (mFastOpenStatus == TFO_DATA_SENT) &&
+        gHttpHandler->CheckIfConnectionIsStalledOnlyIfIdleForThisAmountOfSeconds() &&
+        IdleTime() >= gHttpHandler->CheckIfConnectionIsStalledOnlyIfIdleForThisAmountOfSeconds()) {
+        // If a connection was using the TCP FastOpen and it was idle for a
+        // long time we should check for stalls like bug 1395494.
+        mCheckNetworkStallsWithTFO = true;
+        // Also reset last write. We should start measuring a stall time only
+        // after we really write a request to the network.
+        mLastRequestBytesSentTime = 0;
+    }
     // reset the read timers to wash away any idle time
     mLastWriteTime = mLastReadTime = PR_IntervalNow();
 
@@ -1355,6 +1369,19 @@ nsHttpConnection::ReadTimeoutTick(PRIntervalTime now)
         nextTickAfter = std::max(nextTickAfter, 1U);
     }
 
+    // Check for the TCP Fast Open related stalls.
+    if (mCheckNetworkStallsWithTFO && mLastRequestBytesSentTime) {
+        PRIntervalTime initialResponseDelta = now - mLastRequestBytesSentTime;
+        if (initialResponseDelta >= gHttpHandler->FastOpenStallsTimeout()) {
+            gHttpHandler->IncrementFastOpenStallsCounter();
+            mCheckNetworkStallsWithTFO = false;
+        } else {
+            uint32_t next = PR_IntervalToSeconds(gHttpHandler->FastOpenStallsTimeout()) -
+                            PR_IntervalToSeconds(initialResponseDelta);
+            nextTickAfter = std::min(nextTickAfter, next);
+        }
+    }
+
     if (!mNPNComplete) {
       // We can reuse mLastWriteTime here, because it is set when the
       // connection is activated and only change when a transaction
@@ -1856,6 +1883,9 @@ nsHttpConnection::OnSocketWritable()
                 mTransaction->OnTransportStatus(mSocketTransport,
                                                 NS_NET_STATUS_WAITING_FOR,
                                                 0);
+                if (mCheckNetworkStallsWithTFO) {
+                    mLastRequestBytesSentTime = PR_IntervalNow();
+                }
 
                 rv = ResumeRecv(); // start reading
             }
@@ -1898,6 +1928,8 @@ nsHttpConnection::OnWriteSegment(char *buf,
     else
         mSocketInCondition = NS_OK; // reset condition
 
+    mCheckNetworkStallsWithTFO = false;
+
     return mSocketInCondition;
 }
 

netwerk/protocol/http/nsHttpConnection.h

@@ -234,6 +234,9 @@ public:
     bool JoinConnection(const nsACString &hostname, int32_t port);
 
     void SetFastOpenStatus(uint8_t tfoStatus);
+    uint8_t GetFastOpenStatus() {
+      return mFastOpenStatus;
+    }
 
     void SetEvent(nsresult aStatus);
 
@@ -401,6 +404,8 @@ private:
 
     bool                           mForceSendDuringFastOpenPending;
     bool                           mReceivedSocketWouldBlockDuringFastOpen;
+    bool                           mCheckNetworkStallsWithTFO;
+    PRIntervalTime                 mLastRequestBytesSentTime;
 
 public:
     void BootstrapTimings(TimingStruct times);

netwerk/protocol/http/nsHttpHandler.cpp

@@ -109,8 +109,11 @@
 #define SAFE_HINT_HEADER_VALUE   "safeHint.enabled"
 #define SECURITY_PREFIX          "security."
 
-#define TCP_FAST_OPEN_ENABLE        "network.tcp.tcp_fastopen_enable"
-#define TCP_FAST_OPEN_FAILURE_LIMIT "network.tcp.tcp_fastopen_consecutive_failure_limit"
+#define TCP_FAST_OPEN_ENABLE         "network.tcp.tcp_fastopen_enable"
+#define TCP_FAST_OPEN_FAILURE_LIMIT  "network.tcp.tcp_fastopen_consecutive_failure_limit"
+#define TCP_FAST_OPEN_STALLS_LIMIT   "network.tcp.tcp_fastopen_http_stalls_limit"
+#define TCP_FAST_OPEN_STALLS_IDLE    "network.tcp.tcp_fastopen_http_check_for_stalls_only_if_idle_for"
+#define TCP_FAST_OPEN_STALLS_TIMEOUT "network.tcp.tcp_fastopen_http_stalls_timeout"
 
 #define UA_PREF(_pref) UA_PREF_PREFIX _pref
 #define HTTP_PREF(_pref) HTTP_PREF_PREFIX _pref
@@ -285,6 +288,10 @@ nsHttpHandler::nsHttpHandler()
     , mUseFastOpen(true)
     , mFastOpenConsecutiveFailureLimit(5)
     , mFastOpenConsecutiveFailureCounter(0)
+    , mFastOpenStallsLimit(3)
+    , mFastOpenStallsCounter(0)
+    , mFastOpenStallsIdleTime(10)
+    , mFastOpenStallsTimeout(20)
     , mActiveTabPriority(true)
     , mProcessId(0)
     , mNextChannelId(1)
@@ -452,6 +459,9 @@ nsHttpHandler::Init()
         prefBranch->AddObserver(SECURITY_PREFIX, this, true);
         prefBranch->AddObserver(TCP_FAST_OPEN_ENABLE, this, true);
         prefBranch->AddObserver(TCP_FAST_OPEN_FAILURE_LIMIT, this, true);
+        prefBranch->AddObserver(TCP_FAST_OPEN_STALLS_LIMIT, this, true);
+        prefBranch->AddObserver(TCP_FAST_OPEN_STALLS_IDLE, this, true);
+        prefBranch->AddObserver(TCP_FAST_OPEN_STALLS_TIMEOUT, this, true);
         PrefsChanged(prefBranch, nullptr);
     }
 
@@ -736,6 +746,20 @@ nsHttpHandler::IncrementFastOpenConsecutiveFailureCounter()
     }
 }
 
+void
+nsHttpHandler::IncrementFastOpenStallsCounter()
+{
+  LOG(("nsHttpHandler::IncrementFastOpenStallsCounter - failed=%d "
+        "failure_limit=%d", mFastOpenStallsCounter, mFastOpenStallsLimit));
+  if (mFastOpenStallsCounter < mFastOpenStallsLimit) {
+    mFastOpenStallsCounter++;
+    if (mFastOpenStallsCounter == mFastOpenStallsLimit) {
+      LOG(("nsHttpHandler::IncrementFastOpenStallsCounter - "
+           "There are too many stalls involving TFO and TLS."));
+    }
+  }
+}
+
 nsresult
 nsHttpHandler::GetStreamConverterService(nsIStreamConverterService **result)
 {
@@ -1929,6 +1953,36 @@ nsHttpHandler::PrefsChanged(nsIPrefBranch *prefs, const char *pref)
         }
     }
 
+    if (PREF_CHANGED(TCP_FAST_OPEN_STALLS_LIMIT)) {
+        rv = prefs->GetIntPref(TCP_FAST_OPEN_STALLS_LIMIT, &val);
+        if (NS_SUCCEEDED(rv)) {
+            if (val < 0) {
+                val = 0;
+            }
+            mFastOpenStallsLimit = val;
+        }
+    }
+
+    if (PREF_CHANGED(TCP_FAST_OPEN_STALLS_TIMEOUT)) {
+        rv = prefs->GetIntPref(TCP_FAST_OPEN_STALLS_TIMEOUT, &val);
+        if (NS_SUCCEEDED(rv)) {
+            if (val < 0) {
+                val = 0;
+            }
+            mFastOpenStallsTimeout = val;
+        }
+    }
+
+    if (PREF_CHANGED(TCP_FAST_OPEN_STALLS_IDLE)) {
+        rv = prefs->GetIntPref(TCP_FAST_OPEN_STALLS_IDLE, &val);
+        if (NS_SUCCEEDED(rv)) {
+            if (val < 0) {
+                val = 0;
+            }
+            mFastOpenStallsIdleTime = val;
+        }
+    }
+
     if (PREF_CHANGED(HTTP_PREF("spdy.hpack-default-buffer"))) {
         rv = prefs->GetIntPref(HTTP_PREF("spdy.default-hpack-buffer"), &val);
         if (NS_SUCCEEDED(rv)) {
@@ -2275,8 +2329,10 @@ nsHttpHandler::Observe(nsISupports *subject,
             Telemetry::Accumulate(Telemetry::TCP_FAST_OPEN_STATUS, 1);
         } else if (!mUseFastOpen) {
             Telemetry::Accumulate(Telemetry::TCP_FAST_OPEN_STATUS, 2);
-        } else {
+        } else if (mFastOpenConsecutiveFailureCounter >= mFastOpenConsecutiveFailureLimit) {
             Telemetry::Accumulate(Telemetry::TCP_FAST_OPEN_STATUS, 3);
+        } else {
+            Telemetry::Accumulate(Telemetry::TCP_FAST_OPEN_STATUS, 4);
         }
     } else if (!strcmp(topic, "profile-change-net-restore")) {
         // initialize connection manager

netwerk/protocol/http/nsHttpHandler.h

@@ -177,7 +177,8 @@ public:
     bool UseFastOpen()
     {
         return mUseFastOpen && mFastOpenSupported &&
-               mFastOpenConsecutiveFailureCounter < mFastOpenConsecutiveFailureLimit;
+               (mFastOpenStallsCounter < mFastOpenStallsLimit) &&
+               (mFastOpenConsecutiveFailureCounter < mFastOpenConsecutiveFailureLimit);
     }
     // If one of tcp connections return PR_NOT_TCP_SOCKET_ERROR while trying
     // fast open, it means that Fast Open is turned off so we will not try again
@@ -195,6 +196,14 @@ public:
         mFastOpenConsecutiveFailureCounter = 0;
     }
 
+    void IncrementFastOpenStallsCounter();
+    uint32_t CheckIfConnectionIsStalledOnlyIfIdleForThisAmountOfSeconds() {
+        return mFastOpenStallsIdleTime;
+    }
+    uint32_t FastOpenStallsTimeout() {
+      return mFastOpenStallsTimeout;
+    }
+
     // returns the HTTP framing check level preference, as controlled with
     // network.http.enforce-framing.http1 and network.http.enforce-framing.soft
     FrameCheckLevel GetEnforceH1Framing() { return mEnforceH1Framing; }
@@ -651,6 +660,10 @@ private:
     Atomic<bool, Relaxed> mFastOpenSupported;
     uint32_t mFastOpenConsecutiveFailureLimit;
     uint32_t mFastOpenConsecutiveFailureCounter;
+    uint32_t mFastOpenStallsLimit;
+    uint32_t mFastOpenStallsCounter;
+    uint32_t mFastOpenStallsIdleTime;
+    uint32_t mFastOpenStallsTimeout;
 
     // If true, the transactions from active tab will be dispatched first.
     bool mActiveTabPriority;

toolkit/components/telemetry/Histograms.json

@@ -2437,7 +2437,7 @@
     "expires_in_version": "61",
     "kind": "enumerated",
     "n_values": 8,
-    "description": "TCP Fast Open was: 0=enabled during the session, 1=not available or disabled in the os, 2=disabled by the pref, 3=disabled based on the too many connection failures.",
+    "description": "TCP Fast Open was: 0=enabled during the session, 1=not available or disabled in the os, 2=disabled by the pref, 3=disabled based on the too many connection failures, 4=disable based on too many http transaction stalls after a connection was idle.",
     "alert_emails": ["necko@mozilla.com", "ddamjanovic@mozilla.com"],
     "bug_numbers": [1390881]
   },