ethereum-optimism / optimism

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

op-program panics in MT-Cannon #11753

Closed Inphi closed 2 months ago

Inphi commented 2 months ago

While running the op-program within MT-Cannon (see https://github.com/ethereum-optimism/optimism/pull/11587), I observed a Go runtime panic in the guest program. This issue isn't reproducible and I've seen panics occurring in other areas in the Go runtime. Here are a couple stack traces of the panic:

Example 1
    logw.go:50:                 INFO [09-04|22:06:38.870]                                          module=client stream=stdout text="t=1970-05-13T13:45:17+0000 lvl=info msg=\"Current hardfork version detected\" forkName=canyon"
    logw.go:50:                 INFO [09-04|22:06:39.072]                                          module=client stream=stdout text="t=1970-05-13T13:45:17+0000 lvl=info msg=\"Rewinding derivation-pipeline L1 traversal to handle reset\""
    logw.go:50:                 INFO [09-04|22:06:40.930]                                          module=client stream=stderr text="wirep: p->m=35461408(0) p->status=1"
    logw.go:50:                 INFO [09-04|22:06:40.931]                                          module=client stream=stderr text="fatal error: wirep: invalid p state"
    logw.go:50:                 INFO [09-04|22:06:40.933]                                          module=client stream=stderr text="\nruntime stack:"
    logw.go:50:                 INFO [09-04|22:06:40.936]                                          module=client stream=stderr text="runtime.throw({0x100b907, 0x16})"
    logw.go:50:                 INFO [09-04|22:06:40.938]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/panic.go:1077 +0x54 fp=0x40445ed4 sp=0x40445ec0 pc=0x631ac"
    logw.go:50:                 INFO [09-04|22:06:40.942]                                          module=client stream=stderr text=runtime.wirep(0x40426000)
    logw.go:50:                 INFO [09-04|22:06:40.945]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/proc.go:5359 +0x150 fp=0x40445ef0 sp=0x40445ed4 pc=0x761cc"
    logw.go:50:                 INFO [09-04|22:06:40.947]                                          module=client stream=stderr text=runtime.acquirep(0x40426000)
    logw.go:50:                 INFO [09-04|22:06:40.949]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/proc.go:5328 +0x40 fp=0x40445f10 sp=0x40445ef0 pc=0x75ffc"
    logw.go:50:                 INFO [09-04|22:06:40.980]                                          module=client stream=stderr text=runtime.findRunnable()
    logw.go:50:                 INFO [09-04|22:06:40.983]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/proc.go:3208 +0xe80 fp=0x40445fa8 sp=0x40445f10 pc=0x6f060"
    logw.go:50:                 INFO [09-04|22:06:40.985]                                          module=client stream=stderr text=runtime.schedule()
    logw.go:50:                 INFO [09-04|22:06:40.988]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/proc.go:3582 +0xd8 fp=0x40445fc4 sp=0x40445fa8 pc=0x70954"
    logw.go:50:                 INFO [09-04|22:06:40.993]                                          module=client stream=stderr text=runtime.park_m(0x40403c00)
    logw.go:50:                 INFO [09-04|22:06:40.995]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/proc.go:3745 +0x194 fp=0x40445fe0 sp=0x40445fc4 pc=0x711ac"
    logw.go:50:                 INFO [09-04|22:06:40.998]                                          module=client stream=stderr text=runtime.mcall()
    logw.go:50:                 INFO [09-04|22:06:41.000]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/asm_mipsx.s:141 +0x50 fp=0x40445fe8 sp=0x40445fe0 pc=0xac6a0"
    logw.go:50:                 INFO [09-04|22:06:41.000]                                          module=client stream=stderr text=
    logw.go:50:                 INFO [09-04|22:06:41.001]                                          module=client stream=stderr text="goroutine 1 [runnable]:"
    logw.go:50:                 INFO [09-04|22:06:41.003]                                          module=client stream=stderr text=internal/poll.(*FD).Read.func1()
    logw.go:50:                 INFO [09-04|22:06:41.005]                                          module=client stream=stderr text="\t/home/inphi/go/src/internal/poll/fd_unix.go:144 +0x1c fp=0x406be780 sp=0x406be780 pc=0xf99ac"
    logw.go:50:                 INFO [09-04|22:06:41.017]                                          module=client stream=stderr text="internal/poll.(*FD).Read(0x4067db40, {0x40603128, 0xbe, 0xbe})"
    logw.go:50:                 INFO [09-04|22:06:41.019]                                          module=client stream=stderr text="\t/home/inphi/go/src/internal/poll/fd_unix.go:170 +0x3c8 fp=0x406be7d4 sp=0x406be780 pc=0xf9968"
    logw.go:50:                 INFO [09-04|22:06:41.022]                                          module=client stream=stderr text=os.(*File).read(...)
    logw.go:50:                 INFO [09-04|22:06:41.023]                                          module=client stream=stderr text="\t/home/inphi/go/src/os/file_posix.go:29"
    logw.go:50:                 INFO [09-04|22:06:41.027]                                          module=client stream=stderr text="os.(*File).Read(0x406e0890, {0x40603128, 0xbe, 0xbe})"
    logw.go:50:                 INFO [09-04|22:06:41.030]                                          module=client stream=stderr text="\t/home/inphi/go/src/os/file.go:118 +0xb0 fp=0x406be7f8 sp=0x406be7d4 pc=0x1047d8"
    logw.go:50:                 INFO [09-04|22:06:41.034]                                          module=client stream=stderr text="github.com/ethereum-optimism/optimism/op-preimage.(*ReadWritePair).Read(0x406e08a0, {0x40603128, 0xbe, 0xbe})"
    logw.go:50:                 INFO [09-04|22:06:41.036]                                          module=client stream=stderr text="\t/home/inphi/optimism/optimism/op-preimage/filechan.go:28 +0x5c fp=0x406be818 sp=0x406be7f8 pc=0xb7c5b8"
    logw.go:50:                 INFO [09-04|22:06:41.042]                                          module=client stream=stderr text="io.ReadAtLeast({0x93bc120, 0x406e08a0}, {0x40603080, 0x166, 0x166}, 0x166)"
    logw.go:50:                 INFO [09-04|22:06:41.045]                                          module=client stream=stderr text="\t/home/inphi/go/src/io/io.go:335 +0xc8 fp=0x406be844 sp=0x406be818 pc=0xf1f4c"
    logw.go:50:                 INFO [09-04|22:06:41.047]                                          module=client stream=stderr text=io.ReadFull(...)
    logw.go:50:                 INFO [09-04|22:06:41.048]                                          module=client stream=stderr text="\t/home/inphi/go/src/io/io.go:354"
    logw.go:50:                 INFO [09-04|22:06:41.052]                                          module=client stream=stderr text="github.com/ethereum-optimism/optimism/op-preimage.(*OracleClient).Get(0x406e08c0, {0x1a533e0, 0x40731900})"
    logw.go:50:                 INFO [09-04|22:06:41.055]                                          module=client stream=stderr text="\t/home/inphi/optimism/optimism/op-preimage/oracle.go:33 +0x258 fp=0x406be8c8 sp=0x406be844 pc=0xb7d9dc"
    logw.go:50:                 INFO [09-04|22:06:41.063]                                          module=client stream=stderr text="github.com/ethereum-optimism/optimism/op-program/client/l2.(*PreimageOracle).LoadTransactions.func1({0x2b, 0xbc, 0xb0, 0x2c, 0x14, 0x7, 0x33, 0xf7, 0xf5, 0x6e, ...})"
    logw.go:50:                 INFO [09-04|22:06:41.055]                                          module=client stream=stderr text="\t/home/inphi/optimism/optimism/op-preimage/oracle.go:33 +0x258 fp=0x406be8c8 sp=0x406be844 pc=0xb7d9dc"
    logw.go:50:                 INFO [09-04|22:06:41.063]                                          module=client stream=stderr text="github.com/ethereum-optimism/optimism/op-program/client/l2.(*PreimageOracle).LoadTransactions.func1({0x2b, 0xbc, 0xb0, 0x2c, 0x14, 0x7, 0x33, 0xf7, 0xf5, 0x6e, ...})"
    logw.go:50:                 INFO [09-04|22:06:41.065]                                          module=client stream=stderr text="\t/home/inphi/optimism/optimism/op-program/client/l2/oracle.go:76 +0xa4 fp=0x406be908 sp=0x406be8c8 pc=0xdef998"
    logw.go:50:                 INFO [09-04|22:06:41.069]                                          module=client stream=stderr text="github.com/ethereum-optimism/optimism/op-program/client/mpt.ReadTrie.func1({0x407318e0, 0x20, 0x20})"
    logw.go:50:                 INFO [09-04|22:06:41.072]                                          module=client stream=stderr text="\t/home/inphi/optimism/optimism/op-program/client/mpt/trie.go:24 +0xa0 fp=0x406be968 sp=0x406be908 pc=0xcc5d48"
    logw.go:50:                 INFO [09-04|22:06:41.076]                                          module=client stream=stderr text="github.com/ethereum-optimism/optimism/op-program/client/mpt.(*DB).Get(0x40737200, {0x407318e0, 0x20, 0x20})"
    logw.go:50:                 INFO [09-04|22:06:41.079]                                          module=client stream=stderr text="\t/home/inphi/optimism/optimism/op-program/client/mpt/db.go:21 +0x5c fp=0x406be984 sp=0x406be968 pc=0xcc4d70"
    logw.go:50:                 INFO [09-04|22:06:41.087]                                          module=client stream=stderr text="github.com/ethereum/go-ethereum/core/rawdb.ReadLegacyTrieNode({0x93bd060, 0x40737200}, {0x2b, 0xbc, 0xb0, 0x2c, 0x14, 0x7, 0x33, 0xf7, ...})"
    logw.go:50:                 INFO [09-04|22:06:41.090]                                          module=client stream=stderr text="\t/home/inphi/go/pkg/mod/github.com/ethereum-optimism/op-geth@v1.101408.0-rc.4.0.20240827042333-110c433a2469/core/rawdb/accessors_trie.go:130 +0x9c fp=0x406be9b0 sp=0x406be984 pc=0x9f9218"
    logw.go:50:                 INFO [09-04|22:06:41.100]                                          module=client stream=stderr text="github.com/ethereum/go-ethereum/triedb/hashdb.(*Database).node(0x404c9550, {0x2b, 0xbc, 0xb0, 0x2c, 0x14, 0x7, 0x33, 0xf7, 0xf5, ...})"
    logw.go:50:                 INFO [09-04|22:06:41.102]                                          module=client stream=stderr text="\t/home/inphi/go/pkg/mod/github.com/ethereum-optimism/op-geth@v1.101408.0-rc.4.0.20240827042333-110c433a2469/triedb/hashdb/database.go:205 +0x228 fp=0x406bea30 sp=0x406be9b0 pc=0xc9dbf0"
    logw.go:50:                 INFO [09-04|22:06:41.110]                                          module=client stream=stderr text="github.com/ethereum/go-ethereum/triedb/hashdb.(*Database).Reader(0x404c9550, {0x2b, 0xbc, 0xb0, 0x2c, 0x14, 0x7, 0x33, 0xf7, 0xf5, ...})"
    logw.go:50:                 INFO [09-04|22:06:41.113]                                          module=client stream=stderr text="\t/home/inphi/go/pkg/mod/github.com/ethereum-optimism/op-geth@v1.101408.0-rc.4.0.20240827042333-110c433a2469/triedb/hashdb/database.go:622 +0x68 fp=0x406bea84 sp=0x406bea30 pc=0xca2888"
    logw.go:50:                 INFO [09-04|22:06:41.121]                                          module=client stream=stderr text="github.com/ethereum/go-ethereum/triedb.(*Database).Reader(0x40737220, {0x2b, 0xbc, 0xb0, 0x2c, 0x14, 0x7, 0x33, 0xf7, 0xf5, ...})"
    logw.go:50:                 INFO [09-04|22:06:41.123]                                          module=client stream=stderr text="\t/home/inphi/go/pkg/mod/github.com/ethereum-optimism/op-geth@v1.101408.0-rc.4.0.20240827042333-110c433a2469/triedb/database.go:129 +0x74 fp=0x406beabc sp=0x406bea84 pc=0xcc2ed0"
    logw.go:50:                 INFO [09-04|22:06:41.132]                                          module=client stream=stderr text="github.com/ethereum/go-ethereum/trie.newTrieReader({0x2b, 0xbc, 0xb0, 0x2c, 0x14, 0x7, 0x33, 0xf7, 0xf5, 0x6e, ...}, ...)"
    logw.go:50:                 INFO [09-04|22:06:41.135]                                          module=client stream=stderr text="\t/home/inphi/go/pkg/mod/github.com/ethereum-optimism/op-geth@v1.101408.0-rc.4.0.20240827042333-110c433a2469/trie/trie_reader.go:42 +0x1c4 fp=0x406beb28 sp=0x406beabc pc=0xa6eef8"
    logw.go:50:                 INFO [09-04|22:06:41.139]                                          module=client stream=stderr text="github.com/ethereum/go-ethereum/trie.New(0x4073ab40, {0x1a53c64, 0x40737220})"
    logw.go:50:                 INFO [09-04|22:06:41.141]                                          module=client stream=stderr text="\t/home/inphi/go/pkg/mod/github.com/ethereum-optimism/op-geth@v1.101408.0-rc.4.0.20240827042333-110c433a2469/trie/trie.go:83 +0xf8 fp=0x406bec00 sp=0x406beb28 pc=0xa68b18"
    logw.go:50:                 INFO [09-04|22:06:41.151]                                          module=client stream=stderr text="github.com/ethereum-optimism/optimism/op-program/client/mpt.ReadTrie({0x2b, 0xbc, 0xb0, 0x2c, 0x14, 0x7, 0x33, 0xf7, 0xf5, 0x6e, ...}, ...)"
    logw.go:50:                 INFO [09-04|22:06:41.154]                                          module=client stream=stderr text="\t/home/inphi/optimism/optimism/op-program/client/mpt/trie.go:52 +0x200 fp=0x406bec98 sp=0x406bec00 pc=0xcc5650"
    logw.go:50:                 INFO [09-04|22:06:41.163]                                          module=client stream=stderr text="github.com/ethereum-optimism/optimism/op-program/client/l2.(*PreimageOracle).LoadTransactions(0x4067f5b0, {0x5e, 0xab, 0x3d, 0x47, 0x83, 0xa2, 0x62, 0x1a, 0x2c, ...}, ...)"
    logw.go:50:                 INFO [09-04|22:06:41.166]                                          module=client stream=stderr text="\t/home/inphi/optimism/optimism/op-program/client/l2/oracle.go:75 +0x124 fp=0x406becf4 sp=0x406bec98 pc=0xdef824"
    logw.go:50:                 INFO [09-04|22:06:41.180]                                          module=client stream=stderr text="github.com/ethereum-optimism/optimism/op-program/client/l2.(*PreimageOracle).BlockByHash(0x4067f5b0, {0x5e, 0xab, 0x3d, 0x47, 0x83, 0xa2, 0x62, 0x1a, 0x2c, ...})"
    logw.go:50:                 INFO [09-04|22:06:41.183]                                          module=client stream=stderr text="\t/home/inphi/optimism/optimism/op-program/client/l2/oracle.go:67 +0x100 fp=0x406beda0 sp=0x406becf4 pc=0xdef608"
    logw.go:50:                 INFO [09-04|22:06:41.195]                                          module=client stream=stderr text="github.com/ethereum-optimism/optimism/op-program/client/l2.(*CachingOracle).BlockByHash(0x4063b8f0, {0x5e, 0xab, 0x3d, 0x47, 0x83, 0xa2, 0x62, 0x1a, 0x2c, ...})"
    logw.go:50:                 INFO [09-04|22:06:41.198]                                          module=client stream=stderr text="\t/home/inphi/optimism/optimism/op-program/client/l2/cache.go:63 +0xe0 fp=0x406bedd8 sp=0x406beda0 pc=0xdea374"
    logw.go:50:                 INFO [09-04|22:06:41.207]                                          module=client stream=stderr text="github.com/ethereum-optimism/optimism/op-program/client/l2.(*OracleBackedL2Chain).GetBlockByHash(0x40599b20, {0x5e, 0xab, 0x3d, 0x47, 0x83, 0xa2, 0x62, 0x1a, 0x2c, ...})"
    logw.go:50:                 INFO [09-04|22:06:41.210]                                          module=client stream=stderr text="\t/home/inphi/optimism/optimism/op-program/client/l2/engine_backend.go:121 +0xc4 fp=0x406bee04 sp=0x406bedd8 pc=0xded86c"
    logw.go:50:                 INFO [09-04|22:06:41.219]                                          module=client stream=stderr text="github.com/ethereum-optimism/optimism/op-program/client/l2.(*OracleEngine).L2BlockRefByHash(0x4067ff90, {0x1a587dc, 0x21e6bc0}, {0x5e, 0xab, 0x3d, 0x47, 0x83, 0xa2, 0x62, ...})"
    logw.go:50:                 INFO [09-04|22:06:41.221]                                          module=client stream=stderr text="\t/home/inphi/optimism/optimism/op-program/client/l2/engine.go:131 +0x94 fp=0x406bef1c sp=0x406bee04 pc=0xdec10c"
    logw.go:50:                 INFO [09-04|22:06:41.234]                                          module=client stream=stderr text="github.com/ethereum-optimism/optimism/op-node/rollup/derive.(*DerivationPipeline).initialReset(0x4066d800, {0x1a587dc, 0x21e6bc0}, {{0x87, 0x8e, 0x71, 0xe1, 0xc9, 0xe9, 0x5a, ...}, ...})"
    logw.go:50:                 INFO [09-04|22:06:41.237]                                          module=client stream=stderr text="\t/home/inphi/optimism/optimism/op-node/rollup/derive/pipeline.go:216 +0x418 fp=0x406bf464 sp=0x406bef1c pc=0xc749f0"
    logw.go:50:                 INFO [09-04|22:06:41.247]                                          module=client stream=stderr text="github.com/ethereum-optimism/optimism/op-node/rollup/derive.(*DerivationPipeline).Step(0x4066d800, {0x1a587dc, 0x21e6bc0}, {{0x87, 0x8e, 0x71, 0xe1, 0xc9, 0xe9, 0x5a, ...}, ...})"
    logw.go:50:                 INFO [09-04|22:06:41.250]                                          module=client stream=stderr text="\t/home/inphi/optimism/optimism/op-node/rollup/derive/pipeline.go:157 +0x220 fp=0x406bf858 sp=0x406bf464 pc=0xc73ac0"
    logw.go:50:                 INFO [09-04|22:06:41.256]                                          module=client stream=stderr text="github.com/ethereum-optimism/optimism/op-node/rollup/derive.(*PipelineDeriver).OnEvent(0x407327b0, {0x1a531ec, 0x404f5080})"
    logw.go:50:                 INFO [09-04|22:06:41.259]                                          module=client stream=stderr text="\t/home/inphi/optimism/optimism/op-node/rollup/derive/deriver.go:99 +0x2a8 fp=0x406bfd70 sp=0x406bf858 pc=0xc69890"
    logw.go:50:                 INFO [09-04|22:06:41.263]                                          module=client stream=stderr text="github.com/ethereum-optimism/optimism/op-node/rollup/event.(*DeriverMux).OnEvent(0x4067ffe0, {0x1a531ec, 0x404f5080})"
    logw.go:50:                 INFO [09-04|22:06:41.266]                                          module=client stream=stderr text="\t/home/inphi/optimism/optimism/op-node/rollup/event/events.go:47 +0x84 fp=0x406bfd94 sp=0x406bfd70 pc=0xa90918"
    logw.go:50:                 INFO [09-04|22:06:41.269]                                          module=client stream=stderr text=github.com/ethereum-optimism/optimism/op-program/client/driver.(*Driver).RunComplete(0x4071c4b0)
    logw.go:50:                 INFO [09-04|22:06:41.271]                                          module=client stream=stderr text="\t/home/inphi/optimism/optimism/op-program/client/driver/driver.go:91 +0x164 fp=0x406bfdbc sp=0x406bfd94 pc=0xc9599c"
    logw.go:50:                 INFO [09-04|22:06:41.283]                                          module=client stream=stderr text="github.com/ethereum-optimism/optimism/op-program/client.runDerivation({0x1a5c24c, 0x406e0868}, 0x404d0dc0, 0x405a15f0, {0x3, 0x91, 0x5b, 0xb6, 0x4b, 0x9a, ...}, ...)"
    logw.go:50:                 INFO [09-04|22:06:41.285]                                          module=client stream=stderr text="\t/home/inphi/optimism/optimism/op-program/client/program.go:74 +0x428 fp=0x406bfe28 sp=0x406bfdbc pc=0xdf7650"
    logw.go:50:                 INFO [09-04|22:06:41.295]                                          module=client stream=stderr text="github.com/ethereum-optimism/optimism/op-program/client.RunProgram({0x1a5c24c, 0x406e0868}, {0x93bc108, 0x406e08a0}, {0x93bc108, 0x406e08b8})"
    logw.go:50:                 INFO [09-04|22:06:41.297]                                          module=client stream=stderr text="\t/home/inphi/optimism/optimism/op-program/client/program.go:49 +0x48c fp=0x406bff38 sp=0x406bfe28 pc=0xdf7208"
    logw.go:50:                 INFO [09-04|22:06:41.301]                                          module=client stream=stderr text="github.com/ethereum-optimism/optimism/op-program/client.Main({0x1a5c24c, 0x406e0868})"
    logw.go:50:                 INFO [09-04|22:06:41.303]                                          module=client stream=stderr text="\t/home/inphi/optimism/optimism/op-program/client/program.go:28 +0x100 fp=0x406bff74 sp=0x406bff38 pc=0xdf6b54"
    logw.go:50:                 INFO [09-04|22:06:41.305]                                          module=client stream=stderr text=main.main()
    logw.go:50:                 INFO [09-04|22:06:41.307]                                          module=client stream=stderr text="\t/home/inphi/optimism/optimism/op-program/client/cmd/main.go:21 +0xd4 fp=0x406bffa4 sp=0x406bff74 pc=0xdf7a7c"
    logw.go:50:                 INFO [09-04|22:06:41.313]                                          module=client stream=stderr text=runtime.main()
    logw.go:50:                 INFO [09-04|22:06:41.316]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/proc.go:267 +0x394 fp=0x406bffec sp=0x406bffa4 pc=0x67400"
    logw.go:50:                 INFO [09-04|22:06:41.317]                                          module=client stream=stderr text=runtime.goexit()
    logw.go:50:                 INFO [09-04|22:06:41.320]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/asm_mipsx.s:641 +0x4 fp=0x406bffec sp=0x406bffec pc=0xaea60"
    logw.go:50:                 INFO [09-04|22:06:41.320]                                          module=client stream=stderr text=
    logw.go:50:                 INFO [09-04|22:06:41.321]                                          module=client stream=stderr text="goroutine 2 [force gc (idle)]:"
    logw.go:50:                 INFO [09-04|22:06:41.329]                                          module=client stream=stderr text="runtime.gopark(0x190dbf4, 0x21ce9e8, 0x11, 0x14, 0x1)"
    logw.go:50:                 INFO [09-04|22:06:41.331]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/proc.go:398 +0x128 fp=0x40430fd4 sp=0x40430fc8 pc=0x67a4c"
    logw.go:50:                 INFO [09-04|22:06:41.335]                                          module=client stream=stderr text=runtime.goparkunlock(...)
    logw.go:50:                 INFO [09-04|22:06:41.336]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/proc.go:404"
    logw.go:50:                 INFO [09-04|22:06:41.339]                                          module=client stream=stderr text=runtime.forcegchelper()
    logw.go:50:                 INFO [09-04|22:06:41.341]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/proc.go:322 +0x128 fp=0x40430fec sp=0x40430fd4 pc=0x67828"
    logw.go:50:                 INFO [09-04|22:06:41.343]                                          module=client stream=stderr text=runtime.goexit()
    logw.go:50:                 INFO [09-04|22:06:41.345]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/asm_mipsx.s:641 +0x4 fp=0x40430fec sp=0x40430fec pc=0xaea60"
    logw.go:50:                 INFO [09-04|22:06:41.346]                                          module=client stream=stderr text="created by runtime.init.5 in goroutine 1"
    logw.go:50:                 INFO [09-04|22:06:41.348]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/proc.go:310 +0x44"
    logw.go:50:                 INFO [09-04|22:06:41.348]                                          module=client stream=stderr text=
    logw.go:50:                 INFO [09-04|22:06:41.349]                                          module=client stream=stderr text="goroutine 3 [GC sweep wait]:"
    logw.go:50:                 INFO [09-04|22:06:41.357]                                          module=client stream=stderr text="runtime.gopark(0x190dbf4, 0x21d03f0, 0xc, 0x14, 0x1)"
    logw.go:50:                 INFO [09-04|22:06:41.360]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/proc.go:398 +0x128 fp=0x404317c4 sp=0x404317b8 pc=0x67a4c"
    logw.go:50:                 INFO [09-04|22:06:41.363]                                          module=client stream=stderr text=runtime.goparkunlock(...)
    logw.go:50:                 INFO [09-04|22:06:41.363]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/proc.go:404"
    logw.go:50:                 INFO [09-04|22:06:41.366]                                          module=client stream=stderr text=runtime.bgsweep(0x40446000)
    logw.go:50:                 INFO [09-04|22:06:41.368]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/mgcsweep.go:280 +0xe8 fp=0x404317e4 sp=0x404317c4 pc=0x48934"
    logw.go:50:                 INFO [09-04|22:06:41.370]                                          module=client stream=stderr text=runtime.gcenable.func1()
    logw.go:50:                 INFO [09-04|22:06:41.372]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/mgc.go:200 +0x64 fp=0x404317ec sp=0x404317e4 pc=0x35f08"
    logw.go:50:                 INFO [09-04|22:06:41.374]                                          module=client stream=stderr text=runtime.goexit()
    logw.go:50:                 INFO [09-04|22:06:41.376]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/asm_mipsx.s:641 +0x4 fp=0x404317ec sp=0x404317ec pc=0xaea60"
    logw.go:50:                 INFO [09-04|22:06:41.377]                                          module=client stream=stderr text="created by runtime.gcenable in goroutine 1"
    logw.go:50:                 INFO [09-04|22:06:41.379]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/mgc.go:200 +0xb4"
    logw.go:50:                 INFO [09-04|22:06:41.379]                                          module=client stream=stderr text=
    logw.go:50:                 INFO [09-04|22:06:41.380]                                          module=client stream=stderr text="goroutine 4 [GC scavenge wait]:"
    logw.go:50:                 INFO [09-04|22:06:41.391]                                          module=client stream=stderr text="runtime.gopark(0x190dbf4, 0x21d0b60, 0xd, 0x14, 0x2)"
    logw.go:50:                 INFO [09-04|22:06:41.393]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/proc.go:398 +0x128 fp=0x40431fbc sp=0x40431fb0 pc=0x67a4c"
    logw.go:50:                 INFO [09-04|22:06:41.396]                                          module=client stream=stderr text=runtime.goparkunlock(...)
    logw.go:50:                 INFO [09-04|22:06:41.397]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/proc.go:404"
    logw.go:50:                 INFO [09-04|22:06:41.400]                                          module=client stream=stderr text=runtime.(*scavengerState).park(0x21d0b60)
    logw.go:50:                 INFO [09-04|22:06:41.402]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/mgcscavenge.go:425 +0x98 fp=0x40431fd0 sp=0x40431fbc pc=0x44c10"
    logw.go:50:                 INFO [09-04|22:06:41.404]                                          module=client stream=stderr text=runtime.bgscavenge(0x40446000)
    logw.go:50:                 INFO [09-04|22:06:41.407]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/mgcscavenge.go:653 +0x74 fp=0x40431fe4 sp=0x40431fd0 pc=0x45600"
    logw.go:50:                 INFO [09-04|22:06:41.408]                                          module=client stream=stderr text=runtime.gcenable.func2()
    logw.go:50:                 INFO [09-04|22:06:41.411]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/mgc.go:201 +0x64 fp=0x40431fec sp=0x40431fe4 pc=0x35e94"
    logw.go:50:                 INFO [09-04|22:06:41.412]                                          module=client stream=stderr text=runtime.goexit()
    logw.go:50:                 INFO [09-04|22:06:41.415]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/asm_mipsx.s:641 +0x4 fp=0x40431fec sp=0x40431fec pc=0xaea60"
    logw.go:50:                 INFO [09-04|22:06:41.416]                                          module=client stream=stderr text="created by runtime.gcenable in goroutine 1"
    logw.go:50:                 INFO [09-04|22:06:41.418]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/mgc.go:201 +0x114"
    logw.go:50:                 INFO [09-04|22:06:41.418]                                          module=client stream=stderr text=
    logw.go:50:                 INFO [09-04|22:06:41.419]                                          module=client stream=stderr text="goroutine 5 [finalizer wait]:"
    logw.go:50:                 INFO [09-04|22:06:41.427]                                          module=client stream=stderr text="runtime.gopark(0x190da90, 0x21e6c14, 0x10, 0x14, 0x1)"
    logw.go:50:                 INFO [09-04|22:06:41.429]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/proc.go:398 +0x128 fp=0x40430794 sp=0x40430788 pc=0x67a4c"
    logw.go:50:                 INFO [09-04|22:06:41.433]                                          module=client stream=stderr text=runtime.runfinq()
    logw.go:50:                 INFO [09-04|22:06:41.436]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/mfinal.go:193 +0x164 fp=0x404307ec sp=0x40430794 pc=0x34aa8"
    logw.go:50:                 INFO [09-04|22:06:41.437]                                          module=client stream=stderr text=runtime.goexit()
    logw.go:50:                 INFO [09-04|22:06:41.440]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/asm_mipsx.s:641 +0x4 fp=0x404307ec sp=0x404307ec pc=0xaea60"
    logw.go:50:                 INFO [09-04|22:06:41.441]                                          module=client stream=stderr text="created by runtime.createfing in goroutine 1"
    logw.go:50:                 INFO [09-04|22:06:41.443]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/mfinal.go:163 +0x98"
    logw.go:50:                 INFO [09-04|22:06:41.443]                                          module=client stream=stderr text=
    logw.go:50:                 INFO [09-04|22:06:41.444]                                          module=client stream=stderr text="goroutine 8 [chan receive]:"
    logw.go:50:                 INFO [09-04|22:06:41.453]                                          module=client stream=stderr text="runtime.gopark(0x190da74, 0x4067d570, 0xe, 0x17, 0x2)"
    logw.go:50:                 INFO [09-04|22:06:41.455]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/proc.go:398 +0x128 fp=0x40432758 sp=0x4043274c pc=0x67a4c"
    logw.go:50:                 INFO [09-04|22:06:41.473]                                          module=client stream=stderr text="runtime.chanrecv(0x4067d540, 0x404327e0, 0x1)"
    logw.go:50:                 INFO [09-04|22:06:41.476]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/chan.go:583 +0x5c8 fp=0x40432794 sp=0x40432758 pc=0x1a374"
    logw.go:50:                 INFO [09-04|22:06:41.479]                                          module=client stream=stderr text="runtime.chanrecv2(0x4067d540, 0x404327e0)"
    logw.go:50:                 INFO [09-04|22:06:41.481]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/chan.go:447 +0x2c fp=0x404327a8 sp=0x40432794 pc=0x19d94"
    logw.go:50:                 INFO [09-04|22:06:41.484]                                          module=client stream=stderr text=github.com/ethereum/go-ethereum/core.(*txSenderCacher).cache(0x406e0340)
    logw.go:50:                 INFO [09-04|22:06:41.487]                                          module=client stream=stderr text="\t/home/inphi/go/pkg/mod/github.com/ethereum-optimism/op-geth@v1.101408.0-rc.4.0.20240827042333-110c433a2469/core/sender_cacher.go:63 +0x60 fp=0x404327e4 sp=0x404327a8 pc=0xd88750"
    logw.go:50:                 INFO [09-04|22:06:41.489]                                          module=client stream=stderr text=github.com/ethereum/go-ethereum/core.newTxSenderCacher.func1()
    logw.go:50:                 INFO [09-04|22:06:41.491]                                          module=client stream=stderr text="\t/home/inphi/go/pkg/mod/github.com/ethereum-optimism/op-geth@v1.101408.0-rc.4.0.20240827042333-110c433a2469/core/sender_cacher.go:55 +0x64 fp=0x404327ec sp=0x404327e4 pc=0xd886e0"
    logw.go:50:                 INFO [09-04|22:06:41.493]                                          module=client stream=stderr text=runtime.goexit()
    logw.go:50:                 INFO [09-04|22:06:41.495]                                          module=client stream=stderr text="\t/home/inphi/go/src/runtime/asm_mipsx.s:641 +0x4 fp=0x404327ec sp=0x404327ec pc=0xaea60"
    logw.go:50:                 INFO [09-04|22:06:41.498]                                          module=client stream=stderr text="created by github.com/ethereum/go-ethereum/core.newTxSenderCacher in goroutine 1"
    logw.go:50:                 INFO [09-04|22:06:41.502]                                          module=client stream=stderr text="\t/home/inphi/go/pkg/mod/github.com/ethereum-optimism/op-geth@v1.101408.0-rc.4.0.20240827042333-110c433a2469/core/sender_cacher.go:55 +0xc4"
Example 2
  logw.go:50:                 INFO [08-24|21:59:18.244]                                          module=client stream=stderr text="\t/usr/local/go/src/runtime/asm_mipsx.s:641 +0x4 fp=0x40
42e7ec sp=0x4042e7ec pc=0xaf0fc"
    logw.go:50:                 INFO [08-24|21:59:18.245]                                          module=client stream=stderr text="created by runtime.createfing in goroutine 1"
    logw.go:50:                 INFO [08-24|21:59:18.246]                                          module=client stream=stderr text="\t/usr/local/go/src/runtime/mfinal.go:163 +0x98"
    logw.go:50:                 INFO [08-24|21:59:18.246]                                          module=client stream=stderr text=
    logw.go:50:                 INFO [08-24|21:59:18.247]                                          module=client stream=stderr text="goroutine 8 [chan receive]:"
    logw.go:50:                 INFO [08-24|21:59:18.252]                                          module=client stream=stderr text="runtime.gopark(0x1908a14, 0x4051f570, 0xe, 0x17, 0x2)"
    logw.go:50:                 INFO [08-24|21:59:18.253]                                          module=client stream=stderr text="\t/usr/local/go/src/runtime/proc.go:398 +0x128 fp=0x4043
0758 sp=0x4043074c pc=0x68080"
    logw.go:50:                 INFO [08-24|21:59:18.261]                                          module=client stream=stderr text="runtime.chanrecv(0x4051f540, 0x404307e0, 0x1)"
    logw.go:50:                 INFO [08-24|21:59:18.263]                                          module=client stream=stderr text="\t/usr/local/go/src/runtime/chan.go:583 +0x5c8 fp=0x4043
0794 sp=0x40430758 pc=0x1a60c"
    logw.go:50:                 INFO [08-24|21:59:18.264]                                          module=client stream=stderr text="runtime.chanrecv2(0x4051f540, 0x404307e0)"
    logw.go:50:                 INFO [08-24|21:59:18.265]                                          module=client stream=stderr text="\t/usr/local/go/src/runtime/chan.go:447 +0x2c fp=0x40430
7a8 sp=0x40430794 pc=0x1a02c"
    logw.go:50:                 INFO [08-24|21:59:18.267]                                          module=client stream=stderr text=github.com/ethereum/go-ethereum/core.(*txSenderCacher).ca
che(0x406f0330)
    logw.go:50:                 INFO [08-24|21:59:18.268]                                          module=client stream=stderr text="\t/Users/inphi/go/pkg/mod/github.com/ethereum-optimism/o
p-geth@v1.101408.0-rc.4.0.20240822213944-6c8de76e0720/core/sender_cacher.go:63 +0x60 fp=0x404307e4 sp=0x404307a8 pc=0xd863b8"
    logw.go:50:                 INFO [08-24|21:59:18.269]                                          module=client stream=stderr text=github.com/ethereum/go-ethereum/core.newTxSenderCacher.fu
nc1()
    logw.go:50:                 INFO [08-24|21:59:18.271]                                          module=client stream=stderr text="\t/Users/inphi/go/pkg/mod/github.com/ethereum-optimism/o
p-geth@v1.101408.0-rc.4.0.20240822213944-6c8de76e0720/core/sender_cacher.go:55 +0x64 fp=0x404307ec sp=0x404307e4 pc=0xd86348"
    logw.go:50:                 INFO [08-24|21:59:18.272]                                          module=client stream=stderr text=runtime.goexit()
    logw.go:50:                 INFO [08-24|21:59:18.273]                                          module=client stream=stderr text="\t/usr/local/go/src/runtime/asm_mipsx.s:641 +0x4 fp=0x40
4307ec sp=0x404307ec pc=0xaf0fc"
    logw.go:50:                 INFO [08-24|21:59:18.274]                                          module=client stream=stderr text="created by github.com/ethereum/go-ethereum/core.newTxSen
derCacher in goroutine 1"
    logw.go:50:                 INFO [08-24|21:59:18.275]                                          module=client stream=stderr text="\t/Users/inphi/go/pkg/mod/github.com/ethereum-optimism/op-geth@v1.101408.0-rc.4.0.20240822213944-6c8de76e0720/core/sender_cacher.go:55 +0xc4"
    logw.go:50:                 INFO [08-24|21:59:18.276]                                          module=client stream=stderr text=
    logw.go:50:                 INFO [08-24|21:59:18.276]                                          module=client stream=stderr text="goroutine 9 [GC worker (idle)]:"
    logw.go:50:                 INFO [08-24|21:59:18.281]                                          module=client stream=stderr text="runtime.gopark(0x1908a44, 0x4073cde0, 0x1a, 0x14, 0x0)"
    logw.go:50:                 INFO [08-24|21:59:18.282]                                          module=client stream=stderr text="\t/usr/local/go/src/runtime/proc.go:398 +0x128 fp=0x40430f94 sp=0x40430f88 pc=0x68080"
    logw.go:50:                 INFO [08-24|21:59:18.284]                                          module=client stream=stderr text=runtime.gcBgMarkWorker()
    logw.go:50:                 INFO [08-24|21:59:18.286]                                          module=client stream=stderr text="\t/usr/local/go/src/runtime/mgc.go:1295 +0x124 fp=0x40430fec sp=0x40430f94 pc=0x392cc"
    logw.go:50:                 INFO [08-24|21:59:18.287]                                          module=client stream=stderr text=runtime.goexit()
    logw.go:50:                 INFO [08-24|21:59:18.288]                                          module=client stream=stderr text="\t/usr/local/go/src/runtime/asm_mipsx.s:641 +0x4 fp=0x40430fec sp=0x40430fec pc=0xaf0fc"
    logw.go:50:                 INFO [08-24|21:59:18.289]                                          module=client stream=stderr text="created by runtime.gcBgMarkStartWorkers in goroutine 1"
    logw.go:50:                 INFO [08-24|21:59:18.290]                                          module=client stream=stderr text="\t/usr/local/go/src/runtime/mgc.go:1219 +0x4c"

This needs to be debugged before MT-Cannon is ready for the op-program.

Inphi commented 2 months ago

I took a snapshot of one of these panics, containing the same FPP inputs, op-program ELF binary, and preimages. And I'm no longer able to reproduce this on the latest MT-Cannon VM. And I'm no longer seeing any panic when I run TestVerifyL2Output multiple times. This is most likely fixed by #11757.