bug 603514 - http stalled read detection r=honzab

When a connection that involves a pipelined transaction has been stalled (i.e.
idle with an open transaction, not an idle persistent connection) for a
second move any transactions that are pipelined after the current one onto
different connections (and implicitly close this connection when done with the
current transaction).

when it has been stalled for 10 seconds (pref configurable), cancel the current
transaction itself too - depending on its state it can hopefully be restarted
on a clean connection.

modules/libpref/src/init/all.js

@@ -817,6 +817,7 @@ pref("network.http.pipelining.max-optimistic-requests" , 4);
 
 pref("network.http.pipelining.aggressive", false);
 pref("network.http.pipelining.maxsize" , 300000);
+pref("network.http.pipelining.read-timeout", 10000);
 
 // Prompt for 307 redirects
 pref("network.http.prompt-temp-redirect", true);

netwerk/protocol/http/SpdySession.h

@@ -77,7 +77,7 @@ public:
   bool CanReuse() { return !mShouldGoAway && !mClosed; }
   bool RoomForMoreStreams();
 
-  // When the connection is active this is called every 15 seconds
+  // When the connection is active this is called every 1 second
   void ReadTimeoutTick(PRIntervalTime now);
   
   // Idle time represents time since "goodput".. e.g. a data or header frame

netwerk/protocol/http/nsAHttpTransaction.h

@@ -48,6 +48,7 @@ class nsIInterfaceRequestor;
 class nsIEventTarget;
 class nsITransport;
 class nsHttpRequestHead;
+class nsHttpPipeline;
 
 //----------------------------------------------------------------------------
 // Abstract base class for a HTTP transaction:
@@ -133,6 +134,11 @@ public:
     virtual nsresult SetPipelinePosition(PRInt32) = 0;
     virtual PRInt32  PipelinePosition() = 0;
 
+    // If we used rtti this would be the result of doing
+    // dynamic_cast<nsHttpPipeline *>(this).. i.e. it can be nsnull for
+    // non pipeline implementations of nsAHttpTransaction
+    virtual nsHttpPipeline *QueryPipeline() { return nsnull; }
+    
     // Every transaction is classified into one of the types below. When using
     // HTTP pipelines, only transactions with the same type appear on the same
     // pipeline.

netwerk/protocol/http/nsHttpConnection.cpp

@@ -963,8 +963,56 @@ nsHttpConnection::ReadTimeoutTick(PRIntervalTime now)
         return;
     }
     
-    // Pending patches places pipeline rescheduling code will go here
+    PRIntervalTime delta = PR_IntervalNow() - mLastReadTime;
 
+    // we replicate some of the checks both here and in OnSocketReadable() as
+    // they will be discovered under different conditions. The ones here
+    // will generally be discovered if we are totally hung and OSR does
+    // not get called at all, however OSR discovers them with lower latency
+    // if the issue is just very slow (but not stalled) reading.
+    //
+    // Right now we only take action if pipelining is involved, but this would
+    // be the place to add general read timeout handling if it is desired.
+
+    const PRIntervalTime k1000ms = PR_MillisecondsToInterval(1000);
+
+    if (delta < k1000ms)
+        return;
+
+    PRUint32 pipelineDepth = mTransaction->PipelineDepth();
+
+    // this just reschedules blocked transactions. no transaction
+    // is aborted completely.
+    LOG(("cancelling pipeline due to a %ums stall - depth %d\n",
+         PR_IntervalToMilliseconds(delta), pipelineDepth));
+
+    if (pipelineDepth > 1) {
+        nsHttpPipeline *pipeline = mTransaction->QueryPipeline();
+        NS_ABORT_IF_FALSE(pipeline, "pipelinedepth > 1 without pipeline");
+        // code this defensively for the moment and check for null in opt build
+        if (pipeline)
+            pipeline->CancelPipeline(NS_ERROR_NET_TIMEOUT);
+    }
+    
+    if (delta < gHttpHandler->GetPipelineTimeout())
+        return;
+
+    if (pipelineDepth <= 1 && !mTransaction->PipelinePosition())
+        return;
+    
+    // nothing has transpired on this pipelined socket for many
+    // seconds. Call that a total stall and close the transaction.
+    // There is a chance the transaction will be restarted again
+    // depending on its state.. that will come back araound
+    // without pipelining on, so this won't loop.
+
+    LOG(("canceling transaction stalled for %ums on a pipeline"
+         "of depth %d and scheduled originally at pos %d\n",
+         PR_IntervalToMilliseconds(delta),
+         pipelineDepth, mTransaction->PipelinePosition()));
+
+    // This will also close the connection
+    CloseTransaction(mTransaction, NS_ERROR_NET_TIMEOUT);
 }
 
 void
@@ -1290,8 +1338,20 @@ nsHttpConnection::OnSocketReadable()
     const PRIntervalTime k1200ms = PR_MillisecondsToInterval(1200);
 
     if (delta > k1200ms) {
+        LOG(("Read delta ms of %u causing slow read major "
+             "event and pipeline cancellation",
+             PR_IntervalToMilliseconds(delta)));
+
         gHttpHandler->ConnMgr()->PipelineFeedbackInfo(
             mConnInfo, nsHttpConnectionMgr::BadSlowReadMajor, this, 0);
+
+        if (mTransaction->PipelineDepth() > 1) {
+            nsHttpPipeline *pipeline = mTransaction->QueryPipeline();
+            NS_ABORT_IF_FALSE(pipeline, "pipelinedepth > 1 without pipeline");
+            // code this defensively for the moment and check for null
+            if (pipeline)
+                pipeline->CancelPipeline(NS_ERROR_NET_TIMEOUT);
+        }
     }
     else if (delta > k400ms) {
         gHttpHandler->ConnMgr()->PipelineFeedbackInfo(

netwerk/protocol/http/nsHttpConnection.h

@@ -167,7 +167,7 @@ public:
 
     bool UsingSpdy() { return mUsingSpdy; }
 
-    // When the connection is active this is called every 15 seconds
+    // When the connection is active this is called every 1 second
     void  ReadTimeoutTick(PRIntervalTime now);
 
     nsAHttpTransaction::Classifier Classification() { return mClassification; }
@@ -176,6 +176,9 @@ public:
         mClassification = newclass;
     }
 
+    // When the connection is active this is called every second
+    void  ReadTimeoutTick();
+
 private:
     // called to cause the underlying socket to start speaking SSL
     nsresult ProxyStartSSL();

netwerk/protocol/http/nsHttpConnectionMgr.cpp

@@ -1938,12 +1938,6 @@ nsHttpConnectionMgr::ActivateTimeoutTick()
     LOG(("nsHttpConnectionMgr::ActivateTimeoutTick() "
          "this=%p mReadTimeoutTick=%p\n"));
 
-    // right now the spdy timeout code is the only thing hooked to the timeout
-    // tick, so disable it if spdy is not being used. However pipelining code
-    // will also want this functionality soon.
-    if (!gHttpHandler->IsSpdyEnabled())
-        return;
-
     // The timer tick should be enabled if it is not already pending.
     // Upon running the tick will rearm itself if there are active
     // connections available.
@@ -1961,8 +1955,7 @@ nsHttpConnectionMgr::ActivateTimeoutTick()
 
     NS_ABORT_IF_FALSE(!mReadTimeoutTickArmed, "timer tick armed");
     mReadTimeoutTickArmed = true;
-    // pipeline will expect a 1000ms granuality
-    mReadTimeoutTick->Init(this, 15000, nsITimer::TYPE_REPEATING_SLACK);
+    mReadTimeoutTick->Init(this, 1000, nsITimer::TYPE_REPEATING_SLACK);
 }
 
 void

netwerk/protocol/http/nsHttpHandler.cpp

@@ -189,6 +189,7 @@ nsHttpHandler::nsHttpHandler()
     , mMaxOptimisticPipelinedRequests(4)
     , mPipelineAggressive(false)
     , mMaxPipelineObjectSize(300000)
+    , mPipelineReadTimeout(PR_MillisecondsToInterval(10000))
     , mRedirectionLimit(10)
     , mPhishyUserPassLength(1)
     , mQoSBits(0x00)
@@ -1053,6 +1054,14 @@ nsHttpHandler::PrefsChanged(nsIPrefBranch *prefs, const char *pref)
         }
     }
 
+    if (PREF_CHANGED(HTTP_PREF("pipelining.read-timeout"))) {
+        rv = prefs->GetIntPref(HTTP_PREF("pipelining.read-timeout"), &val);
+        if (NS_SUCCEEDED(rv)) {
+            mPipelineReadTimeout =
+                PR_MillisecondsToInterval(clamped(val, 500, 0xffff));
+        }
+    }
+
     if (PREF_CHANGED(HTTP_PREF("pipelining.ssl"))) {
         rv = prefs->GetBoolPref(HTTP_PREF("pipelining.ssl"), &cVar);
         if (NS_SUCCEEDED(rv))

netwerk/protocol/http/nsHttpHandler.h

@@ -237,6 +237,7 @@ public:
     {
         outVal = mMaxPipelineObjectSize;
     }
+    PRIntervalTime GetPipelineTimeout()   { return mPipelineReadTimeout; }
 
 private:
 
@@ -299,6 +300,8 @@ private:
     bool     mPipelineAggressive;
     PRInt64  mMaxPipelineObjectSize;
 
+    PRIntervalTime mPipelineReadTimeout;
+
     PRUint8  mRedirectionLimit;
 
     // we'll warn the user if we load an URL containing a userpass field

netwerk/protocol/http/nsHttpPipeline.cpp

@@ -175,6 +175,12 @@ nsHttpPipeline::PipelinePosition()
     return 2;
 }
 
+nsHttpPipeline *
+nsHttpPipeline::QueryPipeline()
+{
+    return this;
+}
+
 //-----------------------------------------------------------------------------
 // nsHttpPipeline::nsISupports
 //-----------------------------------------------------------------------------

netwerk/protocol/http/nsHttpPipeline.h

@@ -82,6 +82,9 @@ private:
         return mResponseQ[i];
     }
 
+    // overload of nsAHttpTransaction::QueryPipeline()
+    nsHttpPipeline *QueryPipeline();
+
     nsAHttpConnection            *mConnection;
     nsTArray<nsAHttpTransaction*> mRequestQ;  // array of transactions
     nsTArray<nsAHttpTransaction*> mResponseQ; // array of transactions