exec: chain-tip logging seems wrong

[AskAlexSharov]

now on bormainnet chain-tip:

[INFO] [01-18|03:29:33.289] [4/6 Execution] Done Commit every block  blk=66833605 blks=2 blk/s=18.2 txs=61 tx/s=555 gas/s=90.96M buf=3.6MB/512.0MB stepsInDB=0.00 step=3165.8 inMem=false alloc=22.3GB sys=28.0GB
[DBUG] [01-18|03:29:33.289] [4/6 Execution] DONE                     in=110.17315ms
[DBUG] [01-18|03:29:33.290] [5/6 TxLookup] DONE                      in=738.356µs
[DBUG] [01-18|03:29:33.290] [6/6 Finish] DONE                        in=8.11µs
[DBUG] [01-18|03:29:33.290] RPC Daemon notified of new headers       from=66833604 to=66833606 amount=1 header sending=8.079µs

amount=1 but blks=2. One of them is wrong. (maybe then txs also wrong).

[taratorio]

even worse case (seen on Amoy):

• executes 1 block per update fork choice
• no unwinds (verified this)
• blks increases up to 5 - 1,2,3,4,5
• instead blks should always be 1 in this case
• looking at the code it looks like +1 should be removed from diffBlocks := max(int(outputBlockNum)-int(p.prevOutputBlockNum)+1, 0) but that won't solve the issue (because we go up to a lot more than just 1 off)
• seems like initially Progress.prevOutputBlockNum is set to doms.BlockNum()
• why does doms.BlockNum() lag behind? is this highlighting some bug elsewhere?

[INFO] [01-18|20:04:27.125] [sync] update fork choice                block=17024076 hash=0xd7dc5912bc9ed23d2c1a51f22fca431ecd4632fd48d9d2ffce023296d7eff6d3 age=0
[INFO] [01-18|20:04:27.128] [4/6 Execution] Done Commit every block  blk=17024076 blks=1 blk/s=674.9 txs=2 tx/s=1.34k gas/s=0 buf=8B/512.0MB stepsInDB=0.00 step=35.5 inMem=false alloc=1.2GB sys=1.9GB
[INFO] [01-18|20:04:27.137] head updated                             age=0 head=0xd7dc5912bc9ed23d2c1a51f22fca431ecd4632fd48d9d2ffce023296d7eff6d3 hash=0xd7dc5912bc9ed23d2c1a51f22fca431ecd4632fd48d9d2ffce023296d7eff6d3 commit=438µs alloc=1.2GB sys=1.9GB
[INFO] [01-18|20:04:29.139] [sync] update fork choice                block=17024077 hash=0x8979d4e78a41e740b95a35e686e2e9d4e2fc55d0f293d87ddcceda0bf1e2a72e age=0
[INFO] [01-18|20:04:29.146] [4/6 Execution] Done Commit every block  blk=17024077 blks=2 blk/s=1055.6 txs=4 tx/s=2.11k gas/s=0 buf=0B/512.0MB stepsInDB=0.00 step=35.5 inMem=false alloc=1.3GB sys=1.9GB
[INFO] [01-18|20:04:29.157] head updated                             age=0 head=0x8979d4e78a41e740b95a35e686e2e9d4e2fc55d0f293d87ddcceda0bf1e2a72e hash=0x8979d4e78a41e740b95a35e686e2e9d4e2fc55d0f293d87ddcceda0bf1e2a72e commit=275.709µs alloc=1.3GB sys=1.9GB
[INFO] [01-18|20:04:31.075] [sync] update fork choice                block=17024078 hash=0x20877807c9c6cc2877ab9d33f71bce5d47e984730ab0109f9c46e5fbbfeed145 age=0
[INFO] [01-18|20:04:31.077] [4/6 Execution] Done Commit every block  blk=17024078 blks=3 blk/s=2346.7 txs=6 tx/s=4.69k gas/s=0 buf=0B/512.0MB stepsInDB=0.00 step=35.5 inMem=false alloc=741.5MB sys=1.9GB
[INFO] [01-18|20:04:31.086] head updated                             age=0 head=0x20877807c9c6cc2877ab9d33f71bce5d47e984730ab0109f9c46e5fbbfeed145 hash=0x20877807c9c6cc2877ab9d33f71bce5d47e984730ab0109f9c46e5fbbfeed145 commit=514.209µs alloc=741.5MB sys=1.9GB
[INFO] [01-18|20:04:33.082] [sync] update fork choice                block=17024079 hash=0xcaecd438af44028c1cf0b37194c527dbf1b1bb3f8b711de6a4f91f28362abde1 age=0
[INFO] [01-18|20:04:33.084] [4/6 Execution] Done Commit every block  blk=17024079 blks=4 blk/s=4649.6 txs=8 tx/s=9.29k gas/s=0 buf=0B/512.0MB stepsInDB=0.00 step=35.5 inMem=false alloc=797.6MB sys=1.9GB
[INFO] [01-18|20:04:33.093] head updated                             age=0 head=0xcaecd438af44028c1cf0b37194c527dbf1b1bb3f8b711de6a4f91f28362abde1 hash=0xcaecd438af44028c1cf0b37194c527dbf1b1bb3f8b711de6a4f91f28362abde1 commit=270.583µs alloc=797.7MB sys=1.9GB
[INFO] [01-18|20:04:37.067] [sync] update fork choice                block=17024080 hash=0x0efeb3f1c1dcec76201d56e26b91fcc7d2722d4626fa717e5d68ac0a80167805 age=0
[INFO] [01-18|20:04:37.071] [4/6 Execution] Done Commit every block  blk=17024080 blks=5 blk/s=1945.7 txs=10 tx/s=3.89k gas/s=0 buf=13.5KB/512.0MB stepsInDB=0.00 step=35.5 inMem=false alloc=855.1MB sys=1.9GB
[INFO] [01-18|20:04:37.079] head updated                             age=0 head=0x0efeb3f1c1dcec76201d56e26b91fcc7d2722d4626fa717e5d68ac0a80167805 hash=0x0efeb3f1c1dcec76201d56e26b91fcc7d2722d4626fa717e5d68ac0a80167805 commit=151.583µs alloc=855.1MB sys=1.9GB
[INFO] [01-18|20:04:39.056] [sync] update fork choice                block=17024081 hash=0x0efa4e217479c0bc7e963ef87eb1c1320229ed6bf6307500576560fb4fe41b55 age=0
[INFO] [01-18|20:04:39.059] [4/6 Execution] Done Commit every block  blk=17024081 blks=1 blk/s=704.1 txs=2 tx/s=1.40k gas/s=0 buf=0B/512.0MB stepsInDB=0.00 step=35.5 inMem=false alloc=910.8MB sys=1.9GB
[INFO] [01-18|20:04:39.067] head updated                             age=0 head=0x0efa4e217479c0bc7e963ef87eb1c1320229ed6bf6307500576560fb4fe41b55 hash=0x0efa4e217479c0bc7e963ef87eb1c1320229ed6bf6307500576560fb4fe41b55 commit=472.209µs alloc=910.8MB sys=1.9GB