[Node Operator Question] Node suddenly began reverting blocks, and now seems to be irrecoverable

[angusscott]

Are you running the most up to date node software?

• Yes

Did you check the documentation?

• Yes

Did you check for duplicate questions?

• Yes

Issue Description

Whilst running today, our node suddenly reverted a number of blocks, dropping the block height from 120426290 back to 120407444. op-geth was killed by systemd, and shortly after the following emerged in op-node

When investigating, op-node appears to go through the steps of

1. Walking back L1Block by hash

t=2024-05-23T09:54:57+0000 lvl=info msg="Walking back L1Block by number" curr=0x293cc2e66beca482ea111d43d5aa4480ae0e39841cc54439b57466887f96af12:19928123 next=0x293cc2e66beca482ea111d43d5aa4480ae0e39841cc54439b57466887f96af12:19928123 l2block=0x8450a31377afbbe10aa606660a20667d9aa1dc13086a6427c8855f25d5eac54d:120407444
t=2024-05-23T09:54:57+0000 lvl=info msg="Walking back L1Block by hash" curr=0x293cc2e66beca482ea111d43d5aa4480ae0e39841cc54439b57466887f96af12:19928123 next=0xd8baf6ac29f8a41f75ad4a8db015f1c2e98a152e90ada454d594ae7757960cb8:19928122 l2block=0x1cf4542cf34bfda4079dcc97e200ac3f55465e2c794981b955f133afdb1e75ff:120407441
t=2024-05-23T09:54:57+0000 lvl=info msg="Walking back L1Block by hash" curr=0xd8baf6ac29f8a41f75ad4a8db015f1c2e98a152e90ada454d594ae7757960cb8:19928122 next=0x3dc54c803d1fb17d78e3bdb51ce5e57f39e38c09ccf86f00a663e6d6c5c2b413:19928121 l2block=0x8b526536ea9e08cdb339f7fbb95c02178b2306b1c7e8c0887c6c4a94a4da2200:120407435
t=2024-05-23T09:54:57+0000 lvl=info msg="Walking back L1Block by hash" curr=0x3dc54c803d1fb17d78e3bdb51ce5e57f39e38c09ccf86f00a663e6d6c5c2b413:19928121 next=0x794eee14e8fa698bfdc5fe3f42e0754738adc85362388d0100d06443a8906c34:19928120 l2block=0xf7755523a8c0d1708f1c1cb149a687f0d2f9d47555182056d21a7675f3caaf6c:120407429
t=2024-05-23T09:54:57+0000 lvl=info msg="Walking back L1Block by hash" curr=0x794eee14e8fa698bfdc5fe3f42e0754738adc85362388d0100d06443a8906c34:19928120 next=0x9ac8fb16d629a9ad0db086ab0808c269053e28f119b0a97891aca58ac594de57:19928119 l2block=0xb2f7d9340c915ab890315c4a5c021f15d90c2b9fe48f0486f409009c773aef22:120407423

2. begins to Advance bq origin

t=2024-05-23T09:58:25+0000 lvl=info msg="Optimistically queueing unsafe L2 execution payload" id=0x707028f20c240cf0f9b0408502175ebc5f8315667870435aa17ee470c41d87a8:120429717
t=2024-05-23T09:58:25+0000 lvl=info msg="Received signed execution payload from p2p" id=0x1f65cf0e8acea6b74abc525906ec099ea681a276d6ffdb189b7e96f801269a10:120429731 peer=16Uiu2HAmCZcuBFUPqZs7Cwck8M2fT9W78LfWfLUgYPVQHsCDf19k
t=2024-05-23T09:58:25+0000 lvl=info msg="Advancing bq origin" origin=0xfa21e411bea79a0167bf1053c30c61176219c3c48c00e66cbcb70762038e8f80:19924222 originBehind=true
t=2024-05-23T09:58:25+0000 lvl=info msg="Advancing bq origin" origin=0xfa478790c0cdd46128e00dc35335a51ad29665067c3b45d8eb8343c0cf1cfb6c:19924223 originBehind=true
t=2024-05-23T09:58:25+0000 lvl=info msg="Optimistically queueing unsafe L2 execution payload" id=0x5ada29e5a8d9087a8c994c62fd6194e5481ab425475c124168fe41691b82f1bc:120429721
t=2024-05-23T09:58:25+0000 lvl=info msg="Optimistically queueing unsafe L2 execution payload" id=0xfaa08749ee7a6f4a165b05e6c7b41d1e396617c0341a1feafb840ebe05e5cef9:120429722
t=2024-05-23T09:58:25+0000 lvl=info msg="Advancing bq origin" origin=0x8fce86a5713fdf79e6c87617b991519e68be5e360c1314567d8fb4b4ada70281:19924224 originBehind=true
t=2024-05-23T09:58:25+0000 lvl=info msg="Received signed execution payload from p2p" id=0xbaff4e2065cc3e236dae60c0ac14cf4816c022cbd7794f67b49bfcf35ac3ef12:120429732 peer=16Uiu2HAmL2DpSZPAp7XvygbGU89RtUMPnbLamSs6iG6V2AV6cHTb
t=2024-05-23T09:58:25+0000 lvl=info msg="Received signed execution payload from p2p" id=0x5165424355c5e8867e8a145840e40efba6bb7580bc3a6f125331294be4e799a5:120429733 peer=16Uiu2HAmL2DpSZPAp7XvygbGU89RtUMPnbLamSs6iG6V2AV6cHTb
t=2024-05-23T09:58:25+0000 lvl=info msg="Advancing bq origin" origin=0x2e59504094e10b62e2a9afe9be31149d4a85c26ac42c93a5a872ec83d338e3c0:19924225 originBehind=true
t=2024-05-23T09:58:25+0000 lvl=info msg="attempting connection" peer=16Uiu2HAm2EeUMzPWHWsKk7ZJNz4hbThhGzZhL3Bh3pMi5LR3VqFq
t=2024-05-23T09:58:25+0000 lvl=info msg="Optimistically queueing unsafe L2 execution payload" id=0x2ce7d7e2dc21adb5268e01f9ad1f9501fc05f987c2d1fba21f4ce781180755e5:120429723
t=2024-05-23T09:58:25+0000 lvl=info msg="Advancing bq origin" origin=0xbd5ba5ae37325fa207ee5c94f33f7e07f0f1e3734a26c07a6cdc10ef9b5dadc2:19924226 originBehind=true

3. Begins to reconcile with L1

t=2024-05-23T09:58:41+0000 lvl=info msg="Found next batch" batch_type=SpanBatch batch_timestamp=1716370279 parent_check=0xe9bf56356a76e0a5bad210466d1aeb090893cb0a origin_check=0x385ec8f8c64fa836620b7214825b66089a3a5457 start_epoch_number=19924538 end_epoch_number=19924556 block_count=113
t=2024-05-23T09:58:41+0000 lvl=info msg="generated attributes in payload queue" txs=8 timestamp=1716370279
t=2024-05-23T09:58:41+0000 lvl=info msg="Sync progress" reason="reconciled with L1" l2_finalized=0x2f2e963fb91c83ac0da2a44a900f08430ff65471d6759610912b8a94adc4c245:120425995 l2_safe=0xe9bf56356a76e0a5bad210466d1aeb090893cb0aa51fa382b886ddb09d7cee07:120385750 l2_pending_safe=0x514370114f653587aa43f214472959921f6e1044723745b3677684022bef321c:120385751 l2_unsafe=0x8450a31377afbbe10aa606660a20667d9aa1dc13086a6427c8855f25d5eac54d:120407444 l2_backup_unsafe=0x0000000000000000000000000000000000000000000000000000000000000000:0 l2_time=1716413665 l1_derived=0xaaa45e129a86251156441b4ae85189c5201fdb1e8a264e2dcd0ef7576c031a57:19924566
t=2024-05-23T09:58:41+0000 lvl=info msg="generated attributes in payload queue" txs=12 timestamp=1716370281
t=2024-05-23T09:58:41+0000 lvl=info msg="Sync progress" reason="reconciled with L1" l2_finalized=0x2f2e963fb91c83ac0da2a44a900f08430ff65471d6759610912b8a94adc4c245:120425995 l2_safe=0xe9bf56356a76e0a5bad210466d1aeb090893cb0aa51fa382b886ddb09d7cee07:120385750 l2_pending_safe=0x86b7f6ac3ebcdf73ecbe6cc4c602d291a42f21df45105802bd3212ae795dda6d:120385752 l2_unsafe=0x8450a31377afbbe10aa606660a20667d9aa1dc13086a6427c8855f25d5eac54d:120407444 l2_backup_unsafe=0x0000000000000000000000000000000000000000000000000000000000000000:0 l2_time=1716413665 l1_derived=0xaaa45e129a86251156441b4ae85189c5201fdb1e8a264e2dcd0ef7576c031a57:19924566
t=2024-05-23T09:58:41+0000 lvl=info msg="generated attributes in payload queue" txs=23 timestamp=1716370283

4. Hits some error, and then begins dialling peers

t=2024-05-23T10:05:55+0000 lvl=warn msg="L2 reorg: existing unsafe block does not match derived attributes from L1" err="random field does not match. expected: 0x0e7a3caa04322fe6d9bd5b8064bdebedd7449c43a9a8239444d97fb7c0010ee5. got: 0x6a84caab21324923a66291f94b9b288bbafba7cc0221bdfcc5b6c195d36070ca" unsafe=0xd76f9355db03af51d245d1e13d44e28c29f2e058e81abc80b12b30f2dc5122
dc:120407445 pending_safe=0x220d661e2445e899fde76200f896c92038754c3cd6f511a90b7a7536dac5d077:120407406 safe=0x220d661e2445e899fde76200f896c92038754c3cd6f511a90b7a7536dac5d077:120407406
t=2024-05-23T10:05:55+0000 lvl=warn msg="Failed to share forkchoice-updated signal" state="&{HeadBlockHash:0x220d661e2445e899fde76200f896c92038754c3cd6f511a90b7a7536dac5d077 SafeBlockHash:0x220d661e2445e899fde76200f896c92038754c3cd6f511a90b7a7536dac5d077 FinalizedBlockHash:0x2f2e963fb91c83ac0da2a44a900f08430ff65471d6759610912b8a94adc4c245}" err="Invalid payload attribut
es"
t=2024-05-23T10:05:55+0000 lvl=warn msg="could not process payload derived from L1 data, dropping batch" err="payload attributes are not valid, cannot build block: Invalid payload attributes"
t=2024-05-23T10:05:55+0000 lvl=error msg="deposit only block was invalid" parent=0x220d661e2445e899fde76200f896c92038754c3cd6f511a90b7a7536dac5d077:120407406 err="payload attributes are not valid, cannot build block: Invalid payload attributes"
t=2024-05-23T10:05:55+0000 lvl=error msg="Derivation process critical error" err="engine stage failed: crit: failed to process block with only deposit transactions: payload attributes are not valid, cannot build block: Invalid payload attributes"
t=2024-05-23T10:05:55+0000 lvl=info msg="State loop returned"
t=2024-05-23T10:05:55+0000 lvl=info msg="Received signed execution payload from p2p" id=0xaabb5ffd9abc778e70c99182033fbc47b0f8283d30e70834747473de566890db:120429989 peer=16Uiu2HAmCZcuBFUPqZs7Cwck8M2fT9W78LfWfLUgYPVQHsCDf19k
t=2024-05-23T10:05:55+0000 lvl=info msg="attempting connection" peer=16Uiu2HAkwqPxTqTVWeL3KFKHtbhYfAmuyT5LELZudrAhf1i3qNg2
t=2024-05-23T10:05:56+0000 lvl=info msg="attempting connection" peer=16Uiu2HAmPTprhnTCLmSgAu3qwX5DH758Car36UY3bWJ1Du9A2NWn

op-node is now jsut going through the process of dialing peers and disconnecting, log sample

t=2024-05-23T10:27:16+0000 lvl=info msg="attempting connection" peer=16Uiu2HAmNZd4L7FA2e2A4hxyjjA3Ky5LsZDmQUvWxhFJs9WGz9QF
t=2024-05-23T10:27:16+0000 lvl=info msg="peer-ban expired, unbanning peer" peer_id=16Uiu2HAmNZd4L7FA2e2A4hxyjjA3Ky5LsZDmQUvWxhFJs9WGz9QF expiry=2024-05-23T10:00:35+0000
t=2024-05-23T10:27:17+0000 lvl=info msg="connected to peer" peer=16Uiu2HAmNZd4L7FA2e2A4hxyjjA3Ky5LsZDmQUvWxhFJs9WGz9QF addr=/ip4/65.108.101.96/tcp/9222
t=2024-05-23T10:27:17+0000 lvl=info msg="Starting P2P sync client event loop" peer=16Uiu2HAmNZd4L7FA2e2A4hxyjjA3Ky5LsZDmQUvWxhFJs9WGz9QF
t=2024-05-23T10:28:36+0000 lvl=info msg="disconnected from peer" peer=16Uiu2HAmNZd4L7FA2e2A4hxyjjA3Ky5LsZDmQUvWxhFJs9WGz9QF addr=/ip4/65.108.101.96/tcp/9222

All error level logs here:

t=2024-05-23T09:34:29+0000 lvl=error msg="deposit only block was invalid" parent=0x220d661e2445e899fde76200f896c92038754c3cd6f511a90b7a7536dac5d077:120407406 err="payload attributes are not valid, cannot build block: Invalid payload attributes"
t=2024-05-23T09:34:29+0000 lvl=error msg="Derivation process critical error" err="engine stage failed: crit: failed to process block with only deposit transactions: payload attributes are not valid, cannot build block: Invalid payload attributes"
t=2024-05-23T09:56:19+0000 lvl=warn msg="Derivation process temporary error" attempts=1 err="stage 0 failed resetting: temp: failed to find the L2 Heads to start from: failed to fetch L2 block by hash 0x6cc59df3201d8cf8b169ab6fda326319e47ed50793d9309711383302cc4a6517: failed to determine block-hash of hash 0x6cc59df3201d8cf8b169ab6fda326319e47ed50793d9309711383302cc4a6517, could not get payload: Post \"http://0.0.0.0:8551\": context canceled"
t=2024-05-23T10:05:55+0000 lvl=error msg="deposit only block was invalid" parent=0x220d661e2445e899fde76200f896c92038754c3cd6f511a90b7a7536dac5d077:120407406 err="payload attributes are not valid, cannot build block: Invalid payload attributes"
t=2024-05-23T10:05:55+0000 lvl=error msg="Derivation process critical error" err="engine stage failed: crit: failed to process block with only deposit transactions: payload attributes are not valid, cannot build block: Invalid payload attributes"

Protocol Description

Prior to issue we were running the following:
op-node: v1.7.1
op-geth: 1.101308.2

We are now running
op-node: v1.7.5
op-geth: 1.101315.0

op-node flags:

--l1=http://<INTERNAL_IP>:8545 \
  --l2=http://0.0.0.0:8551 \
  --l1.beacon=http://<INTERNAL_IP>:3500\
  --network=mainnet \
  --rpc.addr=0.0.0.0 \
  --rpc.port=9545 \
  --l2.jwt-secret=/nodes/optimism/jwt.hex \
  --l1.trustrpc \
  --network=op-mainnet \
  --rollup.load-protocol-versions=true \
  --rollup.halt=none \
  --l1.rpckind=erigon"

op-geth flags:

"--http \
  --http.corsdomain="*" \
  --http.vhosts="*" \
  --http.addr=0.0.0.0 \
  --http.port=8645 \
  --http.api=web3,debug,eth,txpool,net,engine \
  --ws \
  --ws.addr=0.0.0.0 \
  --ws.port=8646 \
  --ws.origins="*" \
  --ws.api=debug,eth,txpool,net,engine,web3 \
  --syncmode=full \
  --gcmode="full" \
  --nodiscover \
  --maxpeers=0 \
  --authrpc.vhosts="*" \
  --authrpc.addr=0.0.0.0 \
  --authrpc.port=8551 \
  --authrpc.jwtsecret=/nodes/optimism/jwt.hex \
  --rollup.sequencerhttp=https://mainnet-sequencer.optimism.io/ \
  --rollup.disabletxpoolgossip=true \
  --rollup.halt=major \
  --op-network=op-mainnet"

Node Logs

Only logs from op-geth are basically the below

WARN [05-23|10:46:27.716] Served eth_call                          conn=127.0.0.1:58620 reqid=741941 duration="112.731µs" err="missing trie node 00ac979f85a084da93b0be521c253d8431af1354e3617fbd16474de30a13fe45 (path ) state 0x00ac979f85a084da93b0be521c253d8431af1354e3617fbd16474de30a13fe45 is not available, not found"
WARN [05-23|10:46:27.716] Served eth_call                          conn=127.0.0.1:58604 reqid=741940 duration="68.702µs" err="missing trie node 00ac979f85a084da93b0be521c253d8431af1354e3617fbd16474de30a13fe45 (path ) state 0x00ac979f85a084da93b0be521c253d8431af1354e3617fbd16474de30a13fe45 is not available, not found"
WARN [05-23|10:46:27.716] Served eth_call                          conn=127.0.0.1:58590 reqid=741939 duration="161.594µs" err="missing trie node 00ac979f85a084da93b0be521c253d8431af1354e3617fbd16474de30a13fe45 (path ) state 0x00ac979f85a084da93b0be521c253d8431af1354e3617fbd16474de30a13fe45 is not available, not found"
WARN [05-23|10:46:27.716] Served eth_call                          conn=127.0.0.1:58628 reqid=741942 duration="112.182µs" err="missing trie node 00ac979f85a084da93b0be521c253d8431af1354e3617fbd16474de30a13fe45 (path ) state 0x00ac979f85a084da93b0be521c253d8431af1354e3617fbd16474de30a13fe45 is not available, not found"
WARN [05-23|10:46:27.722] Served eth_getBalance                    conn=127.0.0.1:58664 reqid=741946 duration="170.184µs" err="missing trie node 00ac979f85a084da93b0be521c253d8431af1354e3617fbd16474de30a13fe45 (path ) state 0x00ac979f85a084da93b0be521c253d8431af1354e3617fbd16474de30a13fe45 is not available, not found"
WARN [05-23|10:46:30.762] Served eth_getBalance                    conn=127.0.0.1:40998 reqid=741947 duration="170.488µs" err="missing trie node 00ac979f85a084da93b0be521c253d8431af1354e3617fbd16474de30a13fe45 (path ) state 0x00ac979f85a084da93b0be521c253d8431af1354e3617fbd16474de30a13fe45 is not available, not found"

Additional Information

No response

Feedback

No response

[opfocus]

The database may be damaged. You can restart op-geth to get more logs, which may have relevant information.