BorHeimdall unwinding issue on bor-mainnet

[awskii]

being some time on chain tip and then unrecoverable unwind happen

2b248ca

[INFO] [11-05|10:38:49.190] [7/9 Execution] Done Commit every block  blk=63910938 blks=1 blk/s=0.5 txs=76 tx/s=39 gas/s=7.03M buf=5.8MB/2.0GB stepsInDB=0.00 step=3010.0 alloc=17.2GB sys=42
.1GB
[DBUG] [11-05|10:38:49.190] [7/9 Execution] DONE                     in=1.923826825s
[DBUG] [11-05|10:38:49.192] [8/9 TxLookup] DONE                      in=1.876463ms
[DBUG] [11-05|10:38:49.192] [9/9 Finish] DONE                        in=17.059µs
[DBUG] [11-05|10:38:49.433] RPC Daemon notified of new headers       from=63910937 to=63910939 amount=1 header sending=19.89µs
[INFO] [11-05|10:38:49.434] Timings (slower than 50ms)               Headers=3.624s BorHeimdall=2.097s Execution=1.923s mgas/s=6.883 alloc=17.2GB sys=42.1GB
[DBUG] [11-05|10:38:49.434] [9/9 Finish] Prune done                  in=7.54µs
[DBUG] [11-05|10:38:49.434] [8/9 TxLookup] Prune done                in=3.99µs
[DBUG] [11-05|10:38:49.435] [7/9 Execution] Prune done               in=692.627µs
[DBUG] [11-05|10:38:49.435] [6/9 Senders] Prune done                 in=3.31µs
[DBUG] [11-05|10:38:49.435] [5/9 Bodies] Prune done                  in=2.389µs
[DBUG] [11-05|10:38:49.435] [4/9 BlockHashes] Prune done             in=2.73µs
[DBUG] [11-05|10:38:49.435] [3/9 BorHeimdall] Prune done             in=2.28µs
[DBUG] [11-05|10:38:49.435] [2/9 Headers] Prune done                 in=1.63µs
[DBUG] [11-05|10:38:49.435] [snapshots] Prune Blocks                 to=63908976 limit=10
[DBUG] [11-05|10:38:49.435] [snapshots] Prune Bor Blocks             to=63908976 limit=10 deleted=0 err=nil
[DBUG] [11-05|10:38:49.435] [1/9 OtterSync] Prune done               in=111.047µs
[DBUG] [11-05|10:38:49.535] [1/9 OtterSync] DONE                     in=23.51µs
[INFO] [11-05|10:38:49.535] [2/9 Headers] Waiting for headers...     from=63910938 hash=0xdc8ef1901aa950e54328cf0c3db8110fd572d42c1cbb13a2a0509b83c5174183
[DBUG] [11-05|10:38:49.536] [2/9 Headers] Requested skeleton         from=63910937 length=192
[WARN] [11-05|10:38:49.536] [dbg] HeaderInserter: set unwind point   v=63910937 stack="[header_algos.go:1030 header_algos.go:967 header_algos.go:840 header_algos.go:576 header_algos.go:652
 stage_headers.go:251 stage_headers.go:123 default_stages.go:65 sync.go:526 sync.go:410 stageloop.go:252 stageloop.go:103 asm_amd64.s:1700]"
[DBUG] [11-05|10:38:49.536] UnwindTo                                 block=63910937 stack="[sync.go:173 stage_headers.go:322 stage_headers.go:123 default_stages.go:65 sync.go:526 sync.go:4
10 stageloop.go:252 stageloop.go:103 asm_amd64.s:1700]"
[INFO] [11-05|10:38:49.536] [2/9 Headers] Processed                  highest=63910939 age=1s headers=1 in=0.000 blk/sec=2024
[DBUG] [11-05|10:38:49.536] [2/9 Headers] DONE                       in=518.38µs
[INFO] [11-05|10:38:49.537] [7/9 Execution] Unwind Execution         from=63910938 to=63910937
[INFO] [11-05|10:38:49.538] aggregator unwind                        step=3009 txUnwindTo=4703108389 stepsRangeInDB="accounts:1.0, storage:1.0, code:1.0, commitment:0.0, receipt:1.0, logad
drs: 1.0, logtopics: 1.0, tracesfrom: 1.0, tracesto: 1.0"
[EROR] [11-05|10:38:49.836] Staged Sync                              err="[3/9 BorHeimdall] unexpected missing first processed block info entry when unwinding"
[INFO] [11-05|10:38:50.383] [7/9 Execution] Unwind Execution         from=63910938 to=63910937

[awskii]

then on restart

[INFO] [11-05|13:49:48.203] [snapshots:history] Stat                 blocks=63.87M txs=4.70B txNum2blockNum="2048=49361K,2560=56030K,2816=59892K,2944=62526K,3008=63872K" first_history_idx_in_db=0 last_comitment_block=63872373 last_comitment_tx_num=4700000000 alloc=16.2GB sys=16.3GB[DBUG] [11-05|13:49:48.203] [1/9 OtterSync] DONE                     in=243.540094ms[INFO] [11-05|13:49:48.893] [2/9 Headers] Waiting for headers...     from=63910938 hash=0xdc8ef1901aa950e54328cf0c3db8110fd572d42c1cbb13a2a0509b83c5174183[DBUG] [11-05|13:49:48.893] [2/9 Headers] Requested header           from=63916302 length=192[DBUG] [11-05|13:49:48.893] [2/9 Headers] Requested skeleton         from=63910937 length=192[DBUG] [11-05|13:49:48.918] [2/9 Headers] Requested header           from=63916110 length=192[DBUG] [11-05|13:49:48.929] [2/9 Headers] Requested header           from=63911129 length=192[DBUG] [11-05|13:49:48.951] [2/9 Headers] Requested header           from=63915918 length=192[WARN] [11-05|13:49:48.969] [dbg] HeaderInserter: set unwind point   v=63910937 stack="[header_algos.go:1030 header_algos.go:967 header_algos.go:840 header_algos.go:576 header_algos.go:652 stage_headers.go:251 stage_headers.go:123 default_stages.go:65 sync.go:526 sync.go:410 stageloop.go:152 stageloop.go:77 asm_amd64.s:1700]"[DBUG] [11-05|13:49:49.228] UnwindTo                                 block=63910937 stack="[sync.go:173 stage_headers.go:322 stage_headers.go:123 default_stages.go:65 sync.go:526 sync.go:410 stageloop.go:152 stageloop.go:77 asm_amd64.s:1700]"[INFO] [11-05|13:49:49.235] [2/9 Headers] Processed                  highest=63916304 age=2s headers=5366 in=0.342 blk/sec=15679[DBUG] [11-05|13:49:49.235] [2/9 Headers] DONE                       in=1.031855398s[EROR] [11-05|13:49:49.238] Staged Sync                              err="[3/9 BorHeimdall] unexpected missing first processed block info entry when unwinding"[EROR] [11-05|13:49:49.289] Staged Sync                              err="[3/9 BorHeimdall] unexpected missing first processed block info entry when unwinding"[EROR] [11-05|13:49:49.867] Staged Sync                              err="[3/9 BorHeimdall] unexpected missing first processed block info entry when unwinding"[DBUG] [11-05|13:49:50.037] [bor] no current block marker yet: syncing... incoming=checkpoint
[DBUG] [11-05|13:49:50.037] [bor.heimdall] Got new checkpoint        start=63912870 end=63914405 rootHash=0xa834dabc9bbbacf2704c105492d50788cfa851971262e3a0850d735fcec903e2
[DBUG] [11-05|13:49:50.037] [bor.heimdall] Failed to whitelist checkpoint err="missing blocks"
[EROR] [11-05|13:49:50.438] Staged Sync                              err="[3/9 BorHeimdall] unexpected missing first processed block info entry when unwinding"
[EROR] [11-05|13:49:51.008] Staged Sync                              err="[3/9 BorHeimdall] unexpected missing first processed block info entry when unwinding"
[EROR] [11-05|13:49:51.580] Staged Sync                              err="[3/9 BorHeimdall] unexpected missing first processed block info entry when unwinding"
[EROR] [11-05|13:49:52.154] Staged Sync                              err="[3/9 BorHeimdall] unexpected missing first processed block info entry when unwinding"
[EROR] [11-05|13:49:52.725] Staged Sync                              err="[3/9 BorHeimdall] unexpected missing first processed block info entry when unwinding"
[EROR] [11-05|13:49:53.303] Staged Sync                              err="[3/9 BorHeimdall] unexpected missing first processed block info entry when unwinding"
[EROR] [11-05|13:49:53.874] Staged Sync                              err="[3/9 BorHeimdall] unexpected missing first processed block info entry when unwinding"

[taratorio]

fixed by #12582