Provide meaningful progress updates during backwards/forwards sync

[ajsutton]

Description

Currently when the consensus client jumps ahead and besu needs to perform a backwards sync it gives some really confusing log messages which make it look like it's not making any progress:

{"@timestamp":"2022-10-16T10:00:27,655","level":"INFO","thread":"nioEventLoopGroup-3-3","class":"ForwardSyncStep","message":"No blocks to save...","throwable":""}
{"@timestamp":"2022-10-16T10:00:27,664","level":"INFO","thread":"nioEventLoopGroup-3-3","class":"BackwardsSyncAlgorithm","message":"Backward sync reached ancestor header, starting Forward sync","throwable":""}
{"@timestamp":"2022-10-16T10:00:27,850","level":"INFO","thread":"nioEventLoopGroup-3-3","class":"ForwardSyncStep","message":"No blocks to save...","throwable":""}
{"@timestamp":"2022-10-16T10:00:27,858","level":"INFO","thread":"nioEventLoopGroup-3-3","class":"BackwardsSyncAlgorithm","message":"Backward sync reached ancestor header, starting Forward sync","throwable":""}
{"@timestamp":"2022-10-16T10:00:27,971","level":"INFO","thread":"nioEventLoopGroup-3-3","class":"ForwardSyncStep","message":"No blocks to save...","throwable":""}
{"@timestamp":"2022-10-16T10:00:27,979","level":"INFO","thread":"nioEventLoopGroup-3-3","class":"BackwardsSyncAlgorithm","message":"Backward sync reached ancestor header, starting Forward sync","throwable":""}
{"@timestamp":"2022-10-16T10:00:28,145","level":"INFO","thread":"nioEventLoopGroup-3-3","class":"ForwardSyncStep","message":"No blocks to save...","throwable":""}
{"@timestamp":"2022-10-16T10:00:28,157","level":"INFO","thread":"nioEventLoopGroup-3-3","class":"BackwardsSyncAlgorithm","message":"Backward sync reached ancestor header, starting Forward sync","throwable":""}
{"@timestamp":"2022-10-16T10:00:28,158","level":"WARN","thread":"ForkJoinPool.commonPool-worker-1","class":"BackwardSyncContext","message":"Backward sync failed (org.hyperledger.besu.ethereum.eth.manager.exceptions.NoAvailablePeersException: Task failed: NO_AVAILABLE_PEERS). Current Peers: 0. Retrying in 5000 milliseconds...","throwable":""}
{"@timestamp":"2022-10-16T10:00:33,169","level":"INFO","thread":"EthScheduler-Timer-0","class":"BackwardsSyncAlgorithm","message":"Backward sync reached ancestor header, starting Forward sync","throwable":""}
{"@timestamp":"2022-10-16T10:00:33,169","level":"WARN","thread":"ForkJoinPool.commonPool-worker-1","class":"BackwardSyncContext","message":"Backward sync failed (org.hyperledger.besu.ethereum.eth.manager.exceptions.NoAvailablePeersException: Task failed: NO_AVAILABLE_PEERS). Current Peers: 1. Retrying in 5000 milliseconds...","throwable":""}
{"@timestamp":"2022-10-16T10:00:37,016","level":"INFO","thread":"vert.x-worker-thread-0","class":"EngineForkchoiceUpdated","message":"SYNCING for fork-choice-update: head: 0x972a8b063ec543e1a9ea8cf3f7cb2f9d98926c2845964fedbf93d0684a8d1ea7, finalized: 0xfc82ad881922642e14f091a5db3af932269ffcc9b06bec0dbb1720dbf2ec8bcf, safeBlockHash: 0xd56abb85963124d77cee765fbb01111e1bc56765020a2e4a3a50251c321be41f","throwable":""}
{"@timestamp":"2022-10-16T10:00:38,179","level":"INFO","thread":"EthScheduler-Timer-0","class":"BackwardsSyncAlgorithm","message":"Backward sync reached ancestor header, starting Forward sync","throwable":""}
{"@timestamp":"2022-10-16T10:00:42,666","level":"INFO","thread":"nioEventLoopGroup-3-1","class":"ForwardSyncStep","message":"Saved blocks 7775831 -> 7775844 (target: 7778816)","throwable":""}
{"@timestamp":"2022-10-16T10:00:42,685","level":"INFO","thread":"ForkJoinPool.commonPool-worker-1","class":"BackwardsSyncAlgorithm","message":"Backward sync reached ancestor header, starting Forward sync","throwable":""}
{"@timestamp":"2022-10-16T10:00:59,832","level":"INFO","thread":"ForkJoinPool.commonPool-worker-1","class":"BackwardsSyncAlgorithm","message":"Backward sync reached ancestor header, starting Forward sync","throwable":""}
{"@timestamp":"2022-10-16T10:01:12,576","level":"INFO","thread":"nioEventLoopGroup-3-1","class":"ForwardSyncStep","message":"Saved blocks 7775890 -> 7775923 (target: 7778819)","throwable":""}
{"@timestamp":"2022-10-16T10:01:12,594","level":"INFO","thread":"ForkJoinPool.commonPool-worker-1","class":"BackwardsSyncAlgorithm","message":"Backward sync reached ancestor header, starting Forward sync","throwable":""}

I think based on the way the "Saved blocks" log line numbers are changing that it is actually importing blocks but it looks like it's stuck doing backwards sync and then forward sync does nothing because there were "No blocks to save...".

We should improve this logging to just clearly show the progress being made and how much further it has to sync.

[ajsutton]

Ah actually the:

{"@timestamp":"2022-10-16T10:05:11,856","level":"INFO","thread":"nioEventLoopGroup-3-3","class":"ForwardSyncStep","message":"Saved blocks 7776535 -> 7776577 (target: 7778836)","throwable":""}

lines towards the end are more useful when you can spot them in all the backwards sync noise. Maybe it wasn't actually making progress initially but then I don't know why not.

[non-fungible-nelson]

Closing for logging changes in backwards and forward sync in 22.10.x series.