search

Joystream / joystream

Joystream Monorepo
http://www.joystream.org
GNU General Public License v3.0
1.42k stars 115 forks source link

Hydra Indexer unstable during runtime upgrade #4741

Closed mnaamani closed 1 year ago

mnaamani commented 1 year ago

Problem

When running the runtime upgrade intergration tests, the runtime upgrade works successfully but the test is failing at the step waiting for status of runtime upgrade proposal execution status to go from "ProposalStatusGracing" to "ProposalStatusExecuted" because the QN seems to not be properly processing the runtime upgrade block with the "ProposalExecuted" event in it. And processor altogether stops processing any events.

The first few lines of logs after the runtime upgrade (for the indexer) the RPC-CORE error which comes from polkadot-js/api immediately after upgrade.

API/INIT: Runtime version updated to spec=3000, tx=1
RPC-CORE: getStorage(key: StorageKey, at?: BlockHash): StorageData:: Unable to decode storage system.events:: createType(Vec<FrameSystemEventRecord>):: Vec<FrameSystemEventRecord>:: Decoded input doesn't match input, received 0x0400000000000000d08ae10400000000020000 (19 bytes), created 0x0400000000000000d08ae10400000000 (16 bytes)
After which point there are many getStorage errors.

If we allow indexer to keep running, eventually:

RPC-CORE: getStorage(key: StorageKey, at?: BlockHash): StorageData:: Unable to decode storage system.events:: createType(SpRuntimeDigestDigestItem):: {"_enum":{"Other":"Bytes","__Unused1":"Null","__Unused2":"Null","__Unused3":"Null","Consensus":"([u8;4],Bytes)","Seal":"([u8;4],Bytes)","PreRuntime":"([u8;4],Bytes)","__Unused7":"Null","RuntimeEnvironmentUpdated":"Null"}}:: Decoded input doesn't match input, received 0x0400000000000000d08ae10400000000020000 (19 bytes), created 0x040000000000 (6 bytes)
index-builder:pooled-executor Error during execution
index-builder:indexer Index builder has been stopped
index-builder:redis-factory Closing Redis connections
index-builder:indexer Index builder has been stopped
error Command failed with exit code 255.

Recovery

Although the indexer is observed to make progress fetching additional blocks, the processor behaves correctly, ie it doesn't make progress. That is a good thing (we wouldn't get inconsistent state)

When indexer restarts, it continues processing from a couple of blocks before the runtime upgrade block, logging a few index-builder:indexer Block N has already been indexed lines, until it finally makes progress. The indexer can also be restarted manually (without resetting db) and it also "recovers" in the same way.

Some questions:

Relevant runtime type changes that are at the root cause of this behavior?

Some background about what type changes in the substrate runtime are possibly causing this.

/// Event for the System pallet.
#[pallet::event]
pub enum Event<T: Config> {
  /// An extrinsic completed successfully.
  ExtrinsicSuccess { dispatch_info: DispatchInfo },
  /// An extrinsic failed.
  ExtrinsicFailed { dispatch_error: DispatchError, dispatch_info: DispatchInfo },
  /// `:code` was updated.
  CodeUpdated,
  /// A new account was created.
  NewAccount { account: T::AccountId },
  /// An account was reaped.
  KilledAccount { account: T::AccountId },
  /// On on-chain remark happened.
  Remarked { sender: T::AccountId, hash: T::Hash },
}
pub struct DispatchInfo {
  /// Weight of this transaction.
  pub weight: Weight,
  /// Class of this transaction.
  pub class: DispatchClass,
  /// Does this transaction pay fees.
  pub pays_fee: Pays,
}
/// Weight in new runtime
pub struct Weight {
  #[codec(compact)]
  /// The weight of computational time used based on some reference hardware.
  ref_time: u64,
  #[codec(compact)]
  /// The weight of storage space used by proof of validity.
  proof_size: u64,
}
/// Weight in ephesus runtime (old runtime)
/// Numeric range of a transaction weight.
pub type Weight = u64;

Note that each block has a timestamp.set extrinsic added by the block producer. Therefore each block produced will have a system.extrinsicSuccess Event, and therefore a DispatchInfo type.

Before Upgrade Screenshot 2023-04-19 at 12 13 20 PM

After Upgrade Screenshot 2023-04-19 at 12 17 54 PM

Another changes in new substrate but not likely relevant, adding it just in-case:

I think it just affects the storage_info annotation and how benchmarks handle counting reading/writing to the storage key. The change in new substrate is that this is now an unbounded (git diff):

<<<
        /// Events have a large in-memory size. Box the events to not go out-of-memory
        /// just in case someone still reads them from within the runtime.
        #[pallet::storage]
+       #[pallet::whitelist_storage]
+       #[pallet::unbounded]
        pub(super) type Events<T: Config> =
-               StorageValue<_, Vec<Box<EventRecord<T::Event, T::Hash>>>, ValueQuery>;
+               StorageValue<_, Vec<Box<EventRecord<T::RuntimeEvent, T::Hash>>>, ValueQuery>;
<<<

Indexer Logs

Runtime upgrade at block 607

2023-04-14T22:05:43.608Z index-builder:indexer Done block #603
2023-04-14T22:05:43.609Z index-builder:indexer Saved 11 events
2023-04-14T22:05:43.611Z index-builder:redis-relayer Relaying to redis: hydra:indexer:complete:block {"events":[{"id":"0000000597-000000-92ba5","name":"balances.Deposit","extrinsic":"none"},{"id":"0000000597-000001-92ba5","name":"council.RewardPayment","extrinsic":"none"},{"id":"0000000597-000002-92ba5","name":"balances.Deposit","extrinsic":"none"},{"id":"0000000597-000003-92ba5","name":"council.RewardPayment","extrinsic":"none"},{"id":"0000000597-000004-92ba5","name":"balances.Deposit","extrinsic":"none"},{"id":"0000000597-000005-92ba5","name":"council.RewardPayment","extrinsic":"none"},{"id":"0000000597-000006-92ba5","name":"balances.Deposit","extrinsic":"none"},{"id":"0000000597-000007-92ba5","name":"council.RewardPayment","extrinsic":"none"},{"id":"0000000597-000008-92ba5","name":"balances.Deposit","extrinsic":"none"},{"id":"0000000597-000009-92ba5","name":"council.RewardPayment","extrinsic":"none"},{"id":"0000000597-000010-92ba5","name":"system.ExtrinsicSuccess","extrinsic":"timestamp.set"}],"extrinsics":[{"id":"0000000597-000000-92ba5","name":"timestamp.set"}],"hash":"0x92ba5a9abcbb93af2e7a086b02972812eafbb9ade6fe4087605e3dc999cb1bec","parentHash":"0x17486fb3d778ef18494b1855787b6941e90f1b98b0de690ac4a4c0c30265887e","height":597,"runtimeVersion":{"specVersion":1001},"ts":1681509934000}
2023-04-14T22:05:43.611Z index-builder:indexer Done block #597
2023-04-14T22:05:44.689Z index-builder:indexer Processing block #604
2023-04-14T22:05:44.689Z index-builder:redis-relayer Relaying to redis: hydra:indexer:started:block {"height":604}
2023-04-14T22:05:46.041Z index-builder:indexer Processing block #605
2023-04-14T22:05:46.103Z index-builder:redis-relayer Relaying to redis: hydra:indexer:started:block {"height":605}
2023-04-14 22:05:49        API/INIT: Runtime version updated to spec=3000, tx=1
2023-04-14 22:05:50        RPC-CORE: getStorage(key: StorageKey, at?: BlockHash): StorageData:: Unable to decode storage system.events:: createType(Vec<FrameSystemEventRecord>):: Vec<FrameSystemEventRecord>:: Decoded input doesn't match input, received 0x0400000000000000d08ae10400000000020000 (19 bytes), created 0x0400000000000000d08ae10400000000 (16 bytes)
2023-04-14 22:05:50        RPC-CORE: getStorage(key: StorageKey, at?: BlockHash): StorageData:: Unable to decode storage system.events:: createType(Vec<FrameSystemEventRecord>):: Vec<FrameSystemEventRecord>:: Decoded input doesn't match input, received 0x0400000000000000d08ae10400000000020000 (19 bytes), created 0x0400000000000000d08ae10400000000 (16 bytes)
2023-04-14T22:05:50.197Z index-builder:indexer Processing block #606
2023-04-14T22:05:50.198Z index-builder:indexer Processing block #607
2023-04-14T22:05:50.199Z index-builder:redis-relayer Relaying to redis: hydra:indexer:started:block {"height":606}
2023-04-14T22:05:50.199Z index-builder:redis-relayer Relaying to redis: hydra:indexer:started:block {"height":607}
2023-04-14T22:05:51.208Z index-builder:indexer Saving block data
2023-04-14T22:05:51.305Z index-builder:indexer Saving block data
2023-04-14 22:05:51        RPC-CORE: getStorage(key: StorageKey, at?: BlockHash): StorageData:: Unable to decode storage system.events:: createType(Vec<FrameSystemEventRecord>):: Vec<FrameSystemEventRecord>:: Decoded input doesn't match input, received 0x0400000000000000d08ae10400000000020000 (19 bytes), created 0x0400000000000000d08ae10400000000 (16 bytes)
2023-04-14T22:05:51.309Z index-builder:indexer Saved block data
2023-04-14T22:05:51.309Z index-builder:indexer Saving extrinsics
2023-04-14T22:05:51.362Z index-builder:indexer Saved 1 extrinsics
2023-04-14T22:05:51.362Z index-builder:indexer Saving event entities
2023-04-14T22:05:51.362Z index-builder:indexer Read 5 events; saving in 1 batches
2023-04-14 22:05:51        RPC-CORE: getStorage(key: StorageKey, at?: BlockHash): StorageData:: Unable to decode storage system.events:: createType(SpRuntimeDigestDigestItem):: {"_enum":{"Other":"Bytes","__Unused1":"Null","__Unused2":"Null","__Unused3":"Null","Consensus":"([u8;4],Bytes)","Seal":"([u8;4],Bytes)","PreRuntime":"([u8;4],Bytes)","__Unused7":"Null","RuntimeEnvironmentUpdated":"Null"}}:: Decoded input doesn't match input, received 0x0400000000000000d08ae10400000000020000 (19 bytes), created 0x040000000000 (6 bytes)
2023-04-14T22:05:51.372Z index-builder:indexer Saved block data
2023-04-14T22:05:51.372Z index-builder:indexer Saving extrinsics
2023-04-14T22:05:51.375Z index-builder:indexer Saved 5 events
2023-04-14T22:05:51.378Z index-builder:indexer Saved 1 extrinsics
2023-04-14T22:05:51.378Z index-builder:indexer Saving event entities
2023-04-14T22:05:51.378Z index-builder:indexer Read 6 events; saving in 1 batches
2023-04-14T22:05:51.478Z index-builder:redis-relayer Relaying to redis: hydra:indexer:complete:block {"events":[{"id":"0000000601-000000-acd49","name":"imOnline.AllGood","extrinsic":"none"},{"id":"0000000601-000001-acd49","name":"session.NewSession","extrinsic":"none"},{"id":"0000000601-000002-acd49","name":"council.BudgetRefill","extrinsic":"none"},{"id":"0000000601-000003-acd49","name":"council.BudgetRefillPlanned","extrinsic":"none"},{"id":"0000000601-000004-acd49","name":"system.ExtrinsicSuccess","extrinsic":"timestamp.set"}],"extrinsics":[{"id":"0000000601-000000-acd49","name":"timestamp.set"}],"hash":"0xacd4999be4a3a9264655ea4da40d455b8ba417f36f14884935b5523e9097f464","parentHash":"0xd77460de4b59096588c475f1dbe4c051dd4cc5e572175c2bb6fd06bf477c41dc","height":601,"runtimeVersion":{"specVersion":1001},"ts":1681509938001}
2023-04-14T22:05:51.479Z index-builder:indexer Done block #601
2023-04-14T22:05:51.538Z index-builder:indexer Processing block #608
2023-04-14T22:05:51.539Z index-builder:redis-relayer Relaying to redis: hydra:indexer:started:block {"height":608}
2023-04-14T22:05:51.651Z index-builder:indexer Saving block data
2023-04-14T22:05:51.654Z index-builder:indexer Saved block data
2023-04-14T22:05:51.654Z index-builder:indexer Saving extrinsics
2023-04-14T22:05:51.657Z index-builder:indexer Saved 1 extrinsics
2023-04-14T22:05:51.657Z index-builder:indexer Saving event entities
2023-04-14T22:05:51.657Z index-builder:indexer Read 2 events; saving in 1 batches
2023-04-14T22:05:51.660Z index-builder:indexer Saved 2 events
2023-04-14T22:05:51.662Z index-builder:redis-relayer Relaying to redis: hydra:indexer:complete:block {"events":[{"id":"0000000608-000000-21d92","name":"proposalsEngine.ProposalDecisionMade","extrinsic":"none"},{"id":"0000000608-000001-21d92","name":"system.ExtrinsicSuccess","extrinsic":"timestamp.set"}],"extrinsics":[{"id":"0000000608-000000-21d92","name":"timestamp.set"}],"hash":"0x21d92ec1d3b8d4b203fabf18797b63756b890caa5638cc4a64d30eaad5ec7aae","parentHash":"0x0c658aef5155ba84cb286e572148a14a63f34f9c19a6099ee9f9f01864b5176e","height":608,"runtimeVersion":{"specVersion":3000},"ts":1681509948786}
2023-04-14T22:05:51.662Z index-builder:indexer Done block #608
2023-04-14T22:05:51.800Z index-builder:indexer Saved 6 events
2023-04-14T22:05:51.807Z index-builder:redis-relayer Relaying to redis: hydra:indexer:complete:block {"events":[{"id":"0000000607-000000-0c658","name":"council.BudgetRefill","extrinsic":"none"},{"id":"0000000607-000001-0c658","name":"council.BudgetRefillPlanned","extrinsic":"none"},{"id":"0000000607-000002-0c658","name":"system.CodeUpdated","extrinsic":"none"},{"id":"0000000607-000003-0c658","name":"joystreamUtility.RuntimeUpgraded","extrinsic":"none"},{"id":"0000000607-000004-0c658","name":"proposalsEngine.ProposalExecuted","extrinsic":"none"},{"id":"0000000607-000005-0c658","name":"system.ExtrinsicSuccess","extrinsic":"timestamp.set"}],"extrinsics":[{"id":"0000000607-000000-0c658","name":"timestamp.set"}],"hash":"0x0c658aef5155ba84cb286e572148a14a63f34f9c19a6099ee9f9f01864b5176e","parentHash":"0x9a9e164faa430d9e28cbffe1ff18cfb9b383e4992c652b0210be8dd640cefe20","height":607,"runtimeVersion":{"specVersion":3000},"ts":1681509944000}
2023-04-14T22:05:51.807Z index-builder:indexer Done block #607
2023-04-14T22:05:52.733Z index-builder:indexer Processing block #609
2023-04-14T22:05:52.734Z index-builder:indexer Processing block #610
2023-04-14T22:05:52.735Z index-builder:redis-relayer Relaying to redis: hydra:indexer:started:block {"height":609}
2023-04-14T22:05:52.735Z index-builder:redis-relayer Relaying to redis: hydra:indexer:started:block {"height":610}
2023-04-14T22:05:52.854Z index-builder:indexer Saving block data
2023-04-14T22:05:52.857Z index-builder:indexer Saved block data
2023-04-14T22:05:52.857Z index-builder:indexer Saving extrinsics
2023-04-14T22:05:52.861Z index-builder:indexer Saved 1 extrinsics
2023-04-14T22:05:52.861Z index-builder:indexer Saving event entities
2023-04-14T22:05:52.862Z index-builder:indexer Read 1 events; saving in 1 batches
2023-04-14T22:05:52.864Z index-builder:indexer Saved 1 events
2023-04-14T22:05:52.866Z index-builder:redis-relayer Relaying to redis: hydra:indexer:complete:block {"events":[{"id":"0000000610-000000-a1f37","name":"system.ExtrinsicSuccess","extrinsic":"timestamp.set"}],"extrinsics":[{"id":"0000000610-000000-a1f37","name":"timestamp.set"}],"hash":"0xa1f37180ce8b2c0135b14056252450b56f0b55a088bdf54dcc1a30c4232764dd","parentHash":"0xab685922a2ef43d96231f69f8b022686b8701458fc293590fcc1706d93b32331","height":610,"runtimeVersion":{"specVersion":3000},"ts":1681509950004}
2023-04-14T22:05:52.866Z index-builder:indexer Done block #610
2023-04-14 22:05:53        RPC-CORE: getStorage(key: StorageKey, at?: BlockHash): StorageData:: Unable to decode storage system.events:: createType(SpRuntimeDigestDigestItem):: {"_enum":{"Other":"Bytes","__Unused1":"Null","__Unused2":"Null","__Unused3":"Null","Consensus":"([u8;4],Bytes)","Seal":"([u8;4],Bytes)","PreRuntime":"([u8;4],Bytes)","__Unused7":"Null","RuntimeEnvironmentUpdated":"Null"}}:: Decoded input doesn't match input, received 0x0400000000000000d08ae10400000000020000 (19 bytes), created 0x040000000000 (6 bytes)
2023-04-14 22:05:53        RPC-CORE: getStorage(key: StorageKey, at?: BlockHash): StorageData:: Unable to decode storage system.events:: createType(SpRuntimeDigestDigestItem):: {"_enum":{"Other":"Bytes","__Unused1":"Null","__Unused2":"Null","__Unused3":"Null","Consensus":"([u8;4],Bytes)","Seal":"([u8;4],Bytes)","PreRuntime":"([u8;4],Bytes)","__Unused7":"Null","RuntimeEnvironmentUpdated":"Null"}}:: Decoded input doesn't match input, received 0x0400000000000000d08ae10400000000020000 (19 bytes), created 0x040000000000 (6 bytes)
2023-04-14T22:05:54.067Z index-builder:indexer Processing block #611
2023-04-14T22:05:54.068Z index-builder:redis-relayer Relaying to redis: hydra:indexer:started:block {"height":611}
2023-04-14T22:05:54.210Z index-builder:indexer Saving block data
2023-04-14T22:05:54.213Z index-builder:indexer Saved block data
2023-04-14T22:05:54.213Z index-builder:indexer Saving extrinsics
2023-04-14T22:05:54.216Z index-builder:indexer Saved 1 extrinsics
2023-04-14T22:05:54.217Z index-builder:indexer Saving event entities
2023-04-14T22:05:54.217Z index-builder:indexer Read 1 events; saving in 1 batches
2023-04-14T22:05:54.220Z index-builder:indexer Saved 1 events
2023-04-14T22:05:54.221Z index-builder:redis-relayer Relaying to redis: hydra:indexer:complete:block {"events":[{"id":"0000000611-000000-e8dde","name":"system.ExtrinsicSuccess","extrinsic":"timestamp.set"}],"extrinsics":[{"id":"0000000611-000000-e8dde","name":"timestamp.set"}],"hash":"0xe8ddef8d70c41ea247ff522e6119af84b40a67f98ef45a52d9e049c6d0219a4a","parentHash":"0xa1f37180ce8b2c0135b14056252450b56f0b55a088bdf54dcc1a30c4232764dd","height":611,"runtimeVersion":{"specVersion":3000},"ts":1681509951001}
2023-04-14T22:05:54.221Z index-builder:indexer Done block #611
2023-04-14T22:05:55.398Z index-builder:indexer Processing block #612
2023-04-14T22:05:55.399Z index-builder:redis-relayer Relaying to redis: hydra:indexer:started:block {"height":612}
2023-04-14T22:05:55.626Z index-builder:indexer Saving block data
2023-04-14T22:05:55.631Z index-builder:indexer Saving block data
2023-04-14T22:05:55.632Z index-builder:indexer Saved block data
2023-04-14T22:05:55.632Z index-builder:indexer Saving extrinsics
2023-04-14T22:05:55.636Z index-builder:indexer Saved block data
2023-04-14T22:05:55.636Z index-builder:indexer Saving extrinsics
2023-04-14T22:05:55.637Z index-builder:indexer Saved 1 extrinsics
2023-04-14T22:05:55.637Z index-builder:indexer Saving event entities
2023-04-14T22:05:55.638Z index-builder:indexer Read 1 events; saving in 1 batches
2023-04-14T22:05:55.640Z index-builder:indexer Saved 1 extrinsics
2023-04-14T22:05:55.640Z index-builder:indexer Saving event entities
2023-04-14T22:05:55.640Z index-builder:indexer Read 1 events; saving in 1 batches
2023-04-14T22:05:55.642Z index-builder:indexer Saved 1 events
2023-04-14T22:05:55.643Z index-builder:redis-relayer Relaying to redis: hydra:indexer:complete:block {"events":[{"id":"0000000612-000000-6ec11","name":"system.ExtrinsicSuccess","extrinsic":"timestamp.set"}],"extrinsics":[{"id":"0000000612-000000-6ec11","name":"timestamp.set"}],"hash":"0x6ec11eb75b49af27ac6ab20f23db1689b0ffa8ff1949de56385b8312cf2a04f6","parentHash":"0xe8ddef8d70c41ea247ff522e6119af84b40a67f98ef45a52d9e049c6d0219a4a","height":612,"runtimeVersion":{"specVersion":3000},"ts":1681509952000}
2023-04-14T22:05:55.643Z index-builder:indexer Done block #612
2023-04-14T22:05:55.644Z index-builder:indexer Saved 1 events
2023-04-14T22:05:55.645Z index-builder:redis-relayer Relaying to redis: hydra:indexer:complete:block {"events":[{"id":"0000000606-000000-9a9e1","name":"system.ExtrinsicSuccess","extrinsic":"timestamp.set"}],"extrinsics":[{"id":"0000000606-000000-9a9e1","name":"timestamp.set"}],"hash":"0x9a9e164faa430d9e28cbffe1ff18cfb9b383e4992c652b0210be8dd640cefe20","parentHash":"0x760394b9a8d1b4d1b243b3ec52e025773af94c99f53bdc56716c4f29d503973b","height":606,"runtimeVersion":{"specVersion":1001},"ts":1681509943001}
2023-04-14T22:05:55.646Z index-builder:indexer Done block #606
2023-04-14T22:05:56.733Z index-builder:indexer Processing block #613
2023-04-14T22:05:56.733Z index-builder:indexer Processing block #614
2023-04-14T22:05:56.733Z index-builder:redis-relayer Relaying to redis: hydra:indexer:started:block {"height":613}
2023-04-14T22:05:56.734Z index-builder:redis-relayer Relaying to redis: hydra:indexer:started:block {"height":614}
2023-04-14T22:05:56.841Z index-builder:indexer Saving block data
2023-04-14T22:05:56.844Z index-builder:indexer Saved block data
2023-04-14T22:05:56.844Z index-builder:indexer Saving extrinsics
2023-04-14T22:05:56.848Z index-builder:indexer Saved 1 extrinsics
2023-04-14T22:05:56.848Z index-builder:indexer Saving event entities
2023-04-14T22:05:56.849Z index-builder:indexer Read 1 events; saving in 1 batches
2023-04-14T22:05:56.852Z index-builder:indexer Saved 1 events
2023-04-14T22:05:56.853Z index-builder:redis-relayer Relaying to redis: hydra:indexer:complete:block {"events":[{"id":"0000000614-000000-79bc1","name":"system.ExtrinsicSuccess","extrinsic":"timestamp.set"}],"extrinsics":[{"id":"0000000614-000000-79bc1","name":"timestamp.set"}],"hash":"0x79bc173aa2dd7e8fa75c3ecfa2cb827bed6784a87d566626ce51cb62848f5b71","parentHash":"0x19cbe5382a85b6f2afdf956a69497fde112b7aed1520feb4adbe8f1456434ba8","height":614,"runtimeVersion":{"specVersion":3000},"ts":1681509954000}
2023-04-14T22:05:56.854Z index-builder:indexer Done block #614
2023-04-14 22:05:57        RPC-CORE: getStorage(key: StorageKey, at?: BlockHash): StorageData:: Unable to decode storage system.events:: createType(SpRuntimeDigestDigestItem):: {"_enum":{"Other":"Bytes","__Unused1":"Null","__Unused2":"Null","__Unused3":"Null","Consensus":"([u8;4],Bytes)","Seal":"([u8;4],Bytes)","PreRuntime":"([u8;4],Bytes)","__Unused7":"Null","RuntimeEnvironmentUpdated":"Null"}}:: Decoded input doesn't match input, received 0x0400000000000000d08ae10400000000020000 (19 bytes), created 0x040000000000 (6 bytes)
2023-04-14 22:05:57        RPC-CORE: getStorage(key: StorageKey, at?: BlockHash): StorageData:: Unable to decode storage system.events:: createType(SpRuntimeDigestDigestItem):: {"_enum":{"Other":"Bytes","__Unused1":"Null","__Unused2":"Null","__Unused3":"Null","Consensus":"([u8;4],Bytes)","Seal":"([u8;4],Bytes)","PreRuntime":"([u8;4],Bytes)","__Unused7":"Null","RuntimeEnvironmentUpdated":"Null"}}:: Decoded input doesn't match input, received 0x0400000000000000d08ae10400000000020000 (19 bytes), created 0x040000000000 (6 bytes)
2023-04-14T22:05:58.075Z index-builder:indexer Processing block #615
2023-04-14T22:05:58.076Z index-builder:redis-relayer Relaying to redis: hydra:indexer:started:block {"height":615}
2023-04-14T22:05:58.321Z index-builder:indexer Saving block data
2023-04-14T22:05:58.338Z index-builder:indexer Saved block data
2023-04-14T22:05:58.338Z index-builder:indexer Saving extrinsics
2023-04-14T22:05:58.340Z index-builder:indexer Saving block data
2023-04-14T22:05:58.343Z index-builder:indexer Saved 1 extrinsics
2023-04-14T22:05:58.343Z index-builder:indexer Saving event entities
2023-04-14T22:05:58.343Z index-builder:indexer Read 11 events; saving in 1 batches
2023-04-14T22:05:58.345Z index-builder:indexer Saved block data
2023-04-14T22:05:58.345Z index-builder:indexer Saving extrinsics
2023-04-14T22:05:58.351Z index-builder:indexer Saved 11 events
2023-04-14T22:05:58.352Z index-builder:indexer Saved 1 extrinsics
2023-04-14T22:05:58.352Z index-builder:indexer Saving event entities
2023-04-14T22:05:58.352Z index-builder:indexer Read 11 events; saving in 1 batches
2023-04-14T22:05:58.356Z index-builder:redis-relayer Relaying to redis: hydra:indexer:complete:block {"events":[{"id":"0000000615-000000-681e8","name":"balances.Deposit","extrinsic":"none"},{"id":"0000000615-000001-681e8","name":"council.RewardPayment","extrinsic":"none"},{"id":"0000000615-000002-681e8","name":"balances.Deposit","extrinsic":"none"},{"id":"0000000615-000003-681e8","name":"council.RewardPayment","extrinsic":"none"},{"id":"0000000615-000004-681e8","name":"balances.Deposit","extrinsic":"none"},{"id":"0000000615-000005-681e8","name":"council.RewardPayment","extrinsic":"none"},{"id":"0000000615-000006-681e8","name":"balances.Deposit","extrinsic":"none"},{"id":"0000000615-000007-681e8","name":"council.RewardPayment","extrinsic":"none"},{"id":"0000000615-000008-681e8","name":"balances.Deposit","extrinsic":"none"},{"id":"0000000615-000009-681e8","name":"council.RewardPayment","extrinsic":"none"},{"id":"0000000615-000010-681e8","name":"system.ExtrinsicSuccess","extrinsic":"timestamp.set"}],"extrinsics":[{"id":"0000000615-000000-681e8","name":"timestamp.set"}],"hash":"0x681e8e29928435802f2bc57069e805da9ba10a497bdc96711edff8f19db396b8","parentHash":"0x79bc173aa2dd7e8fa75c3ecfa2cb827bed6784a87d566626ce51cb62848f5b71","height":615,"runtimeVersion":{"specVersion":3000},"ts":1681509955000}
2023-04-14T22:05:58.356Z index-builder:indexer Done block #615
2023-04-14T22:05:58.370Z index-builder:indexer Saved 11 events
2023-04-14T22:05:58.371Z index-builder:redis-relayer Relaying to redis: hydra:indexer:complete:block {"events":[{"id":"0000000609-000000-ab685","name":"balances.Deposit","extrinsic":"none"},{"id":"0000000609-000001-ab685","name":"council.RewardPayment","extrinsic":"none"},{"id":"0000000609-000002-ab685","name":"balances.Deposit","extrinsic":"none"},{"id":"0000000609-000003-ab685","name":"council.RewardPayment","extrinsic":"none"},{"id":"0000000609-000004-ab685","name":"balances.Deposit","extrinsic":"none"},{"id":"0000000609-000005-ab685","name":"council.RewardPayment","extrinsic":"none"},{"id":"0000000609-000006-ab685","name":"balances.Deposit","extrinsic":"none"},{"id":"0000000609-000007-ab685","name":"council.RewardPayment","extrinsic":"none"},{"id":"0000000609-000008-ab685","name":"balances.Deposit","extrinsic":"none"},{"id":"0000000609-000009-ab685","name":"council.RewardPayment","extrinsic":"none"},{"id":"0000000609-000010-ab685","name":"system.ExtrinsicSuccess","extrinsic":"timestamp.set"}],"extrinsics":[{"id":"0000000609-000000-ab685","name":"timestamp.set"}],"hash":"0xab685922a2ef43d96231f69f8b022686b8701458fc293590fcc1706d93b32331","parentHash":"0x21d92ec1d3b8d4b203fabf18797b63756b890caa5638cc4a64d30eaad5ec7aae","height":609,"runtimeVersion":{"specVersion":3000},"ts":1681509949286}
2023-04-14T22:05:58.372Z index-builder:indexer Done block #609
2023-04-14T22:06:00.038Z index-builder:indexer Processing block #616
2023-04-14T22:06:00.056Z index-builder:redis-relayer Relaying to redis: hydra:indexer:started:block {"height":616}
2023-04-14T22:06:00.188Z index-builder:indexer Saving block data
2023-04-14T22:06:00.193Z index-builder:indexer Saved block data
2023-04-14T22:06:00.193Z index-builder:indexer Saving extrinsics
2023-04-14T22:06:00.199Z index-builder:indexer Saved 1 extrinsics
2023-04-14T22:06:00.199Z index-builder:indexer Saving event entities
2023-04-14T22:06:00.199Z index-builder:indexer Read 1 events; saving in 1 batches
2023-04-14T22:06:00.204Z index-builder:indexer Saved 1 events
2023-04-14T22:06:00.206Z index-builder:redis-relayer Relaying to redis: hydra:indexer:complete:block {"events":[{"id":"0000000616-000000-a89e2","name":"system.ExtrinsicSuccess","extrinsic":"timestamp.set"}],"extrinsics":[{"id":"0000000616-000000-a89e2","name":"timestamp.set"}],"hash":"0xa89e25b5f37c6fa7fa3507af00c113437f397a6e6e65d86d79de8e4741ac5551","parentHash":"0x681e8e29928435802f2bc57069e805da9ba10a497bdc96711edff8f19db396b8","height":616,"runtimeVersion":{"specVersion":3000},"ts":1681509956001}
2023-04-14T22:06:00.208Z index-builder:indexer Done block #616
2023-04-14T22:06:01.194Z index-builder:indexer Processing block #617
2023-04-14T22:06:01.195Z index-builder:indexer Processing block #618
2023-04-14T22:06:01.195Z index-builder:redis-relayer Relaying to redis: hydra:indexer:started:block {"height":617}
2023-04-14T22:06:01.195Z index-builder:redis-relayer Relaying to redis: hydra:indexer:started:block {"height":618}
2023-04-14T22:06:01.351Z index-builder:indexer Saving block data
2023-04-14T22:06:01.355Z index-builder:indexer Saved block data
2023-04-14T22:06:01.355Z index-builder:indexer Saving extrinsics
2023-04-14T22:06:01.359Z index-builder:indexer Saved 1 extrinsics
2023-04-14T22:06:01.359Z index-builder:indexer Saving event entities
2023-04-14T22:06:01.360Z index-builder:indexer Read 1 events; saving in 1 batches
2023-04-14T22:06:01.363Z index-builder:indexer Saved 1 events
2023-04-14T22:06:01.365Z index-builder:redis-relayer Relaying to redis: hydra:indexer:complete:block {"events":[{"id":"0000000618-000000-750a0","name":"system.ExtrinsicSuccess","extrinsic":"timestamp.set"}],"extrinsics":[{"id":"0000000618-000000-750a0","name":"timestamp.set"}],"hash":"0x750a04dc4c9d9068b1970e223eacaee1d752a6cbb91c57364cc5ab8b1ef3ea7f","parentHash":"0xfd470452ea35fcc4927d296f850aec5fc7a1c0f4779884ba782e3b7cf389de7a","height":618,"runtimeVersion":{"specVersion":3000},"ts":1681509958000}
2023-04-14T22:06:01.365Z index-builder:indexer Done block #618
2023-04-14T22:06:02.538Z index-builder:indexer Processing block #619
2023-04-14T22:06:02.539Z index-builder:redis-relayer Relaying to redis: hydra:indexer:started:block {"height":619}
2023-04-14T22:06:02.822Z index-builder:indexer Saving block data
2023-04-14T22:06:02.826Z index-builder:indexer Saving block data
2023-04-14T22:06:02.827Z index-builder:indexer Saved block data
2023-04-14T22:06:02.827Z index-builder:indexer Saving extrinsics
2023-04-14T22:06:02.831Z index-builder:indexer Saved block data
2023-04-14T22:06:02.831Z index-builder:indexer Saving extrinsics
2023-04-14T22:06:02.832Z index-builder:indexer Saved 1 extrinsics
2023-04-14T22:06:02.832Z index-builder:indexer Saving event entities
2023-04-14T22:06:02.832Z index-builder:indexer Read 3 events; saving in 1 batches
2023-04-14T22:06:02.835Z index-builder:indexer Saved 1 extrinsics
2023-04-14T22:06:02.835Z index-builder:indexer Saving event entities
2023-04-14T22:06:02.835Z index-builder:indexer Read 3 events; saving in 1 batches
2023-04-14T22:06:02.836Z index-builder:indexer Saved 3 events
2023-04-14T22:06:02.838Z index-builder:redis-relayer Relaying to redis: hydra:indexer:complete:block {"events":[{"id":"0000000619-000000-5d2fc","name":"council.BudgetRefill","extrinsic":"none"},{"id":"0000000619-000001-5d2fc","name":"council.BudgetRefillPlanned","extrinsic":"none"},{"id":"0000000619-000002-5d2fc","name":"system.ExtrinsicSuccess","extrinsic":"timestamp.set"}],"extrinsics":[{"id":"0000000619-000000-5d2fc","name":"timestamp.set"}],"hash":"0x5d2fc02345d16de49c67db5473536dc0015c7c7e4f90d162c904d7712f2949e9","parentHash":"0x750a04dc4c9d9068b1970e223eacaee1d752a6cbb91c57364cc5ab8b1ef3ea7f","height":619,"runtimeVersion":{"specVersion":3000},"ts":1681509959839}
2023-04-14T22:06:02.838Z index-builder:indexer Done block #619
2023-04-14T22:06:02.838Z index-builder:indexer Saved 3 events
2023-04-14T22:06:02.839Z index-builder:redis-relayer Relaying to redis: hydra:indexer:complete:block {"events":[{"id":"0000000613-000000-19cbe","name":"council.BudgetRefill","extrinsic":"none"},{"id":"0000000613-000001-19cbe","name":"council.BudgetRefillPlanned","extrinsic":"none"},{"id":"0000000613-000002-19cbe","name":"system.ExtrinsicSuccess","extrinsic":"timestamp.set"}],"extrinsics":[{"id":"0000000613-000000-19cbe","name":"timestamp.set"}],"hash":"0x19cbe5382a85b6f2afdf956a69497fde112b7aed1520feb4adbe8f1456434ba8","parentHash":"0x6ec11eb75b49af27ac6ab20f23db1689b0ffa8ff1949de56385b8312cf2a04f6","height":613,"runtimeVersion":{"specVersion":3000},"ts":1681509953000}
2023-04-14T22:06:02.839Z index-builder:indexer Done block #613
2023-04-14T22:06:03.865Z index-builder:indexer Processing block #620
2023-04-14T22:06:03.865Z index-builder:indexer Processing block #621

┆Issue is synchronized with this Asana task by Unito

bedeho commented 1 year ago

What runtime ugprade are you talking about here?

  1. Mainnet => Ephesus
  2. Ephesus => Nara
mnaamani commented 1 year ago

What runtime ugprade are you talking about here?

1. `Mainnet` => `Ephesus`

2. `Ephesus` => `Nara`

This would be ephesus to nara, spec version 2001 -> 2002 (in indexer logs however we see the spec update to 3000 that was original planned version but we since reverted to 2002)

mnaamani commented 1 year ago

Upon further investigation the failure to decode storage values at particular blocks are happening to the one ore more blocks that were being fetched (these blocks are always before the runtime upgrade block) just before the node goes through a runtime upgrade and polkadot.js api detects the runtime upgrade.

The indexer uses a ApiDecorated<'promise'> to query storage at a specific block. This is done by using the .at(blockHash) on an ApiPromise (the main api connection to the node being indexed). The decorated api also fetches the runtime types for the runtime version at that particular block to know how to decode the values. This is stored internally in a versioned block registry.

As the indexer happily indexing blocks, and the node runtime is updated, internally the polkadot-js api detects this through metadata subscription updates. It then updates the default registry with new metadata.

I believe there is some data race condition happening that for some reason is causing the decoration for the failing blocks to either be overridden/corrupted or just not created for the correct version when the api is updating the default registry. (I think it is because the default registry was also being used for the decorated api

I can't pinpoint it but the polkadot-js core maintainers might be able to find it more easily.

A few things I tried:

  1. Updated to latest version of polkadot js api to test if this case had been solved.
  2. Manipulate the registries entry with api.getBlockRegistry(..) and call .at(blockHash) again, to nudge polkadot-js api to re-fetch correct metadata for the block.
  3. Finally the simplest solution was to clear the versioned registries (I didn't find a public interface to do so) by creating a new connection to the node, and dropping the old one when the update is detected (api emits the 'decorated' event). I confirmed that the issue was not with the node by creating a new api connection and cloning runtime information from the failing one.

related issues: https://github.com/polkadot-js/api/issues/4596 https://github.com/polkadot-js/api/issues/4518 https://github.com/polkadot-js/api/issues/4557

mnaamani commented 1 year ago

Fixed in https://github.com/Joystream/hydra/pull/534