Backward sync log UX improvements #4655

fab-10 · 2022-11-11T11:58:47Z

Signed-off-by: Fabio Di Fabio fabio.difabio@consensys.net

PR description

Improve the backward sync logging, showing only the progress and critical errors, and pushing transient errors to debug.
Progress logs are printed at least 10 sec apart, to avoid spamming the console

example of the new progress log

{"@timestamp":"2022-11-14T13:52:25,896","level":"INFO","thread":"vert.x-worker-thread-0","class":"BackwardSyncContext","message":"Starting a new backward sync session","throwable":""}
{"@timestamp":"2022-11-14T13:52:26,177","level":"INFO","thread":"nioEventLoopGroup-3-5","class":"BackwardsSyncAlgorithm","message":"Backward sync target block is 2288072 (0x5aa9afcbffaa4e337924bd73fed858321c41aec25267841566185b3e9e4cfaba)","throwable":""}
{"@timestamp":"2022-11-14T13:52:26,608","level":"INFO","thread":"nioEventLoopGroup-3-5","class":"BackwardSyncStep","message":"Backward sync phase 1 of 2, 0.60% completed, downloaded 200 headers of at least 33147. Peers: 1","throwable":""}
{"@timestamp":"2022-11-14T13:52:36,644","level":"INFO","thread":"nioEventLoopGroup-3-5","class":"BackwardSyncStep","message":"Backward sync phase 1 of 2, 42.84% completed, downloaded 14200 headers of at least 33147. Peers: 3","throwable":""}
{"@timestamp":"2022-11-14T13:52:46,712","level":"INFO","thread":"nioEventLoopGroup-3-5","class":"BackwardSyncStep","message":"Backward sync phase 1 of 2, 94.13% completed, downloaded 31200 headers of at least 33147. Peers: 1","throwable":""}
{"@timestamp":"2022-11-14T13:52:47,861","level":"INFO","thread":"nioEventLoopGroup-3-5","class":"BackwardSyncStep","message":"Backward sync phase 1 of 2 completed, downloaded a total of 33200 headers. Peers: 1","throwable":""}
{"@timestamp":"2022-11-14T13:52:56,716","level":"INFO","thread":"nioEventLoopGroup-3-5","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2, 3.23% completed, imported 1070 blocks of at least 33156 (current head 2255995, target head 2288081). Peers: 5","throwable":""}
{"@timestamp":"2022-11-14T13:53:07,109","level":"INFO","thread":"nioEventLoopGroup-3-5","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2, 9.05% completed, imported 3001 blocks of at least 33157 (current head 2257926, target head 2288082). Peers: 2","throwable":""}
{"@timestamp":"2022-11-14T13:53:17,111","level":"INFO","thread":"nioEventLoopGroup-3-6","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2, 11.35% completed, imported 3764 blocks of at least 33158 (current head 2258689, target head 2288083). Peers: 2","throwable":""}
{"@timestamp":"2022-11-14T13:53:27,214","level":"INFO","thread":"nioEventLoopGroup-3-6","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2, 15.08% completed, imported 5001 blocks of at least 33158 (current head 2259926, target head 2288083). Peers: 2","throwable":""}
{"@timestamp":"2022-11-14T13:53:37,286","level":"INFO","thread":"nioEventLoopGroup-3-6","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2, 18.25% completed, imported 6050 blocks of at least 33158 (current head 2260975, target head 2288083). Peers: 5","throwable":""}
{"@timestamp":"2022-11-14T13:53:47,290","level":"INFO","thread":"nioEventLoopGroup-3-6","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2, 21.63% completed, imported 7173 blocks of at least 33159 (current head 2262098, target head 2288084). Peers: 3","throwable":""}
{"@timestamp":"2022-11-14T13:53:57,955","level":"INFO","thread":"nioEventLoopGroup-3-6","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2, 24.13% completed, imported 8001 blocks of at least 33160 (current head 2262926, target head 2288085). Peers: 4","throwable":""}
{"@timestamp":"2022-11-14T13:54:07,957","level":"INFO","thread":"nioEventLoopGroup-3-6","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2, 27.33% completed, imported 9062 blocks of at least 33161 (current head 2263987, target head 2288086). Peers: 2","throwable":""}
{"@timestamp":"2022-11-14T13:54:17,960","level":"INFO","thread":"nioEventLoopGroup-3-6","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2, 29.73% completed, imported 9860 blocks of at least 33162 (current head 2264785, target head 2288087). Peers: 2","throwable":""}
{"@timestamp":"2022-11-14T13:54:28,536","level":"INFO","thread":"nioEventLoopGroup-3-6","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2, 32.57% completed, imported 10801 blocks of at least 33163 (current head 2265726, target head 2288088). Peers: 2","throwable":""}
{"@timestamp":"2022-11-14T13:54:38,540","level":"INFO","thread":"nioEventLoopGroup-3-8","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2, 36.58% completed, imported 12133 blocks of at least 33164 (current head 2267058, target head 2288089). Peers: 4","throwable":""}
{"@timestamp":"2022-11-14T13:54:48,625","level":"INFO","thread":"nioEventLoopGroup-3-8","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2, 42.66% completed, imported 14149 blocks of at least 33164 (current head 2269074, target head 2288089). Peers: 5","throwable":""}
{"@timestamp":"2022-11-14T13:54:58,625","level":"INFO","thread":"nioEventLoopGroup-3-8","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2, 48.76% completed, imported 16171 blocks of at least 33164 (current head 2271096, target head 2288089). Peers: 4","throwable":""}
{"@timestamp":"2022-11-14T13:55:08,667","level":"INFO","thread":"nioEventLoopGroup-3-8","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2, 55.10% completed, imported 18275 blocks of at least 33164 (current head 2273200, target head 2288089). Peers: 3","throwable":""}
{"@timestamp":"2022-11-14T13:55:18,668","level":"INFO","thread":"nioEventLoopGroup-3-8","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2, 59.80% completed, imported 19832 blocks of at least 33165 (current head 2274757, target head 2288090). Peers: 3","throwable":""}
{"@timestamp":"2022-11-14T13:55:28,698","level":"INFO","thread":"nioEventLoopGroup-3-7","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2, 66.85% completed, imported 22170 blocks of at least 33166 (current head 2277095, target head 2288091). Peers: 5","throwable":""}
{"@timestamp":"2022-11-14T13:55:39,104","level":"INFO","thread":"nioEventLoopGroup-3-7","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2, 73.57% completed, imported 24401 blocks of at least 33167 (current head 2279326, target head 2288092). Peers: 4","throwable":""}
{"@timestamp":"2022-11-14T13:55:49,373","level":"INFO","thread":"nioEventLoopGroup-3-7","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2, 79.00% completed, imported 26201 blocks of at least 33167 (current head 2281126, target head 2288092). Peers: 5","throwable":""}
{"@timestamp":"2022-11-14T13:55:59,375","level":"INFO","thread":"nioEventLoopGroup-3-7","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2, 84.39% completed, imported 27991 blocks of at least 33167 (current head 2282916, target head 2288092). Peers: 4","throwable":""}
{"@timestamp":"2022-11-14T13:56:09,462","level":"INFO","thread":"nioEventLoopGroup-3-7","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2, 89.84% completed, imported 29797 blocks of at least 33168 (current head 2284722, target head 2288093). Peers: 5","throwable":""}
{"@timestamp":"2022-11-14T13:56:19,831","level":"INFO","thread":"nioEventLoopGroup-3-7","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2, 93.46% completed, imported 31001 blocks of at least 33169 (current head 2285926, target head 2288094). Peers: 5","throwable":""}
{"@timestamp":"2022-11-14T13:56:29,865","level":"INFO","thread":"nioEventLoopGroup-3-7","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2, 95.87% completed, imported 31801 blocks of at least 33170 (current head 2286726, target head 2288095). Peers: 7","throwable":""}
{"@timestamp":"2022-11-14T13:56:40,126","level":"INFO","thread":"nioEventLoopGroup-3-7","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2, 98.89% completed, imported 32801 blocks of at least 33170 (current head 2287726, target head 2288095). Peers: 4","throwable":""}
{"@timestamp":"2022-11-14T13:56:42,603","level":"INFO","thread":"nioEventLoopGroup-3-7","class":"BackwardSyncContext","message":"Backward sync phase 2 of 2 completed, imported a total of 33170 blocks. Peers: 4","throwable":""}
{"@timestamp":"2022-11-14T13:56:42,612","level":"INFO","thread":"ForkJoinPool.commonPool-worker-3","class":"BackwardsSyncAlgorithm","message":"The Backward sync is done","throwable":""}

Fixed Issue(s)

relates to #4446

Documentation

I thought about documentation and added the doc-change-required label to this PR if
updates are required.

Changelog

I thought about the changelog and included a changelog update if required.

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net>

gezero

Looks good to me

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net>

Signed-off-by: garyschulte <garyschulte@gmail.com>

* squash merge of main * squash commit of small EOF * squash commit of bw-sync ux log improvements #4655 * squash commit of 4656 bw-sync retry switching peers * squashed commit version of pr 4600 * squashed commit of #4648 Signed-off-by: garyschulte <garyschulte@gmail.com>

macfarla · 2022-11-14T01:23:43Z

...merge/src/main/java/org/hyperledger/besu/consensus/merge/blockcreation/MergeCoordinator.java

@@ -439,7 +443,7 @@ public ForkchoiceResult updateForkChoice(

    if (newHead.getNumber() < blockchain.getChainHeadBlockNumber()
        && isDescendantOf(newHead, blockchain.getChainHeadHeader())) {
-      LOG.info("Ignoring update to old head");
+      debugLambda(LOG, "Ignoring update to old head {}", newHead::toLogString);


"Ignoring head update {}", newHead

?

we can be specific here, since we know that FcU is trying to set the head to an old block in the same chain of the current head and so we ignore it

I was just wondering if it could be confusing that it says "old head" but what is inserted is the newHead

what about renaming newHead to something like tentativeNewHead or possibleNewHead to state that it is not yet confirmed?

...h/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java

macfarla

couple of non-blocking suggestions for wording

…g-ux

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net>

fab-10 · 2022-11-14T14:03:24Z

@gezero @macfarla I you want to take another look, I just pushed an update to the block import progess log to also include blocks imported during the final ProcessKnownAncestorsStep since that part could take some time if the backward sync was long.

macfarla

LGTM

...h/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net>

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net> Signed-off-by: wcgcyx <wcgcyx@gmail.com>

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net> Signed-off-by: Sally MacFarlane <macfarla.github@gmail.com>

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net>

fab-10 added 2 commits November 11, 2022 12:58

Backward sync log UX improvements

b22d1a0

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net>

Add CHANGELOG entry

65af5ef

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net>

fab-10 marked this pull request as ready for review November 11, 2022 12:02

fab-10 added the logging label Nov 11, 2022

fab-10 mentioned this pull request Nov 11, 2022

Backward sync: use retry switching peer when fetching data from peers #4656

Merged

2 tasks

gezero approved these changes Nov 11, 2022

View reviewed changes

Fix log in case of sync failures

5003ad7

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net>

fab-10 self-assigned this Nov 11, 2022

fab-10 added 3 commits November 12, 2022 10:53

Backward sync log UX improvements

ca71f6e

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net>

Add CHANGELOG entry

00a5468

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net>

Fix log in case of sync failures

0ad7d31

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net>

garyschulte force-pushed the bwsync-log-ux branch from 5003ad7 to 0ad7d31 Compare November 12, 2022 18:54

garyschulte added a commit to garyschulte/besu that referenced this pull request Nov 12, 2022

squash commit of bw-sync ux log improvements hyperledger#4655

17f3dcb

Signed-off-by: garyschulte <garyschulte@gmail.com>

garyschulte mentioned this pull request Nov 12, 2022

Release 22.10.1 alpha #4665

Merged

2 tasks

macfarla added the mainnet label Nov 14, 2022

macfarla reviewed Nov 14, 2022

View reviewed changes

...h/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java Outdated Show resolved Hide resolved

macfarla approved these changes Nov 14, 2022

View reviewed changes

Merge branch 'bwsync-log-ux' of github.com:fab-10/besu into bwsync-lo…

d8c4628

…g-ux

fab-10 force-pushed the bwsync-log-ux branch from 6dfada4 to d8c4628 Compare November 14, 2022 10:56

Rework log of imported block to support also ProcessKnownAncestorsStep

6c0c302

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net>

fab-10 force-pushed the bwsync-log-ux branch from d801bde to 6c0c302 Compare November 14, 2022 13:46

fab-10 mentioned this pull request Nov 14, 2022

Port backward sync updates from 4655 and 4656 to 22.10.1-alpha #4671

Merged

2 tasks

macfarla approved these changes Nov 14, 2022

View reviewed changes

...h/src/main/java/org/hyperledger/besu/ethereum/eth/sync/backwardsync/BackwardSyncContext.java Outdated Show resolved Hide resolved

fab-10 added 2 commits November 15, 2022 11:09

Improve method naming

d7f55d4

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net>

Merge branch 'main' into bwsync-log-ux

b5edd8f

fab-10 enabled auto-merge (squash) November 15, 2022 13:08

fab-10 merged commit af04357 into hyperledger:main Nov 15, 2022

fab-10 deleted the bwsync-log-ux branch November 15, 2022 13:33

wcgcyx pushed a commit to wcgcyx/besu that referenced this pull request Nov 16, 2022

Backward sync log UX improvements (hyperledger#4655)

dcec1bd

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net> Signed-off-by: wcgcyx <wcgcyx@gmail.com>

macfarla pushed a commit to macfarla/besu that referenced this pull request Jan 10, 2023

Backward sync log UX improvements (hyperledger#4655)

f37d1a0

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net> Signed-off-by: Sally MacFarlane <macfarla.github@gmail.com>

eum602 pushed a commit to lacchain/besu that referenced this pull request Nov 3, 2023

Backward sync log UX improvements (hyperledger#4655)

f298d38

Signed-off-by: Fabio Di Fabio <fabio.difabio@consensys.net>

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Backward sync log UX improvements #4655

Backward sync log UX improvements #4655

fab-10 commented Nov 11, 2022 •

edited

gezero left a comment

macfarla Nov 14, 2022

fab-10 Nov 14, 2022

macfarla Nov 14, 2022

fab-10 Nov 15, 2022

macfarla left a comment

fab-10 commented Nov 14, 2022

macfarla left a comment

Backward sync log UX improvements #4655

Backward sync log UX improvements #4655

Conversation

fab-10 commented Nov 11, 2022 • edited

PR description

Fixed Issue(s)

Documentation

Changelog

gezero left a comment

Choose a reason for hiding this comment

macfarla Nov 14, 2022

Choose a reason for hiding this comment

fab-10 Nov 14, 2022

Choose a reason for hiding this comment

macfarla Nov 14, 2022

Choose a reason for hiding this comment

fab-10 Nov 15, 2022

Choose a reason for hiding this comment

macfarla left a comment

Choose a reason for hiding this comment

fab-10 commented Nov 14, 2022

macfarla left a comment

Choose a reason for hiding this comment

fab-10 commented Nov 11, 2022 •

edited