Alternate to #27276.
Devs were suprised to realize last night that we don’t have definitive logging for when a given header was first received.
This logs to the main stream when new headers are received outside of IBD, as well as when headers come in over cmpctblocks. The rationale of not hiding these under log categories is that they may be useful to have widely available when debugging strange network activity, and the marginal volume is modest.
The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.
See the guideline for information on the review process.
If your review is incorrectly listed, please react with 👎 to this comment and the bot will ignore it on the next update.
Reviewers, this pull request conflicts with the following ones:
ProcessCompactBlockTxns by brunoerg)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.
3831@@ -3832,6 +3832,14 @@ bool ChainstateManager::AcceptBlockHeader(const CBlockHeader& block, BlockValida
3832 if (ppindex)
3833 *ppindex = pindex;
3834
3835+ if (!ActiveChainstate().IsInitialBlockDownload()) {
3836+ // These messages are valuable for detecting potential
3837+ // selfish mining behavior; if multiple displacing headers are seen
3838+ // near simultaneously across many nodes in the network, this might be
3839+ // an indication of selfish mining.
3840+ LogPrintf("saw new valid header hash=%s\n", hash.ToString());
LogPrint(BCLog::VALIDATION, when in IBD?
3839+ // selfish mining behavior; if multiple displacing headers are seen
3840+ // near simultaneously across many nodes in the network, this might be
3841+ // an indication of selfish mining.
3842+ LogPrintf("%s\n", msg);
3843+ } else {
3844+ LogPrint(BCLog::VALIDATION, "%s\n", msg);
3831@@ -3832,6 +3832,18 @@ bool ChainstateManager::AcceptBlockHeader(const CBlockHeader& block, BlockValida
3832 if (ppindex)
3833 *ppindex = pindex;
3834
3835+ const auto msg = strprintf("saw new valid header hash=%s", hash.ToString());
Maybe add an anti-footgun note here, since I almost made that mistake:
0// Not all valid headers have a known height, so we don't log pindex->nHeight.
Also, let’s capitalize the log message: Saw new …
If you drop hash = from the message then the hash aligns with UpdateTip, which makes the log easier to skim over. Update: no it doesn’t :-(
nBits value is valid, which we check in ContextualCheckBlockHeader earlier in this function… (A missing prev block should result in return Invalid(BLOCK_MISSING_PREV) prior to that) The only case where we don’t do all that is if we’re looking at the genesis block header, but we know its height is 0… What am I missing here?
AddToBlockIndex checks if hashPrevBlock is already in the index, and if not it won’t set pprev and nHeight on the CBlockIndex entry it returns. But I didn’t check if that condition can ever be reached from the call in AcceptBlockHeader.
Update: and indeed AcceptBlockHeader( checks for this case and rejects it with prev-blk-not-found.
So in that case it would be nice to log the height.
AddToBlockIndex() is LoadGenesisBlock(), so I guess that’s the only reason for the (generic looking) check of hashPrevBlock.
Concept ACK
Unconditionally logging headers (outside of IBD) makes sense to me. It doubles the number of messages per block, but since we check their proof-of-work, it’s not too bad.
Similarly for compact blocks we check the PoW before logging.
utACK dbd144206a491e3e16d662d0daeffac71bb5b8c7
3837+ if (!ActiveChainstate().IsInitialBlockDownload()) {
3838+ // These messages are valuable for detecting potential
3839+ // selfish mining behavior; if multiple displacing headers are seen
3840+ // near simultaneously across many nodes in the network, this might be
3841+ // an indication of selfish mining.
3842+ LogPrintf("%s\n", msg);
LogPrintfCategory here, if you have a category in mind that this fits into. Ideally we’ll get rid of LogPrintf at some point or rename the former to the latter. (Thanks for updating the second logging call.)
Could just make this:
0const auto level{(IsIBD() ? BCLog::Level::Info : BCLog::Level::Warning)};
1LogPrintf(BCLog::VALIDATION, level, "saw new ...", hash.ToString());
(or None rather than Warning maybe)
@jonatack it might be useful to expand the debug.log section in developer notes with some guidance. E.g. it seems good practice to always use LogPrintfCategory, always pick a category and then use >= BCLog::Level::Warning for things you always want in the logs even when the user did not pick the specific -debug setting.
@ajtowns I think BCLog::Level:None is off-limits, from the description of f1379aeca9d3a8c4d3528de4d0af8298cb42fee4: “replace the unused BCLog::Level:None string “none” with an empty string as the case will never be hit”
That said, warning feels inappropriate* since this message is rarely bad news. Maybe we need a new level above Info, like GlobalInfo?
* = but not a big enough deal to make this PR needlessly complicated, using warning for now seems fine, since we don’t actually print the word “warning” in the log.
Good idea @Sjors, will do.
“None” is internal-only (like Network::NET_MAX, for iterating through the enums) and IIRC a commit in the severity-level logs parent PR ends up removing it
“Info” is planned to be logged unconditionally in the next step, in addition to Warning and Error.
Warning and leave a TODO.
4207@@ -4207,8 +4208,9 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
4208 return;
4209 }
4210
4211- if (!m_chainman.m_blockman.LookupBlockIndex(cmpctblock.header.GetHash())) {
4212+ if (!m_chainman.m_blockman.LookupBlockIndex(blockhash)) {
4213 received_new_header = true;
4214+ LogPrintf("Saw new cmpctblock header hash=%s\n", blockhash.ToString());
I think this LogPrintf call isn’t safe because the work on the header has not actually been checked, that first happens in ProcessNewBlockHeaders below (by “safe” i mean that this location could be used to fill our disk with log messages).
At this point the header is only claiming to have enough work (i.e. prev_block->nChainWork + CalculateHeadersWork({cmpctblock.header}) >= GetAntiDoSWorkThreshold()) but the actual PoW check happens later on.
You can move this log location below the ProcessNewBlockHeaders call to make this safe.
CalculateHeadersWork doesn’t check the work, see #27278 (review)
4221@@ -4221,6 +4222,11 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
4222 }
4223 }
4224
4225+ if (received_new_header) {
4226+ LogPrintfCategory(BCLog::NET, "Saw new cmpctblock header hash=%s peer=%d\n",
ProcessHeadersMessage? Thinking of BIP 130 block announcements.
My thinking was that legacy/low-bandwidth nodes are uninteresting for these logs in the sense that they are either in IBD or […whatever prompts a node to be low-bandwidth-cmpctblock using]. And the log message in AcceptBlockHeader() obviously covers those cases too, and the lack of the cmpctblock message tells you that it’s LB/legacy.
And it gets a little hairy because if you want to stick a log in ProcessHeadersMessage, you have to exclude the compactblock path because PHM() is called in that case after accepting the header…
But now that I’m typing it out, I guess why not add a log to the NetMsgType::HEADERS path too…
I think in terms of DoS risk it is pretty similar as the compact block location. Basically: “Only log for BIP 130 announcements that told us about new headers meeting our DoS threshold”.
From the logs you shared here: https://twitter.com/jamesob/status/1637191706691903488 it looks like logging for headers announcements would have been useful. Looking at PeerManagerImpl::NewPoWValidBlock, we only announce via compact block once per height, so a competing height will be announced via headers.
I guess the only benefit over the AcceptBlockHeader location is that you log the peer id, but that also applies for the compact block path.
Funny enough this message comes after “Saw new header”. So from the point of view of making the log a bit more intuitive it does make sense to handle logging in net_processing. That might also solve the IBD “problem”, since we could log only headers that we didn’t request ourselves.
All that said: from a review point of view I prefer punting this to a followup. It’s already a nice improvement that I can see headers coming in and see which ones came via a compact block.
I wrote:
using
warningfor now seems fine, since we don’t actually print the word “warning” in the log.
I should have tested that, because it actually does print [validation:warning] in the log.
Maybe we should just stick to fprintf and change the TODO to say this should be validation level info once LogPrintf prints those by default.
That said, it seems quite trivial to just change the default log level: https://github.com/Sjors/bitcoin/commit/0ecb8290eeffcd2a2172c6720a2168404870530b
So far that’s not generating noise for me.
That said, it seems quite trivial to just change the default log level: Sjors@0ecb829
So far that’s not generating noise for me.
I’m happy to do that and revert the revert if people will ACK.
3842+ // in case investigation is merited.
3843+ const auto msg = strprintf(
3844+ "Saw new header hash=%s height=%d", hash.ToString(), pindex->nHeight);
3845+
3846+ if (ActiveChainstate().IsInitialBlockDownload()) {
3847+ LogPrintLevel(BCLog::VALIDATION, BCLog::Level::Debug, "%s\n", msg);
-debug=validation right after our headers presync succeeds. But that’s probably fine if someone is actively debugging IBD.
tACK 2c3a90f663a61ee147d785167a2902494d81d34d
Prefer if you leave it like this and leave log level tweaks to a followup.
I should have tested that, because it actually does print
[validation:warning]in the log.Maybe we should just stick to
fprintfand change the TODO to say this should bevalidationlevelinfoonceLogPrintfprints those by default.
Optionally could just go for info, unless it has to be unconditionally logged asap in which case maybe pull in https://github.com/bitcoin/bitcoin/pull/25203/commits/118c7567f62df2b882877590f232242d7c627a05. Making info unconditionally logged is near the top of the next steps in the parent PR #25203 i.e. https://github.com/bitcoin/bitcoin/pull/25203/commits/118c7567f62df2b882877590f232242d7c627a05 (@Sjors, your version doesn’t update the docs). Until then, -debug=validation or enabling the validation category with the logging RPC will print it as well.
3839+ // if multiple displacing headers are seen near simultaneously across many
3840+ // nodes in the network, this might be an indication of selfish mining. Having
3841+ // this log by default when not in IBD ensures broad availability of this data
3842+ // in case investigation is merited.
3843+ const auto msg = strprintf(
3844+ "Saw new header hash=%s height=%d", hash.ToString(), pindex->nHeight);
leaving this style nit in case someone ends up re-touching this in a follow-up, because this makes my eyes burn :sob:
0 const auto msg = strprintf(
1 "Saw new header hash=%s height=%d", hash.ToString(), pindex->nHeight
2 );
@josibake Our clang-format wouldn’t agree. It would revert your diff to what was merged (and propose this change instead).
0@@ -4224,7 +4224,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type,
1
2 if (received_new_header) {
3 LogPrintfCategory(BCLog::NET, "Saw new cmpctblock header hash=%s peer=%d\n",
4- blockhash.ToString(), pfrom.GetId());
5+ blockhash.ToString(), pfrom.GetId());
6 }
ACK https://github.com/bitcoin/bitcoin/pull/27278/commits/2c3a90f663a61ee147d785167a2902494d81d34d
There were some great suggestions for how this could be improved, but I think it’s smart to address them in a follow-up, considering this is useful as-is and addresses a real need.
FWIW I plan to leave this as-is.
If this is something that we might want in the next released version of Core (24.1), then I think that’s preferable. As we’d rather backport a less-involved patch.
Unconditionally logging headers (outside of IBD) makes sense to me. It doubles the number of messages per block, but since we check their proof-of-work, it’s not too bad.
It triples them, the unconditional log output when we receive a header via compact block looks like this with this PR:
02023-03-21T17:10:55Z Saw new header hash=0000000000000000000198c04342dff96f7940111d874c7bc73730a33b268225 height=781829
12023-03-21T17:10:55Z [net] Saw new cmpctblock header hash=0000000000000000000198c04342dff96f7940111d874c7bc73730a33b268225 peer=12
22023-03-21T17:10:55Z UpdateTip: new best=0000000000000000000198c04342dff96f7940111d874c7bc73730a33b268225 height=781829 version=0x20a00000 log2_work=94.071477 tx=816272773 date='2023-03-21T17:10:10Z' progress=1.000000 cache=48.5MiB(24209txo)
I’m concept ACK on adding unconditional logging, but why do there need to be two almost identical messages for this every time?