[contracts] make debug_message execution outcome invariant to node debug logging setting

frame/contracts/fixtures/debug_message_invalid_utf8.wat

@@ -1,18 +1,28 @@
-;; Emit a "Hello World!" debug message
+;; Emit a debug message with an invalid utf-8 code
 (module
 	(import "seal0" "seal_debug_message" (func $seal_debug_message (param i32 i32) (result i32)))
 	(import "env" "memory" (memory 1 1))
 
 	(data (i32.const 0) "\fc")
 
-	(func (export "call")
-		(call $seal_debug_message
-			(i32.const 0)	;; Pointer to the text buffer
-			(i32.const 12)	;; The size of the buffer
+	(func $assert_eq (param i32 i32)
+		(block $ok
+			(br_if $ok
+				(i32.eq (get_local 0) (get_local 1))
+			)
+			(unreachable)
 		)
-		;; the above call traps because we supplied invalid utf8
-		unreachable
 	)
 
+	(func (export "call")
+		(call $assert_eq
+			 (call $seal_debug_message
+				 (i32.const 0)	;; Pointer to the text buffer
+				 (i32.const 12)	;; The size of the buffer
+			 )
+			 (i32.const 0)	;; Success return code
+		)
+	 )
+
 	(func (export "deploy"))
 )

frame/contracts/fixtures/debug_message_logging_disabled.wat

@@ -20,7 +20,7 @@
 				(i32.const 0)	;; Pointer to the text buffer
 				(i32.const 12)	;; The size of the buffer
 			)
-			(i32.const 9)	;; LoggingDisabled return code
+			(i32.const 0)	;; Success return code
 		)
 	)
 

frame/contracts/src/benchmarking/mod.rs

@@ -877,12 +877,11 @@ 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.
 	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 {
@@ -893,15 +892,80 @@ 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.
+		let i in 0 .. (T::Schedule::get().limits.memory_pages * 64);
+		// All ASCII codes + an invalid utf-8 code: 128
+		let codes = (0..129).collect::<Vec<_>>();
+		// Largest debug message we can benchmark for is limited by maximum allowed
+		// contract memory which is defined by T::Schedule::get().limits.memory_pages,
+		// which to the moment is 1 Mb.
+		// We can't however initialize every byte of it, as it would bloat wasm module size which is
+		// limited by T::MaxCodeLen::get(), being far less than 1Mb.
+		//
+		// So we import maximum allowed memory to the module, in which only the beginning will be initialized by
+		// some data which represents following use cases: ASCII printable and control codes, and an invalid utf-8 byte.
+		// All unitialized memory bytes will get 0 value which is decoded to utf-8 NUL control code.
+		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: codes,
+				},
+			],
+			call_body: Some(body::repeated(API_BENCHMARK_BATCH_SIZE, &[
+				Instruction::I32Const(0), // value_ptr
+				Instruction::I32Const((i * 1024) as i32), // value_len increments by i Kb
+				Instruction::Call(0),
+				Instruction::Drop,
+			])),
+			..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

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);
 		});
 	}
 

frame/contracts/src/lib.rs

@@ -905,8 +905,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.

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_batched!(seal_debug_message_per_kb)),
 			set_storage: to_weight!(cost_batched!(seal_set_storage)),
 			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)),

frame/contracts/src/tests.rs

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

frame/contracts/src/wasm/mod.rs

@@ -2294,13 +2294,7 @@ 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,);
 	}
 
 	const CODE_CALL_RUNTIME: &str = r#"

frame/contracts/src/wasm/runtime.rs

@@ -101,9 +101,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
@@ -216,8 +213,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.
@@ -296,7 +293,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()))
@@ -2042,7 +2041,7 @@ pub mod env {
 		_delta_ptr: u32,
 		_delta_count: u32,
 	) -> Result<(), TrapReason> {
-		ctx.charge_gas(RuntimeCosts::DebugMessage)?;
+		ctx.charge_gas(RuntimeCosts::DebugMessage(0))?;
 		Ok(())
 	}
 
@@ -2063,7 +2062,7 @@ pub mod env {
 		_delta_ptr: u32,
 		_delta_count: u32,
 	) -> Result<(), TrapReason> {
-		ctx.charge_gas(RuntimeCosts::DebugMessage)?;
+		ctx.charge_gas(RuntimeCosts::DebugMessage(0))?;
 		Ok(())
 	}
 
@@ -2123,7 +2122,7 @@ pub mod env {
 		_value_ptr: u32,
 		_value_len: u32,
 	) -> Result<(), TrapReason> {
-		ctx.charge_gas(RuntimeCosts::DebugMessage)?;
+		ctx.charge_gas(RuntimeCosts::DebugMessage(0))?;
 		Ok(())
 	}
 
@@ -2136,7 +2135,7 @@ pub mod env {
 	#[version(1)]
 	#[prefixed_alias]
 	fn set_rent_allowance(ctx: _, _memory: _, _value_ptr: u32) -> Result<(), TrapReason> {
-		ctx.charge_gas(RuntimeCosts::DebugMessage)?;
+		ctx.charge_gas(RuntimeCosts::DebugMessage(0))?;
 		Ok(())
 	}
 
@@ -2367,15 +2366,14 @@ pub mod env {
 		str_ptr: u32,
 		str_len: u32,
 	) -> Result<ReturnCode, TrapReason> {
-		ctx.charge_gas(RuntimeCosts::DebugMessage)?;
+		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.