rendezvous: let a node park more than one registration (#113)

A registration was consumed by the first caller and registering again replaced the previous one, so a node was reachable to one peer at a time and unreachable for the gap between being paired and registering again. Measured on a live node: descriptors resolved 53/54, our own registrations paired 11/12, nothing paired and went silent -- and half of every outbound dial failed, 15 of 30 in eleven minutes.

The relay keeps a queue per pubkey capped at four, pairs with the oldest still-alive registration and discards the dead; the node runs three accept threads, each holding its own registration. The wire protocol does not change, so either side can be deployed first.

Bench with both relays built from source and waves of concurrent dialers: old+1 65%, new+1 58%, old+3 68%, new+3 98%. Each half alone lands within noise of doing nothing.

1 files changed, 188 insertions, 6 deletions

diff --git a/src/net.cpp b/src/net.cpp
index 7091981..449d91c 100644
--- a/src/net.cpp
+++ b/src/net.cpp
@@ -51,6 +51,103 @@ int64 nBlocksReceived      = 0;
 int64 nBlocksWithoutParent = 0;
 static int64 nNodeStartTime = 0;
 
+static CCriticalSection cs_btfChurn;
+static int64 nBtfResolveAttempts = 0;
+static int64 nBtfResolveOk = 0;
+static int64 nBtfResolveMiss = 0;
+static int64 nBtfDialAttempts = 0;
+static int64 nBtfDialOk = 0;
+static int64 nBtfDialFailed = 0;
+static int64 nBtfRegisterOk = 0;
+static int64 nBtfRegisterFailed = 0;
+static int64 nBtfPairOk = 0;
+static int64 nBtfPairFailed = 0;
+static int64 nBtfHandshakeNoRecv = 0;
+static int64 nBtfHandshakeNoSend = 0;
+static int64 nBtfHandshakeSilent = 0;
+static string strBtfLastDialFail;
+static string strBtfLastHandshakeTimeout;
+
+void BtfChurnNoteResolveAttempt()
+{
+    CRITICAL_BLOCK(cs_btfChurn)
+        nBtfResolveAttempts++;
+}
+
+void BtfChurnNoteResolveResult(bool fOk)
+{
+    CRITICAL_BLOCK(cs_btfChurn)
+    {
+        if (fOk) nBtfResolveOk++;
+        else    nBtfResolveMiss++;
+    }
+}
+
+void BtfChurnNoteDialAttempt(const string& strBtfAddr, const string& strMeeting)
+{
+    CRITICAL_BLOCK(cs_btfChurn)
+        nBtfDialAttempts++;
+    LogPrint("net", "btfchurn: dial attempt addr=%s meeting=%s\n",
+             strBtfAddr.c_str(), strMeeting.c_str());
+}
+
+void BtfChurnNoteDialResult(const string& strBtfAddr, const string& strMeeting, bool fOk)
+{
+    CRITICAL_BLOCK(cs_btfChurn)
+    {
+        if (fOk)
+            nBtfDialOk++;
+        else
+        {
+            nBtfDialFailed++;
+            strBtfLastDialFail = strBtfAddr + " via " + strMeeting;
+        }
+    }
+    LogPrint("net", "btfchurn: dial %s addr=%s meeting=%s\n",
+             fOk ? "ok" : "failed", strBtfAddr.c_str(), strMeeting.c_str());
+}
+
+void BtfChurnNoteRegisterResult(const string& strMeeting, bool fOk)
+{
+    CRITICAL_BLOCK(cs_btfChurn)
+    {
+        if (fOk) nBtfRegisterOk++;
+        else    nBtfRegisterFailed++;
+    }
+    LogPrint("net", "btfchurn: register %s meeting=%s\n",
+             fOk ? "ok" : "failed", strMeeting.c_str());
+}
+
+void BtfChurnNotePairResult(const string& strMeeting, bool fOk)
+{
+    CRITICAL_BLOCK(cs_btfChurn)
+    {
+        if (fOk) nBtfPairOk++;
+        else    nBtfPairFailed++;
+    }
+    LogPrint("net", "btfchurn: pair %s meeting=%s\n",
+             fOk ? "ok" : "timeout-or-drop", strMeeting.c_str());
+}
+
+void BtfChurnNoteHandshakeTimeout(const string& strBtfAddr, const string& strMeeting,
+                                  bool fRecv, bool fSend)
+{
+    CRITICAL_BLOCK(cs_btfChurn)
+    {
+        if (!fRecv && !fSend)
+            nBtfHandshakeSilent++;
+        else
+        {
+            if (!fRecv) nBtfHandshakeNoRecv++;
+            if (!fSend) nBtfHandshakeNoSend++;
+        }
+        strBtfLastHandshakeTimeout = strprintf("%s via %s recv=%d send=%d",
+                                               strBtfAddr.empty() ? "unknown" : strBtfAddr.c_str(),
+                                               strMeeting.empty() ? "unknown" : strMeeting.c_str(),
+                                               fRecv, fSend);
+    }
+}
+
 // --- Socket accounting (implementation lives in sockcount.h) --------------
 static const char* pszSockSite[SOCK_SITES] = {
     "external-ip probe", "listen socket", "inbound accept",
@@ -199,19 +296,64 @@ string GetDiagnosticsText()
 
     str += SockAccountingText();
 
-    str += "\n  peer                          dir  height   last recv   last send   unsent\n";
+    int64 nResolveAttempts, nResolveOk, nResolveMiss;
+    int64 nDialAttempts, nDialOk, nDialFailed;
+    int64 nRegisterOk, nRegisterFailed, nPairOk, nPairFailed;
+    int64 nHandshakeNoRecv, nHandshakeNoSend, nHandshakeSilent;
+    string strLastDialFail, strLastHandshakeTimeout;
+    CRITICAL_BLOCK(cs_btfChurn)
+    {
+        nResolveAttempts = nBtfResolveAttempts;
+        nResolveOk = nBtfResolveOk;
+        nResolveMiss = nBtfResolveMiss;
+        nDialAttempts = nBtfDialAttempts;
+        nDialOk = nBtfDialOk;
+        nDialFailed = nBtfDialFailed;
+        nRegisterOk = nBtfRegisterOk;
+        nRegisterFailed = nBtfRegisterFailed;
+        nPairOk = nBtfPairOk;
+        nPairFailed = nBtfPairFailed;
+        nHandshakeNoRecv = nBtfHandshakeNoRecv;
+        nHandshakeNoSend = nBtfHandshakeNoSend;
+        nHandshakeSilent = nBtfHandshakeSilent;
+        strLastDialFail = strBtfLastDialFail;
+        strLastHandshakeTimeout = strBtfLastHandshakeTimeout;
+    }
+    str += "\n  .btf churn\n";
+    str += strprintf("  resolves          %lld attempts, %lld ok, %lld no descriptor\n",
+                     (long long)nResolveAttempts, (long long)nResolveOk,
+                     (long long)nResolveMiss);
+    str += strprintf("  outbound dials    %lld attempts, %lld ok, %lld failed\n",
+                     (long long)nDialAttempts, (long long)nDialOk,
+                     (long long)nDialFailed);
+    str += strprintf("  rendezvous local  register ok/fail %lld/%lld, pair ok/drop %lld/%lld\n",
+                     (long long)nRegisterOk, (long long)nRegisterFailed,
+                     (long long)nPairOk, (long long)nPairFailed);
+    str += strprintf("  handshake grace   silent %lld, no recv %lld, no send %lld\n",
+                     (long long)nHandshakeSilent, (long long)nHandshakeNoRecv,
+                     (long long)nHandshakeNoSend);
+    if (!strLastDialFail.empty())
+        str += strprintf("  last dial failure %s\n", strLastDialFail.c_str());
+    if (!strLastHandshakeTimeout.empty())
+        str += strprintf("  last handshake    %s\n", strLastHandshakeTimeout.c_str());
+
+    str += "\n  peer                          dir  height   last recv   last send   unsent  via\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",
+        string strVia;
+        if (!pnode->strBtfMeeting.empty())
+            strVia = pnode->strBtfMeeting;
+        str += strprintf("  %-28s %-4s %6d  %10s  %10s  %7d  %s\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);
+                         nSendSize,
+                         strVia.substr(0, 28).c_str());
     }
     return str;
 }
@@ -814,30 +956,41 @@ static CNode* ConnectNodeBtfTail(const string& strBtfAddr, const unsigned char p
         return pnode;
     }
 
+    BtfChurnNoteDialAttempt(strBtfAddr, strMeeting);
     size_t colon = strMeeting.rfind(':');
     if (colon == string::npos)
+    {
+        BtfChurnNoteDialResult(strBtfAddr, strMeeting, false);
         return NULL;
+    }
     string strHost = strMeeting.substr(0, colon);
     int nPort = atoi(strMeeting.substr(colon + 1).c_str());
     if (nPort <= 0 || nPort > 65535)
+    {
+        BtfChurnNoteDialResult(strBtfAddr, strMeeting, false);
         return NULL;
+    }
 
     btf_socket_t hSocket = btf::BtfClientTunnel(strHost.c_str(), (unsigned short)nPort, pk, enc_pub);
     if (hSocket == INVALID_SOCKET)
     {
         if (fDebug)
             LogPrint("net", "ConnectNodeBtf: tunnel to %s via %s failed\n", strBtfAddr.c_str(), strMeeting.c_str());
+        BtfChurnNoteDialResult(strBtfAddr, strMeeting, false);
         return NULL;
     }
 
     if (fDebug)
         LogPrint("net", "connected %s via rendezvous %s\n", strBtfAddr.c_str(), strMeeting.c_str());
+    BtfChurnNoteDialResult(strBtfAddr, strMeeting, true);
 
     // This one answered -- worth trying first next time we start.
     RememberBtfPeer(strBtfAddr, strMeeting, enc_pub);
 
     // Add node
     pnode = new CNode(hSocket, addr, false);
+    pnode->strBtfAddr = strBtfAddr;
+    pnode->strBtfMeeting = strMeeting;
     pnode->AddRef();
     CRITICAL_BLOCK(cs_vNodes)
         vNodes.push_back(pnode);
@@ -863,12 +1016,15 @@ CNode* ConnectNodeBtf(const string& strBtfAddr)
 
     string strMeeting;
     unsigned char enc_pub[32];
+    BtfChurnNoteResolveAttempt();
     if (!BtfResolve(strBtfAddr, strMeeting, enc_pub))
     {
+        BtfChurnNoteResolveResult(false);
         if (fDebug)
             LogPrint("net", "ConnectNodeBtf: could not resolve a descriptor for %s\n", strBtfAddr.c_str());
         return NULL;
     }
+    BtfChurnNoteResolveResult(true);
     return ConnectNodeBtfTail(strBtfAddr, pk, strMeeting, enc_pub);
 }
 
@@ -951,12 +1107,14 @@ void ThreadBtfAccept(void* parg)
         }
         if (rv == btf::RV_INVALID)
         {
+            BtfChurnNoteRegisterResult(strMeeting, false);
             LogPrint("net", "rendezvous: could not register at %s, trying another\n",
                      strMeeting.c_str());
             iRelay++;       // this relay is down/attacked -> try the next one
             Sleep(3000);
             continue;
         }
+        BtfChurnNoteRegisterResult(strMeeting, true);
 
         // Registered. Advertise THIS relay now, while we are listed and before
         // anybody dials -- a descriptor naming it is what makes a dial possible
@@ -971,7 +1129,9 @@ void ThreadBtfAccept(void* parg)
         // here, the node stopped being reachable, and nothing in the log said
         // so. Re-registering every few minutes when nobody has dialled costs
         // one reconnect and removes the whole failure mode.
-        if (!btf::RvServiceWaitPaired(rv, BTF_RENDEZVOUS_WAIT_SECS))
+        bool fPaired = btf::RvServiceWaitPaired(rv, BTF_RENDEZVOUS_WAIT_SECS);
+        BtfChurnNotePairResult(strMeeting, fPaired);
+        if (!fPaired)
         {
             btf::RvClose(rv);
             LogPrint("net", "rendezvous: no dial at %s within %ds (or it dropped us), "
@@ -981,7 +1141,11 @@ void ThreadBtfAccept(void* parg)
 
         btf_socket_t hSocket = btf::BtfServiceWrap(rv, sk);
         if (hSocket == INVALID_SOCKET)
+        {
+            LogPrint("net", "rendezvous: paired at %s but channel setup failed\n",
+                     strMeeting.c_str());
             continue;
+        }
 
         // The dialer is anonymous (its pubkey never reaches us), so tag the
         // connection with a random marker address.
@@ -991,6 +1155,8 @@ void ThreadBtfAccept(void* parg)
 
         LogPrint("net", "accepted .btf connection via rendezvous %s\n", strMeeting.c_str());
         CNode* pnode = new CNode(hSocket, addr, true);
+        pnode->strBtfAddr = "inbound";
+        pnode->strBtfMeeting = strMeeting;
         pnode->AddRef();
         CRITICAL_BLOCK(cs_vNodes)
             vNodes.push_back(pnode);
@@ -1457,6 +1623,9 @@ void ThreadSocketHandler2(void* parg)
             {
                 if (pnode->nLastRecv == 0 || pnode->nLastSend == 0)
                 {
+                    if (!pnode->strBtfMeeting.empty())
+                        BtfChurnNoteHandshakeTimeout(pnode->strBtfAddr, pnode->strBtfMeeting,
+                                                     pnode->nLastRecv != 0, pnode->nLastSend != 0);
                     LogPrint("net", "socket no message in first %d seconds, recv=%d send=%d\n",
                              BTF_HANDSHAKE_GRACE_SECS, pnode->nLastRecv != 0, pnode->nLastSend != 0);
                     pnode->fDisconnect = true;
@@ -1803,9 +1972,22 @@ bool StartNode(string& strError)
 
     // Anonymous inbound: this node's .btf hidden service, reachable through the
     // meeting relay without exposing our IP or needing a public port.
+    //
+    // Several of these, not one. Each holds its own registration at a
+    // rendezvous, and a registration is consumed the moment a caller is paired
+    // with it -- so with a single thread the node is unreachable for the whole
+    // gap between being paired and registering again. Measured from a node's
+    // own counters: half of all outbound dials failed for exactly that reason,
+    // 15 of 30 in eleven minutes, while descriptors resolved 53 times out of
+    // 54. Spares parked at the relay close that gap.
+    //
+    // Needs a relay that keeps more than one registration per node; against an
+    // older relay the extra threads are harmless, because it drops the previous
+    // registration on each new one and the node ends up where it started.
     if (!vBtfMeetingRelays.empty())
-        if (_beginthread(ThreadBtfAccept, 0, NULL) == -1)
-            printf("Error: _beginthread(ThreadBtfAccept) failed\n");
+        for (int i = 0; i < BTF_ACCEPT_THREADS; i++)
+            if (_beginthread(ThreadBtfAccept, 0, NULL) == -1)
+                printf("Error: _beginthread(ThreadBtfAccept) failed\n");
 
     // Anonymous outbound: keep a connection to a specific .btf peer, if asked.
     if (!strBtfConnect.empty())