search

dymensionxyz / roller

CLI tool for deploying Dymension RollApps
72 stars 58 forks source link

panic: invalid height: 70651; expected: 70664 #607

Closed Megumiiiiii closed 7 months ago

Megumiiiiii commented 7 months ago

Roller version

v0.1.21-beta

OS

Ubuntu 22.04.3 LTS x86_64

Processor Architecture

x86_64

Others

Kernel: 5.15.0-86-generic CPU: AMD EPYC 7282 (6) @ 2.794GHz GPU: 00:02.0 Vendor 1234 Device 1111 Memory: 8935MiB / 15989MiB

Steps to reproduce it

tail -n 100 -f $HOME/.roller/rollapp/rollapp.log

Expected result

Screenshot_129

Actual result

time="2023-11-26T03:06:23-05:00" level=info msg="starting node with ABCI dymint in-process[]"
time="2023-11-26T03:06:23-05:00" level=info msg="service start[msg Starting multiAppConn service impl multiAppConn]" module=proxy
time="2023-11-26T03:06:23-05:00" level=info msg="service start[msg Starting localClient service impl localClient]" connection=query module=abci-client
time="2023-11-26T03:06:23-05:00" level=info msg="service start[msg Starting localClient service impl localClient]" connection=snapshot module=abci-client
time="2023-11-26T03:06:23-05:00" level=info msg="service start[msg Starting localClient service impl localClient]" connection=mempool module=abci-client
time="2023-11-26T03:06:23-05:00" level=info msg="service start[msg Starting localClient service impl localClient]" connection=consensus module=abci-client
time="2023-11-26T03:06:23-05:00" level=info msg="service start[msg Starting EventBus service impl EventBus]" module=events
time="2023-11-26T03:06:23-05:00" level=info msg="service start[msg Starting PubSub service impl PubSub]" module=pubsub
badger 2023/11/26 03:06:24 INFO: All 184 tables opened in 1.113s
badger 2023/11/26 03:06:24 INFO: Discard stats nextEmptySlot: 0
badger 2023/11/26 03:06:24 INFO: Set nextTxnTs to 350415
badger 2023/11/26 03:06:24 INFO: Deleting empty file: /root/.roller/rollapp/data/dymint/000095.vlog
time="2023-11-26T03:06:25-05:00" level=debug msg="Getting latest batch from settlement layer[]" module=settlement_client
time="2023-11-26T03:06:25-05:00" level=info msg="Updated latest height from settlement layer[latestHeight 70634]" module=settlement_client
time="2023-11-26T03:06:25-05:00" level=info msg="Updated sequencers list from settlement layer[sequencersList [0xc00ae85770]]" module=settlement_client
time="2023-11-26T03:06:25-05:00" level=info msg="service start[msg Starting IndexerService service impl IndexerService]" module=txindex
time="2023-11-26T03:06:25-05:00" level=info msg="service start[msg Starting RPC service impl RPC]"
time="2023-11-26T03:06:25-05:00" level=debug msg="limiting number of connections[limit 900]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name consensus_state]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name status]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name validators]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name broadcast_tx_async]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name broadcast_evidence]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name health]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name blockchain]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name tx]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name num_unconfirmed_txs]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name broadcast_tx_sync]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name abci_info]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name unsubscribe_all]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name genesis]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name block_by_hash]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name consensus_params]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name block]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name commit]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name tx_search]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name block_search]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name unconfirmed_txs]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name net_info]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name block_results]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name dump_consensus_state]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name subscribe]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name check_tx]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name unsubscribe]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name genesis_chunked]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name broadcast_tx_commit]"
time="2023-11-26T03:06:25-05:00" level=debug msg="registering method[name abci_query]"
time="2023-11-26T03:06:25-05:00" level=debug msg="CORS enabled[origins [*] methods [HEAD GET POST] headers [Origin Accept Content-Type X-Requested-With X-Server-Time]]"
time="2023-11-26T03:06:25-05:00" level=info msg="service start[msg Starting Node service impl Node]"
time="2023-11-26T03:06:25-05:00" level=info msg="starting P2P client[]"
time="2023-11-26T03:06:25-05:00" level=debug msg="starting P2P client[]" module=p2p
time="2023-11-26T03:06:25-05:00" level=info msg="serving HTTP[listen address [::]:26657]"
time="2023-11-26T03:06:25-05:00" level=info msg="listening on[address /ip4/85.239.230.32/tcp/26656/p2p/12D3KooWKFT6CJ5T6rp2ymKgkXS96RdEBipm3KAQWTp2necppyu9]" module=p2p
time="2023-11-26T03:06:25-05:00" level=info msg="listening on[address /ip4/127.0.0.1/tcp/26656/p2p/12D3KooWKFT6CJ5T6rp2ymKgkXS96RdEBipm3KAQWTp2necppyu9]" module=p2p
time="2023-11-26T03:06:25-05:00" level=debug msg="setting up gossiping[]" module=p2p
time="2023-11-26T03:06:25-05:00" level=debug msg="setting up DHT[]" module=p2p
time="2023-11-26T03:06:25-05:00" level=info msg="no seed nodes - only listening for connections[]" module=p2p
time="2023-11-26T03:06:25-05:00" level=debug msg="setting up active peer discovery[]" module=p2p
time="2023-11-26T03:06:25-05:00" level=info msg="starting Celestia Data Availability Layer Client[]" module=celestia
time="2023-11-26T03:06:25-05:00" level=debug msg="settlement Layer Client starting.[]" module=settlement_client
time="2023-11-26T03:06:25-05:00" level=debug msg="trying to connect to peer[peer {12D3KooWKFT6CJ5T6rp2ymKgkXS96RdEBipm3KAQWTp2necppyu9: [/ip4/85.239.230.32/tcp/26656 /ip4/127.0.0.1/tcp/26656]}]" module=p2p
time="2023-11-26T03:06:25-05:00" level=error msg="failed to connect to peer[peer {12D3KooWKFT6CJ5T6rp2ymKgkXS96RdEBipm3KAQWTp2necppyu9: [/ip4/85.239.230.32/tcp/26656 /ip4/127.0.0.1/tcp/26656]} error failed to find peers: failed to find any peer in table]" module=p2p
time="2023-11-26T03:06:25-05:00" level=info msg="started state updates handler loop[]" module=settlement_client
time="2023-11-26T03:06:26-05:00" level=info msg="Starting the block manager[]" module=BlockManager
time="2023-11-26T03:06:26-05:00" level=info msg="Starting in aggregator mode[]" module=BlockManager
time="2023-11-26T03:06:26-05:00" level=debug msg="Getting latest batch from settlement layer[]" module=settlement_client
time="2023-11-26T03:06:26-05:00" level=info msg="Started sync target loop[]" module=BlockManager
time="2023-11-26T03:06:26-05:00" level=debug msg="Getting latest batch from settlement layer[]" module=settlement_client
time="2023-11-26T03:06:26-05:00" level=info msg="Started retrieve loop[]" module=BlockManager
time="2023-11-26T03:06:26-05:00" level=info msg="service start[msg Starting EVMIndexerService service impl EVMIndexerService]" module=evmindex
time="2023-11-26T03:06:26-05:00" level=info msg="Received new syncTarget[syncTarget 70634]" module=BlockManager
time="2023-11-26T03:06:26-05:00" level=info msg="Synced, Starting to produce[current height 70650 syncTarget 70634]" module=BlockManager
time="2023-11-26T03:06:26-05:00" level=info msg="Received new syncTarget[syncTarget 70634]" module=BlockManager
time="2023-11-26T03:06:26-05:00" level=info msg="Synced at height[height 70650]" module=BlockManager
time="2023-11-26T03:06:26-05:00" level=info msg="Using pending block[height 70651]" module=BlockManager
time="2023-11-26T03:06:26-05:00" level=debug msg="Gossiping block[len 527]" module=p2p
time="2023-11-26T03:06:26-05:00" level=debug msg="Applying block[height 70651 source produced]" module=BlockManager
panic: invalid height: 70651; expected: 70664

goroutine 430 [running]:
github.com/cosmos/cosmos-sdk/baseapp.(*BaseApp).BeginBlock(_, {{0xc002e5a360, 0x20, 0x20}, {{0xb, 0x0}, {0xc00646f908, 0x11}, 0x113fb, {0x39e77e2c, ...}, ...}, ...})
        /home/runner/go/pkg/mod/github.com/cosmos/cosmos-sdk@v0.46.13/baseapp/abci.go:143 +0xaa5
github.com/tendermint/tendermint/abci/client.(*localClient).BeginBlockSync(_, {{0xc002e5a360, 0x20, 0x20}, {{0xb, 0x0}, {0xc00646f908, 0x11}, 0x113fb, {0x39e77e2c, ...}, ...}, ...})
        /home/runner/go/pkg/mod/github.com/cometbft/cometbft@v0.34.29/abci/client/local_client.go:280 +0x118
github.com/tendermint/tendermint/proxy.(*appConnConsensus).BeginBlockSync(_, {{0xc002e5a360, 0x20, 0x20}, {{0xb, 0x0}, {0xc00646f908, 0x11}, 0x113fb, {0x39e77e2c, ...}, ...}, ...})
        /home/runner/go/pkg/mod/github.com/cometbft/cometbft@v0.34.29/proxy/app_conn.go:81 +0x55
github.com/dymensionxyz/dymint/state.(*BlockExecutor).Execute(_, {_, _}, {{{0xb, 0x0}, {0xc004dc3f70, 0x7}}, {0xc00131d188, 0x11}, 0x1, ...}, ...)
        /home/runner/go/pkg/mod/github.com/dymensionxyz/dymint@v0.5.1-rc03/state/executor.go:331 +0x375
github.com/dymensionxyz/dymint/block.(*Manager).executeBlock(0xc00438a580, {0x4049df8, 0xc000196010}, 0x0?, 0x0?)
        /home/runner/go/pkg/mod/github.com/dymensionxyz/dymint@v0.5.1-rc03/block/block.go:157 +0x170
github.com/dymensionxyz/dymint/block.(*Manager).applyBlock(0xc00438a580, {0x4049df8, 0xc000196010}, 0xc0040bb500, 0x179af61be6244e2c?, {{0x3047348?, 0x1f840516081a109e?}, 0xe82c318fde693b85?})
        /home/runner/go/pkg/mod/github.com/dymensionxyz/dymint@v0.5.1-rc03/block/block.go:43 +0x3e5
github.com/dymensionxyz/dymint/block.(*Manager).produceBlock(0xc00438a580, {0x4049df8, 0xc000196010}, 0x1)
        /home/runner/go/pkg/mod/github.com/dymensionxyz/dymint@v0.5.1-rc03/block/produce.go:176 +0x856
github.com/dymensionxyz/dymint/block.(*Manager).ProduceBlockLoop(0xc00438a580, {0x4049df8, 0xc000196010})
        /home/runner/go/pkg/mod/github.com/dymensionxyz/dymint@v0.5.1-rc03/block/produce.go:85 +0x3a5
created by github.com/dymensionxyz/dymint/block.(*Manager).Start
        /home/runner/go/pkg/mod/github.com/dymensionxyz/dymint@v0.5.1-rc03/block/manager.go:181 +0x105

Relevant log output

ts=2023-11-24T09:31:17.029637Z lvl=info msg="Failed to relay packet from sequence" src_chain_id=froopyland_100-1 src_channel_id=channel-7373 src_port_id=transfer dst_chain_id=megumii_4962415-1 dst_channel_id=channel-2 dst_port_id=transfer channel_order=ORDER_UNORDERED error="wrong sequence: expected(323) got(320)"
ts=2023-11-24T09:31:17.328603Z lvl=info msg="Failed to relay packet from sequence" src_chain_id=froopyland_100-1 src_channel_id=channel-7373 src_port_id=transfer dst_chain_id=megumii_4962415-1 dst_channel_id=channel-2 dst_port_id=transfer channel_order=ORDER_UNORDERED error="wrong sequence: expected(322) got(320)"
ts=2023-11-24T09:31:17.719934Z lvl=info msg="Failed to relay packet from sequence" src_chain_id=froopyland_100-1 src_channel_id=channel-7373 src_port_id=transfer dst_chain_id=megumii_4962415-1 dst_channel_id=channel-2 dst_port_id=transfer channel_order=ORDER_UNORDERED error="wrong sequence: expected(321) got(320)"
ts=2023-11-24T09:31:18.119351Z lvl=info msg="Failed to relay packet from sequence" src_chain_id=froopyland_100-1 src_channel_id=channel-7373 src_port_id=transfer dst_chain_id=megumii_4962415-1 dst_channel_id=channel-2 dst_port_id=transfer channel_order=ORDER_UNORDERED error="wrong sequence: expected(318) got(314)"

Notes

then i try:

systemctl stop sequencer
sed -i 's/^aggregator *=.*/aggregator = "false"/' $HOME/.roller/rollapp/config/dymint.toml
systemctl restart sequencer

but the blocks just stuck forever, it won't increase

~# roller version

💈 Roller version v0.1.21-beta 💈 Build time: 2023-11-12T13:35:58+0000" 💈 Git commit: 91828b8725e8bd40831083fd6800a3894e059edc

the block height in here is still 70650 https://exp.kessoku.xyz/#/megumii so the next blocks it should be 70651 but the rollapp expected: 70664

rpcs=https://api.dym.kessoku.xyz/
curl -s ${rpcs}/status | jq
curl -s -X GET -H "Content-Type: application/json" ${rpcs}/rest/cosmos/base/tendermint/v1beta1/node_info | jq .default_node_info
curl -X POST --data '{"jsonrpc":"2.0","method":"eth_blockNumber","params":[],"id":1}' -H "Content-Type: application/json" https://evm.dym.kessoku.xyz/ | jq

Output:

{
  "jsonrpc": "2.0",
  "result": {
    "node_info": {
      "protocol_version": {
        "p2p": "8",
        "block": "11",
        "app": "0"
      },
      "id": "0024080112208c26447470bb67f8a41d39c4afdb7cffddc67b2059deea35a461a5b879a43a98",
      "listen_addr": "/ip4/0.0.0.0/tcp/26656",
      "network": "megumii_4962415-1",
      "version": "<version>",
      "channels": "01",
      "moniker": "vmi1098162.contaboserver.net",
      "other": {
        "tx_index": "on",
        "rpc_address": "tcp://127.0.0.1:26657"
      }
    },
    "sync_info": {
      "latest_block_hash": "565651E3C6371ADBA06FDE9AA1F06ADF4FC81913A8064ED367A3C0E54077DE02",
      "latest_app_hash": "E9A1DEC2C64BDC7BC3714F91B5EBB43B792837863AF50C0A3C270973586AE9F6",
      "latest_block_height": "70650",
      "latest_block_time": "2023-11-25T19:58:59.003258179Z",
      "earliest_block_hash": "",
      "earliest_app_hash": "",
      "earliest_block_height": "0",
      "earliest_block_time": "0001-01-01T00:00:00Z",
      "catching_up": false
    },
    "validator_info": {
      "address": "07506EFD712EC0D170940C3218F5E33CC76EDFE8",
      "pub_key": {
        "type": "tendermint/PubKeyEd25519",
        "value": "z3/mgJGo53h08GhPJfivKlK9+6tApWCrxyWE/09k820="
      },
      "voting_power": "1"
    }
  },
  "id": -1
}

  % Total    % Received % Xferd  Average Speed   Time    Time     Time  Current
                                 Dload  Upload   Total   Spent    Left  Speed
100   107  100    44  100    63    147    210 --:--:-- --:--:-- --:--:--   357

{
  "jsonrpc": "2.0",
  "id": 1,
  "result": "0x11407"
}

And now my rollapp still running with aggregator=false

mtsitrin commented 7 months ago

Thx for the report

u have any clue on how it got to the state where 

so the next blocks it should be 70651 but the rollapp expected: 70664

What u tried to do? run multiple nodes with aggregator=true maybe?

Megumiiiiii commented 7 months ago

already fix that by creating new rollapp,, non of dymension team on discord answering me for 3 weeks about this issue