[Application Development] The issues encountered during the shutdown and restart of the op-stack chain

[opfocus]

Issue Description

The op-stack chain(Goerli as L1 data layer) experienced an extended shutdown, and upon restarting, an issue surfaced:
it appears that every component is running, but op-geth shows an approximately 15-hour lag in the L2 blocks and is unable to catch up.

Below, I will provide specific logs and some anomalies that I've observed. (Note: All data in this thread is provided by a consulting developer)：

op-node log:

t=2023-11-08T10:28:10+0000 lvl=info msg="Sync progress" reason="processed safe block derived from L1" 
l2_finalized=0x7d89c87d896cf2f8bc5c706861a40416187722e62a55c8fd3beeb24489f2da7c:2995879 
l2_safe=0x836c794a70cd852256ffcf1e70f47c29e969bd7c0ad88e054df560f63eb7f2df:2996166 
l2_unsafe=0x836c794a70cd852256ffcf1e70f47c29e969bd7c0ad88e054df560f63eb7f2df:2996166 
l2_engineSyncTarget=0x836c794a70cd852256ffcf1e70f47c29e969bd7c0ad88e054df560f63eb7f2df:2996166 l2_time=1,699,384,254 
l1_derived=0x83840681d1a71a6922e791fbe76b8af3e795b70a52dfe8f1b6c6d9264259f96e:10007131
t=2023-11-08T10:28:10+0000 lvl=info msg="Generating next batch"
epoch=0x7ca3951a641924a9c7ed031bbd15b528148755abda918f256e48fb449005bfee:10003531 timestamp=1,699,384,259
t=2023-11-08T10:28:10+0000 lvl=info msg="generated attributes in payload queue"  txs=1 timestamp=1,699,384,259
t=2023-11-08T10:28:10+0000 lvl=info msg="inserted block"                         
hash=0x73569c2686a0432c5dc35559791a822739196b841579c2b4072ace4db2c0bf77 number=2,996,167 
state_root=0x5d2fd3cef51c79db912476325052a2026de28d65f869602a70e69e828749f517 timestamp=1,699,384,259 
parent=0x836c794a70cd852256ffcf1e70f47c29e969bd7c0ad88e054df560f63eb7f2df 
prev_randao=0x26ae2f0cc8a1e74cf9624208b936606975f1b8d8ea83dc404f923456981a6f1f 
fee_recipient=0x4200000000000000000000000000000000000011 txs=1 update_safe=true

Here, l1_derived=0x83840681d1a71a6922e791fbe76b8af3e795b70a52dfe8f1b6c6d9264259f96e:10007131 shows no lag.

op-geth log: (Shows 15h19m42s lag)

INFO [11-08|10:54:41.673] Imported new potential chain segment number=2,996,455 hash=4433a4..b12bf1 blocks=1 txs=1 mgas=0.047 elapsed="952.744µs" mgasps=49.189 age=15h19m42s dirty=0.00B
INFO [11-08|10:54:41.674] Chain head was updated number=2,996,455 hash=4433a4..b12bf1 root=d99e3e..2ff555 elapsed="112.747µs" age=15h19m42s this is my op geth logs

batcher log: (Continues to submit to the latest L1 block regardless of a 15-hour lag in L2 blocks)

t=2023-11-08T12:03:06+0000 lvl=info msg="Transaction confirmed" service=batcher hash=0x0242f3dc6cd068be08812df19406c12717e94b431aa31dbd8a87e79cfb5594ba
t=2023-11-08T12:03:06+0000 lvl=info msg="tx successfully published" tx_hash=0x0242f3dc6cd068be08812df19406c12717e94b431aa31dbd8a87e79cfb5594ba data_size=121
t=2023-11-08T12:03:06+0000 lvl=info msg="Transaction confirmed" tx_hash=0x0242f3dc6cd068be08812df19406c12717e94b431aa31dbd8a87e79cfb5594ba status=1 block_hash=0x5ff312b3082a73fa194a423a64f3430cdd52ecfe9d3ab74ba61e7f1ab55cda5a block_number=10,007,492
t=2023-11-08T12:03:06+0000 lvl=info msg="Channel is fully submitted" id=e9a958db5dede7892a5a389d90d9d081
t=2023-11-08T12:03:07+0000 lvl=info msg="Creating tx" service=batcher to=0xEB71FA3084f1c3E2A66075760b3E3926F7843f34 from=0xf663792Be0EdD00AFFB8BBe4Ac6d8185efD5671d
t=2023-11-08T12:03:07+0000 lvl=info msg="Publishing transaction" service=batcher hash=0x998a82bc483fca97e79868affd8f49f4e105bfabdd0f5d8e46daef923f014b3d nonce=82458 gasTipCap=2 gasFeeCap=32

Additional Information

No response

[L2nitant]

after restarting the chain,
batcher logs
logs before sync

t=2023-11-08T12:03:06+0000 lvl=info msg="Transaction confirmed" service=batcher hash=0x0242f3dc6cd068be08812df19406c12717e94b431aa31dbd8a87e79cfb5594ba
t=2023-11-08T12:03:06+0000 lvl=info msg="tx successfully published" tx_hash=0x0242f3dc6cd068be08812df19406c12717e94b431aa31dbd8a87e79cfb5594ba data_size=121
t=2023-11-08T12:03:06+0000 lvl=info msg="Transaction confirmed" tx_hash=0x0242f3dc6cd068be08812df19406c12717e94b431aa31dbd8a87e79cfb5594ba status=1 block_hash=0x5ff312b3082a73fa194a423a64f3430cdd52ecfe9d3ab74ba61e7f1ab55cda5a block_number=10,007,492
t=2023-11-08T12:03:06+0000 lvl=info msg="Channel is fully submitted" id=e9a958db5dede7892a5a389d90d9d081
t=2023-11-08T12:03:07+0000 lvl=info msg="Creating tx" service=batcher to=0xEB71FA3084f1c3E2A66075760b3E3926F7843f34 from=0xf663792Be0EdD00AFFB8BBe4Ac6d8185efD5671d
t=2023-11-08T12:03:07+0000 lvl=info msg="Publishing transaction" service=batcher hash=0x998a82bc483fca97e79868affd8f49f4e105bfabdd0f5d8e46daef923f014b3d nonce=82458 gasTipCap=2 gasFeeCap=32

after sync

t=2023-11-08T13:31:35+0000 lvl=warn msg="last submitted block lagged behind L2 safe head: batch submission will continue from the safe head now" last=0x1145bf533fef2280ffa52cc32c2b45f8a5b8bf409839e925a644b816a431e4f6:2998298 safe=0x611a90251cc9f8c1409c285d37ea753540e636d911e026af12c8fe8b7b59fa3a:2998300
t=2023-11-08T13:31:35+0000 lvl=warn msg="Error calculating L2 block range" err="L2 safe head ahead of L2 unsafe head"
t=2023-11-08T13:31:36+0000 lvl=warn msg="Error calculating L2 block range" err="L2 safe head ahead of L2 unsafe head"
i restarted the chain and i am getting this log

[opfocus]

If you are still observing it, please continue to upload the logs

[sbvegan]

I spoke to some client engineers and they noted that the following log is really strange:

t=2023-11-08T13:31:36+0000 lvl=warn msg="Error calculating L2 block range" err="L2 safe head ahead of L2 unsafe head"

Your L2 node could have gotten messed up with a hard shut down. Its likely you'll have to resync your node.

[L2nitant]

no it is not working. I have been waiting for 2 days after restarting the chain

[opfocus]

What I want to confirm is, are you talking about running it for two days with a delay of 15 hours? This is important because the synchronization process needs to be done before this position (I suspect a sequencer window is missed（12hours）)

[rohit9888]

yes, synchronisation process is completed. It is after the synchronisation. And what do you mean by sequencer window? Could you elaborate more about it?

[sbvegan]

@L2nitant yeah removedb is the command I was referring to. I had to use it this morning because my cat killed my node by shutting off my computer 😬

[rohit9888]

she was trying to help you in her own way :)

[opfocus]

yes, synchronisation process is completed. It is after the synchronisation. And what do you mean by sequencer window? Could you elaborate more about it?

https://github.com/ethereum-optimism/optimism/blob/develop/specs/glossary.md#sequencing-window
To be honest, I don't have a clear understanding of this issue. I speculate that it may have reached some kind of limit, and exploring the behavior at this boundary might be meaningful.

[rohit9888]

yes definitely. Let me know if you need anything from me to fix this issue.

[opfocus]

Perhaps it's just necessary to explain why the synchronization is complete. L2 block height shows a lag of 15 hours, 19 minutes, and 42 seconds.

[rohit9888]

my apologies. what i mean is it started sending block to op-geth. but it is not catching up to layer 1. As you mentioned, it is showing lag of 15 hrs

[opfocus]

At this point, the growth of L2 blocks has become extremely slow, with a persistent lag of around 15 hours. This is frustrating. So, it would be best to provide an explanation for this.

[rohit9888]

@sbvegan but resyncing node is a temporary solution. I mean resyncing can take a lot of time as the chain is live for more than a month. In case it again happen after a year. then wouldn't it a problem?

[sbvegan]

Yes it would be a problem, we have to approach it so there isn't a single point of failure. If you're going to run a chain in production, you'll want to have certain infrastructure in place to handle failures or outsource it to a Rollup as a Service (RaaS) provider.

[rohit9888]

Do you have any recommendation for the infrastructure to handle failures?

[sbvegan]

This is a little out of my domain, but something a long the lines of setting up replica backup nodes that are behind a proxy to load balance the requests. If your primary goes down, you can failover to a replica to protect from downtime while you bring that node back up. You would use something like Kubernetes

[L2nitant]

I have removed the geth and it is resyncing but it will take some time.
but my batcher keep showing the logs

t=2023-11-20T06:08:38+0000 lvl=warn msg="last submitted block lagged behind L2 safe head: batch submission will continue from the safe head now" last=0xdfc0a9bc7e6c9c2777274643aa7635bd8ee5c846f9bf57b096148e22e70e02ae:1443764 safe=0x5e836daae1ad0449292edeed1d45f5517a11cf98e8c7fb369aaa931b2ba19ccb:1443781
t=2023-11-20T06:08:38+0000 lvl=warn msg="Error calculating L2 block range" err="L2 safe head ahead of L2 unsafe head"
t=2023-11-20T06:08:40+0000 lvl=warn msg="last submitted block lagged behind L2 safe head: batch submission will continue from the safe head now" last=0x5e836daae1ad0449292edeed1d45f5517a11cf98e8c7fb369aaa931b2ba19ccb:1443781 safe=0x7bb88ad25545915e5b60f970f594afeaa3b054be77eec6ffbb3d85a319094739:1443828
t=2023-11-20T06:08:40+0000 lvl=warn msg="Error calculating L2 block range" err="L2 safe head ahead of L2 unsafe head"

Could you give me more information regarding this log

[sbvegan]

It seems to me that your batcher is lagging behind for some reason, some context on the block tags:

• safe means all of the data to derive a L2 block has been included on L1. safe blocks only reorg if L1 reorg happens.
• unsafe means all of the data to derive a L2 block has been included on L1. unsafe blocks can reorg if the L1 reorgs or there was an issue sequencer.
• finalized means all of the data to derive a L2 block has been finalized on L1. No finalized block can be reorged.