net: stop the failover log naming a peer on every re-request

The line was unconditional on the argument that failover firing is the
pathology of #33 and nobody could otherwise see it. That much is right.
Printing a peer address every time it fires is not: a peer decides how
often the line is written, by announcing hashes it will not serve, and
an address is the one thing the .btf transport otherwise takes trouble
not to spread around. Sustained, that was tens of lines a minute, each
naming a peer, driven entirely from outside.

Split it. The per-peer detail -- which block, how long, which peer is
being tried next -- moves behind the net category, where the rest of the
getdata logging already is. What stays unconditional is a count with no
addresses in it, over a window no peer can shorten: the first failover
after a quiet spell still prints immediately, because the change from
"blocks arrive" to "blocks are announced and not served" is the event
worth seeing, and everything after it is summarised once a minute.

Worst case is now one line per minute regardless of what a peer does,
instead of one per re-request.

1 files changed, 38 insertions, 6 deletions

diff --git a/src/main.cpp b/src/main.cpp
index be89416..a51b5ae 100644
--- a/src/main.cpp
+++ b/src/main.cpp
@@ -101,6 +101,21 @@ static const int BLOCK_FETCH_TRACK_MAX = 8;
 // forever; a re-announcement recreates it.
 static const int BLOCK_FETCH_GIVEUP_SECS = 10 * 60;
 
+// Failover firing at all is worth saying out loud: it means peers are
+// announcing blocks they then do not serve, which is the pathology of #33 and
+// the thing nobody could otherwise see. Naming the peer on every re-request is
+// a different matter. A peer can drive that line as often as it likes by
+// announcing hashes it will not serve, and what it prints is a peer address,
+// which is the one thing the .btf transport otherwise takes trouble not to
+// spread around. So the per-peer detail sits behind the net category and the
+// unconditional line is a count over a window no peer can shorten: the first
+// failover after a quiet spell prints at once, because the change from "blocks
+// arrive" to "blocks are announced and not served" is the event worth seeing,
+// and everything after it is summarised once a minute.
+static const int BLOCK_FETCH_REPORT_SECS = 60;
+static int64 nBlockFetchWindowStart = 0;
+static int   nBlockFetchFailovers   = 0;
+
 // How stale our own best block may be before we stop calling this the tip.
 // Blocks target two minutes, so this is thirty intervals: far longer than any
 // stall worth failing over from -- the one in #33 ran sixteen minutes -- and
@@ -3637,12 +3652,29 @@ bool SendMessages(CNode* pto)
                         fetch.setAsked.clear();
                     if (!fetch.setAsked.count(pto->addr))
                     {
-                        // Deliberately not behind a debug category: this line
-                        // firing is a peer announcing blocks it does not
-                        // serve, which is the pathology of #33.
-                        printf("block fetch failover: %s unanswered for %d s, re-requesting from %s\n",
-                               inv.ToString().c_str(), (int)(nNowSecs - fetch.nTimeAsked),
-                               pto->addr.ToString().c_str());
+                        // Which block, how long, and which peer we are trying
+                        // next. Behind the category because it names a peer
+                        // and a peer decides how often it is written.
+                        if (LogAcceptsCategory("net"))
+                            printf("block fetch failover: %s unanswered for %d s, re-requesting from %s\n",
+                                   inv.ToString().c_str(), (int)(nNowSecs - fetch.nTimeAsked),
+                                   pto->addr.ToString().c_str());
+
+                        // The unconditional half: no addresses, and at most
+                        // one line per BLOCK_FETCH_REPORT_SECS however hard a
+                        // peer tries. See the counters for the reasoning.
+                        nBlockFetchFailovers++;
+                        if (nNowSecs - nBlockFetchWindowStart >= BLOCK_FETCH_REPORT_SECS)
+                        {
+                            printf("block fetch: %d block request%s went unanswered and %s been "
+                                   "re-asked of other peers (%d tracked)\n",
+                                   nBlockFetchFailovers, nBlockFetchFailovers == 1 ? "" : "s",
+                                   nBlockFetchFailovers == 1 ? "has" : "have",
+                                   (int)mapBlockFetch.size());
+                            nBlockFetchWindowStart = nNowSecs;
+                            nBlockFetchFailovers   = 0;
+                        }
+
                         vFailover.push_back(inv);
                         fetch.nTimeAsked = nNowSecs;
                         fetch.setAsked.insert(pto->addr);