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

jonatack commented at 6:46 PM on September 7, 2023: member

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

Don't log p2p bip61 reject messages and improve log output

Rationale for not logging these messages:

- they are not "unknown" and were valid in pre-v20 versions of bitcoin core

- peers have been observed that send a high number of these messages, thereby
  flooding the log when -debug=net

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 who/what/why

a7ac72def7

Add tests for p2p unknown msgtype and BIP61 reject messages 75919dbf46

DrahtBot commented at 6:46 PM on September 7, 2023: contributor

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.

maflcko commented at 3:45 PM on September 10, 2023: member

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.

in src/net_processing.cpp:4886 in 75919dbf46

4880 | @@ -4881,8 +4881,18 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
4881 |          return;
4882 |      }
4883 |  
4884 | +    const auto msg_str{SanitizeString(msg_type)};
4885 | +
4886 | +    // Ignore BIP61 "reject" messages. They can be very frequent, so don't log.

maflcko commented at 3:46 PM on September 10, 2023:

Not sure. I am sure there are other message types that used to be valid and are now logged as "unknown". They can also be frequent, so it seems odd to use that as a reason whether to log or not. Also, the net layer will still log the message type, no?

jonatack commented at 3:56 PM on September 10, 2023:

The only "unknown" messages I've seen these past weeks are these (though they are not unknown), and they can be so high-frequency (10-20k per day) that I'm not sure what the point of logging them is.

maflcko changes_requested

maflcko commented at 3:48 PM on September 10, 2023: member

Not sure. Seems better to be consistent. Also, using a remote-controlled metric as a reason for a change seems hard to maintain and measure.

jonatack commented at 3:57 PM on September 10, 2023: member

Not sure. Seems better to be consistent.

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

maflcko commented at 4:00 PM on September 10, 2023: member

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"?

sipa commented at 4:03 PM on September 10, 2023: member

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.

maflcko commented at 4:23 PM on September 10, 2023: member

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.

jonatack commented at 4:23 PM on September 10, 2023: member

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

maflcko commented at 4:32 PM on September 10, 2023: member

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.

luke-jr changes_requested

luke-jr commented at 4:00 PM on September 13, 2023: member

Concept NACK. Even before "reject" support was removed, we still logged every one we got anyway (see fa25f43ac5692082dba3f90456c501eb08f1b75c).

And agree with @MarcoFalke on logging peer details

DrahtBot added the label CI failed on Jan 17, 2024

jonatack closed this on Apr 8, 2024

bitcoin locked this on Apr 8, 2025