bitcoin icon indicating copy to clipboard operation
bitcoin copied to clipboard

Do not log p2p bip61 reject messages, improve log, add tests

Open jonatack opened this issue 2 years ago • 8 comments

...per the IRC discussion around https://www.erisian.com.au/bitcoin-core-dev/log-2023-09-03.html#l-345.

Rationale for not logging the bip61 reject messages (as unknown commands):

  • they are not unknown and were valid before v20; see ##15437

  • peers have been observed that send a high number of these messages (I've seen 10k-20k messages per day from a single peer), thereby flooding the log when -debug=net

  • another option would be to continue logging bip61 reject messages, but with the trace log level instead

Rationale for improving the log output when receiving unknown commands:

  • logging only a peer id isn't of much help after the fact in understanding the source of the message and debugging what/why

jonatack avatar Sep 07 '23 18:09 jonatack

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

Reviews

See the guideline for information on the review process.

Type Reviewers
Concept NACK luke-jr

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:

  • #29641 (scripted-diff: Use LogInfo/LogDebug over LogPrintf/LogPrint by maflcko)

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.

DrahtBot avatar Sep 07 '23 18:09 DrahtBot

logging only a peer id isn't of much help after the fact in understanding the source of the message and debugging what/why

Not sure. The details are already logged at the beginning of the connection, after the verack. So this seems odd to duplicate here. In any case, it seems like something that would need to be done for the whole codebase and not just here.

maflcko avatar Sep 10 '23 15:09 maflcko

Not sure. Seems better to be consistent.

These aren't "unknown messages", though, so it could be reasonable to treat them differently.

jonatack avatar Sep 10 '23 15:09 jonatack

These aren't "unknown messages", though, so it could be reasonable to treat them differently.

Yeah, but then you'll need to include a list of all known message types, because other unhandled message types can also be frequent for someone. Not sure if this is something we want to maintain.

Seems easier to adjust the log to say "unhandled" instead of "unknown"?

maflcko avatar Sep 10 '23 16:09 maflcko

It doesn't seem inconsistent to me to ignore them. They are messages with a well-known meaning, and we can choose to handle them just as well as every other known message - it just so happens that in this case (a) the action to take when receiving such a message is "do nothing" and (b) we choose to not send such messages ourselves.

sipa avatar Sep 10 '23 16:09 sipa

I mean consistency with other message types that are known but unhandled, like the getutxo message type, or the reqrecon message type, etc. (Both are "known", but they are logged as "unknown").

No objection, if other reviewers are fine with this.

maflcko avatar Sep 10 '23 16:09 maflcko

The details are already logged at the beginning of the connection

Can drop the log improvement if people prefer, but it provides info not in the connection log. In my development environment I have similar peer details for all of the higher-level peer events to better observe and understand them. These allowed uncovering the issues in #28248. (If you are referring to the New outbound peer connected logging, I propose to improve it along with others in that pull.)

jonatack avatar Sep 10 '23 16:09 jonatack

Can drop the log improvement if people prefer, but it provides info not in the connection log. In my development environment I have similar peer details for all of the higher-level peer events to better observe and understand them.

If there is something missing from the connection log, it should be added there, not here, no?

Locally I have a function ToString on a peer connection, which I add to log lines I am interested in, to make parsing easier. It would certainly be easier for me if existing log lines had a call to such a function, which would just print the peer id right now. It could then be modified, with config options, or in the source code to print something else, or hook into tracing, etc. Not sure if it would be useful for others as well, so I haven't made a pull request for this. Also, such a pull would require touching almost all net processing log lines.

maflcko avatar Sep 10 '23 16:09 maflcko