Open brunopgalvao opened 1 year ago
I was able to replicate this on node-template
but not polkadot
.
The bug seems benign (doesn't break any actual functionality), but it would be nice to fix anyway. Confusing that an error is logged right before "TryRuntime_on_runtime_upgrade executed without errors" is logged 😄
Any idea what's going on @kianenigma ?
@cheme I recall I had this issue in the past and you helped shed light into the root cause, consequently helped me move on. Can you provide some info?
I had something similar in the PoV benchmarking, and the joke was that it would not compact an empty proof. So first comparing with the old root worked.
https://github.com/paritytech/substrate/blob/86c6bb9614c437b63f3dbd2afddef52f32af7866/client/db/src/bench.rs#L625-L626
Maybe it is the same here since your migration does not have a Proof size
Possible issue (I did not check) is different state version (https://github.com/paritytech/substrate/blob/471b49b09fd0d2a3057090ab0720f4e39faed5c5/bin/node-template/runtime/src/lib.rs#L110).
With master the wasm and state of node template run on a state version 1. The state version and others versions are read from the wasm heading bytes (state in the past), so if the wasm you use with try-runtime (runtime-try-runtime.wasm
) is using state_version 0 in its source code then things will break.
But empty proof may also be. (state version mismatch should not be the case here since all wasm are build from node-template).
Question from @brunopgalvao on debugging this:
Is there a way that we can debug this? There are only two places in the client that this error occurs:
https://github.com/paritytech/substrate/blob/35d04fb506b00128739b5bead363f0ca651a4ff3/client/service/src/client/client.rs#L698-L703 https://github.com/paritytech/substrate/blob/35d04fb506b00128739b5bead363f0ca651a4ff3/client/service/src/client/client.rs#L892-L895
I tried throwing a dbg! around those lines and re-running the test but nothing appears. I am not sure how this works so that we can get a log from that node:
He's rightfully identified that debugging the node is difficult in these tests. We need an easy way to redirect all node logs to stdout. I'll open an issue and aim to have a PR open early this week.
To check the state versioning use in try_runtime against current chain, I would probably try to debug at : https://github.com/paritytech/substrate/blob/c7d26dcf3d6c19fa7dcbd1f2633e337e5a5cbc40/client/service/src/client/call_executor.rs#L81 (or calling functions).
Edit: used state version is a field of runtime_version. actually could check more https://github.com/paritytech/substrate/blob/c7d26dcf3d6c19fa7dcbd1f2633e337e5a5cbc40/client/executor/src/executor.rs#L606 and https://github.com/paritytech/substrate/blob/c7d26dcf3d6c19fa7dcbd1f2633e337e5a5cbc40/client/executor/src/executor.rs#L516
@brunopgalvao I've opened a PR adding a function allowing you to log node output to the terminal: https://github.com/paritytech/substrate/pull/13991
@liamaharon I have opened a draft PR https://github.com/paritytech/substrate/pull/14074 to test try-runtime's on_runtime_upgrade
which includes your changes from https://github.com/paritytech/substrate/pull/13991
The issue can now be reproduced there and you will get a result similar to:
Running tests/on_runtime_upgrade.rs (target/debug/deps/on_runtime_upgrade-42fa691b866988b5)
running 1 test
2023-05-03 18:38:34 failed to generate compact proof TryRuntime_on_runtime_upgrade: TrieError(InvalidStateRoot(0xc6a78e8f333234ebb08d9061cab09bb65570ef02af51a3992732da064930dede))
thread 'tests::on_runtime_upgrade_works' panicked at 'Error found in stderr', utils/frame/try-runtime/cli/tests/on_runtime_upgrade.rs:67:17
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
test tests::on_runtime_upgrade_works ... FAILED
Additionally, I have noted that if I run the test with substrate
instead of node-template
I get the following error:
Running tests/on_runtime_upgrade.rs (target/debug/deps/on_runtime_upgrade-42fa691b866988b5)
running 1 test
Error: Input("failed to execute TryRuntime_on_runtime_upgrade: Execution aborted due to trap: wasm trap: wasm `unreachable` instruction executed\nWASM backtrace:\nerror while executing at wasm backtrace:\n 0: 0x65f857 - <unknown>!rust_begin_unwind\n 1: 0xd79d - <unknown>!core::panicking::panic_fmt::h2a7f454a5f5da218\n 2: 0xd9a1 - <unknown>!core::panicking::assert_failed_inner::h051eb78a42365260\n 3: 0x52f93b - <unknown>!core::panicking::assert_failed::h8d9c6ec7344e1205\n 4: 0x53fac4 - <unknown>!<(TupleElement0,TupleElement1) as frame_support::traits::hooks::OnRuntimeUpgrade>::try_on_runtime_upgrade::he4215e89d09c788e\n 5: 0x4104df - <unknown>!frame_executive::Executive<System,Block,Context,UnsignedValidator,AllPalletsWithSystem,COnRuntimeUpgrade>::try_runtime_upgrade::h45baed0ddeee0e63\n 6: 0x4f2f2 - <unknown>!<kitchensink_runtime::Runtime as frame_try_runtime::runtime_decl_for_try_runtime::TryRuntimeV1<sp_runtime::generic::block::Block<sp_runtime::generic::header::Header<u32,sp_runtime::traits::BlakeTwo256>,sp_runtime::generic::unchecked_extrinsic::UncheckedExtrinsic<sp_runtime::multiaddress::MultiAddress<<<sp_runtime::MultiSignature as sp_runtime::traits::Verify>::Signer as sp_runtime::traits::IdentifyAccount>::AccountId,u32>,kitchensink_runtime::RuntimeCall,sp_runtime::MultiSignature,(frame_system::extensions::check_non_zero_sender::CheckNonZeroSender<kitchensink_runtime::Runtime>,frame_system::extensions::check_spec_version::CheckSpecVersion<kitchensink_runtime::Runtime>,frame_system::extensions::check_tx_version::CheckTxVersion<kitchensink_runtime::Runtime>,frame_system::extensions::check_genesis::CheckGenesis<kitchensink_runtime::Runtime>,frame_system::extensions::check_mortality::CheckMortality<kitchensink_runtime::Runtime>,frame_system::extensions::check_nonce::CheckNonce<kitchensink_runtime::Runtime>,frame_system::extensions::check_weight::CheckWeight<kitchensink_runtime::Runtime>,pallet_asset_tx_payment::ChargeAssetTxPayment<kitchensink_runtime::Runtime>)>>>>::on_runtime_upgrade::h33051ea4a706593e\n 7: 0x44bdf9 - <unknown>!TryRuntime_on_runtime_upgrade")
thread 'tests::on_runtime_upgrade_works' panicked at 'Error found in stderr', utils/frame/try-runtime/cli/tests/on_runtime_upgrade.rs:68:17
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
test tests::on_runtime_upgrade_works ... FAILED
Running tests/on_runtime_upgrade.rs (target/debug/deps/on_runtime_upgrade-42fa691b866988b5)
running 1 test
Error: Input("failed to execute TryRuntime_on_runtime_upgrade: Execution aborted due to trap: wasm trap: wasm `unreachable` instruction executed\nWASM backtrace:\nerror while executing at wasm backtrace:\n 0: 0x65f857 - <unknown>!rust_begin_unwind\n 1: 0xd79d - <unknown>!core::panicking::panic_fmt::h2a7f454a5f5da218\n 2: 0xd9a1 - <unknown>!core::panicking::assert_failed_inner::h051eb78a42365260\n 3: 0x52f93b - <unknown>!core::panicking::assert_failed::h8d9c6ec7344e1205\n 4: 0x53fac4 - <unknown>!<(TupleElement0,TupleElement1) as frame_support::traits::hooks::OnRuntimeUpgrade>::try_on_runtime_upgrade::he4215e89d09c788e\n 5: 0x4104df - <unknown>!frame_executive::Executive<System,Block,Context,UnsignedValidator,AllPalletsWithSystem,COnRuntimeUpgrade>::try_runtime_upgrade::h45baed0ddeee0e63\n 6: 0x4f2f2 - <unknown>!<kitchensink_runtime::Runtime as frame_try_runtime::runtime_decl_for_try_runtime::TryRuntimeV1<sp_runtime::generic::block::Block<sp_runtime::generic::header::Header<u32,sp_runtime::traits::BlakeTwo256>,sp_runtime::generic::unchecked_extrinsic::UncheckedExtrinsic<sp_runtime::multiaddress::MultiAddress<<<sp_runtime::MultiSignature as sp_runtime::traits::Verify>::Signer as sp_runtime::traits::IdentifyAccount>::AccountId,u32>,kitchensink_runtime::RuntimeCall,sp_runtime::MultiSignature,(frame_system::extensions::check_non_zero_sender::CheckNonZeroSender<kitchensink_runtime::Runtime>,frame_system::extensions::check_spec_version::CheckSpecVersion<kitchensink_runtime::Runtime>,frame_system::extensions::check_tx_version::CheckTxVersion<kitchensink_runtime::Runtime>,frame_system::extensions::check_genesis::CheckGenesis<kitchensink_runtime::Runtime>,frame_system::extensions::check_mortality::CheckMortality<kitchensink_runtime::Runtime>,frame_system::extensions::check_nonce::CheckNonce<kitchensink_runtime::Runtime>,frame_system::extensions::check_weight::CheckWeight<kitchensink_runtime::Runtime>,pallet_asset_tx_payment::ChargeAssetTxPayment<kitchensink_runtime::Runtime>)>>>>::on_runtime_upgrade::h33051ea4a706593e\n 7: 0x44bdf9 - <unknown>!TryRuntime_on_runtime_upgrade")
thread 'tests::on_runtime_upgrade_works' panicked at 'Error found in stderr', utils/frame/try-runtime/cli/tests/on_runtime_upgrade.rs:68:17
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
test tests::on_runtime_upgrade_works ... FAILED
This above error is caused by what looks like are pending migrations in the kitchensink runtime in master
:
https://github.com/paritytech/substrate/blob/9957da3cbb027f9b754c453a4d58a62665e532ef/bin/node/runtime/src/lib.rs#L1897-L1903
Here is the full error:
Running tests/on_runtime_upgrade.rs (target/debug/deps/on_runtime_upgrade-42fa691b866988b5)
running 1 test
test tests::on_runtime_upgrade_works has been running for over 60 seconds
on_runtime_upgrade.stderr: 2023-05-05 17:49:36.306 INFO main remote-ext: replacing ws:// in uri with http://: "http://localhost:45789" (ws is currently unstable for fetching remote storage, for more see https://github.com/paritytech/jsonrpsee/issues/1086)
2023-05-05 17:49:36.311 INFO main remote-ext: since no at is provided, setting it to latest finalized head, 0x1d070f0891c549b699ac6235df236b5d73c5bd8aa644d93d7754cd2396c7f59a
2023-05-05 17:49:36.311 INFO main remote-ext: since no prefix is filtered, the data for all pallets will be downloaded
2023-05-05 17:49:36.313 INFO main remote-ext: scraping key-pairs from remote at block height 0x1d070f0891c549b699ac6235df236b5d73c5bd8aa644d93d7754cd2396c7f59a
2023-05-05 17:49:36.315 INFO main remote-ext: Querying a total of 177 keys from prefix , splitting among 10 threads, 18 keys per thread
2023-05-05 17:49:36.328 INFO main remote-ext: inserting keys progress = 10% [18 / 177]
2023-05-05 17:49:36.331 INFO main remote-ext: inserting keys progress = 20% [36 / 177]
2023-05-05 17:49:36.332 INFO main remote-ext: inserting keys progress = 29% [51 / 177]
2023-05-05 17:49:36.332 INFO main remote-ext: inserting keys progress = 39% [69 / 177]
2023-05-05 17:49:36.333 INFO main remote-ext: inserting keys progress = 49% [87 / 177]
2023-05-05 17:49:36.333 INFO main remote-ext: inserting keys progress = 59% [105 / 177]
2023-05-05 17:49:36.333 INFO main remote-ext: inserting keys progress = 69% [123 / 177]
2023-05-05 17:49:36.334 INFO main remote-ext: inserting keys progress = 80% [141 / 177]
2023-05-05 17:49:36.334 INFO main remote-ext: inserting keys progress = 90% [159 / 177]
2023-05-05 17:49:36.498 INFO main remote-ext: inserting keys progress = 100% [177 / 177]
2023-05-05 17:49:36.498 INFO main remote-ext: adding data for hashed prefix: , took 0s
2023-05-05 17:49:36.498 INFO main remote-ext: adding data for hashed key: 3a636f6465
2023-05-05 17:49:36.672 INFO main remote-ext: adding data for hashed key: 26aa394eea5630e07c48ae0c9558cef7f9cce9c888469bb1a0dceaa129672ef8
2023-05-05 17:49:36.673 INFO main remote-ext: adding data for hashed key: 26aa394eea5630e07c48ae0c9558cef702a5c1b19ab7a04f536c519aca4983ac
2023-05-05 17:49:36.674 INFO main remote-ext: initialized state externalities with storage root 0xa12fe5927b93d592c258dd548b9b500e37d0b168ae4d5692f2017913e9559674 and state_version V1
2023-05-05 17:49:39.970 INFO main runtime::nomination-pools: [1] 🏊♂️ Running migration with current storage version StorageVersion(5) / onchain StorageVersion(5)
2023-05-05 17:49:39.970 INFO main runtime::nomination-pools: [1] 🏊♂️ MigrateToV2 did not executed. This probably should be removed
2023-05-05 17:49:39.970 ERROR main runtime: panicked at 'assertion failed: `(left == right)`
left: `StorageVersion(5)`,
right: `2`', /Users/bruno/src/try-runtime-work/substrate/frame/nomination-pools/src/migration.rs:370:13
Error: Input("failed to execute TryRuntime_on_runtime_upgrade: Execution aborted due to trap: wasm trap: wasm `unreachable` instruction executed\nWASM backtrace:\nerror while executing at wasm backtrace:\n 0: 0x65f857 - <unknown>!rust_begin_unwind\n 1: 0xd79d - <unknown>!core::panicking::panic_fmt::h2a7f454a5f5da218\n 2: 0xd9a1 - <unknown>!core::panicking::assert_failed_inner::h051eb78a42365260\n 3: 0x52f93b - <unknown>!core::panicking::assert_failed::h8d9c6ec7344e1205\n 4: 0x53fac4 - <unknown>!<(TupleElement0,TupleElement1) as frame_support::traits::hooks::OnRuntimeUpgrade>::try_on_runtime_upgrade::he4215e89d09c788e\n 5: 0x4104df - <unknown>!frame_executive::Executive<System,Block,Context,UnsignedValidator,AllPalletsWithSystem,COnRuntimeUpgrade>::try_runtime_upgrade::h45baed0ddeee0e63\n 6: 0x4f2f2 - <unknown>!<kitchensink_runtime::Runtime as frame_try_runtime::runtime_decl_for_try_runtime::TryRuntimeV1<sp_runtime::generic::block::Block<sp_runtime::generic::header::Header<u32,sp_runtime::traits::BlakeTwo256>,sp_runtime::generic::unchecked_extrinsic::UncheckedExtrinsic<sp_runtime::multiaddress::MultiAddress<<<sp_runtime::MultiSignature as sp_runtime::traits::Verify>::Signer as sp_runtime::traits::IdentifyAccount>::AccountId,u32>,kitchensink_runtime::RuntimeCall,sp_runtime::MultiSignature,(frame_system::extensions::check_non_zero_sender::CheckNonZeroSender<kitchensink_runtime::Runtime>,frame_system::extensions::check_spec_version::CheckSpecVersion<kitchensink_runtime::Runtime>,frame_system::extensions::check_tx_version::CheckTxVersion<kitchensink_runtime::Runtime>,frame_system::extensions::check_genesis::CheckGenesis<kitchensink_runtime::Runtime>,frame_system::extensions::check_mortality::CheckMortality<kitchensink_runtime::Runtime>,frame_system::extensions::check_nonce::CheckNonce<kitchensink_runtime::Runtime>,frame_system::extensions::check_weight::CheckWeight<kitchensink_runtime::Runtime>,pallet_asset_tx_payment::ChargeAssetTxPayment<kitchensink_runtime::Runtime>)>>>>::on_runtime_upgrade::h33051ea4a706593e\n 7: 0x44bdf9 - <unknown>!TryRuntime_on_runtime_upgrade")
thread 'tests::on_runtime_upgrade_works' panicked at 'Error found in stderr', utils/frame/try-runtime/cli/tests/on_runtime_upgrade.rs:64:17
note: run with `RUST_BACKTRACE=1` environment variable to display a backtrace
test tests::on_runtime_upgrade_works ... FAILED
Commenting out the migration code fixes the above issue: https://github.com/paritytech/substrate/blob/9957da3cbb027f9b754c453a4d58a62665e532ef/bin/node/runtime/src/lib.rs#L1897-L1903
However, the InvalidStateRoot
error now occurs for both substrate
and node-template
.
The error is actually coming from trie-db
:
https://github.com/paritytech/substrate/blob/9957da3cbb027f9b754c453a4d58a62665e532ef/test-utils/runtime/Cargo.toml#L48
Defined here:
pub enum TrieError<T, E> {
/// Attempted to create a trie with a state root not in the DB.
InvalidStateRoot(T),
I will continue digging but I may need some help @liamaharon
Have you narrowed down which of those 3 migrations is throwing?
Once I'd dialed in on the problematic migration, I'd try to find selectively add/remove logic in the migration and how the changes impacts the error. Hopefully through some experimentation you'd be able find which logic, or better which line in the migration causes the error.
The issue is with this migration: https://github.com/paritytech/substrate/blob/49154cc7b30d2519f03c020bf884b310f8aee4c6/bin/node/runtime/src/lib.rs#L1900 It is a migration to storage_version 2 however the pallet is already at storage_version 5: https://github.com/paritytech/substrate/blob/49154cc7b30d2519f03c020bf884b310f8aee4c6/frame/nomination-pools/src/lib.rs#L1498-L1499
This post_upgrade assert fails: https://github.com/paritytech/substrate/blob/49154cc7b30d2519f03c020bf884b310f8aee4c6/frame/nomination-pools/src/migration.rs#L367-L370
Omitting this MigrateToV2
fixes the wasm trap
issue as well as the InvalidStateRoot
issue.
Is there a reason this migration is still around in the kitchensink runtime? Can I remove it?
Logically, if the actual migration does not run: https://github.com/paritytech/substrate/blob/49154cc7b30d2519f03c020bf884b310f8aee4c6/frame/nomination-pools/src/migration.rs#L346-L347 then there should either be a check in the post_upgrade hook for that and do nothing or the post_upgrade hook should not run at all.
Ah, I think related to https://github.com/paritytech/substrate/issues/13107
I don't think we can proceed with this until it's implemented. I think I'll prioritise it once I'm done with my current large work effort, marking this issue blocked until then.
@brunopgalvao can close this issue by gating those upgrades with VersionedRuntimeUpgrade
, or just remove the old migrations.
In order for the error to go away, I would need to remove all old migrations so everything in: https://github.com/paritytech/substrate/blob/19971bd3eafa6394d918030f4142f85ea54404c0/bin/node/runtime/src/lib.rs#L2000-L2004
It would be nice to leave one in there as an example of a VersionedRuntimeUpgrade
.
Let me see if we already have a VersionedRuntimeUpgrade
somewhere that we can replace here.
You can just update these migrations to use VersionedRuntimeUpgrade
where appropriate.
Is there an existing issue?
Experiencing problems? Have you tried our Stack Exchange first?
Description of bug
When running try-runtime on-runtime-upgrade:
I get the following error:
Steps to reproduce
Clone the repo:
Run your existing node without the runtime changes:
Compile your node with try-runtime enabled:
Copy the runtime's Wasm that has your changes:
Run on-runtime-upgrade:
You will get similar output to this ( notice the
ERROR
towards the end ):