Merge #12569: net: Increase signal-to-noise ratio in debug.log by adjusting log level when logging failed non-manual connect():s

laanwj · laanwj · commit 23e7fe8be827 · 2018-04-13T19:25:18.000+02:00
cba2800 Increase signal-to-noise ratio in debug.log by adjusting log level when logging failed non-manual connect():s (practicalswift) Pull request description: Increase signal-to-noise ratio in `debug.log` by adjusting log level when logging failed non-manual `connect()`:s. Before this patch: ``` $ src/bitcoind -printtoconsole … 2018-02-28 18:42:51 UpdateTip: new best=0000000000005448b10a219683d34b770a28044e1cc421032dea1a79ff548948 height=1286903 version=0x20000000 log2_work=69.791313 tx=17408546 date='2018-02-28 18:42:46' progress=1.000000 cache=0.0MiB(173txo) 2018-02-28 18:37:52 connect() 10.11.21.34:18333 failed after select(): Connection refused (111) 2018-02-28 18:43:22 connect() to 10.11.43.14:18333 failed after select(): Network is unreachable (101) 2018-02-28 18:44:49 UpdateTip: new best=000000000000029a521ff2803e1441b09413b876accff5084a4cccf7747d798b height=1286904 version=0x20000000 log2_work=69.791345 tx=17408559 date='2018-02-28 18:44:51' progress=1.000000 cache=0.1MiB(502txo) 2018-02-28 18:46:54 connect() to [2001:0:9d38:78ff:1234:1234:1234:1234]:18333 failed: Network is unreachable (101) 2018-02-28 18:48:56 connect() to [2001:0:9d38:6aff:1234:1234:1234:1234]:18333 failed: Network is unreachable (101) 2018-02-28 18:49:11 UpdateTip: new best=000000000000000206b79eb235e5dd907b6369de0e5d764330bf40ec0d460311 height=1286905 version=0x20000000 log2_work=69.791377 tx=17408577 date='2018-02-28 18:49:12' progress=1.000000 cache=1.0MiB(5245txo) ``` After this patch: ``` $ src/bitcoind -printtoconsole … 2018-02-28 18:42:51 UpdateTip: new best=0000000000005448b10a219683d34b770a28044e1cc421032dea1a79ff548948 height=1286903 version=0x20000000 log2_work=69.791313 tx=17408546 date='2018-02-28 18:42:46' progress=1.000000 cache=0.0MiB(173txo) 2018-02-28 18:44:49 UpdateTip: new best=000000000000029a521ff2803e1441b09413b876accff5084a4cccf7747d798b height=1286904 version=0x20000000 log2_work=69.791345 tx=17408559 date='2018-02-28 18:44:51' progress=1.000000 cache=0.1MiB(502txo) 2018-02-28 18:49:11 UpdateTip: new best=000000000000000206b79eb235e5dd907b6369de0e5d764330bf40ec0d460311 height=1286905 version=0x20000000 log2_work=69.791377 tx=17408577 date='2018-02-28 18:49:12' progress=1.000000 cache=1.0MiB(5245txo) ``` Please note that "manual `connect()`:s" (invoked via `-connect`, `-proxy` or `addnode`) are still reported at the default log level as these messages are likely to be relevant to end-users: ``` $ src/bitcoind -printtoconsole -connect=127.0.0.1:1234 … 2018-02-28 18:31:13 connect() to 127.0.0.1:1234 failed after select(): Connection refused (111) $ src/bitcoind -printtoconsole -proxy=127.0.0.1:1234 … 2018-02-28 18:32:32 connect() to 127.0.0.1:1234 failed after select(): Connection refused (111) $ src/bitcoind -printtoconsole & $ src/bitcoin-cli addnode 127.0.0.1:1234 onetry … 2018-02-28 18:33:40 connect() to 127.0.0.1:1234 failed after select(): Connection refused (111) ``` Tree-SHA512: 92e3c1e4b54ce8ccdd7ec31de147c8505710cd799ceb2bbc8576a086709967802403c9184df364b3cfa59bd98859f6ac8feb27fb09b9324194c6c47a042fc6d3
diff --git a/src/net.cpp b/src/net.cpp
@@ -368,7 +368,7 @@ static CAddress GetBindAddress(SOCKET sock)
     return addr_bind;
 }
 
-CNode* CConnman::ConnectNode(CAddress addrConnect, const char *pszDest, bool fCountFailure)
+CNode* CConnman::ConnectNode(CAddress addrConnect, const char *pszDest, bool fCountFailure, bool manual_connection)
 {
     if (pszDest == nullptr) {
         if (IsLocal(addrConnect))
@@ -432,7 +432,7 @@ CNode* CConnman::ConnectNode(CAddress addrConnect, const char *pszDest, bool fCo
             if (hSocket == INVALID_SOCKET) {
                 return nullptr;
             }
-            connected = ConnectSocketDirectly(addrConnect, hSocket, nConnectTimeout);
+            connected = ConnectSocketDirectly(addrConnect, hSocket, nConnectTimeout, manual_connection);
         }
         if (!proxyConnectionFailed) {
             // If a connection to the node was attempted, and failure (if any) is not caused by a problem connecting to
@@ -1992,7 +1992,7 @@ void CConnman::OpenNetworkConnection(const CAddress& addrConnect, bool fCountFai
     } else if (FindNode(std::string(pszDest)))
         return;
 
-    CNode* pnode = ConnectNode(addrConnect, pszDest, fCountFailure);
+    CNode* pnode = ConnectNode(addrConnect, pszDest, fCountFailure, manual_connection);
 
     if (!pnode)
         return;
diff --git a/src/net.h b/src/net.h
@@ -338,7 +338,7 @@ class CConnman
     CNode* FindNode(const CService& addr);
 
     bool AttemptToEvictConnection();
-    CNode* ConnectNode(CAddress addrConnect, const char *pszDest, bool fCountFailure);
+    CNode* ConnectNode(CAddress addrConnect, const char *pszDest, bool fCountFailure, bool manual_connection);
     bool IsWhitelistedRange(const CNetAddr &addr);
 
     void DeleteNode(CNode* pnode);
diff --git a/src/netbase.cpp b/src/netbase.cpp
@@ -9,6 +9,7 @@
 #include <sync.h>
 #include <uint256.h>
 #include <random.h>
+#include <tinyformat.h>
 #include <util.h>
 #include <utilstrencodings.h>
 
@@ -468,7 +469,17 @@ SOCKET CreateSocket(const CService &addrConnect)
     return hSocket;
 }
 
-bool ConnectSocketDirectly(const CService &addrConnect, const SOCKET& hSocket, int nTimeout)
+template<typename... Args>
+static void LogConnectFailure(bool manual_connection, const char* fmt, const Args&... args) {
+    std::string error_message = tfm::format(fmt, args...);
+    if (manual_connection) {
+        LogPrintf("%s\n", error_message);
+    } else {
+        LogPrint(BCLog::NET, "%s\n", error_message);
+    }
+}
+
+bool ConnectSocketDirectly(const CService &addrConnect, const SOCKET& hSocket, int nTimeout, bool manual_connection)
 {
     struct sockaddr_storage sockaddr;
     socklen_t len = sizeof(sockaddr);
@@ -513,7 +524,7 @@ bool ConnectSocketDirectly(const CService &addrConnect, const SOCKET& hSocket, i
             }
             if (nRet != 0)
             {
-                LogPrintf("connect() to %s failed after select(): %s\n", addrConnect.ToString(), NetworkErrorString(nRet));
+                LogConnectFailure(manual_connection, "connect() to %s failed after select(): %s", addrConnect.ToString(), NetworkErrorString(nRet));
                 return false;
             }
         }
@@ -523,7 +534,7 @@ bool ConnectSocketDirectly(const CService &addrConnect, const SOCKET& hSocket, i
         else
 #endif
         {
-            LogPrintf("connect() to %s failed: %s\n", addrConnect.ToString(), NetworkErrorString(WSAGetLastError()));
+            LogConnectFailure(manual_connection, "connect() to %s failed: %s", addrConnect.ToString(), NetworkErrorString(WSAGetLastError()));
             return false;
         }
     }
@@ -581,7 +592,7 @@ bool IsProxy(const CNetAddr &addr) {
 bool ConnectThroughProxy(const proxyType &proxy, const std::string& strDest, int port, const SOCKET& hSocket, int nTimeout, bool *outProxyConnectionFailed)
 {
     // first connect to proxy server
-    if (!ConnectSocketDirectly(proxy.proxy, hSocket, nTimeout)) {
+    if (!ConnectSocketDirectly(proxy.proxy, hSocket, nTimeout, true)) {
         if (outProxyConnectionFailed)
             *outProxyConnectionFailed = true;
         return false;
@@ -601,6 +612,7 @@ bool ConnectThroughProxy(const proxyType &proxy, const std::string& strDest, int
     }
     return true;
 }
+
 bool LookupSubNet(const char* pszName, CSubNet& ret)
 {
     std::string strSubnet(pszName);
diff --git a/src/netbase.h b/src/netbase.h
@@ -52,7 +52,7 @@ bool Lookup(const char *pszName, std::vector<CService>& vAddr, int portDefault,
 CService LookupNumeric(const char *pszName, int portDefault = 0);
 bool LookupSubNet(const char *pszName, CSubNet& subnet);
 SOCKET CreateSocket(const CService &addrConnect);
-bool ConnectSocketDirectly(const CService &addrConnect, const SOCKET& hSocketRet, int nTimeout);
+bool ConnectSocketDirectly(const CService &addrConnect, const SOCKET& hSocketRet, int nTimeout, bool manual_connection);
 bool ConnectThroughProxy(const proxyType &proxy, const std::string& strDest, int port, const SOCKET& hSocketRet, int nTimeout, bool *outProxyConnectionFailed);
 /** Return readable error string for a network error code */
 std::string NetworkErrorString(int err);

Original file line number	Diff line number	Diff line change
`@@ -368,7 +368,7 @@ static CAddress GetBindAddress(SOCKET sock)`
`368`	`368`	`return addr_bind;`
`369`	`369`	`}`
`370`	`370`
`371`		`-CNode* CConnman::ConnectNode(CAddress addrConnect, const char *pszDest, bool fCountFailure)`
	`371`	`+CNode* CConnman::ConnectNode(CAddress addrConnect, const char *pszDest, bool fCountFailure, bool manual_connection)`
`372`	`372`	`{`
`373`	`373`	`if (pszDest == nullptr) {`
`374`	`374`	`if (IsLocal(addrConnect))`
`@@ -432,7 +432,7 @@ CNode* CConnman::ConnectNode(CAddress addrConnect, const char *pszDest, bool fCo`
`432`	`432`	`if (hSocket == INVALID_SOCKET) {`
`433`	`433`	`return nullptr;`
`434`	`434`	`}`
`435`		`- connected = ConnectSocketDirectly(addrConnect, hSocket, nConnectTimeout);`
	`435`	`+ connected = ConnectSocketDirectly(addrConnect, hSocket, nConnectTimeout, manual_connection);`
`436`	`436`	`}`
`437`	`437`	`if (!proxyConnectionFailed) {`
`438`	`438`	`// If a connection to the node was attempted, and failure (if any) is not caused by a problem connecting to`
`@@ -1992,7 +1992,7 @@ void CConnman::OpenNetworkConnection(const CAddress& addrConnect, bool fCountFai`
`1992`	`1992`	`} else if (FindNode(std::string(pszDest)))`
`1993`	`1993`	`return;`
`1994`	`1994`
`1995`		`- CNode* pnode = ConnectNode(addrConnect, pszDest, fCountFailure);`
	`1995`	`+ CNode* pnode = ConnectNode(addrConnect, pszDest, fCountFailure, manual_connection);`
`1996`	`1996`
`1997`	`1997`	`if (!pnode)`
`1998`	`1998`	`return;`
Original file line number	Diff line number	Diff line change
`@@ -9,6 +9,7 @@`
`9`	`9`	`#include <sync.h>`
`10`	`10`	`#include <uint256.h>`
`11`	`11`	`#include <random.h>`
	`12`	`+#include <tinyformat.h>`
`12`	`13`	`#include <util.h>`
`13`	`14`	`#include <utilstrencodings.h>`
`14`	`15`
`@@ -468,7 +469,17 @@ SOCKET CreateSocket(const CService &addrConnect)`
`468`	`469`	`return hSocket;`
`469`	`470`	`}`
`470`	`471`
`471`		`-bool ConnectSocketDirectly(const CService &addrConnect, const SOCKET& hSocket, int nTimeout)`
	`472`	`+template<typename... Args>`
	`473`	`+static void LogConnectFailure(bool manual_connection, const char* fmt, const Args&... args) {`
	`474`	`+ std::string error_message = tfm::format(fmt, args...);`
	`475`	`+ if (manual_connection) {`
	`476`	`+ LogPrintf("%s\n", error_message);`
	`477`	`+ } else {`
	`478`	`+ LogPrint(BCLog::NET, "%s\n", error_message);`
	`479`	`+ }`
	`480`	`+}`
	`481`	`+`
	`482`	`+bool ConnectSocketDirectly(const CService &addrConnect, const SOCKET& hSocket, int nTimeout, bool manual_connection)`
`472`	`483`	`{`
`473`	`484`	`struct sockaddr_storage sockaddr;`
`474`	`485`	`socklen_t len = sizeof(sockaddr);`
`@@ -513,7 +524,7 @@ bool ConnectSocketDirectly(const CService &addrConnect, const SOCKET& hSocket, i`
`513`	`524`	`}`
`514`	`525`	`if (nRet != 0)`
`515`	`526`	`{`
`516`		`- LogPrintf("connect() to %s failed after select(): %s\n", addrConnect.ToString(), NetworkErrorString(nRet));`
	`527`	`+ LogConnectFailure(manual_connection, "connect() to %s failed after select(): %s", addrConnect.ToString(), NetworkErrorString(nRet));`
`517`	`528`	`return false;`
`518`	`529`	`}`
`519`	`530`	`}`
`@@ -523,7 +534,7 @@ bool ConnectSocketDirectly(const CService &addrConnect, const SOCKET& hSocket, i`
`523`	`534`	`else`
`524`	`535`	`#endif`
`525`	`536`	`{`
`526`		`- LogPrintf("connect() to %s failed: %s\n", addrConnect.ToString(), NetworkErrorString(WSAGetLastError()));`
	`537`	`+ LogConnectFailure(manual_connection, "connect() to %s failed: %s", addrConnect.ToString(), NetworkErrorString(WSAGetLastError()));`
`527`	`538`	`return false;`
`528`	`539`	`}`
`529`	`540`	`}`
`@@ -581,7 +592,7 @@ bool IsProxy(const CNetAddr &addr) {`
`581`	`592`	`bool ConnectThroughProxy(const proxyType &proxy, const std::string& strDest, int port, const SOCKET& hSocket, int nTimeout, bool *outProxyConnectionFailed)`
`582`	`593`	`{`
`583`	`594`	`// first connect to proxy server`
`584`		`- if (!ConnectSocketDirectly(proxy.proxy, hSocket, nTimeout)) {`
	`595`	`+ if (!ConnectSocketDirectly(proxy.proxy, hSocket, nTimeout, true)) {`
`585`	`596`	`if (outProxyConnectionFailed)`
`586`	`597`	`*outProxyConnectionFailed = true;`
`587`	`598`	`return false;`
`@@ -601,6 +612,7 @@ bool ConnectThroughProxy(const proxyType &proxy, const std::string& strDest, int`
`601`	`612`	`}`
`602`	`613`	`return true;`
`603`	`614`	`}`
	`615`	`+`
`604`	`616`	`bool LookupSubNet(const char* pszName, CSubNet& ret)`
`605`	`617`	`{`
`606`	`618`	`std::string strSubnet(pszName);`