Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

nitro panics on reader-node shutdown #46

Open
matthewdarwin opened this issue Jun 15, 2024 · 3 comments
Open

nitro panics on reader-node shutdown #46

matthewdarwin opened this issue Jun 15, 2024 · 3 comments

Comments

@matthewdarwin
Copy link

matthewdarwin commented Jun 15, 2024 •
edited
Loading

Not sure if there is anything we can do with nitro panicking on reader-node shutdown. This situation sometimes leads to corrupt nitro database.

Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.223Z INFO (reader-node) operator is terminating
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.223Z INFO (reader-node) superviser is terminating
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.223Z INFO (reader-node) supervisor received a stop request, terminating supervised node process
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.223Z INFO (reader-node) stopping underlying process
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: panic: send on closed channel
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: goroutine 97 [running]:
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: os/signal.process({0x5461030?, 0x76248b8})
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: #011/usr/local/go/src/os/signal/signal.go:245 +0x19f
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: os/signal.loop()
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: #011/usr/local/go/src/os/signal/signal_unix.go:23 +0x34
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: created by os/signal.Notify.func1.1
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: #011/usr/local/go/src/os/signal/signal.go:151 +0x2a
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.848Z INFO (reader-node) superviser terminating, waiting for operator...
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.848Z INFO (reader-node) supervised process has been terminated
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.848Z INFO (reader-node) waiting for stdout and stderr to be drained {"stdout_len": 0, "stderr_len": 0}
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.848Z INFO (reader-node) stdout and stderr are now drained
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.849Z INFO (reader-node) shutting down plugins {"last_exit_code": 0}
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.849Z INFO (reader-node) stopping plugin {"plugin_name": "ToConsoleLogPlugin"}
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.849Z INFO (reader-node) stopping plugin {"plugin_name": "MindReaderPlugin"}
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.849Z INFO (reader-node) mindreader is stopping
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.849Z INFO (reader-node) waiting until consume read flow (i.e. blocks) is actually done processing blocks...
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.849Z INFO (reader-node) lines channel has been closed
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.849Z INFO (reader-node) reached end of console reader stream, nothing more to do
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.849Z INFO (reader-node) all blocks in channel were drained, exiting read flow
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.849Z INFO (reader-node) archiver selector is terminating
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.849Z INFO (reader-node) archiver selector is terminated
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.849Z INFO (reader-node) archiver termination code completed
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.849Z INFO (reader-node) consume read flow terminate
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.849Z INFO (reader-node) all plugins closed
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.849Z INFO (reader-node) operator is waiting for superviser to shutdown
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.849Z INFO (reader-node) operator done waiting for superviser to shutdown
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.849Z INFO (reader-node) chain operator terminated shutting down mindreader app
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.849Z INFO (fireeth) all apps terminated gracefully
Jun 15 15:20:25 arbsepolia-sfdm217 sf-nitro[1639]: 2024-06-15T15:20:25.854Z INFO (fireeth) terminated
@matthewdarwin
Copy link
Author

Startup messages:

Jun 15 16:11:08 arbsepolia-sfdm217 sf-nitro[78070]: INFO [06-15|16:11:08.019] Loaded most recent local block           number=54,958,195 hash=9fe3dd..766b92 td=54,958,196 age=50m43s
Jun 15 16:11:08 arbsepolia-sfdm217 sf-nitro[78070]: WARN [06-15|16:11:08.021] Head state missing, repairing            number=54,958,195 hash=9fe3dd..766b92 snaproot=6fe216..e6a0c1
Jun 15 16:11:12 arbsepolia-sfdm217 sf-nitro[78070]: 2024-06-15T16:11:12.497Z INFO (reader-node.sub.relayer) receive block request {"trace_id": "187755bdc094ff3b2c68f72ab8a6e45d", "request": {"requester":"relayer"}}
Jun 15 16:11:12 arbsepolia-sfdm217 sf-nitro[78070]: 2024-06-15T16:11:12.497Z INFO (reader-node.sub.relayer) sending burst {"burst_size": 0}
Jun 15 16:11:12 arbsepolia-sfdm217 sf-nitro[78070]: 2024-06-15T16:11:12.497Z INFO (reader-node) subscribed {"new_length": 1, "subscriber": "relayer"}
Jun 15 16:11:17 arbsepolia-sfdm217 sf-nitro[78070]: INFO [06-15|16:11:17.937] Loaded most recent local header          number=54,958,195 hash=9fe3dd..766b92 td=54,958,196 age=50m52s
Jun 15 16:11:17 arbsepolia-sfdm217 sf-nitro[78070]: INFO [06-15|16:11:17.937] Loaded most recent local block           number=54,928,147 hash=d77068..70dd7e td=54,928,148 age=2h57m39s
Jun 15 16:11:17 arbsepolia-sfdm217 sf-nitro[78070]: INFO [06-15|16:11:17.937] Loaded most recent local snap block      number=54,958,195 hash=9fe3dd..766b92 td=54,958,196 age=50m52s
Jun 15 16:11:17 arbsepolia-sfdm217 sf-nitro[78070]: WARN [06-15|16:11:17.940] Enabling snapshot recovery               chainhead=54,928,147 diskbase=54,957,016
Jun 15 16:11:17 arbsepolia-sfdm217 sf-nitro[78070]: WARN [06-15|16:11:17.941] Loaded snapshot journal                  diskroot=6fe216..e6a0c1 diffs=unmatched
Jun 15 16:11:17 arbsepolia-sfdm217 sf-nitro[78070]: WARN [06-15|16:11:17.941] Snapshot is not continuous with chain    snaproot=6fe216..e6a0c1 chainroot=2dce1e..a001ad
Jun 15 16:11:17 arbsepolia-sfdm217 sf-nitro[78070]: INFO [06-15|16:11:17.941] Initialized transaction indexer          range="last 126230400 blocks"
Jun 15 16:11:17 arbsepolia-sfdm217 sf-nitro[78070]: INFO [06-15|16:11:17.973] Using leveldb as the backing database
Jun 15 16:11:17 arbsepolia-sfdm217 sf-nitro[78070]: INFO [06-15|16:11:17.974] Allocated cache and file handles         database=/var/lib/nitro/nitro/arbitrumdata cache=16.00MiB handles=16
Jun 15 16:11:18 arbsepolia-sfdm217 sf-nitro[78070]: INFO [06-15|16:11:18.124] Using LevelDB as the backing database
Jun 15 16:11:18 arbsepolia-sfdm217 sf-nitro[78070]: INFO [06-15|16:11:18.900] running as validator                     txSender= actingAsWallet=<nil> whitelisted=false strategy=Watchtower
Jun 15 16:11:18 arbsepolia-sfdm217 sf-nitro[78070]: WARN [06-15|16:11:18.907] Unclean shutdown detected                booted=2024-06-15T15:19:42+0000 age=51m36s
Jun 15 16:11:18 arbsepolia-sfdm217 sf-nitro[78070]: INFO [06-15|16:11:18.907] Starting peer-to-peer node               instance=nitro/vdevelopment/linux-amd64/go1.21.10
Jun 15 16:11:18 arbsepolia-sfdm217 sf-nitro[78070]: WARN [06-15|16:11:18.907] P2P server will be useless, neither dialing nor listening
Jun 15 16:11:18 arbsepolia-sfdm217 sf-nitro[78070]: INFO [06-15|16:11:18.911] IPC endpoint opened                      url=/tmp/node.ipc
Jun 15 16:11:18 arbsepolia-sfdm217 sf-nitro[78070]: INFO [06-15|16:11:18.912] HTTP server started                      endpoint=[::]:9657 auth=false prefix= cors=* vhosts=*
Jun 15 16:11:18 arbsepolia-sfdm217 sf-nitro[78070]: INFO [06-15|16:11:18.912] New local node record                    seq=1,718,129,682,464 id=d95707a065e6cec1 ip=127.0.0.1 udp=0 tcp=0
Jun 15 16:11:18 arbsepolia-sfdm217 sf-nitro[78070]: INFO [06-15|16:11:18.912] Started P2P networking                   self=enode://d2dcfaa09c667e345efcd8f233ef5a82f168f0c64acb65c0f28ea791d9659bc7fa5be123081b837c05d81fcc2dc1e40fda79f4e2315ca68d65f0b794f3332ea6@127.0.0.1:0
Jun 15 16:11:20 arbsepolia-sfdm217 sf-nitro[78070]: ERROR[06-15|16:11:20.048] feedOneMsg failed to readMessage         err="leveldb: not found" pos=54928148
Jun 15 16:11:20 arbsepolia-sfdm217 sf-nitro[78070]: INFO [06-15|16:11:20.097] validation not set up                    err="timeout trying to connect lastError: dial tcp :80: connect: connection refused"
Jun 15 16:11:20 arbsepolia-sfdm217 sf-nitro[78070]: WARN [06-15|16:11:20.102] error reading inbox                      err="abi: attempting to unmarshal an empty string while arguments are expected"
Jun 15 16:11:20 arbsepolia-sfdm217 sf-nitro[78070]: INFO [06-15|16:11:20.125] latest assertion not yet in our node     staker=0x0000000000000000000000000000000000000000 assertion=6737 state="{BlockHash:0xfa258780a3a1bdc6dea2070be95120152d01d7f4b19b8b2482f8b62c89efd234 SendRoot:0x278c3cf4461ba9c0824e7f92ceadddf4f2687975a479589e62abd6ab34ee4788 Batch:180250 PosInBatch:17}"
Jun 15 16:11:20 arbsepolia-sfdm217 sf-nitro[78070]: ERROR[06-15|16:11:20.148] feedOneMsg failed to readMessage         err="leveldb: not found" pos=54928148
Jun 15 16:11:20 arbsepolia-sfdm217 sf-nitro[78070]: INFO [06-15|16:11:20.179] catching up to chain batches             localBatches=180,237 target=180,251
Jun 15 16:11:20 arbsepolia-sfdm217 sf-nitro[78070]: ERROR[06-15|16:11:20.248] feedOneMsg failed to readMessage         err="leveldb: not found" pos=54928148
Jun 15 16:11:20 arbsepolia-sfdm217 sf-nitro[78070]: ERROR[06-15|16:11:20.349] feedOneMsg failed to readMessage         err="leveldb: not found" pos=54928148
Jun 15 16:11:20 arbsepolia-sfdm217 sf-nitro[78070]: ERROR[06-15|16:11:20.449] feedOneMsg failed to readMessage         err="leveldb: not found" pos=54928148
Jun 15 16:11:20 arbsepolia-sfdm217 sf-nitro[78070]: ERROR[06-15|16:11:20.550] feedOneMsg failed to readMessage         err="leveldb: not found" pos=54928148

@matthewdarwin
Copy link
Author

Ticket for nitro team: OffchainLabs/nitro#2421

@matthewdarwin
Copy link
Author

This seems to happen on servers with slower CPUs.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@matthewdarwin