diag: let the node say what is wrong with it (#81)

* Bump to 1.2.11

One change, and it is the reason a node on Windows kept collecting peers it
could not hear.

FD_SETSIZE was never defined in this tree, so it defaulted to 64 and select()
could watch the listen socket plus 63 peers -- everything past that stayed
connected and was never read again. Windows FD_SET stops adding once its array
is full and says nothing, so there was no error to notice. Because new
connections go on the end of vNodes, it was always the newest connection that
starved, including the ones dialed to fix connectivity.

Measured on two nodes: 277 and 90 CNode objects against 93 and 90 live
sockets, 316 and 355 sockets in a bound-but-never-connected state, and a status
bar reporting hundreds of peers for a node really talking to thirty.

1.2.11 raises FD_SETSIZE to 1024 on Windows, caps connections at 125, drops a
node stuck undeliverable after 60 seconds instead of holding it forever, stops
answering a failed select() with POSIX code that has no meaning on Windows, and
warns when there are more peers than select can watch.

* diag: let the node say what is wrong with it

Every hard problem in this project so far was found from outside the node --
sockets read over WMI, committed memory compared against a README, a grep over
somebody debug.log. In each case the node knew and had no way to say so.

One report, rendered identically for the GUI panel and the log: peers held vs
peers actually watched by select(), blocks received and how many arrived without
a parent, proof-of-work mode with the live miner thread count, and per peer the
age of the last message in each direction plus anything stuck unsent.

4 files changed, 181 insertions, 0 deletions

diff --git a/src/gui.cpp b/src/gui.cpp
index 53cb6db..db6b69e 100644
--- a/src/gui.cpp
+++ b/src/gui.cpp
@@ -50,6 +50,7 @@ static int64       g_lastWalletRefresh = 0;
 static bool        g_showSend          = false;
 static bool        g_showOptions       = false;
 static bool        g_showAbout         = false;
+static bool        g_showDiagnostics   = false;
 static bool        g_needRefresh       = true;
 
 static char        g_sendAddr[128]        = {};
@@ -310,6 +311,7 @@ static void DrawMainWindow()
             ImGui::EndMenu();
         }
         if (ImGui::MenuItem("Options")) g_showOptions = true;
+        if (ImGui::MenuItem("Diagnostics")) g_showDiagnostics = true;
         if (ImGui::MenuItem("About"))   g_showAbout   = true;
         ImGui::EndMenuBar();
     }
@@ -815,6 +817,41 @@ static void DrawOptionsDialog()
 // ---------------------------------------------------------------------------
 // About dialog
 // ---------------------------------------------------------------------------
+// What the node knows about itself, in the words it writes to the log. Same
+// text in both places on purpose: what a user pastes into an issue is then
+// exactly what a developer has already read a hundred times.
+static void DrawDiagnosticsDialog()
+{
+    if (!g_showDiagnostics) return;
+    ImGui::SetNextWindowSize(ImVec2(720.0f, 460.0f), ImGuiCond_FirstUseEver);
+    ImGui::SetNextWindowPos(ImGui::GetMainViewport()->GetCenter(),
+                            ImGuiCond_FirstUseEver, ImVec2(0.5f, 0.5f));
+    if (ImGui::Begin("Diagnostics", &g_showDiagnostics, ImGuiWindowFlags_NoCollapse))
+    {
+        // Rebuilt at most once a second: it walks every peer and takes their
+        // send locks, which is not something to do at frame rate.
+        static std::string strReport;
+        static int64 nLastBuilt = 0;
+        if (GetTime() != nLastBuilt)
+        {
+            nLastBuilt = GetTime();
+            strReport = GetDiagnosticsText();
+        }
+
+        if (ImGui::Button("Copy to clipboard", ImVec2(160.0f, 0.0f)))
+            ImGui::SetClipboardText(strReport.c_str());
+        ImGui::SameLine();
+        ImGui::TextDisabled("The same report goes to debug.log every ten minutes.");
+        ImGui::Separator();
+
+        ImGui::BeginChild("##diagtext", ImVec2(0.0f, 0.0f), false,
+                          ImGuiWindowFlags_HorizontalScrollbar);
+        ImGui::TextUnformatted(strReport.c_str());
+        ImGui::EndChild();
+    }
+    ImGui::End();
+}
+
 static void DrawAboutDialog()
 {
     if (!g_showAbout) return;
@@ -921,6 +958,7 @@ int RunGUI(int argc, char* argv[])
         DrawMainWindow();
         DrawSendDialog();
         DrawOptionsDialog();
+        DrawDiagnosticsDialog();
         DrawAboutDialog();
         DrawStatusBar();
 
diff --git a/src/main.cpp b/src/main.cpp
index 5610de9..1a4c9ea 100644
--- a/src/main.cpp
+++ b/src/main.cpp
@@ -1494,6 +1494,11 @@ bool CBlock::AcceptBlock()
 
 bool ProcessBlock(CNode* pfrom, CBlock* pblock)
 {
+    // Counted before any check, so the ratio below is against everything that
+    // arrived rather than everything that was any good.
+    if (pfrom)
+        nBlocksReceived++;
+
     // Check for duplicate
     uint256 hash = pblock->GetHash();
     if (mapBlockIndex.count(hash))
@@ -1512,6 +1517,8 @@ bool ProcessBlock(CNode* pfrom, CBlock* pblock)
     if (!mapBlockIndex.count(pblock->hashPrevBlock))
     {
         printf("ProcessBlock: ORPHAN BLOCK, prev=%s\n", pblock->hashPrevBlock.ToString().substr(0,14).c_str());
+        if (pfrom)
+            nBlocksWithoutParent++;
         mapOrphanBlocks.insert(make_pair(hash, pblock));
         mapOrphanBlocksByPrev.insert(make_pair(pblock->hashPrevBlock, pblock));
 
diff --git a/src/net.cpp b/src/net.cpp
index 5ef8316..19893ee 100644
--- a/src/net.cpp
+++ b/src/net.cpp
@@ -46,6 +46,96 @@ CCriticalSection cs_mapRelay;
 map<CInv, int64> mapAlreadyAskedFor;
 string strBtfConnect; // .btf peer to keep connected to (from /connectbtf)
 
+int   nPeersWatched        = 0;
+int64 nBlocksReceived      = 0;
+int64 nBlocksWithoutParent = 0;
+static int64 nNodeStartTime = 0;
+
+// Defined further down, next to the counter it reads. The miner keeps its own
+// live count -- threads bump it on the way in and on the way out -- which is
+// the honest number here: how many are hashing now, not how many were asked to.
+static int MinersRunningCount();
+
+// Seconds rendered the way a person reads them off a screen.
+static string FormatAge(int64 nSeconds)
+{
+    if (nSeconds < 0)  return "never";
+    if (nSeconds < 60) return strprintf("%llds", (long long)nSeconds);
+    if (nSeconds < 3600)
+        return strprintf("%lldm%02llds", (long long)(nSeconds / 60), (long long)(nSeconds % 60));
+    return strprintf("%lldh%02lldm", (long long)(nSeconds / 3600), (long long)((nSeconds % 3600) / 60));
+}
+
+string GetDiagnosticsText()
+{
+    int64 nNow = GetTime();
+    string str;
+
+    int nInbound = 0, nHeld = 0;
+    vector<CNode*> vCopy;
+    CRITICAL_BLOCK(cs_vNodes)
+    {
+        vCopy = vNodes;
+        nHeld = (int)vNodes.size();
+        foreach(CNode* pnode, vNodes)
+            if (pnode->fInbound)
+                nInbound++;
+    }
+
+    int nMedian = GetPeerMedianHeight();
+
+    str += "Bitflash node diagnostics\n";
+    str += strprintf("  uptime            %s\n",
+                     FormatAge(nNodeStartTime ? nNow - nNodeStartTime : -1).c_str());
+    if (nMedian < 0)
+        str += strprintf("  height            %d  (no peer has said where it is)\n", nBestHeight);
+    else
+        str += strprintf("  height            %d  (peers report %d, %s)\n",
+                         nBestHeight, nMedian,
+                         nBestHeight >= nMedian ? "level or ahead"
+                                                : strprintf("behind by %d", nMedian - nBestHeight).c_str());
+    str += strprintf("  peers held        %d  (%d inbound, %d outbound)\n",
+                     nHeld, nInbound, nHeld - nInbound);
+
+    // The number that would have made the deafness obvious. Anything held but
+    // not watched is a socket this node will never read again.
+    str += strprintf("  peers watched     %d of %d that select() can hold%s\n",
+                     nPeersWatched, (int)FD_SETSIZE - 1,
+                     nHeld > nPeersWatched ? "   <-- NOT ALL PEERS ARE BEING READ" : "");
+
+    if (nBlocksReceived > 0)
+        str += strprintf("  blocks received   %lld  (%lld arrived without a parent, %.1f%%)\n",
+                         (long long)nBlocksReceived, (long long)nBlocksWithoutParent,
+                         100.0 * nBlocksWithoutParent / nBlocksReceived);
+    else
+        str += "  blocks received   0\n";
+
+    int nMining = MinersRunningCount();
+    str += strprintf("  proof of work     %s mode%s\n",
+                     RandomXFastReady() ? "fast (2 GB dataset)" : "light (256 MB cache)",
+                     nMining > 0
+                         ? strprintf(", mining on %d thread(s), about %d MB",
+                                     nMining,
+                                     (RandomXFastReady() ? 2080 : 256) + 2 * nMining).c_str()
+                         : ", not mining");
+
+    str += "\n  peer                          dir  height   last recv   last send   unsent\n";
+    foreach(CNode* pnode, vCopy)
+    {
+        int nSendSize = 0;
+        TRY_CRITICAL_BLOCK(pnode->cs_vSend)
+            nSendSize = (int)pnode->vSend.size();
+        str += strprintf("  %-28s %-4s %6d  %10s  %10s  %7d\n",
+                         pnode->addr.ToString().substr(0, 28).c_str(),
+                         pnode->fInbound ? "in" : "out",
+                         pnode->nStartingHeight,
+                         FormatAge(pnode->nLastRecv ? nNow - pnode->nLastRecv : -1).c_str(),
+                         FormatAge(pnode->nLastSend ? nNow - pnode->nLastSend : -1).c_str(),
+                         nSendSize);
+    }
+    return str;
+}
+
 
 bool GetMyExternalIP(unsigned int& ipRet)
 {
@@ -1058,6 +1148,24 @@ void ThreadSocketHandler2(void* parg)
                            (int)vNodes.size() - (int)FD_SETSIZE + 1);
                 }
             }
+            nPeersWatched = (int)nWatched - 1;   // less the listen socket
+        }
+
+        // Say the state of the node out loud now and then, so a log pulled off
+        // a machine three weeks later still answers "was it hearing anybody".
+        {
+            static int64 nLastReport = 0;
+            // Wound forward on the first pass so the first report lands about a
+            // minute in, once peers have had time to connect. A report written
+            // at second zero says nothing, and waiting ten minutes for the
+            // first one is ten minutes of a log that cannot answer anything.
+            if (nLastReport == 0)
+                nLastReport = GetTime() - 9 * 60;
+            if (GetTime() - nLastReport > 10 * 60)
+            {
+                nLastReport = GetTime();
+                printf("%s\n", GetDiagnosticsText().c_str());
+            }
         }
 
         vfThreadRunning[0] = false;
@@ -1432,6 +1540,14 @@ void ThreadMessageHandler2(void* parg)
 static CCriticalSection cs_nMinersRunning;
 static int nMinersRunning = 0;
 
+static int MinersRunningCount()
+{
+    int n = 0;
+    CRITICAL_BLOCK(cs_nMinersRunning)
+        n = nMinersRunning;
+    return n;
+}
+
 void ThreadBitcoinMiner(void* parg)
 {
     int nThreadId = (int)(intptr_t)parg;
@@ -1490,6 +1606,7 @@ int StartMinerThreads()
 bool StartNode(string& strError)
 {
     strError = "";
+    nNodeStartTime = GetTime();
 
     // Sockets startup
     WSADATA wsadata;
diff --git a/src/net.h b/src/net.h
index 01f314d..bd4eb77 100644
--- a/src/net.h
+++ b/src/net.h
@@ -102,6 +102,25 @@ static const int          BTF_PING_INTERVAL_SECS   = 10 * 60;
 static const int          BTF_BEHIND_GRACE_SECS         = 5 * 60;
 static const int          BTF_BEHIND_WARN_INTERVAL_SECS = 5 * 60;
 
+// --- Self-diagnosis -------------------------------------------------------
+//
+// A node that has stopped working looks exactly like a node with nothing to
+// do. That has cost this project real time more than once: a node deaf to
+// most of its peers, a miner allocating one RandomX dataset per thread, a
+// third of arriving blocks missing their parent -- each was found from
+// outside, by reading the process's sockets or its memory from another
+// machine, because the node itself had no way to say so.
+//
+// These counters exist so it can. Cheap to keep, and they name the failures
+// that actually happened rather than the ones that sound impressive.
+extern int   nPeersWatched;        // peers in the last select() set
+extern int64 nBlocksReceived;      // blocks handed to ProcessBlock
+extern int64 nBlocksWithoutParent; // ...of those, how many arrived orphaned
+
+// One report, rendered the same way for the GUI panel and the log, so what a
+// user pastes into an issue is what a developer already knows how to read.
+string GetDiagnosticsText();
+
 // Defined in main.cpp. Declared here because CNode announces it in the version
 // message, and net.h is included before main.h.
 extern int nBestHeight;