net: start every peer's stall clock stopped, not at whatever was in memory

CNode's constructor never wrote nMsgWaitSince or nMsgWaitSize, so every peer
began life with indeterminate values in the pair ProcessMessages uses to
decide whether that peer has stopped sending, and the first partial message
it read was measured against them.

The guard restarts the clock only when nMsgWaitSince is 0 or the buffer has
grown since the last look. Garbage in nMsgWaitSince is neither, so the very
first look fell through to the timeout branch. A peer that merely split a
message across two TCP segments -- header in one, body in the next, which is
ordinary on any real link -- could be dropped as unreadable on first contact,
before it had sent anything wrong and often before its version message. It
was never reproducible either: what happened depended on what had last used
that heap. The log reported the stall as roughly the age of the epoch:

  peer 127.0.0.1:8433 announced a 100 byte 'block' and has sent nothing more
  for 1786593923 s (0 of 100 payload bytes) -- dropping, this peer is
  unreadable

Every node is running this.

Introduced in 7f6e5ad, which added the pair to the class and to
ProcessMessages but not to the constructor; the constructor went on
initialising nIncompleteMessageStart, nIncompleteMessageSize and
strIncompleteMessageCommand, the upstream members our implementation
supersedes. 5490d66 removed their last reader from ProcessMessages, and
nothing has read or written them since, so they go, with
BTF_INCOMPLETE_MESSAGE_TIMEOUT_SECS -- decoy state in a networking struct is
how this happened, and the merge ahead of us would carry it further. The
initialiser list now follows declaration order, so a member missing from it
is visible.

The net-message selftest was asserting on those dead members too, which is
why it could not have caught this: it read state no code path writes, and its
stale-message case passed only when the garbage in nMsgWaitSince happened to
look old. Rewired onto nMsgWaitSince / nMsgWaitSize / BTF_MSG_WAIT_MAX_SECS,
and given the two cases it never covered -- a new peer's clock must start
stopped, and a peer that is still delivering payload must not be dropped
however old its clock is.

Measured on the build host, 20 runs each: before, net-message failed 20/20
("a fresh incomplete message does not disconnect immediately" failed 17/20 by
itself). After, 20/20 pass. Rewired selftest against a reverted constructor
fix: fails 20/20, deterministically, where the old suite caught it by luck or
not at all.

2 files changed, 38 insertions, 15 deletions

diff --git a/src/net.h b/src/net.h
index 8b0245a..3c8c409 100644
--- a/src/net.h
+++ b/src/net.h
@@ -89,10 +89,9 @@ static const int          BTF_HANDSHAKE_GRACE_SECS = 60;
 
 // A serialized object cannot be larger than MAX_SIZE, so no valid network
 // message needs the old 256 MB header allowance. Keep the wire cap aligned with
-// what the deserializer can accept and bound how long one peer may sit on a
-// partial payload after a complete header has arrived.
+// what the deserializer can accept. How long a peer may sit on a partial
+// payload after a complete header has arrived is BTF_MSG_WAIT_MAX_SECS, below.
 static const unsigned int MAX_PROTOCOL_MESSAGE_SIZE = MAX_SIZE;
-static const int          BTF_INCOMPLETE_MESSAGE_TIMEOUT_SECS = 2 * 60;
 
 // Ceiling on simultaneous connections.
 //
@@ -656,9 +655,6 @@ public:
     int64 nLastSend;
     int64 nLastRecv;
     int64 nLastSendEmpty;
-    int64 nIncompleteMessageStart;
-    unsigned int nIncompleteMessageSize;
-    string strIncompleteMessageCommand;
     string strBtfAddr;
     string strBtfMeeting;
 
@@ -699,11 +695,13 @@ public:
         nLastSend = 0;
         nLastRecv = 0;
         nLastSendEmpty = GetTime();
-        nIncompleteMessageStart = 0;
-        nIncompleteMessageSize = 0;
-        strIncompleteMessageCommand.clear();
         strBtfAddr.clear();
         strBtfMeeting.clear();
+        // Not waiting on anything yet. Left indeterminate, the first partial
+        // message this peer sends is measured against whatever was in this
+        // memory, and ProcessMessages drops it as unreadable on first contact.
+        nMsgWaitSince = 0;
+        nMsgWaitSize = 0;
         nStartingHeight = -1;
 
         // Push a version message
diff --git a/src/selftest.cpp b/src/selftest.cpp
index ff0289b..d12c96b 100644
--- a/src/selftest.cpp
+++ b/src/selftest.cpp
@@ -1105,6 +1105,13 @@ static int RunNetMessageSelfTest()
     int nFail = 0;
     try
     {
+        // A peer that has not yet been kept waiting must not look like one that
+        // has been waiting since the epoch. This is the whole bug: the stall
+        // clock lives in CNode, so only the constructor can start it at zero.
+        CNode opened(INVALID_SOCKET, CAddress("127.0.0.1"));
+        nFail += Check(opened.nMsgWaitSince == 0 && opened.nMsgWaitSize == 0,
+                       "a new peer starts with its stall clock stopped") ? 0 : 1;
+
         CNode complete(INVALID_SOCKET, CAddress("127.0.0.1"));
         complete.nVersion = VERSION;
         complete.vRecv << CMessageHeader("ping", 0);
@@ -1119,20 +1126,38 @@ static int RunNetMessageSelfTest()
         nFail += Check(ProcessMessages(&partial), "an incomplete message returns cleanly") ? 0 : 1;
         nFail += Check(partial.vRecv.size() == nPartialBefore,
                        "an incomplete message keeps one header in the buffer") ? 0 : 1;
-        nFail += Check(partial.nIncompleteMessageStart != 0,
-                       "an incomplete message starts a timeout clock") ? 0 : 1;
+        nFail += Check(partial.nMsgWaitSince != 0,
+                       "an incomplete message starts the stall clock") ? 0 : 1;
+        nFail += Check(partial.nMsgWaitSize == 0,
+                       "the stall clock records how much payload had arrived") ? 0 : 1;
         nFail += Check(!partial.fDisconnect,
                        "a fresh incomplete message does not disconnect immediately") ? 0 : 1;
 
+        // Still arriving, just slowly: more payload is here than when the clock
+        // was started, so the clock restarts however old it was. Timing the
+        // wait instead of the stall would drop this peer.
+        CNode slow(INVALID_SOCKET, CAddress("127.0.0.1"));
+        slow.nVersion = VERSION;
+        slow.vRecv << CMessageHeader("block", 100);
+        slow.vRecv.insert(slow.vRecv.end(), 50, '\0');
+        slow.nMsgWaitSince = GetTime() - BTF_MSG_WAIT_MAX_SECS - 1;
+        slow.nMsgWaitSize = 10;
+        ProcessMessages(&slow);
+        nFail += Check(!slow.fDisconnect,
+                       "a peer still sending payload is not dropped") ? 0 : 1;
+        nFail += Check(slow.nMsgWaitSize == 50,
+                       "progress restarts the stall clock") ? 0 : 1;
+
+        // Nothing more has arrived since the clock started, and the clock is
+        // older than the limit.
         CNode stale(INVALID_SOCKET, CAddress("127.0.0.1"));
         stale.nVersion = VERSION;
         stale.vRecv << CMessageHeader("block", 100);
-        stale.nIncompleteMessageStart = GetTime() - BTF_INCOMPLETE_MESSAGE_TIMEOUT_SECS - 1;
-        stale.nIncompleteMessageSize = 100;
-        stale.strIncompleteMessageCommand = "block";
+        stale.nMsgWaitSince = GetTime() - BTF_MSG_WAIT_MAX_SECS - 1;
+        stale.nMsgWaitSize = 0;
         ProcessMessages(&stale);
         nFail += Check(stale.fDisconnect,
-                       "a stale incomplete message disconnects the peer") ? 0 : 1;
+                       "a stalled incomplete message disconnects the peer") ? 0 : 1;
 
         CNode oversized(INVALID_SOCKET, CAddress("127.0.0.1"));
         oversized.nVersion = VERSION;