Do not make it trivial for inbound peers to generate log entries #11583

TheBlueMatt · 2017-10-30T23:01:18Z

Based on #11580 because I'm lazy.

We should generally avoid writing to debug.log unconditionally for
inbound peers which misbehave (the peer being about to be banned
being an exception, since they cannot do this twice).

practicalswift · 2017-10-31T06:03:31Z

Concept ACK

promag

Concept ACK.

promag · 2017-10-31T14:29:52Z

src/net_processing.cpp

@@ -1514,7 +1511,9 @@ bool static ProcessMessage(CNode* pfrom, const std::string& strCommand, CDataStr
        if (nVersion < MIN_PEER_PROTO_VERSION)
        {
            // disconnect from peers older than this proto version
-            LogPrintf("peer=%d using obsolete version %i; disconnecting\n", pfrom->GetId(), nVersion);
+            std::string obsolete_msg(strprintf("peer=%d using obsolete version %i; disconnecting\n", pfrom->GetId(), nVersion));
+            if (pfrom->fInbound) LogPrint(BCLog::NET, "%s", obsolete_log);


obsolete_msg or above obsolete_log?

promag · 2017-10-31T14:32:28Z

src/net_processing.cpp

-            LogPrintf("peer=%d using obsolete version %i; disconnecting\n", pfrom->GetId(), nVersion);
+            std::string obsolete_msg(strprintf("peer=%d using obsolete version %i; disconnecting\n", pfrom->GetId(), nVersion));
+            if (pfrom->fInbound) LogPrint(BCLog::NET, "%s", obsolete_log);
+            else                 LogPrintf(           "%s", obsolete_log);


Same as above.

ryanofsky

utACK dba516034898cd390a07edf86af3e9ff9f52c911. I didn't try to verify there were no missing logprints, but these changes seem reasonable.

I think it would be good to add your "We should generally avoid writing to debug.log unconditionally..." comment from the commit message to the LogFlags enum, so there is a little information about good logging practices and how the enum values are supposed to be used.

meshcollider · 2017-11-05T04:53:47Z

Concept ACK

laanwj · 2017-11-09T13:38:36Z

"We should generally avoid writing to debug.log unconditionally"

Yes please. Loose logging practices just cause scared users.

Concept ACK.

laanwj · 2017-11-09T14:14:44Z

src/net_processing.cpp

-            LogPrintf("peer=%d using obsolete version %i; disconnecting\n", pfrom->GetId(), nVersion);
+            std::string obsolete_log(strprintf("peer=%d using obsolete version %i; disconnecting\n", pfrom->GetId(), nVersion));
+            if (pfrom->fInbound) LogPrint(BCLog::NET, "%s", obsolete_log);
+            else                 LogPrintf(           "%s", obsolete_log);


Would prefer to create a BCLog::ALWAYS category and use something like pfrom->fInbound ? BCLog::NET: BCLog::ALWAYS instead of repeating the log statements in this way.
(after that you could even factor it to a uint32_t log_category = ...` at the beginning of the function ProcessMessage)

TheBlueMatt · 2017-11-09T17:41:16Z

After discussion on IRC I removed the weird branching on fInbound to decide between LogPrint and LogPrintf...added a new "New outbound peer connected" log to ::VERACK handling to replace it. Also added a general comment in util.h about LogPrint/LogPrintf usage.

ghost · 2017-11-09T23:27:44Z

What about the debug.log message "connection from <Peer> dropped (banned)"?
I banned the nodes in gmaxwells banlist.cli.txt, and some of them aggressively try to connect permanently every few seconds after being banned, e.g. this one (this is a original cutout of the debug.log, the messages are exactly like this (except the x-anonymization), I did not remove other log entries in between)

2017-11-x 15:55:34 connection from 129.13.252.x:36133 dropped (banned)
2017-11-x 15:55:39 connection from 129.13.252.x:36225 dropped (banned)
2017-11-x 15:55:43 connection from 129.13.252.x:36363 dropped (banned)
2017-11-x 15:55:47 connection from 129.13.252.x:36474 dropped (banned)
2017-11-x 15:55:50 connection from 129.13.252.x:36579 dropped (banned)
2017-11-x 15:55:53 connection from 129.13.252.x:36673 dropped (banned)
2017-11-x 15:55:56 connection from 129.13.252.x:36780 dropped (banned)
2017-11-x 15:56:00 connection from 129.13.252.x:36888 dropped (banned)
2017-11-x 15:56:03 connection from 129.13.252.x:36989 dropped (banned)
2017-11-x 15:56:07 connection from 129.13.252.x:37108 dropped (banned)
2017-11-x 15:56:10 connection from 129.13.252.x:37210 dropped (banned)
2017-11-x 15:56:13 connection from 129.13.252.x:37307 dropped (banned)
2017-11-x 15:56:17 connection from 129.13.252.x:37409 dropped (banned)
2017-11-x 15:56:20 connection from 129.13.252.x:37516 dropped (banned)
2017-11-x 15:56:23 connection from 129.13.252.x:37612 dropped (banned)
2017-11-x 15:56:27 connection from 129.13.252.x:37712 dropped (banned)
2017-11-x 15:56:30 connection from 129.13.252.x:37814 dropped (banned)

Because this permanently spammed the debug.log, I added iptables rules to drop these silently on OS layer :-/

Edit: running 0.15.1rc1

We should generally avoid writing to debug.log unconditionally for inbound peers which misbehave (the peer being about to be banned being an exception, since they cannot do this twice). To avoid removing logs for outbound peers, a new log is added to notify users when a new outbound peer is connected which mimics the version print.

TheBlueMatt · 2017-11-09T23:41:57Z

Added the banned listing to the list as well (thanks!)...I'm sure there's others that are missed that can be triggered in validation logic, but I'll leave those for a future PR.

greenaddress · 2017-12-09T15:24:35Z

Concept ACK.

laanwj · 2017-12-11T15:51:57Z

utACK be9f38c

…g entries be9f38c Do not make it trivial for inbound peers to generate log entries (Matt Corallo) Pull request description: Based on #11580 because I'm lazy. We should generally avoid writing to debug.log unconditionally for inbound peers which misbehave (the peer being about to be banned being an exception, since they cannot do this twice). Tree-SHA512: 8e59c8d08d00b1527951b30f4842d010a4c2fc440503ade112baa2c1b9afd0e0d1c5c2df83dde25183a242af45089cf9b9f873b71796771232ffb6c5fc6cc0cc

This moves the error messages for misbehavior (when available) into the line that reports the misbehavior, as well as moves the logging to the `net` category. This is a continuation of bitcoin#11583 and avoids serious-looking errors due to misbehaving peers. To do this, Misbehaving() gains an optional `message` argument. E.g. change: 2018-01-18 16:02:27 Misbehaving: x.x.x.x:62174 peer=164603 (80 -> 100) BAN THRESHOLD EXCEEDED 2018-01-18 16:02:27 ERROR: non-continuous headers sequence to 2018-01-18 16:02:27 Misbehaving: x.x.x.x:62174 peer=164603 (80 -> 100) BAN THRESHOLD EXCEEDED: non-continuous headers sequence

…non-contributing peers (port scanners?) 37% of the log default log entries for a node that has been up for ~24hrs was "version handshake timeout..."

…ssage c887f87 Extend #11583 to include the most common message generated by non-contributing peers (port scanners?) 37% of the log default log entries for a node that has been up for ~24hrs was "version handshake timeout..." (Clem Taylor) Pull request description: 37% of the default log entries for a node that has been up for ~24hrs was "version handshake timeout..." Tree-SHA512: dceeee5d55a9ff7570174aeb63faac9beda239087220522adefef7ed11e0eeffa008ca28726011247c8834c1a222d37817baf895635ab874a95ebc435959070e

d3a185a net: Move misbehaving logging to net logging category (Wladimir J. van der Laan) Pull request description: This moves the error messages for misbehavior (when available) into the line that reports the misbehavior, as well as moves the logging to the `net` category. This is a continuation of #11583 and avoids serious-looking errors due to misbehaving peers. As it is impossible to correlate the `peer=X` numbers to specific incoming connections now without enabling the `net` category, it doesn't really help to see these messages by default. To do this, Misbehaving() gains an optional `message` argument. E.g. change: 2018-01-18 16:02:27 Misbehaving: x.x.x.x:62174 peer=164603 (80 -> 100) BAN THRESHOLD EXCEEDED 2018-01-18 16:02:27 ERROR: non-continuous headers sequence to 2018-01-18 16:02:27 Misbehaving: x.x.x.x:62174 peer=164603 (80 -> 100) BAN THRESHOLD EXCEEDED: non-continuous headers sequence When there is a category for "important" net messages (see #12219 ), we should move it there. Tree-SHA512: 51c97e9a649bf5409f2fd4625fa1243a036e9c9de6037bb064244207408c2e0eb025e3af80866df673cdc006b8f35dc4078d074033f0d4c6a73bbb03949a269f

This moves the error messages for misbehavior (when available) into the line that reports the misbehavior, as well as moves the logging to the `net` category. This is a continuation of bitcoin#11583 and avoids serious-looking errors due to misbehaving peers. To do this, Misbehaving() gains an optional `message` argument. E.g. change: 2018-01-18 16:02:27 Misbehaving: x.x.x.x:62174 peer=164603 (80 -> 100) BAN THRESHOLD EXCEEDED 2018-01-18 16:02:27 ERROR: non-continuous headers sequence to 2018-01-18 16:02:27 Misbehaving: x.x.x.x:62174 peer=164603 (80 -> 100) BAN THRESHOLD EXCEEDED: non-continuous headers sequence

…non-contributing peers (port scanners?) 37% of the log default log entries for a node that has been up for ~24hrs was "version handshake timeout..."

This moves the error messages for misbehavior (when available) into the line that reports the misbehavior, as well as moves the logging to the `net` category. This is a continuation of bitcoin#11583 and avoids serious-looking errors due to misbehaving peers. To do this, Misbehaving() gains an optional `message` argument. E.g. change: 2018-01-18 16:02:27 Misbehaving: x.x.x.x:62174 peer=164603 (80 -> 100) BAN THRESHOLD EXCEEDED 2018-01-18 16:02:27 ERROR: non-continuous headers sequence to 2018-01-18 16:02:27 Misbehaving: x.x.x.x:62174 peer=164603 (80 -> 100) BAN THRESHOLD EXCEEDED: non-continuous headers sequence

Summary: bitcoin/bitcoin#11583 We should generally avoid writing to debug.log unconditionally for inbound peers which misbehave (the peer being about to be banned being an exception, since they cannot do this twice). To avoid removing logs for outbound peers, a new log is added to notify users when a new outbound peer is connected which mimics the version print. This is a backport of Core PR11583 Test Plan: CI Reviewers: #bitcoin_abc, deadalnix, Fabien Reviewed By: #bitcoin_abc, deadalnix, Fabien Subscribers: Fabien, teamcity, schancel Differential Revision: https://reviews.bitcoinabc.org/D2323

…rate log entries be9f38c Do not make it trivial for inbound peers to generate log entries (Matt Corallo) Pull request description: Based on bitcoin#11580 because I'm lazy. We should generally avoid writing to debug.log unconditionally for inbound peers which misbehave (the peer being about to be banned being an exception, since they cannot do this twice). Tree-SHA512: 8e59c8d08d00b1527951b30f4842d010a4c2fc440503ade112baa2c1b9afd0e0d1c5c2df83dde25183a242af45089cf9b9f873b71796771232ffb6c5fc6cc0cc

…egory d3a185a net: Move misbehaving logging to net logging category (Wladimir J. van der Laan) Pull request description: This moves the error messages for misbehavior (when available) into the line that reports the misbehavior, as well as moves the logging to the `net` category. This is a continuation of bitcoin#11583 and avoids serious-looking errors due to misbehaving peers. As it is impossible to correlate the `peer=X` numbers to specific incoming connections now without enabling the `net` category, it doesn't really help to see these messages by default. To do this, Misbehaving() gains an optional `message` argument. E.g. change: 2018-01-18 16:02:27 Misbehaving: x.x.x.x:62174 peer=164603 (80 -> 100) BAN THRESHOLD EXCEEDED 2018-01-18 16:02:27 ERROR: non-continuous headers sequence to 2018-01-18 16:02:27 Misbehaving: x.x.x.x:62174 peer=164603 (80 -> 100) BAN THRESHOLD EXCEEDED: non-continuous headers sequence When there is a category for "important" net messages (see bitcoin#12219 ), we should move it there. Tree-SHA512: 51c97e9a649bf5409f2fd4625fa1243a036e9c9de6037bb064244207408c2e0eb025e3af80866df673cdc006b8f35dc4078d074033f0d4c6a73bbb03949a269f

…ke timeout" message c887f87 Extend bitcoin#11583 to include the most common message generated by non-contributing peers (port scanners?) 37% of the log default log entries for a node that has been up for ~24hrs was "version handshake timeout..." (Clem Taylor) Pull request description: 37% of the default log entries for a node that has been up for ~24hrs was "version handshake timeout..." Tree-SHA512: dceeee5d55a9ff7570174aeb63faac9beda239087220522adefef7ed11e0eeffa008ca28726011247c8834c1a222d37817baf895635ab874a95ebc435959070e

…egory d3a185a net: Move misbehaving logging to net logging category (Wladimir J. van der Laan) Pull request description: This moves the error messages for misbehavior (when available) into the line that reports the misbehavior, as well as moves the logging to the `net` category. This is a continuation of bitcoin#11583 and avoids serious-looking errors due to misbehaving peers. As it is impossible to correlate the `peer=X` numbers to specific incoming connections now without enabling the `net` category, it doesn't really help to see these messages by default. To do this, Misbehaving() gains an optional `message` argument. E.g. change: 2018-01-18 16:02:27 Misbehaving: x.x.x.x:62174 peer=164603 (80 -> 100) BAN THRESHOLD EXCEEDED 2018-01-18 16:02:27 ERROR: non-continuous headers sequence to 2018-01-18 16:02:27 Misbehaving: x.x.x.x:62174 peer=164603 (80 -> 100) BAN THRESHOLD EXCEEDED: non-continuous headers sequence When there is a category for "important" net messages (see bitcoin#12219 ), we should move it there. Tree-SHA512: 51c97e9a649bf5409f2fd4625fa1243a036e9c9de6037bb064244207408c2e0eb025e3af80866df673cdc006b8f35dc4078d074033f0d4c6a73bbb03949a269f

…ke timeout" message c887f87 Extend bitcoin#11583 to include the most common message generated by non-contributing peers (port scanners?) 37% of the log default log entries for a node that has been up for ~24hrs was "version handshake timeout..." (Clem Taylor) Pull request description: 37% of the default log entries for a node that has been up for ~24hrs was "version handshake timeout..." Tree-SHA512: dceeee5d55a9ff7570174aeb63faac9beda239087220522adefef7ed11e0eeffa008ca28726011247c8834c1a222d37817baf895635ab874a95ebc435959070e

… to generate log entries 4801464 Do not make it trivial for inbound peers to generate log entries (Matt Corallo) Pull request description: Adapted from bitcoin#11583, following the same rationale: We have to be much more conservative when using LogPrintf/error or other things which unconditionally log to debug.log, It should not be the case that an inbound peer can fill up a users disk with debug.log entries (DoS). This rule should be applied in many other areas of the sources as well (not only on the net area). But well, step by step. ACKs for top commit: random-zebra: utACK 4801464 Fuzzbawls: utACK 4801464 Tree-SHA512: 746bdb46f286d34a0bd109b3f4d278f714ce3140c34c897ccfbe948b8c56eb7e04e91b004a9ff9e60e56c312dfc4f47d31a1f77c5e8f0f71310c3e77f5d47460

…rate log entries be9f38c Do not make it trivial for inbound peers to generate log entries (Matt Corallo) Pull request description: Based on bitcoin#11580 because I'm lazy. We should generally avoid writing to debug.log unconditionally for inbound peers which misbehave (the peer being about to be banned being an exception, since they cannot do this twice). Tree-SHA512: 8e59c8d08d00b1527951b30f4842d010a4c2fc440503ade112baa2c1b9afd0e0d1c5c2df83dde25183a242af45089cf9b9f873b71796771232ffb6c5fc6cc0cc

fanquake added the P2P label Oct 30, 2017

promag reviewed Oct 31, 2017

View reviewed changes

TheBlueMatt force-pushed the 2017-10-no-net-log branch from 7344795 to dba5160 Compare October 31, 2017 15:40

ryanofsky reviewed Nov 2, 2017

View reviewed changes

laanwj reviewed Nov 9, 2017

View reviewed changes

TheBlueMatt force-pushed the 2017-10-no-net-log branch from dba5160 to 0d763ef Compare November 9, 2017 17:40

TheBlueMatt force-pushed the 2017-10-no-net-log branch from 0d763ef to be9f38c Compare November 9, 2017 23:41

laanwj merged commit be9f38c into bitcoin:master Dec 11, 2017

This was referenced Jan 18, 2018

net: Move misbehaving logging to net logging category #12218

Merged

More granular net logging #12219

Closed

furszy mentioned this pull request Jan 11, 2021

[Backport][Net] Do not make it trivial for inbound peers to generate log entries PIVX-Project/PIVX#2130

Merged

bitcoin locked as resolved and limited conversation to collaborators Sep 8, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Do not make it trivial for inbound peers to generate log entries #11583

Do not make it trivial for inbound peers to generate log entries #11583

Uh oh!

TheBlueMatt commented Oct 30, 2017

Uh oh!

practicalswift commented Oct 31, 2017

Uh oh!

promag left a comment

Uh oh!

promag Oct 31, 2017

Uh oh!

promag Oct 31, 2017

Uh oh!

ryanofsky left a comment

Uh oh!

meshcollider commented Nov 5, 2017

Uh oh!

laanwj commented Nov 9, 2017

Uh oh!

laanwj Nov 9, 2017 •

edited

Loading

Uh oh!

TheBlueMatt commented Nov 9, 2017

Uh oh!

ghost commented Nov 9, 2017 •

edited by ghost

Loading

Uh oh!

TheBlueMatt commented Nov 9, 2017

Uh oh!

greenaddress commented Dec 9, 2017

Uh oh!

laanwj commented Dec 11, 2017

Uh oh!

Uh oh!

Do not make it trivial for inbound peers to generate log entries #11583

Do not make it trivial for inbound peers to generate log entries #11583

Uh oh!

Conversation

TheBlueMatt commented Oct 30, 2017

Uh oh!

practicalswift commented Oct 31, 2017

Uh oh!

promag left a comment

Choose a reason for hiding this comment

Uh oh!

promag Oct 31, 2017

Choose a reason for hiding this comment

Uh oh!

promag Oct 31, 2017

Choose a reason for hiding this comment

Uh oh!

ryanofsky left a comment

Choose a reason for hiding this comment

Uh oh!

meshcollider commented Nov 5, 2017

Uh oh!

laanwj commented Nov 9, 2017

Uh oh!

laanwj Nov 9, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

TheBlueMatt commented Nov 9, 2017

Uh oh!

ghost commented Nov 9, 2017 • edited by ghost Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

TheBlueMatt commented Nov 9, 2017

Uh oh!

greenaddress commented Dec 9, 2017

Uh oh!

laanwj commented Dec 11, 2017

Uh oh!

Uh oh!

laanwj Nov 9, 2017 •

edited

Loading

ghost commented Nov 9, 2017 •

edited by ghost

Loading