Log new headers #27278

jamesob · 2023-03-19T14:06:23Z

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.

DrahtBot · 2023-03-19T14:06:25Z

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
ACK	Sjors, dergoegge, josibake, achow101
Concept ACK	darosior

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:

#26969 (net, refactor: net_processing, add 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.

Sjors · 2023-03-19T14:15:01Z

The second commit 8828f03 (compact blocks) is useful regardless of whether this PR or #27276 makes it in. I'll let you rebase it in the latter case, because if I were to cherry-pick it, it would make my PR less trivial to review :-)

src/validation.cpp

Sjors

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 dbd1442~~

Sjors · 2023-03-19T15:30:32Z

src/validation.cpp

@@ -3832,6 +3832,18 @@ bool ChainstateManager::AcceptBlockHeader(const CBlockHeader& block, BlockValida
    if (ppindex)
        *ppindex = pindex;

+    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:

// 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 :-(

How do you have a valid header without a known height? If you don't know all the ancestors, you can't tell if the 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.

The only other call site for AddToBlockIndex() is LoadGenesisBlock(), so I guess that's the only reason for the (generic looking) check of hashPrevBlock.

Indeed this code is pretty ancient (and could use a comment): https://github.com/bitcoin/bitcoin/blame/f3ae51dcced8a16175426051ce888130cc2493af/src/main.cpp#L2056-L2063

src/validation.cpp

dergoegge

Concept ACK

Prefer this over #27276 as well I think.

Maybe add the peer id to the log locations as well?

src/net_processing.cpp

Sjors · 2023-03-20T11:20:47Z

Retracting ACK because I missed that CalculateHeadersWork doesn't check the work, see #27278 (comment)

darosior · 2023-03-20T11:30:15Z

Concept ACK.

jamesob · 2023-03-20T12:41:57Z

Thanks for quick feedback, all. I think the latest update should make everyone happy.

src/net_processing.cpp

Sjors · 2023-03-20T16:42:09Z

I wrote:

using warning for 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.

Sjors · 2023-03-20T16:58:24Z

That said, it seems quite trivial to just change the default log level: Sjors@0ecb829

So far that's not generating noise for me.

jamesob · 2023-03-20T17:10:29Z

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.

Sjors

tACK 2c3a90f

Prefer if you leave it like this and leave log level tweaks to a followup.

Sjors · 2023-03-20T17:14:44Z

src/validation.cpp

+        "Saw new header hash=%s height=%d", hash.ToString(), pindex->nHeight);
+
+    if (ActiveChainstate().IsInitialBlockDownload()) {
+        LogPrintLevel(BCLog::VALIDATION, BCLog::Level::Debug, "%s\n", msg);


This creates a nice flood of messages when running with -debug=validation right after our headers presync succeeds. But that's probably fine if someone is actively debugging IBD.

src/net_processing.cpp

jonatack · 2023-03-20T18:01:58Z

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.

Optionally could just go for info, unless it has to be unconditionally logged asap in which case maybe pull in 118c756. Making info unconditionally logged is near the top of the next steps in the parent PR #25203 i.e. 118c756 (@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.

jamesob · 2023-03-21T13:56:17Z

FWIW I plan to leave this as-is.

dergoegge · 2023-03-21T14:24:18Z

Code review ACK 2c3a90f

josibake

ACK 2c3a90f

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.

josibake · 2023-03-21T15:17:19Z

src/validation.cpp

+    const auto msg = strprintf(
+        "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 😭

Suggested change

const auto msg = strprintf(

"Saw new header hash=%s height=%d", hash.ToString(), pindex->nHeight);

const auto msg = strprintf(

"Saw new header hash=%s height=%d", hash.ToString(), pindex->nHeight

);

@josibake Our clang-format wouldn't agree. It would revert your diff to what was merged (and propose this change instead).

@@ -4224,7 +4224,7 @@ void PeerManagerImpl::ProcessMessage(CNode& pfrom, const std::string& msg_type, if (received_new_header) { LogPrintfCategory(BCLog::NET, "Saw new cmpctblock header hash=%s peer=%d\n", - blockhash.ToString(), pfrom.GetId()); + blockhash.ToString(), pfrom.GetId()); }

fanquake · 2023-03-21T15:20:53Z

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.

achow101 · 2023-03-21T17:42:08Z

ACK 2c3a90f

mzumsande · 2023-03-21T17:48:56Z

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:

2023-03-21T17:10:55Z Saw new header hash=0000000000000000000198c04342dff96f7940111d874c7bc73730a33b268225 height=781829
2023-03-21T17:10:55Z [net] Saw new cmpctblock header hash=0000000000000000000198c04342dff96f7940111d874c7bc73730a33b268225 peer=12
2023-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?

Sjors · 2023-03-21T18:08:34Z

@mzumsande this can be reduced to one, but requires some additional complexity: #27278 (comment) . Basically it involves handling the messages in net_processing rather than validation, but being careful not to introduce a log-spam DoS vector.

2c3a90f log: on new valid header (James O'Beirne) e5ce857 log: net: new header over cmpctblock (James O'Beirne) Pull request description: Alternate to bitcoin#27276. Devs were [suprised to realize](https://twitter.com/jamesob/status/1637237917201383425) 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. ACKs for top commit: dergoegge: Code review ACK 2c3a90f achow101: ACK 2c3a90f Sjors: tACK 2c3a90f josibake: ACK bitcoin@2c3a90f Tree-SHA512: 49fdcbe07799c8adc24143d7e5054a0c93fef120d2e9d5fddbd3b119550d895e2985be6ac10dd1825ea23a6fa5479c1b76d5518c136fbd983fa76c0d39dc354f

eb7cc9f Rename CalculateHeadersWork to CalculateClaimedHeadersWork (Greg Sanders) Pull request description: And clean up some comments. Confusion about what this is doing seems to be a running theme: #29549 (comment) #27278 (comment) ACKs for top commit: achow101: ACK eb7cc9f pablomartin4btc: ACK eb7cc9f 0xB10C: ACK eb7cc9f dergoegge: ACK eb7cc9f BrandonOdiwuor: ACK eb7cc9f Tree-SHA512: 6ccbc5e417155516487bb220753d189b5341dec05366db88a3fa5b1932eace21fbfaf23408c639bb54b36169a8d0a7536a1ee5e63b4ce5a3b70f2ff8407b6e07

Sjors reviewed Mar 19, 2023

View reviewed changes

src/validation.cpp Outdated Show resolved Hide resolved

jamesob force-pushed the 2023-03-log-new-headers branch 2 times, most recently from babe8ac to 75ee0d4 Compare March 19, 2023 14:44

jonatack reviewed Mar 19, 2023

View reviewed changes

src/validation.cpp Outdated Show resolved Hide resolved

jamesob force-pushed the 2023-03-log-new-headers branch from 75ee0d4 to dbd1442 Compare March 19, 2023 14:48

Sjors mentioned this pull request Mar 19, 2023

Log successful AcceptBlockHeader() #27276

Closed

Sjors approved these changes Mar 19, 2023

View reviewed changes

jonatack reviewed Mar 19, 2023

View reviewed changes

src/validation.cpp Outdated Show resolved Hide resolved

DrahtBot mentioned this pull request Mar 20, 2023

net, refactor: net_processing, add ProcessCompactBlockTxns #26969

Merged

dergoegge suggested changes Mar 20, 2023

View reviewed changes

src/net_processing.cpp Outdated Show resolved Hide resolved

log: net: new header over cmpctblock

e5ce857

jamesob force-pushed the 2023-03-log-new-headers branch from dbd1442 to 6d2f4d5 Compare March 20, 2023 12:40

dergoegge reviewed Mar 20, 2023

View reviewed changes

src/net_processing.cpp Show resolved Hide resolved

log: on new valid header

2c3a90f

jamesob force-pushed the 2023-03-log-new-headers branch from 6d2f4d5 to 2c3a90f Compare March 20, 2023 17:05

Sjors approved these changes Mar 20, 2023

View reviewed changes

josibake approved these changes Mar 21, 2023

View reviewed changes

achow101 merged commit 664500f into bitcoin:master Mar 21, 2023

reez mentioned this pull request Apr 6, 2023

Socratic Seminar #6 Topics NashBitDevs/nashbitdevs.org#7

Closed

Sjors mentioned this pull request May 24, 2023

Log which peer sent us a header (first) #27744

Closed

Sjors mentioned this pull request Jun 5, 2023

validation: log which peer sent us a header #27826

Merged

Sjors mentioned this pull request Mar 5, 2024

p2p: log mutated blocks when unknown & valid PoW #29549

Closed

instagibbs mentioned this pull request Mar 5, 2024

Rename CalculateHeadersWork to CalculateClaimedHeadersWork #29569

Merged

bitcoin locked and limited conversation to collaborators Mar 20, 2024

		const auto msg = strprintf(
		"Saw new header hash=%s height=%d", hash.ToString(), pindex->nHeight);

Log new headers #27278

Log new headers #27278

Uh oh!

Conversation

jamesob commented Mar 19, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

DrahtBot commented Mar 19, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Reviews

Conflicts

Uh oh!

Sjors commented Mar 19, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Sjors left a comment • 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!

Sjors Mar 19, 2023

Choose a reason for hiding this comment

Uh oh!

Sjors Mar 19, 2023 • 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!

ajtowns Mar 20, 2023

Choose a reason for hiding this comment

Uh oh!

Sjors Mar 20, 2023 • 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!

Sjors Mar 20, 2023

Choose a reason for hiding this comment

Uh oh!

Sjors Mar 20, 2023

Choose a reason for hiding this comment

Uh oh!

Uh oh!

dergoegge left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Sjors commented Mar 20, 2023

Uh oh!

darosior commented Mar 20, 2023

Uh oh!

jamesob commented Mar 20, 2023

Uh oh!

Uh oh!

Sjors commented Mar 20, 2023

Uh oh!

Sjors commented Mar 20, 2023

Uh oh!

jamesob commented Mar 20, 2023

Uh oh!

Sjors left a comment

Choose a reason for hiding this comment

Uh oh!

Sjors Mar 20, 2023

Choose a reason for hiding this comment

Uh oh!

Uh oh!

jonatack commented Mar 20, 2023 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jamesob commented Mar 21, 2023

Uh oh!

dergoegge commented Mar 21, 2023

Uh oh!

josibake left a comment

Choose a reason for hiding this comment

Uh oh!

josibake Mar 21, 2023

Choose a reason for hiding this comment

Uh oh!

jonatack Mar 21, 2023

jamesob commented Mar 19, 2023 •

edited

Loading

DrahtBot commented Mar 19, 2023 •

edited

Loading

Sjors commented Mar 19, 2023 •

edited

Loading

Sjors left a comment •

edited

Loading

Sjors Mar 19, 2023 •

edited

Loading

Sjors Mar 20, 2023 •

edited

Loading

jonatack commented Mar 20, 2023 •

edited

Loading

Sjors commented Mar 21, 2023 •

edited

Loading