(poc): Add Event Recording in Dry Run Flow to Improve XCM Debugging

polkadot/xcm/pallet-xcm/src/lib.rs

@@ -326,6 +326,7 @@ pub mod pallet {
 				))
 			})()
 			.map_err(|e: DispatchError| {
+				tracing::error!(target: "xcm::pallet_xcm::execute", ?e, "XCM execution failed with dispatch error");
 				e.with_weight(<Self::WeightInfo as ExecuteControllerWeightInfo>::execute())
 			})?;
 
@@ -845,6 +846,9 @@ pub mod pallet {
 	#[pallet::storage]
 	pub(crate) type RecordedXcm<T: Config> = StorageValue<_, Xcm<()>>;
 
+	#[pallet::storage]
+	pub type EmittedEvent<T: Config> = StorageValue<_, <T as frame_system::Config>::RuntimeEvent>;
+
 	#[pallet::genesis_config]
 	pub struct GenesisConfig<T: Config> {
 		#[serde(skip)]
@@ -2599,10 +2603,14 @@ impl<T: Config> Pallet<T> {
 					);
 				},
 			)?;
-		let events: Vec<<Runtime as frame_system::Config>::RuntimeEvent> =
+		let mut events: Vec<<Runtime as frame_system::Config>::RuntimeEvent> =
 			frame_system::Pallet::<Runtime>::read_events_no_consensus()
 				.map(|record| record.event.clone())
 				.collect();
+		if let Some(failed_event) = Pallet::<Runtime>::emitted_event() {
+			tracing::debug!("Failed event: {:?}", failed_event);
+			events.push(failed_event);
+		}
 		Ok(CallDryRunEffects {
 			local_xcm: local_xcm.map(VersionedXcm::<()>::from),
 			forwarded_xcms,
@@ -3501,6 +3509,8 @@ impl<T: Config> CheckSuspension for Pallet<T> {
 }
 
 impl<T: Config> RecordXcm for Pallet<T> {
+	type RuntimeEvent = <T as frame_system::Config>::RuntimeEvent;
+
 	fn should_record() -> bool {
 		ShouldRecordXcm::<T>::get()
 	}
@@ -3516,6 +3526,25 @@ impl<T: Config> RecordXcm for Pallet<T> {
 	fn record(xcm: Xcm<()>) {
 		RecordedXcm::<T>::put(xcm);
 	}
+
+	fn record_last_event() {
+		let records = frame_system::Pallet::<T>::events();
+		if let Some(record) = records.last() {
+			let event = record.event.clone();
+			tracing::debug!(?event, "-> Recording");
+			EmittedEvent::<T>::put(event);
+		} else {
+			tracing::debug!("-> Missing");
+		};
+		let event = EmittedEvent::<T>::get();
+		tracing::debug!(?event, "<- Recorded");
+	}
+
+	fn emitted_event() -> Option<Self::RuntimeEvent> {
+		let event = EmittedEvent::<T>::get();
+		tracing::debug!(?event, "Emitted");
+		event
+	}
 }
 
 /// Ensure that the origin `o` represents an XCM (`Transact`) origin.

polkadot/xcm/xcm-executor/src/lib.rs

@@ -293,6 +293,12 @@ impl<Config: config::Config> ExecuteXcm<Config::RuntimeCall> for XcmExecutor<Con
 			}
 		}
 
+
+
+		if Config::XcmRecorder::should_record() {
+			Config::XcmRecorder::record_last_event();
+		}
+
 		vm.post_process(xcm_weight)
 	}
 

polkadot/xcm/xcm-executor/src/traits/record_xcm.rs

@@ -20,6 +20,8 @@ use xcm::latest::Xcm;
 
 /// Trait for recording XCMs.
 pub trait RecordXcm {
+	type RuntimeEvent;
+
 	/// Whether or not we should record incoming XCMs.
 	fn should_record() -> bool;
 	/// Enable or disable recording.
@@ -29,9 +31,15 @@ pub trait RecordXcm {
 	fn recorded_xcm() -> Option<Xcm<()>>;
 	/// Record `xcm`.
 	fn record(xcm: Xcm<()>);
+	/// Record the last event.
+	fn record_last_event();
+	/// Get emitted events.
+	fn emitted_event() -> Option<Self::RuntimeEvent>;
 }
 
 impl RecordXcm for () {
+	type RuntimeEvent = ();
+
 	fn should_record() -> bool {
 		false
 	}
@@ -43,4 +51,8 @@ impl RecordXcm for () {
 	}
 
 	fn record(_: Xcm<()>) {}
+
+	fn record_last_event() {}
+
+	fn emitted_event() -> Option<Self::RuntimeEvent> { None }
 }

polkadot/xcm/xcm-runtime-apis/Cargo.toml

@@ -29,7 +29,7 @@ pallet-assets = { workspace = true }
 pallet-balances = { workspace = true }
 pallet-xcm = { workspace = true }
 sp-io = { workspace = true }
-sp-tracing = { workspace = true, default-features = true }
+sp-tracing = { features = ["test-utils"], workspace = true, default-features = true }
 xcm-builder = { workspace = true }
 xcm-executor = { workspace = true }
 

polkadot/xcm/xcm-runtime-apis/tests/fee_estimation.rs

@@ -464,3 +464,50 @@ fn calling_payment_api_with_a_lower_version_works() {
 		.unwrap();
 	assert!(execution_fees.is_ok());
 }
+
+#[test]
+fn dry_run_error_event_check() {
+	use frame_support::{
+		dispatch::DispatchErrorWithPostInfo,
+		sp_runtime::{DispatchError, ModuleError},
+	};
+	use sp_tracing::{capture_test_logs, tracing::Level};
+
+	let who = 1;
+	let balances = vec![(who, DeliveryFees::get() + ExistentialDeposit::get())];
+	let assets = vec![(1, who, 100)];
+	new_test_ext_with_balances_and_assets(balances, assets).execute_with(|| {
+		let client = TestClient;
+		let runtime_api = client.runtime_api();
+		sp_tracing::init_for_tests();
+		let xcm_call = RuntimeCall::XcmPallet(pallet_xcm::Call::transfer_assets {
+			dest: VersionedLocation::from((Parent, Parachain(1000))).into(),
+			beneficiary: VersionedLocation::from(AccountId32 { id: [0u8; 32], network: None })
+				.into(),
+			assets: VersionedAssets::from((Parent, 1984u128)).into(),
+			fee_asset_item: 0,
+			weight_limit: Unlimited,
+		});
+
+		let origin = OriginCaller::system(RawOrigin::Signed(who));
+		let log_capture = capture_test_logs!(Level::DEBUG, true, {
+			let dry_run_effects = runtime_api
+				.dry_run_call(H256::zero(), origin, xcm_call, XCM_VERSION)
+				.unwrap()
+				.unwrap();
+			if let Err(DispatchErrorWithPostInfo {
+				error: DispatchError::Module(ModuleError { message: Some(err_msg), .. }),
+				..
+			}) = dry_run_effects.execution_result
+			{
+				assert_eq!(err_msg, "LocalExecutionIncomplete");
+			} else {
+				assert!(false, "Expected LocalExecutionIncomplete error");
+			}
+			sp_tracing::tracing::debug!("dry_run_effects.emitted_events={:?}", dry_run_effects.emitted_events);
+			assert!(dry_run_effects.emitted_events.is_empty());
+		});
+		assert!(log_capture.contains("xcm::pallet_xcm::execute_xcm_transfer: origin=Location"));
+		assert!(log_capture.contains("XCM execution failed with error with outcome: Incomplete"));
+	});
+}