Chain height not updated?

[Tbaut]

Hello there, here is my next error. My setup is still the same, still forking rococo at the same block. #7,437,969 and pointing my indexer at it. Then I make a transaction, Chopsticks creates a block, and the indexer fires some rpc at it. Then it fails because it seems that the chain head didn't get updated in Chopsticks.

Here's the log of Chopsticks

[20:15:03.569] INFO (xcm/117471): Rococo RPC listening on port 8000
[20:24:02.410] INFO (block-builder/117471): Try building block #7,437,970
    number: 7437970
    extrinsicsCount: 1
    umpCount: 0
[20:24:02.789] INFO (117471): RuntimeLogs:
elems: [0x767aabdd9605b4ad8e09c075d2112bf545d63fc83c3e5959f795ceb5ff47e160, 0x72480007222f3c3586d4b415f28907804a5700c607349878963824ba45fcf8a3]
peaks_before: [4194302, 6291453, 6815740, 7077883, 7208954, 7241721, 7258104, 7266295, 7267318, 7267829, 7267860, 7267867, 7267868]
peaks_after: [4194302, 6291453, 6815740, 7077883, 7208954, 7241721, 7258104, 7266295, 7267318, 7267829, 7267860, 7267867, 7267870]
offchain db set: pos 7267869 parent_hash 0xfd5bbc6e2cd2221a2f608b51c63ca5e1f124a92980f7ab6eafd581c49d2b6c27 key [12, 109, 109, 114, 29, 230, 110, 0, 0, 0, 0, 0, 253, 91, 188, 110, 44, 210, 34, 26, 47, 96, 139, 81, 198, 60, 165, 225, 241, 36, 169, 41, 128, 247, 171, 110, 175, 213, 129, 196, 157, 43, 108, 39]
offchain db set: pos 7267870 parent_hash 0xfd5bbc6e2cd2221a2f608b51c63ca5e1f124a92980f7ab6eafd581c49d2b6c27 key [12, 109, 109, 114, 30, 230, 110, 0, 0, 0, 0, 0, 253, 91, 188, 110, 44, 210, 34, 26, 47, 96, 139, 81, 198, 60, 165, 225, 241, 36, 169, 41, 128, 247, 171, 110, 175, 213, 129, 196, 157, 43, 108, 39]

[20:24:03.396] INFO (117471): RuntimeLogs:
[enter_inner] parent_header=0xfd5bbc6e2cd2221a2f608b51c63ca5e1f124a92980f7ab6eafd581c49d2b6c27 bitfields.len(): 0, backed_candidates.len(): 0, disputes.len(): 0

[20:24:03.979] INFO (117471): RuntimeLogs:
[7437970] 0 extrinsics, length: 544 (normal 0%, op: 0%, mandatory 0%) / normal weight:Weight(ref_time: 427633639, proof_size: 6811) (0%) op weight Weight(ref_time: 0, proof_size: 0) (0%) / mandatory weight Weight(ref_time: 22012140070, proof_size: 53095) (0%)

[20:24:03.982] INFO (block-builder/117471): Block built
    number: 7437970
    hash: "0xe786b54466eb089a6c96f7d6849ecb5d2fc21ff03bd9e301887d5bef72d0b200"
    extrinsics: [
      "0x11038400d43593c715fdd31c61141abd…9b4c3d17001e04000000000000000000"
    ]
    pendingExtrinsicsCount: 0
    ump: {}

Subsquid rpcs and error at the end:

20:24:04 DEBUG sqd:processor:rpc rpc call
                                 rpcUrl: ws://localhost:8000
                                 rpcId: 466
                                 rpcMethod: chain_getHead
20:24:04 DEBUG sqd:processor:rpc rpc send
                                 rpcUrl: ws://localhost:8000
                                 rpcId: 466
20:24:04 DEBUG sqd:processor:rpc rpc response
                                 rpcUrl: ws://localhost:8000
                                 rpcId: 466
                                 rpcMethod: chain_getHead
                                 rpcResponse: {"id":466,"jsonrpc":"2.0","result":"0xe786b54466eb089a6c96f7d6849ecb5d2fc21ff03bd9e301887d5bef72d0b200"}
20:24:04 DEBUG sqd:processor:rpc rpc call
                                 rpcUrl: ws://localhost:8000
                                 rpcId: 467
                                 rpcMethod: chain_getFinalizedHead
20:24:04 DEBUG sqd:processor:rpc rpc send
                                 rpcUrl: ws://localhost:8000
                                 rpcId: 467
20:24:04 DEBUG sqd:processor:rpc rpc response
                                 rpcUrl: ws://localhost:8000
                                 rpcId: 467
                                 rpcMethod: chain_getFinalizedHead
                                 rpcResponse: {"id":467,"jsonrpc":"2.0","result":"0xe786b54466eb089a6c96f7d6849ecb5d2fc21ff03bd9e301887d5bef72d0b200"}
20:24:04 DEBUG sqd:processor:rpc rpc call
                                 rpcUrl: ws://localhost:8000
                                 rpcId: 468
                                 rpcMethod: chain_getBlock
                                 rpcParams: ["0xe786b54466eb089a6c96f7d6849ecb5d2fc21ff03bd9e301887d5bef72d0b200"]
20:24:04 DEBUG sqd:processor:rpc rpc send
                                 rpcUrl: ws://localhost:8000
                                 rpcId: 468
20:24:04 DEBUG sqd:processor:rpc rpc response
                                 rpcUrl: ws://localhost:8000
                                 rpcId: 468
                                 rpcMethod: chain_getBlock
                                 rpcParams: ["0xe786b54466eb089a6c96f7d6849ecb5d2fc21ff03bd9e301887d5bef72d0b200"]
                                 rpcResponse: {"id":468,"jsonrpc":"2.0","result":{"block":{"header":{"parentHash":"0xfd5bbc6e2cd2221a2f608b51c63ca5e1f124a92980f7ab6eafd581c49d2b6c27","number":7437970,"stateRoot":"0x0000000000000000000000000000000000000000000000000000000000000000","extrinsicsRoot":"0x0000000000000000000000000000000000000000000000000000000000000000","digest":{"logs":[{"preRuntime":["0x42414245","0x031100000056cfdb1000000000caa97c339ef3ceb7c69b399817dcc1acc6f85ce06b9959ddb2d51c616d3380587634b6d7fb1ed20987d0ceda1cd6575de4fbdd332471a1e684cef511ef9f190d66a5b1b80c4ed7792fe12fa603f1eeb269c69feda7c1f3566972f4741b2d780e"]},{"consensus":["0x42454546","0x0388bbd6b4254ca820fe56941a2fd51d585cebd88ba18d9a48fed354d689eb255d"]},{"seal":["0x42414245","0xa6e8a0542c7cd3afa8087536bae0c87300cfc467c27c49cc262024cfaf93c40bbf6466cac6f1c1dd03bf69baafb4e470f6f8ea8c75686ab710a4b4f5d75cc489"]}]}},"extrinsics":["0x280402000ba16fcb1f8b01","0x3505043[ redacting this part as it is irrelevant ] 0000000000"]},"justifications":null}}
20:24:04 DEBUG sqd:processor:rpc rpc response
                                 rpcUrl: ws://localhost:8000
                                 rpcId: 469
                                 rpcMethod: chain_getBlock
                                 rpcParams: ["0xfd5bbc6e2cd2221a2f608b51c63ca5e1f124a92980f7ab6eafd581c49d2b6c27"]
                                 rpcResponse: {"id":469,"jsonrpc":"2.0","result":{"block":{"header":{"parentHash":"0xf3d14420002265fbc4e0884ab0ebde58bc76e7b26a7e28c7a2bd4603c060e5e3","number":7437969,"stateRoot":"0xb4f3461975cc0c145a6ccbfd904e9a431a147dc50cec68c709a50da6dc1bb239","extrinsicsRoot":"0x958ab035b01d8762759a42f7b8a012e5483f5d011d30c5668f11edf7156751db","digest":{"logs":[{"preRuntime":["0x42414245","0x031100000055cfdb1000000000caa97c339ef3ceb7c69b399817dcc1acc6f85ce06b9959ddb2d51c616d3380587634b6d7fb1ed20987d0ceda1cd6575de4fbdd332471a1e684cef511ef9f190d66a5b1b80c4ed7792fe12fa603f1eeb269c69feda7c1f3566972f4741b2d780e"]},{"consensus":["0x42454546","0x0388bbd6b4254ca820fe56941a2fd51d585cebd88ba18d9a48fed354d689eb255d"]},{"seal":["0x42414245","0xa6e8a0542c7cd3afa8087536bae0c87300cfc467c27c49cc262024cfaf93c40bbf6466cac6f1c1dd03bf69baafb4e470f6f8ea8c75686ab710a4b4f5d75cc489"]}]}},"extrinsics":["0x280402000b3158cb1f8b01","0x929901000436009901c01410000004200100 [ redacting this part as it is irrelevant ] 63769483f2f40c37d0829ff84a96869d565ac0c0e8519909ac9977c5c2aa76ee5058a420bd730f4519152df089"]},"justifications":null}}
20:24:04 FATAL sqd:processor AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:

                               (0, assert_1.default)((0, util_internal_1.last)(chain).height === head.height)

                                 at HotProcessor.moveToBlock (/home/thib/Github/ChainSafe/multix/squid/node_modules/@subsquid/util-internal-ingest-tools/lib/hot.js:82:30)
                                 at process.processTicksAndRejections (node:internal/process/task_queues:95:5)
                                 at async RpcDataSource.processHotBlocks (/home/thib/Github/ChainSafe/multix/squid/node_modules/@subsquid/substrate-data-raw/lib/datasource.js:124:13)
                                 generatedMessage: true
                                 code: ERR_ASSERTION
                                 actual: false
                                 expected: true
                                 operator: ==

[xlc]

This is the failed assertion https://github.com/subsquid/squid-sdk/blob/85c33df3231d0feb985d5cb8c568c4129cb5d470/util/util-internal-ingest-tools/src/hot.ts#L106

I don't really see anything wrong with Chopsticks. Will ask subsquid team for help.

[Tbaut]

Did you manage to get some more insight into this?

[xlc]

Haven't got an answer from subsquid team. Will followup.

[eldargab]

Hey, @Tbaut , could you post full reproduction instructions here?

[Tbaut]

Sure, it's not straight forward unfortunately since it involves many systems. Here is something that's as simple as it gets:

Chopsticks

• Chopsticks is ran with the following chopsticks-config.yml

endpoint: wss://rococo-rpc.polkadot.io
mock-signature-host: true
block: 7437969
db: ./db.sqlite

import-storage:
  System:
    Account:
      - - - 5GrwvaEF5zXb26Fz9rcQpDWS57CtERHpNehXCPcNoHGKutQY
        - providers: 1
          data:
            free: '10000000000000000000'
  Council:
    Members: [5GrwvaEF5zXb26Fz9rcQpDWS57CtERHpNehXCPcNoHGKutQY]
  PhragmenElection:
    Members:
      - who: 5GrwvaEF5zXb26Fz9rcQpDWS57CtERHpNehXCPcNoHGKutQY
        stake: 1000000000000
        deposit: 1000000000000
  TechnicalCommittee:
    Members: [5GrwvaEF5zXb26Fz9rcQpDWS57CtERHpNehXCPcNoHGKutQY]
  TechnicalMembership:
    Members: [5GrwvaEF5zXb26Fz9rcQpDWS57CtERHpNehXCPcNoHGKutQY]

And the command

npx @acala-network/chopsticks@latest --config ./chopsticks-config.yml

Subsquid

Install the squid cli to be able to use sqd

npm i -g @subsquid/cli@latest

Clone the example repo that indexes Rococo transfers, I changed minor things to point it at Chopsticks, and run it (it's with npm as yarn isn't supported by subsquid)

git clone https://github.com/Tbaut/squid-substrate-template.git;
cd squid-substrate-template;
npm ci;
# start target Postgres database and detach
sqd up;
# build the project and start the processor
sqd process;

This will start an indexer pointed at chopsticks and start at the same block height, 7437969, (see the .env).
It should be firing a bunch of rpcMethod: chain_getHead at chopsticks.

Make a Tx

• Go on pjs/apps, pointed at ws://localhost:8000: https://polkadot.js.org/apps/?rpc=ws%3A%2F%2Flocalhost%3A8000#/explorer
• Make a transfer to create a new block, e.g with Alice that has funds.
• Get the fatal error on the processor

9:30:58 FATAL sqd:processor AssertionError [ERR_ASSERTION]: The expression evaluated to a falsy value:

                               (0, assert_1.default)((0, util_internal_1.last)(chain).height === head.height)

[eldargab]

Here is the reason

15:10:11 DEBUG sqd:processor:rpc rpc response
                                 rpcUrl: ws://localhost:8000
                                 rpcId: 365
                                 rpcMethod: chain_getBlock
                                 rpcParams: ["0xe786b54466eb089a6c96f7d6849ecb5d2fc21ff03bd9e301887d5bef72d0b200"]
                                 rpcResponse: {"id":365,"jsonrpc":"2.0","result":{"block":{"header":{"parentHash":"0xfd5bbc6e2cd2221a2f608b51c63ca5e1f124a92980f7ab6eafd581c49d2b6c27","number":7437970, ....

chain_getBlock returns block.header.number equal to 7437970, but standard RPC endpoints return hex encoded number.

As a result block number becomes misparsed to a wrong value.

[Tbaut]

Nice one, it's now fully working 🎉 thank you so much for your work.