Cleanup of -debug=net log messages #20724

pull ajtowns wants to merge 5 commits into bitcoin:master from ajtowns:202012-net-log-cleanup changing 3 files +38 −17
  1. ajtowns commented at 6:49 pm on December 19, 2020: member

    A few changes to -debug=net logging:

    • always log when disconnecting a peer
    • only log various connection errors when -debug=net is enabled, since errors from random untrusted peers is completely expected
    • log when ignoring a message due to violating protocol (primarily to make it easier to debug other implementations)
    • use “peer=123” rather than “from 123” to make grepping logs a bit easier
    • log the value of the bip-37 fRelay field in version messages both when sending and receiving a version message
  2. jonatack commented at 6:59 pm on December 19, 2020: member
    Concept ACK
  3. ajtowns commented at 7:17 pm on December 19, 2020: member

    Having run this patch on a node that does tor and accepts incoming connections for a couple of days, with debug logging disabled, my logs have:

    • 248x UpdateTip: new best=…
    • 160x New outbound peer connected: … (block-relay)
    • 15x New outbound peer connected: … (full-relay)
    • 7x Potential stale tip detected, will try using extra outbound peer (last tip update: 1805 seconds ago)

    which mostly seem pretty reasonable indicators of what’s going on.

    But they do also still have:

    validation debug info:

    • 11x ERROR: AcceptBlockHeader: Consensus::ContextualCheckBlockHeader: xxx, bad-diffbits, incorrect proof of work

    socks/tor debug info (netbase.cpp):

    • 2x Socks5() connect to XXX.onion:8333 failed: host unreachable
    • 5x Socks5() connect to XXX.onion:8333 failed: connection refused

    block file management info:

    • 61x Pre-allocating up to position 0xf00000 in rev02368.dat
    • 6x FlushStateToDisk: write coins cache to disk (264560 coins, 36800kB) completed (0.19s)
    • 3x Prune: UnlinkPrunedFiles deleted blk/rev (02353)
    • 2x Leaving block file xxx: CBlockFileInfo(xxx)

    For comparison: #19832 (comment)

  4. practicalswift commented at 7:26 pm on December 19, 2020: contributor

    Very strong Concept ACK: this is a great signal-to-noise improvement!

    Having run this patch on a node that does tor and accepts incoming connections for a couple of days, with debug logging disabled, my logs have:

    • 248x UpdateTip: new best=…
    • 160x New outbound peer connected: … (block-relay)
    • 15x New outbound peer connected: … (full-relay)
    • 7x Potential stale tip detected, will try using extra outbound peer (last tip update: 1805 seconds ago)

    Perfect!

  5. jonatack commented at 7:29 pm on December 19, 2020: member
    Yeah, I’ve resigned myself to always running nodes with net logging on now and grepping for things.
  6. DrahtBot added the label P2P on Dec 19, 2020
  7. DrahtBot commented at 0:27 am on December 20, 2020: member

    The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

    Conflicts

    Reviewers, this pull request conflicts with the following ones:

    • #20942 ([refactor] Move some net_processing globals into PeerManagerImpl by ajtowns)
    • #20721 (Net: Move ping data to net_processing by jnewbery)
    • #20646 (doc: refer to BIPs 339/155 in feature negotiation by jonatack)

    If you consider this pull request important, please also help to review the conflicting pull requests. Ideally, start with the one that should be merged first.

  8. jnewbery commented at 4:02 pm on December 29, 2020: member

    Concept ACK. I have a draft branch that makes fDisconnect private and adds a CNode::Disconncect(), which net processing has to call if it wants to disconnect a peer. That function takes a required message argument which gets logged to the NET category. That’d fix all instances of net_processing not logging disconnections, and ensure that none are introduced in future.

    The branch is here: https://github.com/jnewbery/bitcoin/commits/2020-12-log-disconnect. It doesn’t necessarily need to go in at the same time as this, but it might make sense to try to fix this definitively.

  9. Sjors commented at 2:33 pm on December 30, 2020: member
    Concept ACK
  10. ajtowns force-pushed on Jan 6, 2021
  11. ajtowns marked this as ready for review on Jan 6, 2021
  12. ajtowns commented at 7:46 am on January 6, 2021: member
    Removed dep on #20646 since it’s no longer changing late sendaddrv2 from a disconnect, and marked as ready for review.
  13. ajtowns commented at 7:48 am on January 6, 2021: member
    @jnewbery Didn’t like the change to always evaluating the args to the LogPrint format that comes with a CNode::Disconnect(args...) method, or any of the ideas I had to prevent it, so have left it as is for this PR.
  14. jnewbery commented at 10:50 am on January 6, 2021: member

    Didn’t like the change to always evaluating the args to the LogPrint format that comes with a CNode::Disconnect(args…) method, or any of the ideas I had to prevent it, so have left it as is for this PR.

    Good point about always evaluating the LogPrint args. In practice, I don’t think it matters very much here. These logs are infrequent, only happen once per connection, and none of them have expensive-to-evaluate log args, so the performance impact would be negligible. Still, if you wanted to do it with zero cost, we could implement some NET_LOG_MESSAGE macro that returns a null object if net logging is disabled and returns the formatted string if net logging is enabled.

  15. in src/net_processing.cpp:2567 in 2219a8d896 outdated
    2562@@ -2560,6 +2563,8 @@ void PeerManager::ProcessMessage(CNode& pfrom, const std::string& msg_type, CDat
    2563             if (!State(pfrom.GetId())->m_wtxid_relay) {
    2564                 State(pfrom.GetId())->m_wtxid_relay = true;
    2565                 g_wtxid_relay_peers++;
    2566+            } else {
    2567+                LogPrint(BCLog::NET, "ignoring wtxidrelay due to old common version=%d from peer=%d\n", pfrom.GetCommonVersion(), pfrom.GetId());
    


    jnewbery commented at 10:59 am on January 6, 2021:

    This should be in the next scope out, ie:

    0if (pfrom.GetCommonVersion() >= WTXID_RELAY_VERSION) {
    1    ...
    2} else {
    3    LogPrint(BCLog::NET, "ignoring wtxidrelay...");
    4}
    

    ajtowns commented at 0:46 am on January 7, 2021:
    fixed
  16. felipsoarez commented at 4:51 pm on January 6, 2021: none
    Concept ACK
  17. in src/net.cpp:828 in 2219a8d896 outdated
    824@@ -825,7 +825,7 @@ size_t CConnman::SocketSendData(CNode *pnode) const EXCLUSIVE_LOCKS_REQUIRED(pno
    825                 int nErr = WSAGetLastError();
    826                 if (nErr != WSAEWOULDBLOCK && nErr != WSAEMSGSIZE && nErr != WSAEINTR && nErr != WSAEINPROGRESS)
    827                 {
    828-                    LogPrintf("socket send error %s\n", NetworkErrorString(nErr));
    829+                    LogPrint(BCLog::NET, "socket send error for peer=%d: %s\n", pnode->GetId(), NetworkErrorString(nErr));
    


    ajtowns commented at 0:44 am on January 7, 2021:

    @jnewbery

    (Attaching to an edit to make this a thread instead of top-level comments)

    Good point about always evaluating the LogPrint args. In practice, I don’t think it matters very much here.

    Yeah, I kind-of agree, just didn’t feel comfortable about it. I suspect:

    0    pnode->Disconnect(strprintf("socket send error: %s", NetworkErrorString(nErr));
    

    and

    0void CNode::Disconnect(std::string msg)
    1{
    2    LogPrint(BCLog::NET, "%s; disconnecting peer=%d\n", msg, GetId());
    3    fDisconnect = true;
    4}
    

    would work pretty well.

    Could then retain the “only evaluate args when needed” part by adding a:

    0#define LOGSTRPRINTF(category, fmt, ...) \
    1     (LogAcceptCategory((category)) ? strprintf(fmt, __VA_ARGS__) : "")
    

    to logging.h and making it be pnode->Disconnect(LOGSTRPRINTF(BCLog::NET, "socket send error: %s", NetworkErrorString(nErr)); but, as you say, not sure that’s actually worth the effort.

    (Could potentially have Disconnect() check IsManualConn() and always log disconnection of manual connections too – though would need to do something cleverer to match this with the LOGSTRPRINTF idea…)


    jnewbery commented at 9:07 am on January 7, 2021:
    I agree! Could be done in a follow up.
  18. ajtowns force-pushed on Jan 7, 2021
  19. jnewbery commented at 9:15 am on January 7, 2021: member
    utACK e28d7405c11d407b4665a378ad17bc3e9b81c4f0
  20. DrahtBot added the label Needs rebase on Jan 7, 2021
  21. ajtowns force-pushed on Jan 10, 2021
  22. DrahtBot removed the label Needs rebase on Jan 10, 2021
  23. jnewbery commented at 10:02 am on January 10, 2021: member

    utACK b0070717b4fe33f21d6d0d15bc30a26473f06a90

    Checked range-diff. Only conflict was change from CNode* pnode to CNode& node in SocketSendData().

  24. practicalswift commented at 3:53 pm on January 10, 2021: contributor

    ACK b0070717b4fe33f21d6d0d15bc30a26473f06a90

    Very nice to see so many “attacker log spam” vectors (or worst-case: attacker disk fill vectors) be removed in one go.

    Looking forward to seeing this merged!

  25. DrahtBot commented at 11:46 am on January 13, 2021: member

    ðŸ•ĩïļ @sipa has been requested to review this pull request as specified in the REVIEWERS file.

  26. in src/net.cpp:1007 in b0070717b4 outdated
    1003@@ -1004,6 +1004,7 @@ bool CConnman::AttemptToEvictConnection()
    1004     LOCK(cs_vNodes);
    1005     for (CNode* pnode : vNodes) {
    1006         if (pnode->GetId() == *node_id_to_evict) {
    1007+            LogPrint(BCLog::NET, "selected %s node for eviction peer=%d; disconnecting\n", pnode->ConnectionTypeAsString(), pnode->GetId());
    


    MarcoFalke commented at 3:54 pm on January 13, 2021:

    in commit 9c247a74f0e6b448f9c879c41956e318c753783a:

    nit, since %s is a connection type:

    0            LogPrint(BCLog::NET, "selected %s connection for eviction peer=%d; disconnecting\n", pnode->ConnectionTypeAsString(), pnode->GetId());
    

    ajtowns commented at 1:42 pm on January 14, 2021:
    done
  27. in src/net.cpp:2666 in b0070717b4 outdated
    2662@@ -2662,6 +2663,7 @@ bool CConnman::DisconnectNode(const std::string& strNode)
    2663 {
    2664     LOCK(cs_vNodes);
    2665     if (CNode* pnode = FindNode(strNode)) {
    2666+        LogPrint(BCLog::NET, "DisconnectNode(%s) matches peer=%d; disconnecting\n", strNode, pnode->GetId());
    


    MarcoFalke commented at 3:58 pm on January 13, 2021:

    in commit 9c247a74f0e6b448f9c879c41956e318c753783a:

    Not sure if it makes sense to mention the function name. This will be duplicate if #19809 and force a break anyway on rename. Maybe something like “disconnect {strNode} matches peer={id}” is better?


    ajtowns commented at 10:37 am on January 14, 2021:

    Actually, I guess this logging leaks IP info even with -nologips. Maybe

    0LogPrint(BCLog::NET, "disconnect by address%s matched peer=%d",
    1     (fLogIPs ? strprintf("=%s", strNode) : ""),
    2     pnode->GetId());
    

    ajtowns commented at 1:42 pm on January 14, 2021:
    done
  28. in src/net.cpp:2679 in b0070717b4 outdated
    2675@@ -2674,6 +2676,7 @@ bool CConnman::DisconnectNode(const CSubNet& subnet)
    2676     LOCK(cs_vNodes);
    2677     for (CNode* pnode : vNodes) {
    2678         if (subnet.Match(pnode->addr)) {
    2679+            LogPrint(BCLog::NET, "DisconnectNode(subnet=%s) matches peer=%d; disconnecting\n", subnet.ToString(), pnode->GetId());
    


    MarcoFalke commented at 3:58 pm on January 13, 2021:
    same
  29. in src/net.cpp:2697 in b0070717b4 outdated
    2693@@ -2691,6 +2694,7 @@ bool CConnman::DisconnectNode(NodeId id)
    2694     LOCK(cs_vNodes);
    2695     for(CNode* pnode : vNodes) {
    2696         if (id == pnode->GetId()) {
    2697+            LogPrint(BCLog::NET, "DisconnectNode() peer=%d; disconnecting\n", pnode->GetId());
    


    MarcoFalke commented at 3:58 pm on January 13, 2021:
    same
  30. in src/net_processing.cpp:2663 in b0070717b4 outdated
    2465@@ -2465,6 +2466,7 @@ void PeerManager::ProcessMessage(CNode& pfrom, const std::string& msg_type, CDat
    2466 
    2467         // Feeler connections exist only to verify if address is online.
    2468         if (pfrom.IsFeelerConn()) {
    2469+            LogPrint(BCLog::NET, "feeler connection completed peer=%d; disconnecting\n", pfrom.GetId());
    


    MarcoFalke commented at 4:00 pm on January 13, 2021:

    in commit 9c247a74f0e6b448f9c879c41956e318c753783a:

    Could use the helper to avoid having to change the string here if feeler connections get renamed in any way? (E.g. see https://github.com/bitcoin/bitcoin/pull/20729/files#diff-00021eed586a482abdb09d6cdada1d90115abe988a91421851960e26658bed02L513 which changes a connection type string)

    0            LogPrint(BCLog::NET, "%s connection completed peer=%d; disconnecting\n", pfrom.ConnectionTypeAsString(), pfrom.GetId());
    

    ajtowns commented at 9:34 am on January 14, 2021:
    It’s being disconnected because it matches IsFeelerConn, which is “hardcoded” above – matching that seems right to me
  31. in src/net_processing.cpp:2848 in b0070717b4 outdated
    2649@@ -2638,8 +2650,10 @@ void PeerManager::ProcessMessage(CNode& pfrom, const std::string& msg_type, CDat
    2650         m_connman.AddNewAddresses(vAddrOk, pfrom.addr, 2 * 60 * 60);
    2651         if (vAddr.size() < 1000)
    2652             pfrom.fGetAddr = false;
    2653-        if (pfrom.IsAddrFetchConn())
    2654+        if (pfrom.IsAddrFetchConn()) {
    2655+            LogPrint(BCLog::NET, "addrfetch connection completed peer=%d; disconnecting\n", pfrom.GetId());
    


    MarcoFalke commented at 4:01 pm on January 13, 2021:
    same

    ajtowns commented at 9:34 am on January 14, 2021:
    same :)
  32. MarcoFalke commented at 4:11 pm on January 13, 2021: member

    review ACK b0070717b4fe33f21d6d0d15bc30a26473f06a90 🔘

    Signature:

     0-----BEGIN PGP SIGNED MESSAGE-----
     1Hash: SHA512
     2
     3review ACK b0070717b4fe33f21d6d0d15bc30a26473f06a90 🔘
     4-----BEGIN PGP SIGNATURE-----
     5
     6iQGzBAEBCgAdFiEE+rVPoUahrI9sLGYTzit1aX5ppUgFAlwqrYAACgkQzit1aX5p
     7pUgJAQwAt8D/Rh7yHcjI6ZS+S010qa2U/jXHrKnTvbItbCDH6SMlqyd0djxIfw2t
     8fDT0bOKNGEZOgfy9v5pnDy9ZbtZmO9t/kLwiRYDTvkX0UigWczjkuXnEWIp3QFjL
     9XedcGIRRe5jvVNVS0TIJNGwcNxez5cbnfKVcFMX0aRPoC5h+7IxCOBZQ6PvRlFmC
    10bIj6Z3yhPFBjWXNsfLOPEYGZ74680ahH1GSkJ2ww4aIx/6CNCJhSSH4gIjsbVPBc
    11jDiXwzgPolnv9LPmpLGfoVzAriV4Z9fcA8bewohzLwAJDJHzCE8/LhziPM+fqYpv
    121KHSIL/wJN93UnGtzWQJyWl2p1+meerqUIgqh4sbgBCsL3pQg8AD9sC6HgVOcAxL
    138RDh3f3lDSIHkmk+RC5zm6FzfUurEratFs530w6OwTtgdFoyeeuiZ3RlTHBbdoXG
    14FBaqGjLy3NagvHXqiLFnJJs/pFvQH8hJHh3qosvn2cjF4HB0FLhD/ihcfPw+u9hk
    15f3hY8LO9
    16=VKWw
    17-----END PGP SIGNATURE-----
    

    Timestamp of file with hash d559c553e0361215784d099000b159ebc6ba1b880fcf3dd5cc55c844632bb1fd -

  33. ajtowns force-pushed on Jan 14, 2021
  34. ajtowns commented at 1:44 pm on January 14, 2021: member
    Addressed marco’s comments
  35. practicalswift commented at 1:52 pm on January 14, 2021: contributor
    cr ACK 4424d136c45b6b078afd58d5e8fc609ec7e047eb
  36. MarcoFalke commented at 2:08 pm on January 14, 2021: member

    re-ACK 4424d136c45b6b078afd58d5e8fc609ec7e047eb only change is fLogIPs fixup in first commit ðŸĪš

    Signature:

     0-----BEGIN PGP SIGNED MESSAGE-----
     1Hash: SHA512
     2
     3re-ACK 4424d136c45b6b078afd58d5e8fc609ec7e047eb only change is fLogIPs fixup in first commit ðŸĪš
     4-----BEGIN PGP SIGNATURE-----
     5
     6iQGzBAEBCgAdFiEE+rVPoUahrI9sLGYTzit1aX5ppUgFAlwqrYAACgkQzit1aX5p
     7pUgqoQwAqISXnlIpP4THjATHwGs+vLBlbeZuFHDAS6u5UMga5WFym3t99lsZIspM
     8SMdYiaGJvdPZGgGVw/PRHkQi+ujoC3aBAStbTVgQdz1vjklKRLGtvD6n3+z/xf+o
     9xlE54T5JjSTQUsqVuT6POjJ2fV/DN70PpfZBE/8NU9gl34LQZ5qjCn4C+XkRGiSd
    10fqbyeZj+5Z7Lh7b6nAiRiuZrWBaopcCXYb104ocnSh4O0T4xD1VMv8oeyS5dEcZF
    11H4HA83Y0u9gD4121Qcj41y+XW7uVVp2JXRLEp8bgrgM5jM6WPIRi/AfdtkvV9TXN
    12+Cg5w6jVHzDKKH0BseDfNPB07CbB0fNkZnd6QqdEdLsMFMObtsOInwNXRqXLDPBF
    13ggFa+FKVZ0F4v5Nie0IAHvq840CCtMwO5abSm8Q/wQQUJbpOEiksDqPlUd6JudAM
    14QtOGB3Da3wD4KCWyPzNgyztdTiiDJyc6GP3KE/T3tDuMwGdFm9ZyBHALUhx2j25e
    15cXJ2Zw9M
    16=xx8F
    17-----END PGP SIGNATURE-----
    

    Timestamp of file with hash 60eed5124ad741183bbbac3829cdb44ecd93be7850cab223e0d08ecf68aafea0 -

  37. decryp2kanon commented at 6:36 pm on January 19, 2021: contributor
    Concept ACK. I really wanted this!
  38. DrahtBot added the label Needs rebase on Jan 22, 2021
  39. jnewbery commented at 2:42 pm on January 22, 2021: member

    My PR being merged made this one conflict with master. I’ve rebased it here: https://github.com/jnewbery/bitcoin/tree/pr20724.1. Feel free to take that if it helps.

    utACK dd0aeacd1892d225bf24402fe8f1f73b829d1293 if you take it.

  40. net, net_processing: log disconnect reasons with -debug=net a410ae8cb0
  41. net: make debug logging conditional on -debug=net f7edea3b7c
  42. net_processing: additional debug logging for ignored messages 12302105bb
  43. net: use peer=N instead of from=N in debug log 98fab37ca0
  44. net_processing: log txrelay flag from version message 48c8a9b964
  45. ajtowns force-pushed on Jan 28, 2021
  46. ajtowns commented at 8:07 am on January 28, 2021: member

    My PR being merged made this one conflict with master. I’ve rebased it here: https://github.com/jnewbery/bitcoin/tree/pr20724.1. Feel free to take that if it helps.

    I manually rebased it onto master in order to include #21000, but I think I got the same changes as your rebase anyway.

  47. jnewbery commented at 8:47 am on January 28, 2021: member

    ACK 48c8a9b96453ca429b38fc5d5181a310ae5a93bf

    Confirmed I got the same rebase.

  48. DrahtBot removed the label Needs rebase on Jan 28, 2021
  49. MarcoFalke commented at 1:12 pm on January 28, 2021: member

    re-ACK 48c8a9b96453ca429b38fc5d5181a310ae5a93bf only change is rebase 🚓

    Signature:

     0-----BEGIN PGP SIGNED MESSAGE-----
     1Hash: SHA512
     2
     3re-ACK 48c8a9b96453ca429b38fc5d5181a310ae5a93bf only change is rebase 🚓
     4-----BEGIN PGP SIGNATURE-----
     5
     6iQGzBAEBCgAdFiEE+rVPoUahrI9sLGYTzit1aX5ppUgFAlwqrYAACgkQzit1aX5p
     7pUgnVwwAlze3mNIb4mRh4Mr+XMEaMI6bUlDanx4Rgcp4R8Dqu0wJvbIxbfuHbQpR
     8Rs5gmC+aSBb+Orjp1WOxNfOuJ9us3BAb4082jeUH1Pm+UCQ3c2LxmKBQpJlLcHJA
     9b1U1QaDWph8PoXCubnc1RUkYQV5iSJFqjr2WHnEQdRNmlbKWCWBEmxYGT6jBZ6jg
    10+i/GziAkpHvuyBlJ/XveizM/sLMeLMFwejb7PJHba5y2+d5p0auBdnLbm0h+V+iy
    11k8khtntYpJE00Dx+e/IN9ts2b5tNlQm7cr1MsRcy2o4W0LJAKtfM/cUl9GtGP6NF
    12UKp8qWoWJ9oo0sz4jkbnCPjjAEm88pJG8gCabfLW8wOmGSq5sCfwfg9fMcqefo/L
    13TbISj8/UppDUY6VRHCQ12EenEPBFOn0fr3SJSg/NtDIS2AKRRKuwNl5nBUm38lGx
    14sOcRWaVUyGCvABLSXVHVu2NSw/bK8ASHWk7CzgVQkCsD02BUvuTWW7JZsqh5/zvY
    15LN47eajM
    16=pRyt
    17-----END PGP SIGNATURE-----
    

    Timestamp of file with hash 0e792c55bddfb72884acc7a3bc32aebea29b43c845e5ef32b815c89f74e24c28 -

  50. practicalswift commented at 9:07 pm on January 28, 2021: contributor
    re-ACK 48c8a9b96453ca429b38fc5d5181a310ae5a93bf
  51. MarcoFalke merged this on Jan 29, 2021
  52. MarcoFalke closed this on Jan 29, 2021

  53. RonSherfey referenced this in commit 7f37fbc3b6 on Jan 29, 2021
  54. sidhujag referenced this in commit eaae2a17c1 on Jan 29, 2021
  55. laanwj referenced this in commit 937dfa8398 on Feb 11, 2021
  56. sidhujag referenced this in commit d60eaac0e8 on Feb 11, 2021
  57. deadalnix referenced this in commit b98c847ec1 on Jan 28, 2022
  58. DrahtBot locked this on Aug 16, 2022

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-12-18 21:12 UTC

This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me