search

ethereum-optimism / optimism

Optimism is Ethereum, scaled.
https://optimism.io
MIT License
5.55k stars 3.2k forks source link

Sequencer stops producing blocks on L1 error #12041

Open bearpebble opened 4 days ago

bearpebble commented 4 days ago

Bug Description When the sequencer starts building a block and encounters a temporary error while fetching receipts, it does not get scheduled again, requiring a stop/start through the admin API or a restart of op-node.

The problem stems from the fact that the sequencer does not update the nextAction if it encounters a temporary error from the PreparePayloadAttributes() call here. While it emits a rollup.EngineTemporaryErrorEvent, it will not schedule a new time in its handler since the first if statement is true and it returns immediately here.

I'm not entirely sure if removing the if d.latest == (BuildingState{}) check in onEngineTemporaryError() is a good idea or if this has unintended side effects.

Steps to Reproduce

  1. Add the following failure simulation to the code here 
    if rand.Int() % 15 == 0 {
return nil, NewTemporaryError(fmt.Errorf("failed to fetch L1 block info and receipts: Simulating failure"))
}
  2. Run make devnet-up
  3. The sequencer will stop building new blocks at some point

See grepped output from docker logs ops-bedrock-op-node-1 | rg "sequencer action|simulating" -i

``` t=2024-09-21T06:48:50+0000 lvl=info msg="Scheduled sequencer action" delta=-131.129µs t=2024-09-21T06:48:50+0000 lvl=info msg="Scheduled sequencer action" delta=1.99987939s t=2024-09-21T06:48:52+0000 lvl=info msg="Scheduled sequencer action" delta=-9.118µs t=2024-09-21T06:48:52+0000 lvl=info msg="Scheduled sequencer action" delta=-44.905µs t=2024-09-21T06:48:52+0000 lvl=info msg="Scheduled sequencer action" delta=-3.937µs t=2024-09-21T06:48:52+0000 lvl=info msg="Scheduled sequencer action" delta=-37.07µs t=2024-09-21T06:48:52+0000 lvl=info msg="Scheduled sequencer action" delta=-4.429µs t=2024-09-21T06:48:52+0000 lvl=info msg="Scheduled sequencer action" delta=-60.565µs t=2024-09-21T06:48:52+0000 lvl=info msg="Scheduled sequencer action" delta=-4.819µs t=2024-09-21T06:48:52+0000 lvl=info msg="Scheduled sequencer action" delta=-41.839µs t=2024-09-21T06:48:52+0000 lvl=info msg="Scheduled sequencer action" delta=-3.457µs t=2024-09-21T06:48:52+0000 lvl=info msg="Scheduled sequencer action" delta=-33.745µs t=2024-09-21T06:48:52+0000 lvl=info msg="Scheduled sequencer action" delta=-3.737µs t=2024-09-21T06:48:52+0000 lvl=info msg="Scheduled sequencer action" delta=-58.13µs t=2024-09-21T06:48:52+0000 lvl=info msg="Scheduled sequencer action" delta=336.503204ms t=2024-09-21T06:48:53+0000 lvl=info msg="Scheduled sequencer action" delta=-31.991µs t=2024-09-21T06:48:53+0000 lvl=info msg="Scheduled sequencer action" delta=1.932702071s t=2024-09-21T06:48:55+0000 lvl=info msg="Scheduled sequencer action" delta=-49.414µs t=2024-09-21T06:48:55+0000 lvl=info msg="Scheduled sequencer action" delta=1.933645244s t=2024-09-21T06:48:57+0000 lvl=info msg="Scheduled sequencer action" delta=-24.357µs t=2024-09-21T06:48:57+0000 lvl=info msg="Scheduled sequencer action" delta=1.936828968s t=2024-09-21T06:48:59+0000 lvl=info msg="Scheduled sequencer action" delta=-31.951µs t=2024-09-21T06:48:59+0000 lvl=info msg="Scheduled sequencer action" delta=1.93056257s t=2024-09-21T06:49:01+0000 lvl=info msg="Scheduled sequencer action" delta=-51.839µs t=2024-09-21T06:49:01+0000 lvl=info msg="Scheduled sequencer action" delta=1.935661018s t=2024-09-21T06:49:03+0000 lvl=info msg="Scheduled sequencer action" delta=-36.45µs t=2024-09-21T06:49:03+0000 lvl=info msg="Scheduled sequencer action" delta=1.937822347s t=2024-09-21T06:49:05+0000 lvl=info msg="Scheduled sequencer action" delta=-35.257µs t=2024-09-21T06:49:05+0000 lvl=info msg="Scheduled sequencer action" delta=1.93067585s t=2024-09-21T06:49:07+0000 lvl=info msg="Scheduled sequencer action" delta=-36.579µs t=2024-09-21T06:49:07+0000 lvl=info msg="Scheduled sequencer action" delta=1.936753368s t=2024-09-21T06:49:09+0000 lvl=info msg="Scheduled sequencer action" delta=-36.079µs t=2024-09-21T06:49:09+0000 lvl=info msg="Scheduled sequencer action" delta=1.93781555s t=2024-09-21T06:49:11+0000 lvl=info msg="Scheduled sequencer action" delta=-42.601µs t=2024-09-21T06:49:11+0000 lvl=info msg="Scheduled sequencer action" delta=1.930113622s t=2024-09-21T06:49:13+0000 lvl=info msg="Scheduled sequencer action" delta=-52.249µs t=2024-09-21T06:49:13+0000 lvl=info msg="Scheduled sequencer action" delta=1.935989201s t=2024-09-21T06:49:15+0000 lvl=info msg="Scheduled sequencer action" delta=-46.819µs t=2024-09-21T06:49:15+0000 lvl=info msg="Scheduled sequencer action" delta=1.934585379s t=2024-09-21T06:49:16+0000 lvl=info msg="Scheduled sequencer action" delta=898.317µs t=2024-09-21T06:49:17+0000 lvl=info msg="Scheduled sequencer action" delta=1.938675581s t=2024-09-21T06:49:18+0000 lvl=info msg="Scheduled sequencer action" delta=6.420491ms t=2024-09-21T06:49:19+0000 lvl=info msg="Scheduled sequencer action" delta=1.935855176s t=2024-09-21T06:49:21+0000 lvl=info msg="Scheduled sequencer action" delta=-125.668µs t=2024-09-21T06:49:21+0000 lvl=info msg="Scheduled sequencer action" delta=1.939025182s t=2024-09-21T06:49:23+0000 lvl=info msg="Scheduled sequencer action" delta=-39.385µs t=2024-09-21T06:49:23+0000 lvl=info msg="Scheduled sequencer action" delta=1.915524009s t=2024-09-21T06:49:25+0000 lvl=info msg="Scheduled sequencer action" delta=-47.359µs t=2024-09-21T06:49:25+0000 lvl=info msg="Scheduled sequencer action" delta=1.937121449s t=2024-09-21T06:49:27+0000 lvl=info msg="Scheduled sequencer action" delta=-30.007µs t=2024-09-21T06:49:27+0000 lvl=info msg="Scheduled sequencer action" delta=1.939010621s t=2024-09-21T06:49:29+0000 lvl=info msg="Scheduled sequencer action" delta=-40.356µs t=2024-09-21T06:49:29+0000 lvl=info msg="Scheduled sequencer action" delta=1.930717014s t=2024-09-21T06:49:31+0000 lvl=info msg="Scheduled sequencer action" delta=-43.002µs t=2024-09-21T06:49:31+0000 lvl=info msg="Scheduled sequencer action" delta=1.934422395s t=2024-09-21T06:49:33+0000 lvl=info msg="Scheduled sequencer action" delta=-29.065µs t=2024-09-21T06:49:33+0000 lvl=info msg="Scheduled sequencer action" delta=1.93796296s t=2024-09-21T06:49:35+0000 lvl=info msg="Scheduled sequencer action" delta=-38.653µs t=2024-09-21T06:49:35+0000 lvl=info msg="Scheduled sequencer action" delta=1.930540346s t=2024-09-21T06:49:37+0000 lvl=info msg="Scheduled sequencer action" delta=-58.471µs t=2024-09-21T06:49:37+0000 lvl=info msg="Scheduled sequencer action" delta=1.934734164s t=2024-09-21T06:49:39+0000 lvl=info msg="Scheduled sequencer action" delta=-29.285µs t=2024-09-21T06:49:39+0000 lvl=info msg="Scheduled sequencer action" delta=1.9373236s t=2024-09-21T06:49:41+0000 lvl=info msg="Scheduled sequencer action" delta=-44.344µs t=2024-09-21T06:49:41+0000 lvl=info msg="Scheduled sequencer action" delta=1.930593914s t=2024-09-21T06:49:43+0000 lvl=info msg="Scheduled sequencer action" delta=-43.302µs t=2024-09-21T06:49:43+0000 lvl=info msg="Scheduled sequencer action" delta=1.934000038s t=2024-09-21T06:49:45+0000 lvl=info msg="Scheduled sequencer action" delta=-40.136µs t=2024-09-21T06:49:45+0000 lvl=info msg="Scheduled sequencer action" delta=1.936952513s t=2024-09-21T06:49:45+0000 lvl=warn msg="Engine temporary error" err="derivation failed: temp: failed to fetch L1 block info and receipts: Simulating failure" t=2024-09-21T06:49:45+0000 lvl=error msg="Engine failed temporarily, backing off sequencer" err="derivation failed: temp: failed to fetch L1 block info and receipts: Simulating failure" t=2024-09-21T06:49:45+0000 lvl=info msg="Scheduled sequencer action" delta=999.981635ms t=2024-09-21T06:49:46+0000 lvl=info msg="Scheduled sequencer action" delta=826.297186ms t=2024-09-21T06:49:47+0000 lvl=info msg="Scheduled sequencer action" delta=1.928519083s t=2024-09-21T06:49:49+0000 lvl=info msg="Scheduled sequencer action" delta=-34.936µs t=2024-09-21T06:49:49+0000 lvl=info msg="Scheduled sequencer action" delta=1.936302756s t=2024-09-21T06:49:51+0000 lvl=info msg="Scheduled sequencer action" delta=-39.825µs t=2024-09-21T06:49:51+0000 lvl=info msg="Scheduled sequencer action" delta=1.935653828s t=2024-09-21T06:49:53+0000 lvl=info msg="Scheduled sequencer action" delta=-48.231µs t=2024-09-21T06:49:53+0000 lvl=info msg="Scheduled sequencer action" delta=1.875738597s t=2024-09-21T06:49:55+0000 lvl=info msg="Scheduled sequencer action" delta=-37.932µs t=2024-09-21T06:49:55+0000 lvl=info msg="Scheduled sequencer action" delta=1.935375503s t=2024-09-21T06:49:57+0000 lvl=info msg="Scheduled sequencer action" delta=-41.498µs t=2024-09-21T06:49:57+0000 lvl=info msg="Scheduled sequencer action" delta=1.937977728s t=2024-09-21T06:49:59+0000 lvl=info msg="Scheduled sequencer action" delta=-38.774µs t=2024-09-21T06:49:59+0000 lvl=warn msg="Engine temporary error" err="temp: failed to fetch L1 block info and receipts: Simulating failure" ```

Expected behavior The sequencer should retry building the block after the temporary error.

Environment Information:

bearpebble commented 1 day ago

Tagging @protolambda for visibility. From the commit history it looks like you are most familiar with the code after the event refactoring