net: Disconnect message follow-ups to #28521 #31633

pull hodlinator wants to merge 4 commits into bitcoin:master from hodlinator:2024/12/disconnecting changing 3 files +9 −8
  1. hodlinator commented at 10:43 am on January 10, 2025: contributor
  2. net_processing: Add missing use of DisconnectMsg 
    Makes it easier to grep logs for "disconnecting" when investigating disconnections.
    0c4954ac7d
  3. net: Specify context in disconnecting log message 04b848e482
  4. net: Bring back log message when resetting socket 
    Useful in case new disconnects creep in which are not using DisconnectMsg().
    bbac17608d
  5. DrahtBot commented at 10:43 am on January 10, 2025: contributor

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

    Code Coverage & Benchmarks

    For details see: https://corecheck.dev/bitcoin/bitcoin/pulls/31633.

    Reviews

    See the guideline for information on the review process.

    Type Reviewers
    ACK Sjors, l0rinc, danielabrozzoni, davidgumberg, achow101
    Stale ACK maflcko

    If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.

    Conflicts

    Reviewers, this pull request conflicts with the following ones:

    • #30988 (Split CConnman by vasild)
    • #25832 (tracing: network connection tracepoints by 0xB10C)

    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.

  6. DrahtBot added the label P2P on Jan 10, 2025
  7. maflcko commented at 11:06 am on January 10, 2025: member

    review ACK 286de9749612565fd8d42f08f66c8426faf8a1f7 📋

    Signature:

    0untrusted comment: signature from minisign secret key on empty file; verify via: minisign -Vm "${path_to_any_empty_file}" -P RWTRmVTMeKV5noAMqVlsMugDDCyyTSbA3Re5AkUrhvLVln0tSaFWglOw -x "${path_to_this_whole_four_line_signature_blob}"
1RUTRmVTMeKV5npGrKx1nqXCw5zeVHdtdYURB/KlyA/LMFgpNCs+SkW9a8N95d+U4AP1RJMi+krxU1A3Yux4bpwZNLvVBKy0wLgM=
2trusted comment: review ACK 286de9749612565fd8d42f08f66c8426faf8a1f7 📋
3KIc3ZvWyWMcblu8xFcmTzLk/937/Mbtwhz9zc6/xQx5LWmvhMIpVwAXU2Z+0Lh0UfNs09bOeyVM3/HZtxfNODA==
  8. in src/net.cpp:561 in 286de97496 outdated 
    557@@ -558,6 +558,7 @@ void CNode::CloseSocketDisconnect()
558     fDisconnect = true;
559     LOCK(m_sock_mutex);
560     if (m_sock) {
561+        LogDebug(BCLog::NET, "Resetting socket for peer=%d%s", GetId(), LogIP(fLogIPs));
    l0rinc commented at 11:14 am on January 10, 2025:
    I found the %d%s format weird at first, but I see it is an existing format, e.g. https://github.com/bitcoin/bitcoin/blob/master/src/net.cpp#L705
    Sjors commented at 12:44 pm on January 14, 2025:
    This does make the debug level even noisier. But since it doesn’t have the word “disconnect” it’s probably fine.
    hodlinator commented at 3:19 pm on January 14, 2025:
    What do you think about downgrading it to LogTrace?
    Sjors commented at 1:34 pm on January 27, 2025:
    That seems better, if you need to retouch.
    davidgumberg commented at 5:26 pm on January 27, 2025:

    I’m OK with having each phase of node disconnect logged like this since I could imagine there are edge cases where it might be important to know whether or not the peer’s socket has been reset or if we’ve just made the decision to disconnect the peer, in playing with it a few times it looks like this log has already revealed some interesting behavior where we’re retrying with v1 transport when maybe we shouldn’t be:

     0$ bitcoin-cli setnetworkactive=false
 1$ tail -n 60 debug.log | grep "\[net\]"
 22025-01-27T17:20:38Z [net] Network not active, disconnecting peer=1
 32025-01-27T17:20:38Z [net] Network not active, disconnecting peer=4
 42025-01-27T17:20:38Z [net] Network not active, disconnecting peer=7
 52025-01-27T17:20:38Z [net] Network not active, disconnecting peer=11
 62025-01-27T17:20:38Z [net] Network not active, disconnecting peer=12
 72025-01-27T17:20:38Z [net] Resetting socket for peer=1
 82025-01-27T17:20:38Z [net] Resetting socket for peer=4
 92025-01-27T17:20:38Z [net] Resetting socket for peer=7
102025-01-27T17:20:38Z [net] Resetting socket for peer=11
112025-01-27T17:20:38Z [net] retrying with v1 transport protocol for peer=12 # <-----
122025-01-27T17:20:38Z [net] Resetting socket for peer=12
132025-01-27T17:20:38Z [net] Cleared nodestate for peer=1
142025-01-27T17:20:38Z [net] Cleared nodestate for peer=4
152025-01-27T17:20:38Z [net] Cleared nodestate for peer=7
162025-01-27T17:20:38Z [net] Cleared nodestate for peer=11
172025-01-27T17:20:38Z [net] Cleared nodestate for peer=12
    hodlinator commented at 7:34 pm on January 27, 2025:

    Hm.. seems like maybe we should be checking fNetworkActive in another place - in the same condition as ShouldReconnectV1()?

    https://github.com/bitcoin/bitcoin/blob/551a09486c495e1a3cfc296eafdf95e914856bff/src/net.cpp#L1890-L1912

  9. in src/net.cpp:3611 in 286de97496 outdated 
    3607@@ -3607,7 +3608,7 @@ bool CConnman::DisconnectNode(const std::string& strNode)
3608 {
3609     LOCK(m_nodes_mutex);
3610     if (CNode* pnode = FindNode(strNode)) {
3611-        LogDebug(BCLog::NET, "disconnect by address%s matched peer=%d; disconnecting\n", (fLogIPs ? strprintf("=%s", strNode) : ""), pnode->GetId());
3612+        LogDebug(BCLog::NET, "disconnect by address%s match; %s", (fLogIPs ? strprintf("=%s", strNode) : ""), pnode->DisconnectMsg(fLogIPs));
    l0rinc commented at 11:16 am on January 10, 2025:
    super-nit: above we’re using a simple , before the DisconnectMsg, not a ;.
    hodlinator commented at 3:20 pm on January 14, 2025:
    Agree, will change if I re-touch.
    hodlinator commented at 1:25 pm on January 27, 2025:
    Done in latest push.
  10. in src/net.cpp:3624 in 286de97496 outdated 
    3620@@ -3620,7 +3621,7 @@ bool CConnman::DisconnectNode(const CSubNet& subnet)
3621     LOCK(m_nodes_mutex);
3622     for (CNode* pnode : m_nodes) {
3623         if (subnet.Match(pnode->addr)) {
3624-            LogDebug(BCLog::NET, "disconnect by subnet%s matched peer=%d; disconnecting\n", (fLogIPs ? strprintf("=%s", subnet.ToString()) : ""), pnode->GetId());
3625+            LogDebug(BCLog::NET, "disconnect by subnet%s match; %s", (fLogIPs ? strprintf("=%s", subnet.ToString()) : ""), pnode->DisconnectMsg(fLogIPs));
    l0rinc commented at 11:17 am on January 10, 2025:
    nit: many other similar logs here were capitalized
    hodlinator commented at 3:28 pm on January 14, 2025:
    I feel a slight itch here as well, but will probably leave casing as-is as in keeping with the original pull request.
  11. in src/net_processing.cpp:5210 in 286de97496 outdated 
    5206@@ -5207,7 +5207,7 @@ void PeerManagerImpl::MaybeSendPing(CNode& node_to, Peer& peer, std::chrono::mic
5207     {
5208         // The ping timeout is using mocktime. To disable the check during
5209         // testing, increase -peertimeout.
5210-        LogDebug(BCLog::NET, "ping timeout: %fs peer=%d\n", 0.000001 * count_microseconds(now - peer.m_ping_start.load()), peer.m_id);
5211+        LogDebug(BCLog::NET, "ping timeout: %fs, %s", 0.000001 * count_microseconds(now - peer.m_ping_start.load()), node_to.DisconnectMsg(fLogIPs));
    l0rinc commented at 11:30 am on January 10, 2025:
    unrelated: do we really need this level of detail for a timeout (i.e. ms precision expressed in seconds)?
    hodlinator commented at 3:24 pm on January 14, 2025:

    ping on my main system seems to care about ms+3 decimals (I’m guessing that’s milliseconds+3 decimals => microseconds):

    0₿ ping 192.168.1.133
1PING 192.168.1.133 (192.168.1.133): 56 data bytes
264 bytes from 192.168.1.133: icmp_seq=0 ttl=214 time=0.765 ms
  12. l0rinc approved
  13. l0rinc commented at 11:30 am on January 10, 2025: contributor
    utACK 286de9749612565fd8d42f08f66c8426faf8a1f7
  14. Sjors commented at 12:47 pm on January 14, 2025: member
    utACK 286de9749612565fd8d42f08f66c8426faf8a1f7
  15. danielabrozzoni commented at 5:21 pm on January 24, 2025: contributor

    Concept ACK, I think there’s still one log to update to use DisconnectMsg in net.cpp :

    https://github.com/bitcoin/bitcoin/blob/286de9749612565fd8d42f08f66c8426faf8a1f7/src/net.cpp#L1710

  16. net: Switch to DisconnectMsg in CConnman 551a09486c
  17. hodlinator force-pushed on Jan 27, 2025
  18. hodlinator commented at 1:24 pm on January 27, 2025: contributor

    I think there’s still one log to update to use DisconnectMsg in net.cpp :

    Thanks! Clear enough case to warrant a new push together with the remaining nit.

    After the latest push, there still remain 4 cases, but they are a bit harder to re-word, and at least contain “disconnecting”:

    0₿ git grep -n "\bLog.*disconnecting"
1src/net_processing.cpp:3446:            LogPrintf("connected to self at %s, disconnecting\n", pfrom.addr.ToStringAddrPort());
2src/net_processing.cpp:4913:        LogDebug(BCLog::NET, "Warning: disconnecting but not discouraging %s peer %d!\n",
3src/net_processing.cpp:5103:                LogDebug(BCLog::NET, "disconnecting extra block-relay-only peer=%d (last block received at time %d)\n",
4src/net_processing.cpp:5154:                    LogDebug(BCLog::NET, "disconnecting extra outbound peer=%d (last block announcement received at time %d)\n", pnode->GetId(), oldest_block_announcement);

    Also attempted to double-check using git grep -n -A1 -B1 -E "(fDisconnect.*=[^=]*|CloseSocketDisconnect)", didn’t spot any further cases.

  19. Sjors commented at 1:33 pm on January 27, 2025: member

    re-utACK 551a09486c495e1a3cfc296eafdf95e914856bff

    Adds the case @danielabrozzoni found and replaces 3 ; with ,

  20. DrahtBot requested review from maflcko on Jan 27, 2025
  21. DrahtBot requested review from l0rinc on Jan 27, 2025
  22. DrahtBot requested review from danielabrozzoni on Jan 27, 2025
  23. l0rinc commented at 1:39 pm on January 27, 2025: contributor
    utACK 551a09486c495e1a3cfc296eafdf95e914856bff
  24. danielabrozzoni approved
  25. danielabrozzoni commented at 2:15 pm on January 27, 2025: contributor

    Thanks for the update!

    ACK 551a09486c495e1a3cfc296eafdf95e914856bff

  26. davidgumberg commented at 5:39 pm on January 27, 2025: contributor

    Tested and Review ACK https://github.com/bitcoin/bitcoin/commit/551a09486c495e1a3cfc296eafdf95e914856bff

    More disconnectmsg reuse, provides context in the node shutdown disconnect case, and makes disconnect logging more granular.

     0$ bitcoin-cli stop
 1$ tail -n 60 debug.log | grep "\[net\]"
 22025-01-27T17:37:29Z [net] Stopping node, disconnecting peer=1
 32025-01-27T17:37:29Z [net] Resetting socket for peer=1
 42025-01-27T17:37:29Z [net] Cleared nodestate for peer=1
 52025-01-27T17:37:29Z [net] Stopping node, disconnecting peer=2
 62025-01-27T17:37:29Z [net] Resetting socket for peer=2
 72025-01-27T17:37:29Z [net] Cleared nodestate for peer=2
 82025-01-27T17:37:29Z [net] Stopping node, disconnecting peer=3
 92025-01-27T17:37:29Z [net] Resetting socket for peer=3
102025-01-27T17:37:29Z [net] Cleared nodestate for peer=3
112025-01-27T17:37:29Z [net] Stopping node, disconnecting peer=4
122025-01-27T17:37:29Z [net] Resetting socket for peer=4
132025-01-27T17:37:29Z [net] Cleared nodestate for peer=4
142025-01-27T17:37:29Z [net] Stopping node, disconnecting peer=5
152025-01-27T17:37:29Z [net] Resetting socket for peer=5
162025-01-27T17:37:29Z [net] Cleared nodestate for peer=5
172025-01-27T17:37:29Z [net] Stopping node, disconnecting peer=6
182025-01-27T17:37:29Z [net] Resetting socket for peer=6
192025-01-27T17:37:29Z [net] Cleared nodestate for peer=6
202025-01-27T17:37:29Z [net] Stopping node, disconnecting peer=12
212025-01-27T17:37:29Z [net] Resetting socket for peer=12
222025-01-27T17:37:29Z [net] Cleared nodestate for peer=12
232025-01-27T17:37:29Z [net] Stopping node, disconnecting peer=13
242025-01-27T17:37:29Z [net] Resetting socket for peer=13
252025-01-27T17:37:29Z [net] Cleared nodestate for peer=13
262025-01-27T17:37:29Z [net] Stopping node, disconnecting peer=15
272025-01-27T17:37:29Z [net] Resetting socket for peer=15
282025-01-27T17:37:29Z [net] Cleared nodestate for peer=15

     0$ bitcoin-cli setnetworkactive=false
 1$ tail -n 60 debug.log | grep "\[net\]"
 22025-01-27T17:33:40Z [net] Network not active, disconnecting peer=0
 32025-01-27T17:33:40Z [net] Network not active, disconnecting peer=1
 42025-01-27T17:33:40Z [net] Network not active, disconnecting peer=2
 52025-01-27T17:33:40Z [net] Network not active, disconnecting peer=3
 62025-01-27T17:33:40Z [net] Network not active, disconnecting peer=4
 72025-01-27T17:33:40Z [net] Network not active, disconnecting peer=5
 82025-01-27T17:33:40Z [net] Resetting socket for peer=0
 92025-01-27T17:33:40Z [net] Resetting socket for peer=1
102025-01-27T17:33:40Z [net] Resetting socket for peer=2
112025-01-27T17:33:40Z [net] Resetting socket for peer=3
122025-01-27T17:33:40Z [net] Resetting socket for peer=4
132025-01-27T17:33:40Z [net] Resetting socket for peer=5
142025-01-27T17:33:40Z [net] Cleared nodestate for peer=0
152025-01-27T17:33:40Z [net] Cleared nodestate for peer=1
162025-01-27T17:33:40Z [net] Cleared nodestate for peer=2
172025-01-27T17:33:40Z [net] Cleared nodestate for peer=3
182025-01-27T17:33:40Z [net] Cleared nodestate for peer=4
192025-01-27T17:33:40Z [net] Cleared nodestate for peer=5
  27. achow101 commented at 8:18 pm on January 29, 2025: member
    ACK 551a09486c495e1a3cfc296eafdf95e914856bff
  28. achow101 merged this on Jan 29, 2025
  29. achow101 closed this on Jan 29, 2025


hodlinator DrahtBot maflcko l0rinc Sjors davidgumberg danielabrozzoni achow101


l0rinc maflcko

Labels
P2P

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: 2025-02-22 15:12 UTC
This site is hosted by @0xB10C
More mirrored repositories can be found on mirror.b10c.me