[contracts] make debug_message execution outcome invariant to node debug logging setting (#13197)

* update benchmark for seal_debug_message

* add seal_debug_message_per_kb benchmark

* un-fallable debug buffer: silently drops excessive and wrong utf-8 encoded messages

* charge debug_message per byte of the message

* improved benchmark

* cap debug_message

* ".git/.scripts/commands/bench/bench.sh" pallet dev pallet_contracts

* Apply suggestions from code review

Co-authored-by: Alexander Theißen <alex.theissen@me.com>

* fix applied buggy suggestion

* make sure i*1024 < MaxDebugBufferLen

* fix schedule for our non-batched benchmark

* Switch to a `wasmtime` fork with LTO linking failure workaround

* ".git/.scripts/commands/bench/bench.sh" pallet dev pallet_contracts

---------

Co-authored-by: command-bot <>
Co-authored-by: Alexander Theißen <alex.theissen@me.com>
Co-authored-by: Jan Bujak <jan@parity.io>

substrate/frame/contracts/src/benchmarking/mod.rs

@@ -910,13 +910,12 @@ benchmarks! {
 		let origin = RawOrigin::Signed(instance.caller.clone());
 	}: call(origin, instance.addr, 0u32.into(), Weight::MAX, None, vec![])
 
-	// The size of the supplied message does not influence the weight because as it is never
-	// processed during on-chain execution: It is only ever read during debugging which happens
-	// when the contract is called as RPC where weights do not matter.
+	// Benchmark debug_message call with zero input data.
+	// Whereas this function is used in RPC mode only, it still should be secured
+	// against an excessive use.
 	#[pov_mode = Ignored]
 	seal_debug_message {
 		let r in 0 .. API_BENCHMARK_BATCHES;
-		let max_bytes = code::max_pages::<T>() * 64 * 1024;
 		let code = WasmModule::<T>::from(ModuleDefinition {
 			memory: Some(ImportedMemory { min_pages: 1, max_pages: 1 }),
 			imported_functions: vec![ImportedFunction {
@@ -927,15 +926,75 @@ benchmarks! {
 			}],
 			call_body: Some(body::repeated(r * API_BENCHMARK_BATCH_SIZE, &[
 				Instruction::I32Const(0), // value_ptr
-				Instruction::I32Const(max_bytes as i32), // value_len
+				Instruction::I32Const(0), // value_len
 				Instruction::Call(0),
 				Instruction::Drop,
 			])),
 			.. Default::default()
 		});
 		let instance = Contract::<T>::new(code, vec![])?;
-		let origin = RawOrigin::Signed(instance.caller.clone());
-	}: call(origin, instance.addr, 0u32.into(), Weight::MAX, None, vec![])
+	}: {
+		<Contracts<T>>::bare_call(
+			instance.caller,
+			instance.account_id,
+			0u32.into(),
+			Weight::MAX,
+			None,
+			vec![],
+			true,
+			Determinism::Deterministic,
+		)
+		.result?;
+	}
+
+	seal_debug_message_per_kb {
+		// Vary size of input in kilobytes up to maximum allowed contract memory
+		// or maximum allowed debug buffer size, whichever is less.
+		let i in 0 .. (T::Schedule::get().limits.memory_pages * 64).min(T::MaxDebugBufferLen::get() / 1024);
+		// We benchmark versus messages containing printable ASCII codes.
+		// About 1Kb goes to the instrumented contract code instructions,
+		// whereas all the space left we use for the initialization of the debug messages data.
+		let message = (0 .. T::MaxCodeLen::get() - 1024).zip((32..127).cycle()).map(|i| i.1).collect::<Vec<_>>();
+		let code = WasmModule::<T>::from(ModuleDefinition {
+			memory: Some(ImportedMemory {
+				min_pages: T::Schedule::get().limits.memory_pages,
+				max_pages: T::Schedule::get().limits.memory_pages,
+			}),
+			imported_functions: vec![ImportedFunction {
+				module: "seal0",
+				name: "seal_debug_message",
+				params: vec![ValueType::I32, ValueType::I32],
+				return_type: Some(ValueType::I32),
+			 }],
+			data_segments: vec![
+				DataSegment {
+					offset: 0,
+					value: message,
+				},
+			],
+			call_body: Some(body::plain(vec![
+				Instruction::I32Const(0), // value_ptr
+				Instruction::I32Const((i * 1024) as i32), // value_len increments by i Kb
+				Instruction::Call(0),
+				Instruction::Drop,
+				Instruction::End,
+			])),
+			..Default::default()
+		});
+		let instance = Contract::<T>::new(code, vec![])?;
+	}: {
+		<Contracts<T>>::bare_call(
+			instance.caller,
+			instance.account_id,
+			0u32.into(),
+			Weight::MAX,
+			None,
+			vec![],
+			true,
+			Determinism::Deterministic,
+		)
+		.result?;
+	}
 
 	// Only the overhead of calling the function itself with minimal arguments.
 	// The contract is a bit more complex because it needs to use different keys in order

substrate/frame/contracts/src/exec.rs

@@ -1336,31 +1336,16 @@ where
 
 	fn append_debug_buffer(&mut self, msg: &str) -> bool {
 		if let Some(buffer) = &mut self.debug_message {
-			let err_msg = scale_info::prelude::format!(
-				"Debug message too big (size={}) for debug buffer (bound={})",
-				msg.len(),
-				DebugBufferVec::<T>::bound(),
-			);
-
-			let mut msg = if msg.len() > DebugBufferVec::<T>::bound() {
-				err_msg.bytes()
-			} else {
-				msg.bytes()
-			};
-
-			let num_drain = {
-				let capacity = DebugBufferVec::<T>::bound().checked_sub(buffer.len()).expect(
-					"
-					`buffer` is of type `DebugBufferVec`,
-					`DebugBufferVec` is a `BoundedVec`,
-					`BoundedVec::len()` <= `BoundedVec::bound()`;
-					qed
-				",
-				);
-				msg.len().saturating_sub(capacity).min(buffer.len())
-			};
-			buffer.drain(0..num_drain);
-			buffer.try_extend(&mut msg).ok();
+			buffer
+				.try_extend(&mut msg.bytes())
+				.map_err(|_| {
+					log::debug!(
+						target: "runtime::contracts",
+						"Debug buffer (of {} bytes) exhausted!",
+						DebugBufferVec::<T>::bound(),
+					)
+				})
+				.ok();
 			true
 		} else {
 			false
@@ -2603,9 +2588,11 @@ mod tests {
 			exec_success()
 		});
 
-		// Pre-fill the buffer up to its limit
-		let mut debug_buffer =
-			DebugBufferVec::<Test>::try_from(vec![0u8; DebugBufferVec::<Test>::bound()]).unwrap();
+		// Pre-fill the buffer almost up to its limit, leaving not enough space to the message
+		let debug_buf_before =
+			DebugBufferVec::<Test>::try_from(vec![0u8; DebugBufferVec::<Test>::bound() - 5])
+				.unwrap();
+		let mut debug_buf_after = debug_buf_before.clone();
 
 		ExtBuilder::default().build().execute_with(|| {
 			let schedule: Schedule<Test> = <Test as Config>::Schedule::get();
@@ -2622,15 +2609,11 @@ mod tests {
 				&schedule,
 				0,
 				vec![],
-				Some(&mut debug_buffer),
+				Some(&mut debug_buf_after),
 				Determinism::Deterministic,
 			)
 			.unwrap();
-			assert_eq!(
-				&String::from_utf8(debug_buffer[DebugBufferVec::<Test>::bound() - 17..].to_vec())
-					.unwrap(),
-				"overflowing bytes"
-			);
+			assert_eq!(debug_buf_before, debug_buf_after);
 		});
 	}
 

substrate/frame/contracts/src/lib.rs

@@ -912,8 +912,6 @@ pub mod pallet {
 		///
 		/// This can be triggered by a call to `seal_terminate`.
 		TerminatedInConstructor,
-		/// The debug message specified to `seal_debug_message` does contain invalid UTF-8.
-		DebugMessageInvalidUTF8,
 		/// A call tried to invoke a contract that is flagged as non-reentrant.
 		ReentranceDenied,
 		/// Origin doesn't have enough balance to pay the required storage deposits.

substrate/frame/contracts/src/schedule.rs

@@ -323,6 +323,9 @@ pub struct HostFnWeights<T: Config> {
 	/// Weight of calling `seal_debug_message`.
 	pub debug_message: Weight,
 
+	/// Weight of calling `seal_debug_message` per byte of the message.
+	pub debug_message_per_byte: Weight,
+
 	/// Weight of calling `seal_set_storage`.
 	pub set_storage: Weight,
 
@@ -644,6 +647,7 @@ impl<T: Config> Default for HostFnWeights<T> {
 				1
 			)),
 			debug_message: to_weight!(cost_batched!(seal_debug_message)),
+			debug_message_per_byte: to_weight!(cost_byte!(seal_debug_message_per_kb)),
 			set_storage: to_weight!(cost_batched!(seal_set_storage), 1024u64),
 			set_code_hash: to_weight!(cost_batched!(seal_set_code_hash)),
 			set_storage_per_new_byte: to_weight!(cost_byte_batched!(seal_set_storage_per_new_kb)),

substrate/frame/contracts/src/tests.rs

@@ -2714,7 +2714,8 @@ fn debug_message_invalid_utf8() {
 			true,
 			Determinism::Deterministic,
 		);
-		assert_err!(result.result, <Error<Test>>::DebugMessageInvalidUTF8);
+		assert_ok!(result.result);
+		assert!(result.debug_message.is_empty());
 	});
 }
 

substrate/frame/contracts/src/wasm/mod.rs

@@ -2363,13 +2363,8 @@ mod tests {
 "#;
 		let mut ext = MockExt::default();
 		let result = execute(CODE_DEBUG_MESSAGE_FAIL, vec![], &mut ext);
-		assert_eq!(
-			result,
-			Err(ExecError {
-				error: Error::<Test>::DebugMessageInvalidUTF8.into(),
-				origin: ErrorOrigin::Caller,
-			})
-		);
+		assert_ok!(result);
+		assert!(ext.debug_buffer.is_empty());
 	}
 
 	const CODE_CALL_RUNTIME: &str = r#"

substrate/frame/contracts/src/wasm/runtime.rs

@@ -21,7 +21,7 @@ use crate::{
 	exec::{ExecError, ExecResult, Ext, FixSizedKey, TopicOf, VarSizedKey},
 	gas::{ChargedAmount, Token},
 	schedule::HostFnWeights,
-	BalanceOf, CodeHash, Config, Error, SENTINEL,
+	BalanceOf, CodeHash, Config, DebugBufferVec, Error, SENTINEL,
 };
 
 use bitflags::bitflags;
@@ -114,9 +114,6 @@ pub enum ReturnCode {
 	CodeNotFound = 7,
 	/// The contract that was called is no contract (a plain account).
 	NotCallable = 8,
-	/// The call to `seal_debug_message` had no effect because debug message
-	/// recording was disabled.
-	LoggingDisabled = 9,
 	/// The call dispatched by `seal_call_runtime` was executed but returned an error.
 	CallRuntimeReturnedError = 10,
 	/// ECDSA pubkey recovery failed (most probably wrong recovery id or signature), or
@@ -229,8 +226,8 @@ pub enum RuntimeCosts {
 	Random,
 	/// Weight of calling `seal_deposit_event` with the given number of topics and event size.
 	DepositEvent { num_topic: u32, len: u32 },
-	/// Weight of calling `seal_debug_message`.
-	DebugMessage,
+	/// Weight of calling `seal_debug_message` per byte of passed message.
+	DebugMessage(u32),
 	/// Weight of calling `seal_set_storage` for the given storage item sizes.
 	SetStorage { old_bytes: u32, new_bytes: u32 },
 	/// Weight of calling `seal_clear_storage` per cleared byte.
@@ -309,7 +306,9 @@ impl RuntimeCosts {
 				.deposit_event
 				.saturating_add(s.deposit_event_per_topic.saturating_mul(num_topic.into()))
 				.saturating_add(s.deposit_event_per_byte.saturating_mul(len.into())),
-			DebugMessage => s.debug_message,
+			DebugMessage(len) => s
+				.debug_message
+				.saturating_add(s.deposit_event_per_byte.saturating_mul(len.into())),
 			SetStorage { new_bytes, old_bytes } => s
 				.set_storage
 				.saturating_add(s.set_storage_per_new_byte.saturating_mul(new_bytes.into()))
@@ -2054,7 +2053,7 @@ pub mod env {
 		_delta_ptr: u32,
 		_delta_count: u32,
 	) -> Result<(), TrapReason> {
-		ctx.charge_gas(RuntimeCosts::DebugMessage)?;
+		ctx.charge_gas(RuntimeCosts::DebugMessage(0))?;
 		Ok(())
 	}
 
@@ -2076,7 +2075,7 @@ pub mod env {
 		_delta_ptr: u32,
 		_delta_count: u32,
 	) -> Result<(), TrapReason> {
-		ctx.charge_gas(RuntimeCosts::DebugMessage)?;
+		ctx.charge_gas(RuntimeCosts::DebugMessage(0))?;
 		Ok(())
 	}
 
@@ -2094,7 +2093,7 @@ pub mod env {
 		_value_ptr: u32,
 		_value_len: u32,
 	) -> Result<(), TrapReason> {
-		ctx.charge_gas(RuntimeCosts::DebugMessage)?;
+		ctx.charge_gas(RuntimeCosts::DebugMessage(0))?;
 		Ok(())
 	}
 
@@ -2108,7 +2107,7 @@ pub mod env {
 	#[prefixed_alias]
 	#[deprecated]
 	fn set_rent_allowance(ctx: _, _memory: _, _value_ptr: u32) -> Result<(), TrapReason> {
-		ctx.charge_gas(RuntimeCosts::DebugMessage)?;
+		ctx.charge_gas(RuntimeCosts::DebugMessage(0))?;
 		Ok(())
 	}
 
@@ -2362,7 +2361,7 @@ pub mod env {
 	/// Emit a custom debug message.
 	///
 	/// No newlines are added to the supplied message.
-	/// Specifying invalid UTF-8 triggers a trap.
+	/// Specifying invalid UTF-8 just drops the message with no trap.
 	///
 	/// This is a no-op if debug message recording is disabled which is always the case
 	/// when the code is executing on-chain. The message is interpreted as UTF-8 and
@@ -2383,15 +2382,15 @@ pub mod env {
 		str_ptr: u32,
 		str_len: u32,
 	) -> Result<ReturnCode, TrapReason> {
-		ctx.charge_gas(RuntimeCosts::DebugMessage)?;
+		let str_len = str_len.min(DebugBufferVec::<E::T>::bound() as u32);
+		ctx.charge_gas(RuntimeCosts::DebugMessage(str_len))?;
 		if ctx.ext.append_debug_buffer("") {
 			let data = ctx.read_sandbox_memory(memory, str_ptr, str_len)?;
-			let msg =
-				core::str::from_utf8(&data).map_err(|_| <Error<E::T>>::DebugMessageInvalidUTF8)?;
-			ctx.ext.append_debug_buffer(msg);
-			return Ok(ReturnCode::Success)
+			if let Some(msg) = core::str::from_utf8(&data).ok() {
+				ctx.ext.append_debug_buffer(msg);
+			}
 		}
-		Ok(ReturnCode::LoggingDisabled)
+		Ok(ReturnCode::Success)
 	}
 
 	/// Call some dispatchable of the runtime.