block already unpinned panic in runtime_service

[tomaka]

I am just getting different crashes every time

$ yarn start
yarn run v1.22.17
$ node prepare.mjs --debug && rimraf ./dist && npm run buildModules && node demo/demo.mjs
/Users/xiliangchen/.rustup/toolchains/1.61.0-aarch64-apple-darwin/bin/cargo
info: component 'rust-std' for target 'wasm32-wasi' is up to date
    Finished dev [optimized + debuginfo] target(s) in 0.22s

> @substrate/smoldot-light@0.6.29 buildModules
> tsc -p tsconfig-mjs.json && tsc -p tsconfig-cjs.json && bash fix-package-type.sh

JSON-RPC server now listening on port 9944
Please visit one of:
- westend2: https://polkadot.js.org/apps/?rpc=ws%3A%2F%2F127.0.0.1%3A9944%2Fwestend2
- westmint: https://polkadot.js.org/apps/?rpc=ws%3A%2F%2F127.0.0.1%3A9944%2Fwestmint
- polkadot: https://polkadot.js.org/apps/?rpc=ws%3A%2F%2F127.0.0.1%3A9944%2Fpolkadot
- acala: https://polkadot.js.org/apps/?rpc=ws%3A%2F%2F127.0.0.1%3A9944%2Facala
- ksmcc3: https://polkadot.js.org/apps/?rpc=ws%3A%2F%2F127.0.0.1%3A9944%2Fksmcc3
- statemine: https://polkadot.js.org/apps/?rpc=ws%3A%2F%2F127.0.0.1%3A9944%2Fstatemine
- karura: https://polkadot.js.org/apps/?rpc=ws%3A%2F%2F127.0.0.1%3A9944%2Fkarura
- rococo_v2_2: https://polkadot.js.org/apps/?rpc=ws%3A%2F%2F127.0.0.1%3A9944%2Frococo_v2_2
- adz_rococo: https://polkadot.js.org/apps/?rpc=ws%3A%2F%2F127.0.0.1%3A9944%2Fadz_rococo
- canvas-rococo: https://polkadot.js.org/apps/?rpc=ws%3A%2F%2F127.0.0.1%3A9944%2Fcanvas-rococo

[20:41:10.460] [smoldot] Smoldot v0.6.29
[20:41:10.537] [smoldot] Chain initialization complete for westend2. Name: "Westend". Genesis hash: 0xe143…423e. State root hash: 0x7e92439a94f79671f9cade9dff96a094519b9001a7432244d46ab644bb6f746f. Network identity: 12D3KooWRse9u6Z9ukP4C92YCCH2gXziNm8ThRch2owaaFh9H6D1. Chain specification or database starting at: 0xf55e…a836 (#11771600)
[20:41:10.537] [smoldot] Chain westend2 has bad blocks in its chain specification. Bad blocks are not implemented in the light client.
[20:41:16.350] [sync-service-westend2] GrandPa warp sync finished to #12131976 (0x8130…7da6)
[20:41:16.977] [runtime-westend2] Finalized block runtime ready. Spec version: 9271. Size of `:code`: 1.1 MiB.
[20:42:10.537] [smoldot] Smoldot v0.6.29. Current memory usage: 130 MiB. Average download: 45.7 kiB/s. Average upload: 325 B/s.
(demo) New JSON-RPC client connected: ::ffff:127.0.0.1.
[20:42:13.478] [smoldot] Chain initialization complete for ksmcc3. Name: "Kusama". Genesis hash: 0xb0a8…dafe. State root hash: 0xb0006203c3a6e6bd2c6a17b1d4ae8ca49a31da0f4579da950b127774b44aef6b. Network identity: 12D3KooWKHpfkDsB5eg6Nc3gyHEx8yNfjvUnePZwdiz2S4ZXThSt. Chain specification or database starting at: 0xb6ca…fe2a (#13626505)
[20:42:13.478] [smoldot] Chain ksmcc3 has bad blocks in its chain specification. Bad blocks are not implemented in the light client.
[20:42:28.654] [sync-service-ksmcc3] GrandPa warp sync still in progress and taking a long time
[20:42:44.099] [sync-service-ksmcc3] GrandPa warp sync finished to #13971869 (0x238b…886b)
[20:42:44.813] [runtime-ksmcc3] Finalized block runtime ready. Spec version: 9260. Size of `:code`: 1.3 MiB.
[20:42:44.820] [smoldot] Parachain initialization complete for karura. Name: "Karura". Genesis hash: 0xbaf5…126b. State root hash: 0x388e346937d485c71c53c80ca8e1aca55f3857a55efe3d3baf86371b14067318. Network identity: 12D3KooWLrmgJpddU5TGyFw2kdCycp57dHCx3uRHsdz34fZNDFib. Relay chain: ksmcc3 (id: 2000)
[20:42:58.292] [runtime-karura] Successfully compiled runtime. Spec version: 2091. Size of `:code`: 1.4 MiB.
[20:43:10.538] [smoldot] Smoldot v0.6.29. Current memory usage: 451 MiB. Average download: 450 kiB/s. Average upload: 1.3 kiB/s.
[20:44:10.538] [smoldot] Smoldot v0.6.29. Current memory usage: 451 MiB. Average download: 55.5 kiB/s. Average upload: 739 B/s.
[20:45:10.538] [smoldot] Smoldot v0.6.29. Current memory usage: 451 MiB. Average download: 49.9 kiB/s. Average upload: 955 B/s.
[20:46:10.539] [smoldot] Smoldot v0.6.29. Current memory usage: 451 MiB. Average download: 51.6 kiB/s. Average upload: 1.0 kiB/s.
(demo) JSON-RPC client ::ffff:127.0.0.1 disconnected.
[20:47:05.277] [smoldot] Shutting down chain ksmcc3
[20:47:05.278] [smoldot] Shutting down chain karura
(demo) New JSON-RPC client connected: ::ffff:127.0.0.1.
[20:47:06.421] [smoldot] Chain initialization complete for ksmcc3. Name: "Kusama". Genesis hash: 0xb0a8…dafe. State root hash: 0xb0006203c3a6e6bd2c6a17b1d4ae8ca49a31da0f4579da950b127774b44aef6b. Network identity: 12D3KooWGPeM5swsXkXw8rNmXsoWHELnRcKAGjAzaD2V5UesFiV5. Chain specification or database starting at: 0xb6ca…fe2a (#13626505)
[20:47:06.421] [smoldot] Chain ksmcc3 has bad blocks in its chain specification. Bad blocks are not implemented in the light client.
[20:47:10.716] [smoldot] Smoldot v0.6.29. Current memory usage: 164 MiB. Average download: 210 kiB/s. Average upload: 1.1 kiB/s.
[20:47:21.901] [sync-service-ksmcc3] GrandPa warp sync still in progress and taking a long time
[20:47:37.234] [sync-service-ksmcc3] GrandPa warp sync still in progress and taking a long time
[20:47:43.244] [sync-service-ksmcc3] GrandPa warp sync finished to #13971919 (0xbc41…c21d)
[20:47:43.540] [runtime-ksmcc3] Finalized block runtime ready. Spec version: 9260. Size of `:code`: 1.3 MiB.
[20:47:43.550] [smoldot] Parachain initialization complete for karura. Name: "Karura". Genesis hash: 0xbaf5…126b. State root hash: 0x388e346937d485c71c53c80ca8e1aca55f3857a55efe3d3baf86371b14067318. Network identity: 12D3KooWLBzSXcpUeXWAtUQvhCGP65hyJwtDZifReX1hmP2Jttcx. Relay chain: ksmcc3 (id: 2000)
[20:47:55.663] [runtime-karura] Successfully compiled runtime. Spec version: 2091. Size of `:code`: 1.4 MiB.
[20:48:10.718] [smoldot] Smoldot v0.6.29. Current memory usage: 451 MiB. Average download: 314 kiB/s. Average upload: 1.1 kiB/s.
[20:49:10.719] [smoldot] Smoldot v0.6.29. Current memory usage: 451 MiB. Average download: 53.2 kiB/s. Average upload: 805 B/s.
(demo) New JSON-RPC client connected: ::ffff:127.0.0.1.
[20:49:21.960] [smoldot] Chain initialization complete for polkadot. Name: "Polkadot". Genesis hash: 0x91b1…90c3. State root hash: 0x29d0d972cd27cbc511e9589fcb7a4506d5eb6a9e8df205f00472e5ab354a4e17. Network identity: 12D3KooWEHfmeifNNYNeU1QFDsVBQKaU4QgygUcL4joPQyX3ijkd. Chain specification or database starting at: 0xd359…ac08 (#9768333)
[20:49:36.961] [sync-service-polkadot] GrandPa warp sync still in progress and taking a long time
[20:49:37.675] [sync-service-polkadot] GrandPa warp sync finished to #11570910 (0x45de…5fae)
[20:49:37.928] [runtime-polkadot] Finalized block runtime ready. Spec version: 9260. Size of `:code`: 1.2 MiB.
[20:50:10.723] [smoldot] Smoldot v0.6.29. Current memory usage: 593 MiB. Average download: 255 kiB/s. Average upload: 2.1 kiB/s.
[20:51:10.724] [smoldot] Smoldot v0.6.29. Current memory usage: 593 MiB. Average download: 81.2 kiB/s. Average upload: 2.7 kiB/s.
[20:52:10.724] [smoldot] Smoldot v0.6.29. Current memory usage: 593 MiB. Average download: 83.2 kiB/s. Average upload: 2.7 kiB/s.
Smoldot has panicked while executing task `json-rpc-karura`. This is a bug in smoldot. Please open an issue at https://github.com/paritytech/smoldot/issues with the following message:
panicked at 'block already unpinned', /Users/xiliangchen/projects/smoldot/bin/light-base/src/runtime_service.rs:383:29
(demo) Error during JSON-RPC request: Error: panicked at 'block already unpinned', /Users/xiliangchen/projects/smoldot/bin/light-base/src/runtime_service.rs:383:29
error Command failed with exit code 1.
info Visit https://yarnpkg.com/en/docs/cli/run for documentation about this command.

Originally posted by @xlc in #2593 (comment)

[tomaka]

#2631 doesn't solve the issue but changes the panic message to include the service that has a bug in it, so if it happens again it would be nice to update this issue.

[tomaka]

Just personally encountered this:

panicked at 'block already unpinned for subscribe-best subscription', /home/tomaka/Projets/smoldot/bin/light-base/src/runtime_service.rs:394:25

It's unclear whether it's the same panic as the OP, but I'm going to go with the assumption that yes.

This happened while I connected to Westmint.
Presumably this could maybe be reproduced by connecting to a chain.
EDIT: can somewhat be reproduced by starting the demo, then only opening a browser tab to Westmint

[tomaka]

The subscription code is definitely behaving as intended. There's probably a bug in the runtime service unfortunately.

[tomaka]

This newly-added debug_assertion panics:

smoldot/bin/light-base/src/runtime_service.rs

Line 317 in c537c40

debug_assert!(_prev_value.is_none());

[tomaka]

Problem comes from here: https://github.com/paritytech/substrate-lite/blob/ca2bc4a01e1ef52a81595a80c7f064c2ebaf0500/bin/light-base/src/sync_service/parachain.rs#L571-L574
We report blocks in a completely incorrect way.