on_runtime_upgrade is not working

[ayushmishra2005]

I am experimenting with storage migration. I have a struct

#[derive(Encode, Decode, Clone, Default, Eq, PartialEq, Debug)]
pub struct Product {
	name: Vec<u8>,
	metadata: Vec<u8>,
}

decl_storage! {
	trait Store for Module<T: Config> as BarcodeScanner {
		ProductInformation : map hasher(blake2_128_concat) T::Hash => Option<Product>;
	}
}

I am able to run node using RUST_LOG=runtime=debug ./node-template --dev -lexample=debug successfully, store and get data using the below method:

    pub fn get_product_details(id: T::Hash) -> Result<Product, DispatchError> {
        if let Some(product) = ProductInformation::<T>::get(id) {
            Ok(product)
        } else {
            fail!(Error::<T>::ProductDoesNotExist)
        }
    }

Now I want to add a new optional field details in Product and want to put None in exiting data.

I added new field and a method on_runtime_upgrade in decl_module! after following @shawntabrizi 's pull request paritytech/substrate#5058

        fn on_runtime_upgrade() -> frame_support::weights::Weight {
            frame_support::debug::info!(
				"Upgradation Start:::::::::::::::::::::::::::::::::::::::::."
			);
            T::MaximumBlockWeight::get()
        }

I wanted to check whether this method on_runtime_upgrade is getting executed on runtime upgrade or not.

I changed runtime spec_version and followed forkless_upgrade. But I am not getting the above log after forkless runtime upgrade.

Please let me know what I am missing. Please help me to fix this.

[ayushmishra2005]

@shawntabrizi

#[derive(Encode, Decode, Clone, Default, Eq, PartialEq, Debug)]
pub struct Product {
	name: Vec<u8>,
	metadata: Vec<u8>,
	details: Option<Vec<u8>>  // new field added
}

decl_storage! {
	trait Store for Module<T: Config> as BarcodeScanner {
		ProductInformation : map hasher(blake2_128_concat) T::Hash => Option<Product>;
	}
}
pub mod migrations {
    use super::*;

    #[derive(Encode, Decode, Clone, PartialEq, Eq, Default, RuntimeDebug)]
    #[cfg_attr(feature = "serde", derive(serde::Serialize, serde::Deserialize))]
    pub(crate) struct OldProduct {
        name: Vec<u8>,
	metadata: Vec<u8>,
    }
    impl OldProduct {
        pub fn upgraded(self) -> Product {
            Product {
                name: self.name,
                metadata: self.metadata,
                details: None,
            }
        }
    }
}

use crate::migrations::OldProduct;

decl_module! {
    pub struct Module<T: Trait> for enum Call where origin: T::Origin {

        /// Deposit events
        fn deposit_event() = default;
        type Error = Error<T>;

        fn on_runtime_upgrade() -> frame_support::weights::Weight {
            ProductInformation::<T>::translate::<Option<OldProduct>, _>(|_, p| Some(
                p.map( |product|  product.upgraded()).unwrap()
            ));
            T::MaximumBlockWeight::get()
        }
}
}

impl<T: Trait> Module<T> {
  pub fn get_product_details(id: T::Hash) -> Result<Product, DispatchError> {
        if let Some(product) = ProductInformation::<T>::get(id) {
            Ok(product)
        } else {
            fail!(Error::<T>::ProductDoesNotExist)
        }
    }
}

@shawntabrizi I have removed logger and added the actual migration script. After doing runtime upgrade, I am getting

DEBUG ERROR: Corrupted state at [140, 0, 202, 157, 54, 219, 216, 180, 216, 230, 183, 135, 152, 33, 72, 188, 227, 149, 171, 88, 51, 141, 131, 210, 82, 112, 163, 161, 44, 232, 114, 248, 45, 170, 153, 67, 129, 107, 85, 222, 53, 40, 51, 56, 51, 230, 50, 197, 116, 109, 112, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0]

When I try to hit get_product_details against existing id, I get ProductDoesNotExist. Please help me and tell me what I am missing here.

[al3mart]

Hey @ayushmishra2005

About the logging, you can add this line frame_support::debug::RuntimeLogger::init(); in your migration function, so you make sure you can follow what was executed.
As well as turning on debug runtime log with the flag -l runtime=debug when launching your node.

Is clear that your migration is running at least, as the result is some corrupted state, I am having a look at your migration and translate logic for the moment

[ayushmishra2005]

Hey @ayushmishra2005

About the logging, you can add this line frame_support::debug::RuntimeLogger::init(); in your migration function, so you make sure you can follow what was executed.
As well as turning on debug runtime log with the flag -l runtime=debug when launching your node.

Is clear that your migration is running at least, as the result is some corrupted state, I am having a look at your migration and translate logic for the moment

@al3mart Thanks for looking into it. I just want to tell you one more thing I haven't made any change in runtime. I just added above code in my pallet. I only changed spec_version in runtime.

[ayushmishra2005]

@al3mart Adding frame_support::debug::RuntimeLogger::init(); in migration function didn't help. I also added -l runtime=debug before running node.

[gui1117]

the migration code looks wrong to me:

        fn on_runtime_upgrade() -> frame_support::weights::Weight {
            ProductInformation::<T>::translate::<Option<OldProduct>, _>(|_, p| Some(
                p.map( |product|  product.upgraded()).unwrap()
            ));
            T::MaximumBlockWeight::get()
        }

It should be OldProduct:

<             ProductInformation::<T>::translate::<Option<OldProduct>, _>(|_, p| Some(
---
>             ProductInformation::<T>::translate::<OldProduct, _>(|_, p| Some(

If the translate fail to decode a value then it doesn't remove the original value.

I think your issue is about not being able to show the log, the on_runtime_upgrade should should be executed. To be sure you could just write a value in another storage somewhere and see if the value is written.

[ayushmishra2005]

It worked @thiolliere . Great thanks.