Cleanup of -debug=net log messages by ajtowns · Pull Request #20724 · bitcoin/bitcoin

ajtowns · 2020-12-19T18:49:51Z

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

jonatack · 2020-12-19T18:59:11Z

Concept ACK

ajtowns · 2020-12-19T19:17:39Z

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)

practicalswift · 2020-12-19T19:26:04Z

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!

jonatack · 2020-12-19T19:29:33Z

Yeah, I've resigned myself to always running nodes with net logging on now and grepping for things.

DrahtBot · 2020-12-20T00:27:55Z

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

Conflicts

Reviewers, this pull request conflicts with the following ones:

[refactor] Move some net_processing globals into PeerManagerImpl #20942 ([refactor] Move some net_processing globals into PeerManagerImpl by ajtowns)
Net: Move ping data to net_processing #20721 (Net: Move ping data to net_processing by jnewbery)
doc: refer to BIPs 339/155 in feature negotiation #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.

jnewbery · 2020-12-29T16:02:57Z

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.

Sjors · 2020-12-30T14:33:24Z

Concept ACK

ajtowns · 2021-01-06T07:46:03Z

Removed dep on #20646 since it's no longer changing late sendaddrv2 from a disconnect, and marked as ready for review.

ajtowns · 2021-01-06T07:48:30Z

@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.

jnewbery · 2021-01-06T10:50:00Z

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.

src/net_processing.cpp

felipsoarez

Concept ACK

src/net.cpp

jnewbery · 2021-01-07T09:15:34Z

utACK e28d7405c11d407b4665a378ad17bc3e9b81c4f0

jnewbery · 2021-01-10T10:02:01Z

utACK b0070717b4fe33f21d6d0d15bc30a26473f06a90

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

practicalswift · 2021-01-10T15:53:16Z

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!

DrahtBot · 2021-01-13T11:46:27Z

🕵️ @sipa has been requested to review this pull request as specified in the REVIEWERS file.

maflcko

review ACK b0070717b4fe33f21d6d0d15bc30a26473f06a90 🔘

Show signature and timestamp

Signature:

Timestamp of file with hash d559c553e0361215784d099000b159ebc6ba1b880fcf3dd5cc55c844632bb1fd -

src/net.cpp

src/net_processing.cpp

ajtowns · 2021-01-14T13:44:02Z

Addressed marco's comments

practicalswift · 2021-01-14T13:52:43Z

cr ACK 4424d136c45b6b078afd58d5e8fc609ec7e047eb

maflcko · 2021-01-14T14:08:49Z

re-ACK 4424d136c45b6b078afd58d5e8fc609ec7e047eb only change is fLogIPs fixup in first commit 🤺

Show signature and timestamp

Signature:

Timestamp of file with hash 60eed5124ad741183bbbac3829cdb44ecd93be7850cab223e0d08ecf68aafea0 -

decryp2kanon · 2021-01-19T18:36:52Z

Concept ACK. I really wanted this!

jnewbery · 2021-01-22T14:42:56Z

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 dd0aeac if you take it.

ajtowns · 2021-01-28T08:07:46Z

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.

jnewbery · 2021-01-28T08:47:04Z

ACK 48c8a9b

Confirmed I got the same rebase.

maflcko · 2021-01-28T13:12:14Z

re-ACK 48c8a9b only change is rebase 🚓

Show signature and timestamp

Signature:

Timestamp of file with hash 0e792c55bddfb72884acc7a3bc32aebea29b43c845e5ef32b815c89f74e24c28 -

practicalswift · 2021-01-28T21:07:37Z

re-ACK 48c8a9b

48c8a9b net_processing: log txrelay flag from version message (Anthony Towns) 98fab37 net: use peer=N instead of from=N in debug log (Anthony Towns) 1230210 net_processing: additional debug logging for ignored messages (Anthony Towns) f7edea3 net: make debug logging conditional on -debug=net (Anthony Towns) a410ae8 net, net_processing: log disconnect reasons with -debug=net (Anthony Towns) Pull request description: 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 ACKs for top commit: jnewbery: ACK 48c8a9b MarcoFalke: re-ACK 48c8a9b only change is rebase 🚓 practicalswift: re-ACK 48c8a9b Tree-SHA512: 6ac530d883dffc4fd7fe20b1dc5ebb5394374c9b499aa7a253eb4a3a660d8901edd72e5ad21ce4a2bf71df25e8f142087755f9756f3497f564ef453a7e9246c1

…at" log message to debug category 25f899c log: Move "Pre-allocating up to position 0x[...] in [...].dat" log message to debug category (practicalswift) acd7980 log: Move "Leaving block file [...]: [...]" log message to debug category (practicalswift) Pull request description: Move `Pre-allocating up to position 0x[…] in […].dat` log message to debug category. After the cleanup of `-debug=net` log messages PR (#20724) was merged recently the console log now has very high signal to noise ratio. That's great! :) This PR increases the signal to noise ratio slightly more by moving the most common remaining implementation detail log message (`Pre-allocating up to position 0x[…] in […].dat`) to the debug category where it belongs :) Expected standard output from `bitcoind` (when in steady state) before this patch: ``` $ src/bitcoind … 0000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo) 0000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo) 0000-00-00T00:00:00Z Pre-allocating up to position 0x0000000 in blk00000.dat 0000-00-00T00:00:00Z Pre-allocating up to position 0x000000 in rev00000.dat 0000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo) 0000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo) 0000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo) ``` Expected standard output from `bitcoind` (when in steady state) after this patch: ``` $ src/bitcoind … 0000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo) 0000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo) 0000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo) 0000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo) 0000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo) ``` I find the latter alternative much easier to visually scan for anomalies (and more aesthetically pleasing TBH!). Non-GUI users deserve nice interfaces too :) ACKs for top commit: laanwj: ACK 25f899c Tree-SHA512: 5970798c41b041527ebdcbd843c5e136c257c28c3b21fc74102da8970406ca5c0c7e406305c5e6e67de5c1708dc1858af07a77a2e05f44159b7103423e8ab32f

…n […].dat" log message to debug category 25f899c log: Move "Pre-allocating up to position 0x[...] in [...].dat" log message to debug category (practicalswift) acd7980 log: Move "Leaving block file [...]: [...]" log message to debug category (practicalswift) Pull request description: Move `Pre-allocating up to position 0x[…] in […].dat` log message to debug category. After the cleanup of `-debug=net` log messages PR (bitcoin#20724) was merged recently the console log now has very high signal to noise ratio. That's great! :) This PR increases the signal to noise ratio slightly more by moving the most common remaining implementation detail log message (`Pre-allocating up to position 0x[…] in […].dat`) to the debug category where it belongs :) Expected standard output from `bitcoind` (when in steady state) before this patch: ``` $ src/bitcoind … 0000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo) 0000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo) 0000-00-00T00:00:00Z Pre-allocating up to position 0x0000000 in blk00000.dat 0000-00-00T00:00:00Z Pre-allocating up to position 0x000000 in rev00000.dat 0000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo) 0000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo) 0000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo) ``` Expected standard output from `bitcoind` (when in steady state) after this patch: ``` $ src/bitcoind … 0000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo) 0000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo) 0000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo) 0000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo) 0000-00-00T00:00:00Z UpdateTip: new best=0000000000000000000000000000000000000000000000000000000000000000 height=000000 version=0x00000000 log0_work=00.000000 tx=000000000 date='0000-00-00T00:00:00Z' progress=0.000000 cache=000.0MiB(0000000txo) ``` I find the latter alternative much easier to visually scan for anomalies (and more aesthetically pleasing TBH!). Non-GUI users deserve nice interfaces too :) ACKs for top commit: laanwj: ACK 25f899c Tree-SHA512: 5970798c41b041527ebdcbd843c5e136c257c28c3b21fc74102da8970406ca5c0c7e406305c5e6e67de5c1708dc1858af07a77a2e05f44159b7103423e8ab32f

Summary: ``` 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 ``` Some differences from the source material are due to segwit and out of order backports. Backport of [[bitcoin/bitcoin#20724 | core#20724]]. Ref T1696. Test Plan: ninja all check-extended Reviewers: #bitcoin_abc, PiRK Reviewed By: #bitcoin_abc, PiRK Maniphest Tasks: T1696 Differential Revision: https://reviews.bitcoinabc.org/D10923

DrahtBot added the P2P label Dec 19, 2020

This was referenced Dec 20, 2020

Add I2P support using I2P SAM #20685

Merged

net processing: Move block inventory state to net_processing #19829

Merged

ajtowns force-pushed the 202012-net-log-cleanup branch from 07c606c to 2219a8d Compare January 6, 2021 04:32

ajtowns marked this pull request as ready for review January 6, 2021 04:48

This was referenced Jan 6, 2021

p2p: Add DISABLETX message for negotiating block-relay-only connections #20726

Closed

doc: refer to BIPs 339/155 in feature negotiation #20646

Merged

jnewbery reviewed Jan 6, 2021

View reviewed changes

src/net_processing.cpp Outdated Show resolved Hide resolved

DrahtBot mentioned this pull request Jan 6, 2021

net: Move SocketSendData lock annotation to header #20864

Merged

felipsoarez reviewed Jan 6, 2021

View reviewed changes

ajtowns commented Jan 7, 2021

View reviewed changes

src/net.cpp Outdated Show resolved Hide resolved

ajtowns force-pushed the 202012-net-log-cleanup branch from 2219a8d to e28d740 Compare January 7, 2021 00:46

DrahtBot added the Needs rebase label Jan 7, 2021

ajtowns force-pushed the 202012-net-log-cleanup branch from e28d740 to b007071 Compare January 10, 2021 04:33

DrahtBot removed the Needs rebase label Jan 10, 2021

DrahtBot mentioned this pull request Jan 10, 2021

net-processing refactoring -- lose globals, move implementation details from .h to .cpp #20758

Closed

maflcko reviewed Jan 13, 2021

View reviewed changes

This was referenced Jan 13, 2021

[refactor] [net] Clean up InactivityCheck() #20927

Merged

Net: Move ping data to net_processing #20721

Merged

ajtowns force-pushed the 202012-net-log-cleanup branch from b007071 to 4424d13 Compare January 14, 2021 13:42

DrahtBot mentioned this pull request Jan 15, 2021

[refactor] Move some net_processing globals into PeerManagerImpl #20942

Merged

DrahtBot added the Needs rebase label Jan 22, 2021

ajtowns added 5 commits January 28, 2021 16:04

net, net_processing: log disconnect reasons with -debug=net

a410ae8

net: make debug logging conditional on -debug=net

f7edea3

net_processing: additional debug logging for ignored messages

1230210

net: use peer=N instead of from=N in debug log

98fab37

net_processing: log txrelay flag from version message

48c8a9b

ajtowns force-pushed the 202012-net-log-cleanup branch from 4424d13 to 48c8a9b Compare January 28, 2021 08:06

DrahtBot removed the Needs rebase label Jan 28, 2021

maflcko merged commit c8b8351 into bitcoin:master Jan 29, 2021

sidhujag pushed a commit to syscoin/syscoin that referenced this pull request Jan 29, 2021

Merge bitcoin#20724: Cleanup of -debug=net log messages

eaae2a1

practicalswift mentioned this pull request Jan 31, 2021

log: Move "Pre-allocating up to position 0x[…] in […].dat" log message to debug category #21041

Merged

bitcoin locked as resolved and limited conversation to collaborators Aug 16, 2022

Conversation

ajtowns commented Dec 19, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jonatack commented Dec 19, 2020

Uh oh!

ajtowns commented Dec 19, 2020

Uh oh!

practicalswift commented Dec 19, 2020

Uh oh!

jonatack commented Dec 19, 2020

Uh oh!

DrahtBot commented Dec 20, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Conflicts

Uh oh!

jnewbery commented Dec 29, 2020

Uh oh!

Sjors commented Dec 30, 2020

Uh oh!

ajtowns commented Jan 6, 2021

Uh oh!

ajtowns commented Jan 6, 2021

Uh oh!

jnewbery commented Jan 6, 2021

Uh oh!

Uh oh!

felipsoarez left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

jnewbery commented Jan 7, 2021

Uh oh!

jnewbery commented Jan 10, 2021

Uh oh!

practicalswift commented Jan 10, 2021

Uh oh!

DrahtBot commented Jan 13, 2021

Uh oh!

maflcko left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

ajtowns commented Jan 14, 2021

Uh oh!

practicalswift commented Jan 14, 2021

Uh oh!

maflcko commented Jan 14, 2021

Uh oh!

decryp2kanon commented Jan 19, 2021

Uh oh!

jnewbery commented Jan 22, 2021

Uh oh!

ajtowns commented Jan 28, 2021

Uh oh!

jnewbery commented Jan 28, 2021

Uh oh!

maflcko commented Jan 28, 2021

Uh oh!

practicalswift commented Jan 28, 2021

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

9 participants

ajtowns commented Dec 19, 2020 •

edited

Loading

DrahtBot commented Dec 20, 2020 •

edited

Loading