banlist: log post-swept banlist size at startup #19470

pull fanquake wants to merge 1 commits into bitcoin:master from fanquake:log_post_sweep_banlist_size changing 1 files +1 −1

fanquake commented at 1:58 PM on July 8, 2020: member

We are currently logging the size of the banlist from before SweepBanned() has been called, meaning the value may be incorrect.

i.e banlist.dat had 1ban. That ban is swept on startup. We log "loaded 1 banned node..". Actual banlist size is 0.

banlist: log post-swept banlist size at startup

We are currently logging the size of the banlist before SweepBanned()
has been called, meaning the value may be incorrect.

0b8ba84659

fanquake added the label P2P on Jul 8, 2020
fanquake added the label Utils/log/libs on Jul 8, 2020
laanwj commented at 3:03 PM on July 8, 2020: member

Code review ACK 0b8ba84659b56b12d74587ea31b6062fce887ba3
jnewbery commented at 10:50 AM on July 9, 2020: member

Code review ACK 0b8ba84659b56b12d74587ea31b6062fce887ba3

Now that the local banmap isn't being used after SetBanned(), we could change SetBanned() to take an rvalue reference and do a move, rather than the expensive copy. (not in this PR)
jonatack commented at 11:51 AM on July 9, 2020: member

Code review ACK 0b8ba84659b m_banned is set in SetBanned and is updated by SweepBanned before the logging.

In a couple of manual checks, both master and this branch logged the correct number with 0 and 1 banned peers using setban/clearbanned, so I didn't hit the timing to produce a wrong count.

in src/banman.cpp:28 in 0b8ba84659

  25 | @@ -26,7 +26,7 @@ BanMan::BanMan(fs::path ban_file, CClientUIInterface* client_interface, int64_t
  26 |          SweepBanned();            // sweep out unused entries
  27 |  
  28 |          LogPrint(BCLog::NET, "Loaded %d banned node ips/subnets from banlist.dat  %dms\n",

jonatack commented at 11:59 AM on July 9, 2020:

FWIW I would find this logging handy as a regular debug log LogPrintf, like the other ones in this function.

fanquake commented at 12:10 PM on July 9, 2020: member

In a couple of manual checks, both master and this branch logged the correct number with 0 and 1 banned peers using setban/clearbanned, so I didn't hit the timing to produce a wrong count.

You can observe the issue on master by just setting a short ban, and restarting bitcoind. i.e:

src/bitcoind -regtest

# set a short-lived ban
src/bitcoin-cli -regtest setban "2001:4d48:ac57:400:cacf:e9ff:fe1d:1" "add" "10"

#  shutdown bitcoind, wait 11 seconds, restart bitcoind
....
2020-07-09T12:06:54.944698Z [init] SweepBanned: Removed banned node ip/subnet from banlist.dat: 2001:4d48:ac57:400:cacf:e9ff:fe1d:1/128
2020-07-09T12:06:54.944731Z [init] Loaded 1 banned node ips/subnets from banlist.dat  0ms

The loaded count is logged as 1 when it should be 0.

jonatack commented at 12:25 PM on July 9, 2020: member

Ok, reproduced on mainnet. I wasn't shutting down bitcoind fast enough before it expired.
fanquake merged this on Jul 9, 2020
fanquake closed this on Jul 9, 2020
fanquake deleted the branch on Jul 9, 2020
Fabcien referenced this in commit 9f2cfa7069 on May 26, 2021
PastaPastaPasta referenced this in commit 0b6b1573c3 on Sep 17, 2021
PastaPastaPasta referenced this in commit 0fe3dc8c0a on Sep 19, 2021
thelazier referenced this in commit ea62fb4e0b on Sep 25, 2021
DrahtBot locked this on Feb 15, 2022

Contributors

Labels