Include post dispatch corrected weight in extrinsic events (#6024)

* Include post dispatch corrected weight in extrinsic events

* Drop the 'Post' from ApplyExtrinsicResultWithPostInfo to make it less verbose

* Apply suggestions from code review

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>

* Use proper Event type in pallet_system tests

* Add test that the actual weight is returned by events

* Make fn extract_actual_weight cap at pre dispatch weight

* Bump spec version

Co-authored-by: Bastian Köcher <bkchr@users.noreply.github.com>
Co-authored-by: Gavin Wood <gavin@parity.io>

substrate/bin/node/runtime/src/lib.rs

@@ -93,8 +93,8 @@ pub const VERSION: RuntimeVersion = RuntimeVersion {
 	// and set impl_version to 0. If only runtime
 	// implementation changes and behavior does not, then leave spec_version as
 	// is and increment impl_version.
-	spec_version: 248,
-	impl_version: 2,
+	spec_version: 249,
+	impl_version: 1,
 	apis: RUNTIME_API_VERSIONS,
 	transaction_version: 1,
 };

substrate/frame/executive/src/lib.rs

@@ -119,6 +119,7 @@ use sp_std::{prelude::*, marker::PhantomData};
 use frame_support::{
 	storage::StorageValue, weights::{GetDispatchInfo, DispatchInfo, DispatchClass},
 	traits::{OnInitialize, OnFinalize, OnRuntimeUpgrade, OffchainWorker},
+	dispatch::PostDispatchInfo,
 };
 use sp_runtime::{
 	generic::Digest, ApplyExtrinsicResult,
@@ -174,7 +175,7 @@ where
 	CheckedOf<Block::Extrinsic, Context>:
 		Applyable +
 		GetDispatchInfo,
-	CallOf<Block::Extrinsic, Context>: Dispatchable<Info=DispatchInfo>,
+	CallOf<Block::Extrinsic, Context>: Dispatchable<Info=DispatchInfo, PostInfo=PostDispatchInfo>,
 	OriginOf<Block::Extrinsic, Context>: From<Option<System::AccountId>>,
 	UnsignedValidator: ValidateUnsigned<Call=CallOf<Block::Extrinsic, Context>>,
 {
@@ -200,7 +201,7 @@ where
 	CheckedOf<Block::Extrinsic, Context>:
 		Applyable +
 		GetDispatchInfo,
-	CallOf<Block::Extrinsic, Context>: Dispatchable<Info=DispatchInfo>,
+	CallOf<Block::Extrinsic, Context>: Dispatchable<Info=DispatchInfo, PostInfo=PostDispatchInfo>,
 	OriginOf<Block::Extrinsic, Context>: From<Option<System::AccountId>>,
 	UnsignedValidator: ValidateUnsigned<Call=CallOf<Block::Extrinsic, Context>>,
 {
@@ -368,9 +369,9 @@ where
 		let dispatch_info = xt.get_dispatch_info();
 		let r = Applyable::apply::<UnsignedValidator>(xt, &dispatch_info, encoded_len)?;
 
-		<frame_system::Module<System>>::note_applied_extrinsic(&r, encoded_len as u32, dispatch_info);
+		<frame_system::Module<System>>::note_applied_extrinsic(&r, dispatch_info);
 
-		Ok(r)
+		Ok(r.map(|_| ()).map_err(|e| e.error))
 	}
 
 	fn final_checks(header: &System::Header) {

substrate/frame/support/src/weights.rs

@@ -134,7 +134,7 @@ use sp_runtime::{
 	traits::SignedExtension,
 	generic::{CheckedExtrinsic, UncheckedExtrinsic},
 };
-use crate::dispatch::{DispatchErrorWithPostInfo, DispatchError};
+use crate::dispatch::{DispatchErrorWithPostInfo, DispatchResultWithPostInfo, DispatchError};
 
 /// Re-export priority as type
 pub use sp_runtime::transaction_validity::TransactionPriority;
@@ -281,6 +281,14 @@ impl PostDispatchInfo {
 	}
 }
 
+/// Extract the actual weight from a dispatch result if any or fall back to the default weight.
+pub fn extract_actual_weight(result: &DispatchResultWithPostInfo, info: &DispatchInfo) -> Weight {
+	match result {
+		Ok(post_info) => &post_info.actual_weight,
+		Err(err) => &err.post_info.actual_weight,
+	}.unwrap_or_else(|| info.weight).min(info.weight)
+}
+
 impl From<Option<Weight>> for PostDispatchInfo {
 	fn from(actual_weight: Option<Weight>) -> Self {
 		Self {
@@ -616,4 +624,31 @@ mod tests {
 		assert_eq!(Call::<TraitImpl>::f21().get_dispatch_info().weight, 45600);
 		assert_eq!(Call::<TraitImpl>::f2().get_dispatch_info().class, DispatchClass::Normal);
 	}
+
+	#[test]
+	fn extract_actual_weight_works() {
+		let pre = DispatchInfo {
+			weight: 1000,
+			.. Default::default()
+		};
+		assert_eq!(extract_actual_weight(&Ok(Some(7).into()), &pre), 7);
+		assert_eq!(extract_actual_weight(&Ok(Some(1000).into()), &pre), 1000);
+		assert_eq!(
+			extract_actual_weight(&Err(DispatchError::BadOrigin.with_weight(9)), &pre),
+			9
+		);
+	}
+
+	#[test]
+	fn extract_actual_weight_caps_at_pre_weight() {
+		let pre = DispatchInfo {
+			weight: 1000,
+			.. Default::default()
+		};
+		assert_eq!(extract_actual_weight(&Ok(Some(1250).into()), &pre), 1000);
+		assert_eq!(
+			extract_actual_weight(&Err(DispatchError::BadOrigin.with_weight(1300)), &pre),
+			1000
+		);
+	}
 }

substrate/frame/system/src/lib.rs

@@ -102,7 +102,7 @@ use sp_std::marker::PhantomData;
 use sp_std::fmt::Debug;
 use sp_version::RuntimeVersion;
 use sp_runtime::{
-	RuntimeDebug, Perbill, DispatchOutcome, DispatchError, DispatchResult,
+	RuntimeDebug, Perbill, DispatchError, DispatchResult,
 	generic::{self, Era},
 	transaction_validity::{
 		ValidTransaction, TransactionPriority, TransactionLongevity, TransactionValidityError,
@@ -126,8 +126,9 @@ use frame_support::{
 	},
 	weights::{
 		Weight, RuntimeDbWeight, DispatchInfo, PostDispatchInfo, DispatchClass,
-		FunctionOf, Pays,
-	}
+		FunctionOf, Pays, extract_actual_weight,
+	},
+	dispatch::DispatchResultWithPostInfo,
 };
 use codec::{Encode, Decode, FullCodec, EncodeLike};
 
@@ -1150,13 +1151,14 @@ impl<T: Trait> Module<T> {
 	}
 
 	/// To be called immediately after an extrinsic has been applied.
-	pub fn note_applied_extrinsic(r: &DispatchOutcome, _encoded_len: u32, info: DispatchInfo) {
+	pub fn note_applied_extrinsic(r: &DispatchResultWithPostInfo, mut info: DispatchInfo) {
+		info.weight = extract_actual_weight(r, &info);
 		Self::deposit_event(
 			match r {
-				Ok(()) => RawEvent::ExtrinsicSuccess(info),
+				Ok(_) => RawEvent::ExtrinsicSuccess(info),
 				Err(err) => {
 					sp_runtime::print(err);
-					RawEvent::ExtrinsicFailed(err.clone(), info)
+					RawEvent::ExtrinsicFailed(err.error, info)
 				},
 			}
 		);
@@ -1830,7 +1832,10 @@ pub(crate) mod tests {
 	use sp_std::cell::RefCell;
 	use sp_core::H256;
 	use sp_runtime::{traits::{BlakeTwo256, IdentityLookup, SignedExtension}, testing::Header, DispatchError};
-	use frame_support::{impl_outer_origin, parameter_types, assert_ok, assert_noop};
+	use frame_support::{
+		impl_outer_origin, parameter_types, assert_ok, assert_noop,
+		weights::WithPostDispatchInfo,
+	};
 
 	impl_outer_origin! {
 		pub enum Origin for Test where system = super {}
@@ -1894,7 +1899,7 @@ pub(crate) mod tests {
 		type AccountId = u64;
 		type Lookup = IdentityLookup<Self::AccountId>;
 		type Header = Header;
-		type Event = u16;
+		type Event = Event<Self>;
 		type BlockHashCount = BlockHashCount;
 		type MaximumBlockWeight = MaximumBlockWeight;
 		type DbWeight = DbWeight;
@@ -1909,18 +1914,8 @@ pub(crate) mod tests {
 		type OnKilledAccount = RecordKilled;
 	}
 
-	impl From<Event<Test>> for u16 {
-		fn from(e: Event<Test>) -> u16 {
-			match e {
-				Event::<Test>::ExtrinsicSuccess(..) => 100,
-				Event::<Test>::ExtrinsicFailed(..) => 101,
-				Event::<Test>::CodeUpdated => 102,
-				_ => 103,
-			}
-		}
-	}
-
 	type System = Module<Test>;
+	type SysEvent = <Test as Trait>::Event;
 
 	const CALL: &<Test as Trait>::Call = &Call;
 
@@ -1978,14 +1973,14 @@ pub(crate) mod tests {
 				InitKind::Full,
 			);
 			System::note_finished_extrinsics();
-			System::deposit_event(1u16);
+			System::deposit_event(SysEvent::CodeUpdated);
 			System::finalize();
 			assert_eq!(
 				System::events(),
 				vec![
 					EventRecord {
 						phase: Phase::Finalization,
-						event: 1u16,
+						event: SysEvent::CodeUpdated,
 						topics: vec![],
 					}
 				]
@@ -1998,22 +1993,131 @@ pub(crate) mod tests {
 				&Default::default(),
 				InitKind::Full,
 			);
-			System::deposit_event(32u16);
+			System::deposit_event(SysEvent::NewAccount(32));
 			System::note_finished_initialize();
-			System::deposit_event(42u16);
-			System::note_applied_extrinsic(&Ok(()), 0, Default::default());
-			System::note_applied_extrinsic(&Err(DispatchError::BadOrigin), 0, Default::default());
+			System::deposit_event(SysEvent::KilledAccount(42));
+			System::note_applied_extrinsic(&Ok(().into()), Default::default());
+			System::note_applied_extrinsic(
+				&Err(DispatchError::BadOrigin.into()),
+				Default::default()
+			);
 			System::note_finished_extrinsics();
-			System::deposit_event(3u16);
+			System::deposit_event(SysEvent::NewAccount(3));
 			System::finalize();
 			assert_eq!(
 				System::events(),
 				vec![
-					EventRecord { phase: Phase::Initialization, event: 32u16, topics: vec![] },
-					EventRecord { phase: Phase::ApplyExtrinsic(0), event: 42u16, topics: vec![] },
-					EventRecord { phase: Phase::ApplyExtrinsic(0), event: 100u16, topics: vec![] },
-					EventRecord { phase: Phase::ApplyExtrinsic(1), event: 101u16, topics: vec![] },
-					EventRecord { phase: Phase::Finalization, event: 3u16, topics: vec![] }
+					EventRecord {
+						phase: Phase::Initialization,
+						event: SysEvent::NewAccount(32),
+						topics: vec![],
+					},
+					EventRecord {
+						phase: Phase::ApplyExtrinsic(0),
+						event: SysEvent::KilledAccount(42),
+						topics: vec![]
+					},
+					EventRecord {
+						phase: Phase::ApplyExtrinsic(0),
+						event: SysEvent::ExtrinsicSuccess(Default::default()),
+						topics: vec![]
+					},
+					EventRecord {
+						phase: Phase::ApplyExtrinsic(1),
+						event: SysEvent::ExtrinsicFailed(
+							DispatchError::BadOrigin.into(),
+							Default::default()
+						),
+						topics: vec![]
+					},
+					EventRecord {
+						phase: Phase::Finalization,
+						event: SysEvent::NewAccount(3),
+						topics: vec![]
+					},
+				]
+			);
+		});
+	}
+
+	#[test]
+	fn deposit_event_uses_actual_weight() {
+		new_test_ext().execute_with(|| {
+			System::initialize(
+				&1,
+				&[0u8; 32].into(),
+				&[0u8; 32].into(),
+				&Default::default(),
+				InitKind::Full,
+			);
+			System::note_finished_initialize();
+
+			let pre_info = DispatchInfo {
+				weight: 1000,
+				.. Default::default()
+			};
+			System::note_applied_extrinsic(
+				&Ok(Some(300).into()),
+				pre_info,
+			);
+			System::note_applied_extrinsic(
+				&Ok(Some(1000).into()),
+				pre_info,
+			);
+			System::note_applied_extrinsic(
+				// values over the pre info should be capped at pre dispatch value
+				&Ok(Some(1200).into()),
+				pre_info,
+			);
+			System::note_applied_extrinsic(
+				&Err(DispatchError::BadOrigin.with_weight(999)),
+				pre_info,
+			);
+
+			assert_eq!(
+				System::events(),
+				vec![
+					EventRecord {
+						phase: Phase::ApplyExtrinsic(0),
+						event: SysEvent::ExtrinsicSuccess(
+							DispatchInfo {
+								weight: 300,
+								.. Default::default()
+							},
+						),
+						topics: vec![]
+					},
+					EventRecord {
+						phase: Phase::ApplyExtrinsic(1),
+						event: SysEvent::ExtrinsicSuccess(
+							DispatchInfo {
+								weight: 1000,
+								.. Default::default()
+							},
+						),
+						topics: vec![]
+					},
+					EventRecord {
+						phase: Phase::ApplyExtrinsic(2),
+						event: SysEvent::ExtrinsicSuccess(
+							DispatchInfo {
+								weight: 1000,
+								.. Default::default()
+							},
+						),
+						topics: vec![]
+					},
+					EventRecord {
+						phase: Phase::ApplyExtrinsic(3),
+						event: SysEvent::ExtrinsicFailed(
+							DispatchError::BadOrigin.into(),
+							DispatchInfo {
+								weight: 999,
+								.. Default::default()
+							},
+						),
+						topics: vec![]
+					},
 				]
 			);
 		});
@@ -2040,9 +2144,9 @@ pub(crate) mod tests {
 			];
 
 			// We deposit a few events with different sets of topics.
-			System::deposit_event_indexed(&topics[0..3], 1u16);
-			System::deposit_event_indexed(&topics[0..1], 2u16);
-			System::deposit_event_indexed(&topics[1..2], 3u16);
+			System::deposit_event_indexed(&topics[0..3], SysEvent::NewAccount(1));
+			System::deposit_event_indexed(&topics[0..1], SysEvent::NewAccount(2));
+			System::deposit_event_indexed(&topics[1..2], SysEvent::NewAccount(3));
 
 			System::finalize();
 
@@ -2052,17 +2156,17 @@ pub(crate) mod tests {
 				vec![
 					EventRecord {
 						phase: Phase::Finalization,
-						event: 1u16,
+						event: SysEvent::NewAccount(1),
 						topics: topics[0..3].to_vec(),
 					},
 					EventRecord {
 						phase: Phase::Finalization,
-						event: 2u16,
+						event: SysEvent::NewAccount(2),
 						topics: topics[0..1].to_vec(),
 					},
 					EventRecord {
 						phase: Phase::Finalization,
-						event: 3u16,
+						event: SysEvent::NewAccount(3),
 						topics: topics[1..2].to_vec(),
 					}
 				]
@@ -2485,7 +2589,11 @@ pub(crate) mod tests {
 
 			assert_eq!(
 				System::events(),
-				vec![EventRecord { phase: Phase::Initialization, event: 102u16, topics: vec![] }],
+				vec![EventRecord {
+					phase: Phase::Initialization,
+					event: SysEvent::CodeUpdated,
+					topics: vec![],
+				}],
 			);
 		});
 	}

substrate/primitives/runtime/src/generic/checked_extrinsic.rs

@@ -19,7 +19,8 @@
 //! stage.
 
 use crate::traits::{
-	self, Member, MaybeDisplay, SignedExtension, Dispatchable, DispatchInfoOf, ValidateUnsigned,
+	self, Member, MaybeDisplay, SignedExtension, Dispatchable, DispatchInfoOf, PostDispatchInfoOf,
+	ValidateUnsigned,
 };
 use crate::transaction_validity::{TransactionValidity, TransactionSource};
 
@@ -67,7 +68,7 @@ where
 		self,
 		info: &DispatchInfoOf<Self::Call>,
 		len: usize,
-	) -> crate::ApplyExtrinsicResult {
+	) -> crate::ApplyExtrinsicResultWithInfo<PostDispatchInfoOf<Self::Call>> {
 		let (maybe_who, pre) = if let Some((id, extra)) = self.signed {
 			let pre = Extra::pre_dispatch(extra, &id, &self.function, info, len)?;
 			(Some(id), pre)
@@ -81,8 +82,7 @@ where
 			Ok(info) => info,
 			Err(err) => err.post_info,
 		};
-		let res = res.map(|_| ()).map_err(|e| e.error);
-		Extra::post_dispatch(pre, info, &post_info, len, &res)?;
+		Extra::post_dispatch(pre, info, &post_info, len, &res.map(|_| ()).map_err(|e| e.error))?;
 		Ok(res)
 	}
 }

substrate/primitives/runtime/src/lib.rs

@@ -536,6 +536,10 @@ pub type DispatchOutcome = Result<(), DispatchError>;
 /// - The extrinsic supplied a bad signature. This transaction won't become valid ever.
 pub type ApplyExtrinsicResult = Result<DispatchOutcome, transaction_validity::TransactionValidityError>;
 
+/// Same as `ApplyExtrinsicResult` but augmented with `PostDispatchInfo` on success.
+pub type ApplyExtrinsicResultWithInfo<T> =
+	Result<DispatchResultWithInfo<T>, transaction_validity::TransactionValidityError>;
+
 /// Verify a signature on an encoded value in a lazy manner. This can be
 /// an optimization if the signature scheme has an "unsigned" escape hash.
 pub fn verify_encoded_lazy<V: Verify, T: codec::Encode>(

substrate/primitives/runtime/src/testing.rs

@@ -22,10 +22,10 @@ use std::{fmt::{self, Debug}, ops::Deref, cell::RefCell};
 use crate::codec::{Codec, Encode, Decode};
 use crate::traits::{
 	self, Checkable, Applyable, BlakeTwo256, OpaqueKeys,
-	SignedExtension, Dispatchable, DispatchInfoOf,
+	SignedExtension, Dispatchable, DispatchInfoOf, PostDispatchInfoOf,
 };
 use crate::traits::ValidateUnsigned;
-use crate::{generic, KeyTypeId, CryptoTypeId, ApplyExtrinsicResult};
+use crate::{generic, KeyTypeId, CryptoTypeId, ApplyExtrinsicResultWithInfo};
 pub use sp_core::{H256, sr25519};
 use sp_core::{crypto::{CryptoType, Dummy, key_types, Public}, U256};
 use crate::transaction_validity::{TransactionValidity, TransactionValidityError, TransactionSource};
@@ -382,7 +382,7 @@ impl<Origin, Call, Extra> Applyable for TestXt<Call, Extra> where
 		self,
 		info: &DispatchInfoOf<Self::Call>,
 		len: usize,
-	) -> ApplyExtrinsicResult {
+	) -> ApplyExtrinsicResultWithInfo<PostDispatchInfoOf<Self::Call>> {
 		let maybe_who = if let Some((who, extra)) = self.signature {
 			Extra::pre_dispatch(extra, &who, &self.call, info, len)?;
 			Some(who)
@@ -391,6 +391,6 @@ impl<Origin, Call, Extra> Applyable for TestXt<Call, Extra> where
 			None
 		};
 
-		Ok(self.call.dispatch(maybe_who.into()).map(|_| ()).map_err(|e| e.error))
+		Ok(self.call.dispatch(maybe_who.into()))
 	}
 }

substrate/primitives/runtime/src/traits.rs

@@ -892,7 +892,7 @@ pub trait Applyable: Sized + Send + Sync {
 		self,
 		info: &DispatchInfoOf<Self::Call>,
 		len: usize,
-	) -> crate::ApplyExtrinsicResult;
+	) -> crate::ApplyExtrinsicResultWithInfo<PostDispatchInfoOf<Self::Call>>;
 }
 
 /// A marker trait for something that knows the type of the runtime block.