ERROR AcceptBlockHeader log messages are kind of noisy #17421

This is the "harvest" of one day on one normal-running node (31 messages):

2019-11-07T00:32:02Z ERROR: AcceptBlockHeader: prev block not found
2019-11-07T01:02:36Z ERROR: AcceptBlockHeader: Consensus::ContextualCheckBlockHeader: 000000000000014219120d5167a4281437fc379129d4ba6f6e956ca1db77f5fa, bad-diffbits, incorrect proof of work
2019-11-07T01:08:55Z ERROR: AcceptBlockHeader: Consensus::ContextualCheckBlockHeader: 000000004bfb561102f5f04d4bab0cc70a403da70b82ce33657e10ed46b9000f, bad-diffbits, incorrect proof of work
2019-11-07T01:56:13Z ERROR: AcceptBlockHeader: Consensus::ContextualCheckBlockHeader: 000000000000001daed8bac77bdf571441649e51732e91bec984cf97a39005a1, bad-diffbits, incorrect proof of work
2019-11-07T03:11:12Z ERROR: AcceptBlockHeader: Consensus::ContextualCheckBlockHeader: 00000000bdcf539dc39dce363d791103e80c8a7180dff3c9c8a4f25f3500b8c9, bad-diffbits, incorrect proof of work
2019-11-07T04:04:51Z ERROR: AcceptBlockHeader: Consensus::ContextualCheckBlockHeader: 000000004bfb561102f5f04d4bab0cc70a403da70b82ce33657e10ed46b9000f, bad-diffbits, incorrect proof of work
2019-11-07T04:05:45Z ERROR: AcceptBlockHeader: Consensus::CheckBlockHeader: 2d94a35159bf59897eb709534f707ac587112ef8e2db52a7c7153099e77cecf3, high-hash, proof of work failed
2019-11-07T04:16:24Z ERROR: AcceptBlockHeader: Consensus::ContextualCheckBlockHeader: 000000000000001daed8bac77bdf571441649e51732e91bec984cf97a39005a1, bad-diffbits, incorrect proof of work
2019-11-07T04:22:01Z ERROR: AcceptBlockHeader: Consensus::CheckBlockHeader: 0fd7ab36246daf61802e10a0316cc2b0f17a1d6404bfdd53878ba34e158b4680, high-hash, proof of work failed
2019-11-07T04:28:31Z ERROR: AcceptBlockHeader: Consensus::CheckBlockHeader: 0fd7ab36246daf61802e10a0316cc2b0f17a1d6404bfdd53878ba34e158b4680, high-hash, proof of work failed
2019-11-07T04:40:18Z ERROR: AcceptBlockHeader: Consensus::ContextualCheckBlockHeader: 000000004bfb561102f5f04d4bab0cc70a403da70b82ce33657e10ed46b9000f, bad-diffbits, incorrect proof of work
2019-11-07T04:54:09Z ERROR: AcceptBlockHeader: Consensus::ContextualCheckBlockHeader: 000000000000001daed8bac77bdf571441649e51732e91bec984cf97a39005a1, bad-diffbits, incorrect proof of work
2019-11-07T06:36:36Z ERROR: AcceptBlockHeader: Consensus::ContextualCheckBlockHeader: 000000004bfb561102f5f04d4bab0cc70a403da70b82ce33657e10ed46b9000f, bad-diffbits, incorrect proof of work
2019-11-07T08:06:25Z ERROR: AcceptBlockHeader: prev block not found
2019-11-07T08:35:49Z ERROR: AcceptBlockHeader: Consensus::ContextualCheckBlockHeader: 000000000000001daed8bac77bdf571441649e51732e91bec984cf97a39005a1, bad-diffbits, incorrect proof of work
2019-11-07T08:36:30Z ERROR: AcceptBlockHeader: Consensus::ContextualCheckBlockHeader: 00000000bdcf539dc39dce363d791103e80c8a7180dff3c9c8a4f25f3500b8c9, bad-diffbits, incorrect proof of work
2019-11-07T08:56:15Z ERROR: AcceptBlockHeader: Consensus::ContextualCheckBlockHeader: 000000000000001daed8bac77bdf571441649e51732e91bec984cf97a39005a1, bad-diffbits, incorrect proof of work
2019-11-07T09:39:10Z ERROR: AcceptBlockHeader: Consensus::CheckBlockHeader: 2d94a35159bf59897eb709534f707ac587112ef8e2db52a7c7153099e77cecf3, high-hash, proof of work failed
2019-11-07T10:12:22Z ERROR: AcceptBlockHeader: Consensus::CheckBlockHeader: 0fd7ab36246daf61802e10a0316cc2b0f17a1d6404bfdd53878ba34e158b4680, high-hash, proof of work failed
2019-11-07T10:25:25Z ERROR: AcceptBlockHeader: Consensus::ContextualCheckBlockHeader: 00000000bdcf539dc39dce363d791103e80c8a7180dff3c9c8a4f25f3500b8c9, bad-diffbits, incorrect proof of work
2019-11-07T11:56:59Z ERROR: AcceptBlockHeader: Consensus::ContextualCheckBlockHeader: 000000000000014219120d5167a4281437fc379129d4ba6f6e956ca1db77f5fa, bad-diffbits, incorrect proof of work
2019-11-07T13:59:09Z ERROR: AcceptBlockHeader: Consensus::ContextualCheckBlockHeader: 000000000000000000639be19a0123a1c99d9fef89f0b8ac055a77f4ef86ae3b, bad-diffbits, incorrect proof of work
2019-11-07T14:54:46Z ERROR: AcceptBlockHeader: Consensus::CheckBlockHeader: 0fd7ab36246daf61802e10a0316cc2b0f17a1d6404bfdd53878ba34e158b4680, high-hash, proof of work failed
2019-11-07T15:57:01Z ERROR: AcceptBlockHeader: Consensus::ContextualCheckBlockHeader: 000000000000014219120d5167a4281437fc379129d4ba6f6e956ca1db77f5fa, bad-diffbits, incorrect proof of work
2019-11-07T18:27:44Z ERROR: AcceptBlockHeader: Consensus::ContextualCheckBlockHeader: 000000000000000000639be19a0123a1c99d9fef89f0b8ac055a77f4ef86ae3b, bad-diffbits, incorrect proof of work
2019-11-07T18:50:31Z ERROR: AcceptBlockHeader: Consensus::CheckBlockHeader: 0fd7ab36246daf61802e10a0316cc2b0f17a1d6404bfdd53878ba34e158b4680, high-hash, proof of work failed
2019-11-07T19:58:57Z ERROR: AcceptBlockHeader: Consensus::ContextualCheckBlockHeader: 000000000000014219120d5167a4281437fc379129d4ba6f6e956ca1db77f5fa, bad-diffbits, incorrect proof of work
2019-11-07T20:29:11Z ERROR: AcceptBlockHeader: Consensus::ContextualCheckBlockHeader: 000000000000000000639be19a0123a1c99d9fef89f0b8ac055a77f4ef86ae3b, bad-diffbits, incorrect proof of work
2019-11-07T21:07:06Z ERROR: AcceptBlockHeader: prev block not found
2019-11-07T22:30:22Z ERROR: AcceptBlockHeader: prev block not found
2019-11-07T23:10:53Z ERROR: AcceptBlockHeader: prev block not found

That's a lot of ERROR.

Usually we follow the principle that we don't want to have any things in the log by default that might worry users unnecessarily. I think these are ERRORs which are easily to trigger on the P2P network by feeding invalid headers, we might want to tone them down to normal log messages or even hide them in a debug category.

Maybe it is now a good idea to add a --verbose option to bitcoind, which does show such kinds of messages but without it won't

@emilengler That option is called -debug

Concept ACK on moving this to debug: improved signal-to-noise is good

@MarcoFalke Didn't knew it existed but then I agree with @practicalswift

The reason I'm creating a discussion topic here is not because I'm confused how to implement this (:smile:), but because it's slightly controversial and I might be confused about the 'easy to generate' part.

I think we do want ERROR for validation errors on blocks unconditionally, after checking proof-of-work, because significant computation time went into generating them, and miners sending them might be indication of a deeper problem with the network.

I think this is not the case for block headers, definitely not "bad-diffbits" or "proof of work failed". We made a similar decision about transactions. They're easy to send so they should not clutter the log by default.

Concept ACK removing the worrying ERROR text from these logs.

I think we do want ERROR for validation errors on blocks unconditionally

I don't think I agree. I'd usually associate ERROR in the debug logs as a software error rather than a peer feeding us bad data. Perhaps change all validation logs to print something like validation error rather than ERROR?

I don't think I agree. I'd usually associate ERROR in the debug logs as a software error rather than a peer feeding us bad data. Perhaps change all validation logs to print something like validation error rather than ERROR?

OK, maybe. My point here is that headers are categorically different from blocks in this regard.

Also in many cases, block validation errors do mean there's database corruption. You can't really distinguish all your peers feeding you bad blocks with valid PoW from local corruption.

Also in many cases, block validation errors do mean there's database corruption. You can't really distinguish all your peers feeding you bad blocks with valid PoW from local corruption.

We absolutely do want to distinguish these cases. That's why we have BlockValidationState.IsValid() and BlockValidationState.IsError(). The second is used in cases where there is local corruption.

@jnewbery I think @laanwj is referring to failed block validation that are due to local corruption, but aren't detected as corruption.

Maybe it's possible to distinguish some cases, but definitely not in general. Let's say, I've had cases of UTXO database corruption due to failing hardware that weren't detected by that. The only thing that was revealing it was that it was rejecting every single block on the network.

I mean, how can you even know if your local UTXO database is missing entries (or has additional ones that shouldn't be there)? In a decentralized network, your own database is the only reference.

According to my understanding, ERROR: AcceptBlockHeader: Consensus::CheckBlockHeader: can be excluded from log file using -debug or -debugexclude mentioned in https://github.com/bitcoin/bitcoin/pull/10123/ because it is assigned a category 'VALIDATION' in: https://github.com/bitcoin/bitcoin/blob/48c1083632687a42ac603d4f241e70616a1d3815/src/validation.cpp#L3643

Other error messages saved in logs are not assigned any category and LogPrintf is used instead of LogPrint in https://github.com/bitcoin/bitcoin/blob/48c1083632687a42ac603d4f241e70616a1d3815/src/validation.cpp#L3622