Investigate: ETH1_ERROR_NON_CONSECUTIVE_LOGS

[g11tech]

Running on kiln testnet pre-merge, lodestar sometimes ends up with ETH1_ERROR_NON_CONSECUTIVE_LOGS which resolves itself on a restart of lodestar (without restarting ethereumjs). This got resolved each time via a restart.

Investigate/discuss and brainstorm and fix if any issue. The current hypothesis is PoW chain reorged which caused the deposit history to alter as the follow distance is just 16. restarting lodestar resets its tracker and everything gets back on track.

Error: ETH1_ERROR_NON_CONSECUTIVE_LOGS
    at Eth1DepositsCache.add (/usr/app/lodestar/packages/lodestar/src/eth1/eth1DepositsCache.ts:93:15)
    at Eth1DepositDataTracker.updateDepositCache (/usr/app/lodestar/packages/lodestar/src/eth1/eth1DepositDataTracker.ts:178:5)
    at Eth1DepositDataTracker.update (/usr/app/lodestar/packages/lodestar/src/eth1/eth1DepositDataTracker.ts:159:33)
    at Eth1DepositDataTracker.runAutoUpdate (/usr/app/lodestar/packages/lodestar/src/eth1/eth1DepositDataTracker.ts:133:29)
^CMar-12 06:31:10.104[]                 info: Stopping gracefully, use Ctrl+C again to force process exit
Mar-12 06:31:10.491[ETH1]            error: Error updating eth1 chain cache  code=ETH1_ERROR_NON_CONSECUTIVE_LOGS, newIndex=1333, lastLogIndex=1329
Error: ETH1_ERROR_NON_CONSECUTIVE_LOGS
    at Eth1DepositsCache.add (/usr/app/lodestar/packages/lodestar/src/eth1/eth1DepositsCache.ts:93:15)
    at Eth1DepositDataTracker.updateDepositCache (/usr/app/lodestar/packages/lodestar/src/eth1/eth1DepositDataTracker.ts:178:5)
    at Eth1DepositDataTracker.update (/usr/app/lodestar/packages/lodestar/src/eth1/eth1DepositDataTracker.ts:159:33)
    at Eth1DepositDataTracker.runAutoUpdate (/usr/app/lodestar/packages/lodestar/src/eth1/eth1DepositDataTracker.ts:133:29)
/usr/app/lodestar # /usr/app/lodestar/kintsugi/devnets/./runLodestarK8s.sh /usr/app/lodestar/kiln/devnets/kiln.vars /data/kiln-data
./lodestar beacon --rootDir /data/kiln-data/lodestar --paramsFile /data/kiln-data/kiln/config.yaml --genesisStateFile /data/kiln-data/kiln/genesis.ssz --network.discv5.enabled true --eth1.enabled true --eth1.providerUrls http://127.0.0.1:8545 --execution.urls http://127.0.0.1:8551 --api.rest.enabled --api.rest.host 0.0.0.0 --eth1.depositContractDeployBlock 0x0000000000000000000000000000000000000000000000000000000000000000 --network.discv5.bootEnrs enr:-Iq4QMCTfIMXnow27baRUb35Q8iiFHSIDBJh6hQM5Axohhf4b6Kr_cOCu0htQ5WvVqKvFgY28893DHAg8gnBAXsAVqmGAX53x8JggmlkgnY0gmlwhLKAlv6Jc2VjcDI1NmsxoQK6S-Cii_KmfFdUJL2TANL3ksaKUnNXvTCv1tLwXs0QgIN1ZHCCIyk --network.connectToDiscv5Bootnodes --jwt-secret /data/kiln-data/jwtsecret
Mar-12 06:31:15.930[]                 info: Lodestar version=v0.26.0/master/+576/e30eca0b (git), network=mainnet
Mar-12 06:31:15.943[]                 info: Connected to LevelDB database name=/data/kiln-data/lodestar/peerstore
Mar-12 06:31:15.957[DB]               info: Connected to LevelDB database name=/data/kiln-data/lodestar/chain-db
Mar-12 06:31:19.170[]                 info: Initializing beacon state from anchor state slot=4224, epoch=132, stateRoot=0x29844cfef7e3b7b206a44f342966c49ad3386d43398b72295dafe707cb8b7e4f
Mar-12 06:31:19.476[ETH1]             info: Starting search for terminal POW block TERMINAL_TOTAL_DIFFICULTY=20000000000000
Mar-12 06:31:23.605[API]              info: Started REST api server address=http://0.0.0.0:9596, namespaces=beacon,config,events,node,validator
Mar-12 06:31:23.880[NETWORK]          info: PeerId 16Uiu2HAmJVZ1zB7kHtRJ7oe7pFVVDLxx2A4WKmvrRKbwCLMaCw7c, Multiaddrs /ip4/127.0.0.1/tcp/9000,/ip4/10.244.0.163/tcp/9000
Mar-12 06:31:23.880[]                 warn: Low peer count peers=0
Mar-12 06:31:23.881[]                 info: Searching peers - peers: 0 - slot: 4931 (skipped 707) - head: 4224 0xc1f9…9e43 - finalized: 0xfb59…aa64:130
Mar-12 06:31:30.001[]                 info: Searching peers - peers: 0 - slot: 4932 (skipped 708) - head: 4224 0xc1f9…9e43 - finalized: 0xfb59…aa64:130
Mar-12 06:31:42.003[]                 info: Searching peers - peers: 0 - slot: 4933 (skipped 709) - head: 4224 0xc1f9…9e43 - finalized: 0xfb59…aa64:130
Mar-12 06:31:54.000[]                 info: Searching peers - peers: 0 - slot: 4934 (skipped 710) - head: 4224 0xc1f9…9e43 - finalized: 0xfb59…aa64:130
Mar-12 06:32:06.001[]                 info: Searching peers - peers: 0 - slot: 4935 (skipped 711) - head: 4224 0xc1f9…9e43 - finalized: 0xfb59…aa64:130
Mar-12 06:32:18.001[]                 info: Searching peers - peers: 0 - slot: 4936 (skipped 712) - head: 4224 0xc1f9…9e43 - finalized: 0xfb59…aa64:130
Mar-12 06:32:30.024[]                 info: Syncing - ? left - 0.00 slots/s - slot: 4937 (skipped 713) - head: 4224 0xc1f9…9e43 - finalized: 0xfb59…aa64:130 - peers: 1
Mar-12 06:32:42.014[]                 info: Syncing - 4.9 minutes left - 1.67 slots/s - slot: 4938 (skipped 488) - head: 4450 0xb12b…2017 - finalized: 0x7be1…c72f:137 - peers: 1
Mar-12 06:32:54.010[]                 info: Syncing - 1.4 minutes left - 3.48 slots/s - slot: 4939 (skipped 288) - head: 4651 0x9bf7…5328 - finalized: 0x730b…eda4:143 - peers: 1
Mar-12 06:33:06.589[]                 info: Syncing - 29 seconds left - 4.87 slots/s - slot: 4940 (skipped 142) - head: 4798 0x97a6…12e3 - finalized: 0xffed…118c:148 - peers: 1
Mar-12 06:33:18.000[]                 info: Synced - slot: 4941 (skipped 23) - head: 4918 0x18bc…6ace - finalized: 0xe687…81e2:151 - peers: 1
Mar-12 06:33:19.491[NETWORK]          info: Subscribed gossip core topics
Mar-12 06:33:19.494[SYNC]             info: Subscribed gossip core topics
Mar-12 06:33:30.001[]                 info: Synced - slot: 4942 (skipped 1) - head: 4941 0xb86c…040a - finalized: 0x5b01…cd9d:152 - peers: 2
Mar-12 06:33:42.001[]                 info: Synced - slot: 4943 (skipped 2) - head: 4941 0xb86c…040a - finalized: 0x5b01…cd9d:152 - peers: 2

[dapplion]

Related #3845 the issue was triggered when switching EL nodes

[g11tech]

Closing as no more observed, #3845 might further address this