ChainSafe / ChainSafe/lodestar
Consider changing block error verbosity from `debug` to `error`
- Dominant language
- TypeScript
- Stars
- 1.4k
- Forks
- 483
- Avg merge
- 1d 16h
- Merged PRs (30d)
- 150
Description
We should consider changing [Block error](https://github.com/ChainSafe/lodestar/blob/7ce493932623e63998aea7faea167acaae7ac3ea/packages/beacon-node/src/chain/blocks/index.ts#L118) verbosity from `debug` to `error`. As far as I remember this was previously using `error` but we moved it to `debug` due to the fact that is was falsely alarming users and just generally producing too many errors. But the issue with this is that if the node is stuck because we or the connected EL does not properly handle a valid block or produce an invalid block ourselves then we also just emit the error to `debug` and it's not immediately visible that there was a issue.
Based on [Lido mainnet nodes over the last 7 days](https://grafana-lodestar.chainsafe.io/explore?schemaVersion=1&panes=%7B%22nce%22:%7B%22datasource%22:%22mWyrm924z%22,%22queries%22:%5B%7B%22refId%22:%22A%22,%22expr%22:%22%7Bgroup%3D%5C%22lido_prod%5C%22,%20container%3D%5C%22beacon%5C%22%7D%20%7C%3D%20%60Block%20error%60%22,%22queryType%22:%22range%22,%22datasource%22:%7B%22type%22:%22loki%22,%22uid%22:%22mWyrm924z%22%7D,%22editorMode%22:%22builder%22%7D%5D,%22range%22:%7B%22from%22:%22now-7d%22,%22to%22:%22now%22%7D%7D%7D&orgId=1) we have a bunch of different block errors (there might be more)
- `Block error slot=11246434, code=BLOCK_ERROR_DATA_UNAVAILABLE`
- `Block error slot=11243775, code=BLOCK_ERROR_FUTURE_SLOT, blockSlot=11243775, currentSlot=11243774`
- `Block error slot=11242720, code=BLOCK_ERROR_BEACON_CHAIN_ERROR, error=No block for root 0x5159554202bac983fe6b52c6b5ebad3e987dc11e9cf83c1eea6e22431afde8b2`
- `Block error slot=11220076, code=BLOCK_ERROR_EXECUTION_ERROR, execStatus=INVALID, errorMessage=invalid number of versionedHashes: [0x015ecbaace192b850d12d264339d0f18f66148a533d2f9431d0323a7a6d61bd0 0x01da00914f6227fae50f621432722ea0f496b519845c5dbb8b5bfa1c87d34cd5] blobHashes: [0x015ecbaace192b850d12d264339d0f18f66148a533d2f9431d0323a7a6d61bd0 0x01da00914f6227fae50f621432722ea0f496b519845c5dbb8b5bfa1c87d34cd5 0x01da00914f6227fae50f621432722ea0f496b519845c5dbb8b5bfa1c87d34cd5]`
- `Block error slot=11220076, code=BLOCK_ERROR_EXECUTION_ERROR, execStatus=INVALID, errorMessage=Blob versioned hashes do not match`
- `Block error slot=11220073, code=BLOCK_ERROR_EXECUTION_ERROR, execStatus=INVALID, errorMessage=Versioned hashes from blob transactions do not match expected values`
- `Block error slot=11205697, code=BLOCK_ERROR_EXECUTION_ERROR, execStatus=INVALID, errorMessage=blockhash mismatch, want 2ba795e5de6020859f736871c476e7507a75f9be7d89a2e369d66d0d092c4a1b, got 7d04df99ec9282b6e696e6524873e0b69069a8fed38d26acb788177ec51bd4f5`
This suggests to me that simply printing out all block errors to `error` might be too verbose as all of these seem to be issues the user doesn't really need to know about as they suggest faulty or slow nodes in the network.
And we already log a bunch of these errors as part of the log [Error receiving block](https://github.com/ChainSafe/lodestar/blob/7ce493932623e63998aea7faea167acaae7ac3ea/packages/beacon-node/src/network/processor/gossipHandlers.ts#L335), see [Lido mainnet nodes over the last 7 days](https://grafana-lodestar.chainsafe.io/explore?schemaVersion=1&panes=%7B%22bzp%22:%7B%22datasource%22:%22mWyrm924z%22,%22queries%22:%5B%7B%22refId%22:%22A%22,%22expr%22:%22%7Bgroup%3D%5C%22lido_prod%5C%22,%20container%3D%5C%22beacon%5C%22%7D%20%7C%3D%20%60Error%20receiving%20block%60%22,%22queryType%22:%22range%22,%22datasource%22:%7B%22type%22:%22loki%22,%22uid%22:%22mWyrm924z%22%7D,%22editorMode%22:%22builder%22%7D%5D,%22range%22:%7B%22from%22:%22now-7d%22,%22to%22:%22now%22%7D%7D%7D&orgId=1) for examples
the notable difference between those two is that we dynamically change the log level of `Error receiving block ...` based on the block error type, see https://github.com/ChainSafe/lodestar/pull/6430 for more details
So essentially the question here is what errors are not caputred by `Error receiving block ...` and printed to `error` / `warn` which instead we should print out in `Block error ...` as `error`. A candidate that comes to mind is blocks we produce locally ourselves which then fail state transition as those are not captured by the log we have in gossip handler. A great example of this is just a recent issue we had https://github.com/ChainSafe/lodestar/issues/7487, this log was just printed to `debug` (see log in issue) and the node stalled but from a user perspective that is just looking at `info` logs it's not clear why the node stalled.
Contributor guide
Assessment
This issue has not been assessed yet.