runtime upgrade stream API: fetched metadata is "outdated" when upgrade is applied

[niklasad1]

Currently, I'm using the runtime update stream API in subxt as follows:

async fn runtime_upgrade_task(api: ChainClient, tx: oneshot::Sender<Error>) {
    let update_stream = ...;

    loop {
        // if the runtime upgrade subscription fails then try establish a new one and if it fails quit.
        let update = match update_stream.next().await {
            Some(Ok(update)) => update,
            _ => {
                log::warn!(target: LOG_TARGET, "Runtime upgrade subscription failed");
                update_stream = match updater.runtime_updates().await {
                    Ok(u) => u,
                    Err(e) => {
                        let _ = tx.send(e.into());
                        return;
                    }
                };
                continue;
            }
        };

        let version = update.runtime_version().spec_version;
        match updater.apply_update(update) {
            Ok(()) => {
                if let Err(e) = epm::update_metadata_constants(&api).await {
                    let _ = tx.send(e);
                    return;
                }
                prometheus::on_runtime_upgrade();
                log::info!(target: LOG_TARGET, "upgrade to version: {} successful", version);
            }
            Err(e) => {
                log::debug!(target: LOG_TARGET, "upgrade to version: {} failed: {:?}", version, e);
            }
        }
    }
}

Thus, I'm expecting the metadata in the runtime upgrade to have been updated after apply_update returns

Logs from the code

# start-up
2023-12-13T16:49:56.195801Z  INFO polkadot-staking-miner: Connected to chain: westend
2023-12-13T16:50:26.197747Z TRACE polkadot-staking-miner: updating metadata constant `ElectionProviderMultiPhase::MaxWinners`: 1000
2023-12-13T16:50:26.197759Z TRACE polkadot-staking-miner: updating metadata constant `ElectionProviderMultiPhase::SignedPhase`: 10
2023-12-13T16:50:26.259158Z DEBUG polkadot-staking-miner: upgrade to version: 1005000 failed: SameVersion

# runtime upgrade,  expecting MaxWinners=13, SignedPhase=5
# the metadata doesn't contain the runtime upgrade
2023-12-13T16:54:30.843695Z TRACE polkadot-staking-miner: updating metadata constant `ElectionProviderMultiPhase::MaxWinners`: 1000
2023-12-13T16:54:30.843706Z TRACE polkadot-staking-miner: updating metadata constant `ElectionProviderMultiPhase::SignedPhase`: 10
2023-12-13T16:54:30.843791Z  INFO polkadot-staking-miner: upgrade to version: 1009000 successful

# restart the client, now it works as expected.
2023-12-13T16:55:38.808698Z TRACE polkadot-staking-miner: updating metadata constant `ElectionProviderMultiPhase::MaxWinners`: 13
2023-12-13T16:55:38.808709Z TRACE polkadot-staking-miner: updating metadata constant `ElectionProviderMultiPhase::SignedPhase`: 5

After some investigation, I was able to track down that the issue is really that the fetched metadata in the runtime upgrade doesn't really contain the latest metadata. The reason is that state_subscribeStorage emits an runtime upgrade event before it's actually applied, and subxt's RuntimeUpgradeStream should really assert that the runtime upgrade has occurred at the block or earlier that the metadata is fetched at (with the exception for the initial runtime upgrade)

With the following hack in subxt the issue goes away:

diff --git a/Cargo.lock b/Cargo.lock
index b8b0ab7..febe2bf 100644
--- a/Cargo.lock
+++ b/Cargo.lock
@@ -4695,7 +4695,9 @@ dependencies = [
  "libc",
  "mio",
  "num_cpus",
+ "parking_lot",
  "pin-project-lite",
+ "signal-hook-registry",
  "socket2 0.5.5",
  "tokio-macros",
  "windows-sys 0.48.0",
diff --git a/subxt/Cargo.toml b/subxt/Cargo.toml
index cc8ff58..d3196ee 100644
--- a/subxt/Cargo.toml
+++ b/subxt/Cargo.toml
@@ -96,6 +96,7 @@ tokio-stream = { workspace = true, optional = true }
 
 # Included if "web" feature is enabled, to enable its js feature.
 getrandom = { workspace = true, optional = true }
+tokio = { workspace = true, features = ["full"] }
 
 [dev-dependencies]
 bitvec = { workspace = true }
diff --git a/subxt/src/client/online_client.rs b/subxt/src/client/online_client.rs
index 338643e..73b02e3 100644
--- a/subxt/src/client/online_client.rs
+++ b/subxt/src/client/online_client.rs
@@ -3,6 +3,7 @@
 // see LICENSE for license details.
 
 use super::{OfflineClient, OfflineClientT};
+use crate::config::Header;
 use crate::custom_values::CustomValuesClient;
 use crate::{
     backend::{
@@ -437,11 +438,24 @@ impl<T: Config> RuntimeUpdaterStream<T> {
             Err(err) => return Some(Err(err)),
         };
 
+        // Sleep a few blocks to ensure that fetch metadata below 
+        // is the metadata from the runtime upgrade.
+        tokio::time::sleep(std::time::Duration::from_secs(5 * 6)).await;
+
         let latest_block_ref = match self.client.backend().latest_finalized_block_ref().await {
             Ok(block_ref) => block_ref,
             Err(e) => return Some(Err(e)),
         };
 
+        let header = self
+            .client
+            .backend()
+            .block_header(latest_block_ref.hash())
+            .await
+            .unwrap()
+            .unwrap();
+        tracing::info!("Fetching metadata at: {}", header.number().into());
+
         let metadata = match OnlineClient::fetch_metadata(
             self.client.backend(),
             latest_block_ref.hash(),

[niklasad1]

It's possible to workaround this issue by using the upgrade low-level API, you can find an example here

[jsdw]

The chainHead APIs provide runtime updates in new block events, so with that API we should be able to be more precise about things. It's just the old APIs I'd guess that are a bit more problematic.

In an ideal world, Subxt should probably store multiple metadatas/runtime infos for different blocks. If we store them at block heights, then we don't account for forks and so should only pay attention to updates at finalized blocks.

For now though, the stream_runtime_version Backend call should probably be tweaked to ensure that runtime updates are only applied when a finalized block containing the update is encountered (I think the update takes effect after this block and not on it, right?). The legacy method will need updating here and the chainHead one may already be ok (need to verify this, ideally with a test).

There will still be race conditions etc until we support multiple metadatas, because once we update to a newer metadata/runtime version we may fail to decode some older blocks all of a sudden. Also, working with blocks that haven't been finalized will always cause issues. Eventually, supporting multiple metadatas in Subxt will help to deal with this, so that then we can register the update against the exact block number and keep (some) older metadatas around to keep handling blocks before that.

[niklasad1]

Yeah, I'm more in favor of removing the runtime update stream API completely and let the users decide how/when to upgrade the metadata because the current one will always lag behind what's on chain after at least one runtime upgrade has occurred.

For instance in the staking-miner I decide to subscribe to System::LastRuntimeUpgrade instead...