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

pull practicalswift wants to merge 1 commits into bitcoin:master from practicalswift:logging-signal-to-noise changing 4 files +21 −9
  1. practicalswift commented at 8:34 pm on February 28, 2018: contributor

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

    Before this patch:

    0$ src/bitcoind -printtoconsole
1…
22018-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)
32018-02-28 18:37:52 connect() 10.11.21.34:18333 failed after select(): Connection refused (111)
42018-02-28 18:43:22 connect() to 10.11.43.14:18333 failed after select(): Network is unreachable (101)
52018-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)
62018-02-28 18:46:54 connect() to [2001:0:9d38:78ff:1234:1234:1234:1234]:18333 failed: Network is unreachable (101)
72018-02-28 18:48:56 connect() to [2001:0:9d38:6aff:1234:1234:1234:1234]:18333 failed: Network is unreachable (101)
82018-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:

    0$ src/bitcoind -printtoconsole
1…
22018-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)
32018-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)
42018-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:

     0$ src/bitcoind -printtoconsole -connect=127.0.0.1:1234
 1…
 22018-02-28 18:31:13 connect() to 127.0.0.1:1234 failed after select(): Connection refused (111)
 3
 4$ src/bitcoind -printtoconsole -proxy=127.0.0.1:1234
 5…
 62018-02-28 18:32:32 connect() to 127.0.0.1:1234 failed after select(): Connection refused (111)
 7
 8$ src/bitcoind -printtoconsole &
 9$ src/bitcoin-cli addnode 127.0.0.1:1234 onetry
10…
112018-02-28 18:33:40 connect() to 127.0.0.1:1234 failed after select(): Connection refused (111)
  2. practicalswift renamed this:
    Increase signal-to-noise ratio in debug.log by adjusting log level when logging failed non-manual connect():s
    net: Increase signal-to-noise ratio in debug.log by adjusting log level when logging failed non-manual connect():s
    on Feb 28, 2018
  3. randolf commented at 9:38 pm on February 28, 2018: contributor
    Just to confirm: With a higher debug level set, all those “connect” errors can still be logged?
  4. practicalswift commented at 9:42 pm on February 28, 2018: contributor
    @randolf Exactly :-)
  5. randolf approved
  6. in src/net.cpp:1963 in 70feb3d252 outdated 
    1959@@ -1960,7 +1960,7 @@ void CConnman::ThreadOpenAddedConnections()
1960 }
1961 
1962 // if successful, this moves the passed grant to the constructed node
1963-void CConnman::OpenNetworkConnection(const CAddress& addrConnect, bool fCountFailure, CSemaphoreGrant *grantOutbound, const char *pszDest, bool fOneShot, bool fFeeler, bool manual_connection)
1964+void CConnman::OpenNetworkConnection(const CAddress& addrConnect, bool fCountFailure, CSemaphoreGrant *grantOutbound, const char *pszDest, bool fOneShot, bool fFeeler, bool fManualConnection)
    Empact commented at 0:18 am on March 1, 2018:
    FYI the style guide prefers the prior style: “Variable and namespace names are all lowercase, and may use _ to separate words (snake_case)”
  7. in src/netbase.cpp:536 in 70feb3d252 outdated 
    532+            std::string strConnectFailure = strprintf("connect() to %s failed: %s", addrConnect.ToString(), NetworkErrorString(WSAGetLastError()));
533+            if (fManualConnection) {
534+                LogPrintf("%s\n", strConnectFailure);
535+            } else {
536+                LogPrint(BCLog::NET, "%s\n", strConnectFailure);
537+            }
    Empact commented at 0:22 am on March 1, 2018:
    Maybe extract a LogConnectFailure method to DRY these two up?
  8. fanquake added the label Utils/log/libs on Mar 1, 2018
  9. practicalswift force-pushed on Mar 9, 2018
  10. practicalswift force-pushed on Mar 9, 2018
  11. practicalswift commented at 3:17 pm on March 9, 2018: contributor
    @Empact Thanks for reviewing. Updated in light of review. Please re-review :-)
  12. in src/netbase.cpp:595 in 84b4fe3a83 outdated 
    588@@ -581,7 +589,7 @@ bool IsProxy(const CNetAddr &addr) {
589 bool ConnectThroughProxy(const proxyType &proxy, const std::string& strDest, int port, const SOCKET& hSocket, int nTimeout, bool *outProxyConnectionFailed)
590 {
591     // first connect to proxy server
592-    if (!ConnectSocketDirectly(proxy.proxy, hSocket, nTimeout)) {
593+    if (!ConnectSocketDirectly(proxy.proxy, hSocket, nTimeout, true)) {
    instagibbs commented at 8:15 pm on March 9, 2018:

    not totally clear to me this should be true?

    I admit I don’t know the networking code as well.

    practicalswift commented at 5:20 pm on March 10, 2018:
    This is the connection to the proxy server. Since the proxy server is specified by the user it is handled as a “manual” connection since any connection errors are likely of relevance to the end-user and thus should be logged. Makes sense? :-)
  13. in src/netbase.cpp:471 in 84b4fe3a83 outdated 
    467@@ -468,7 +468,15 @@ SOCKET CreateSocket(const CService &addrConnect)
468     return hSocket;
469 }
470 
471-bool ConnectSocketDirectly(const CService &addrConnect, const SOCKET& hSocket, int nTimeout)
472+void LogConnectFailure(const std::string& error_message, bool manual_connection) {
    eklitzke commented at 8:29 am on March 11, 2018:
    I know this is annoying, but can you use argument forwarding or make this variadic? That would avoid allocation when the message is not going to be logged.
  14. eklitzke commented at 8:32 am on March 11, 2018: contributor
    Concept ACK. Regarding argument forwarding, there’s related code for FatalError() in #11857 that I think you could re-use here.
  15. 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-28T18:37:52Z 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 as usual:

```
$ src/bitcoind -printtoconsole -connect=10.11.12.13
…
2018-02-28 18:33:13 connect() to 10.11.12.13:18333 failed after select(): Connection refused (111)
$ src/bitcoind -printtoconsole -proxy=10.11.12.13
…
2018-02-28 18:32:32 connect() to 10.11.12.13:9050 failed after select(): Connection refused (111)
$ src/bitcoind -printtoconsole &
$ src/bitcoin-cli addnode "10.11.12.13" onetry
…
2018-02-28 18:34:40 connect() to 10.11.12.13:18333 failed after select(): Connection refused (111)
```
    cba2800e8c
  16. practicalswift force-pushed on Mar 11, 2018
  17. practicalswift commented at 9:50 am on March 11, 2018: contributor
    @eklitzke Good point! Updated. Please re-review :-)
  18. eklitzke commented at 5:19 am on March 13, 2018: contributor
    That change looks good, but one other thing occurred to me just now. I think we already have special logic for handling peers added using addnode, and that should definitely be treated as a “manual” connection case. Can you take a look at that?
  19. practicalswift commented at 6:58 am on March 13, 2018: contributor

    @eklitzke It already is:

    0$ src/bitcoind -printtoconsole &
1$ src/bitcoin-cli addnode 127.0.0.1:1234 onetry
2…
32018-02-28 18:33:40 connect() to 127.0.0.1:1234 failed after select(): Connection refused (111)

    :-)

  20. sipa commented at 0:21 am on March 17, 2018: member
    utACK cba2800e8c4e73c2eddff76880b55d930c5010f6
  21. eklitzke commented at 1:16 am on March 17, 2018: contributor
    utACK cba2800e8c4e73c2eddff76880b55d930c5010f6
  22. minhhoang123 changes_requested
  23. minhhoang123 commented at 1:02 am on March 28, 2018: none
    Good
  24. eklitzke approved
  25. practicalswift commented at 2:38 am on March 28, 2018: contributor
    @laanwj Would it be possible to get this PR tagged with a 0.17.0 milestone? :-)
  26. ajtowns commented at 9:15 am on April 12, 2018: member
    utACK cba2800e8c4e73c2eddff76880b55d930c5010f6
  27. laanwj merged this on Apr 13, 2018
  28. laanwj closed this on Apr 13, 2018
  29. laanwj referenced this in commit 23e7fe8be8 on Apr 13, 2018
  30. PastaPastaPasta referenced this in commit 7be4e84847 on Nov 10, 2020
  31. PastaPastaPasta referenced this in commit 396c42dfde on Nov 12, 2020
  32. PastaPastaPasta referenced this in commit 0c6ba028c1 on Nov 17, 2020
  33. practicalswift deleted the branch on Apr 10, 2021
  34. furszy referenced this in commit 5bc3245e6e on Feb 20, 2022
  35. gades referenced this in commit 7468bbc51f on Mar 17, 2022
  36. DrahtBot locked this on Aug 18, 2022


practicalswift randolf Empact instagibbs eklitzke sipa minhhoang123 ajtowns

Labels
Utils/log/libs

github-metadata-mirror

This is a metadata mirror of the GitHub repository bitcoin/bitcoin. This site is not affiliated with GitHub. Content is generated from a GitHub metadata backup.
generated: 2024-07-05 19:13 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me