[contracts] make debug_message execution outcome invariant to node …

…debug logging setting (paritytech#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>

client/executor/wasmtime/Cargo.toml

@@ -27,7 +27,7 @@ wasmtime = { version = "5.0.0", default-features = false, features = [
 	"jitdump",
 	"parallel-compilation",
 	"pooling-allocator"
-] }
+], git = "https://github.com/paritytech/wasmtime.git", branch = "v5.0.0_lto_fix" }
 anyhow = "1.0.68"
 sc-allocator = { version = "4.1.0-dev", path = "../../allocator" }
 sc-executor-common = { version = "0.10.0-dev", path = "../common" }

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

@@ -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