v0.2Report
Report for Europa v0.2#
Six weeks ago, Patract Hub (https://patract.io) applied a Treasury Proposal #27 for Europa v0.2 , and now we have finished all the development work in (https://github.com/patractlabs/Europa). Europa is kind of another implementation for Substrate client in our design. We know that the runtime of a blockchain is the business logic that defines its behavior, and the Substrate runtime need to run by an executor and environment. So that we design the executor and environment more like a "sandbox" to run a Substrate runtime.
In v0.2, the primary target is to modify Pallet Contracts in runtime to provide more detailed debugging information, including contract execution process information (in Pallet Contracts layer) and Wasm execution information (in WASMI execution layer).
Recap of Europa's future plan#
v0.1: Have an independent runtime environment to facilitate more subsequent expansion directions.v0.2: Modify at FRAME Contracts pallet level to provide more information- v0.3: Improve the development experience, strengthen collaboration with other tools, and extend the sandbox to be compatible with other runtime modules。
Recap of verification for Europa v0.2:#
- Construct incorrect contracts and execute logs printing to determine whether it meets expectations
- Display the call statistics of the
define_env!interface during contract execution- Execute the log printing function, provide formatted printing examples of different data, and judge whether it meets expectations
- Construct a contract that crashes under different conditions and record the log after execution. Then judge whether the backtrace information of the contract execution is completely printed, and check whether it matches the actual execution of the collapsed contract.
1.Design#
In 0.2, the debugging information function of the upgrade contract module is divided into three parts of modification:
- Modification on the
Pallet Contractslayer: By adding trace during the execution of the contract byPallet Contracts, the information in the contract layer is recorded, and the calling level of the contract is recorded. On the other hand, the error message of calling Wasm execution is improved. - Modification on the
wasmilayer: We have provided the backtrace function of recording wasm execution forwasmi, and provided support forparity-wasm,pwasm-utils, andcargo-contractduring wasm processing of the contract contains the function of the name section. - Contract logging function: Use the function of
ChainExtensionsto realize the library for printing thelogin the contract.
In the current Pallet Contracts, when an error occurs in the execution of wasmi, and in the host_function call of Pallet Contracts during the execution of wasmi, it will be displayed as a ContractTrap error externally. In this situation, it is difficult for developers to locate the cause of the error. Only from this information, it is impossible to tell whether the problem is the contract itself, ink!, or Pallet Contracts. Therefore, the rich information that Europa v0.2 can provide allows developers to directly locate the cause of the problem.
1.1 on Pallet Contracts layer#
During the contract debugging process, Europa believes that developers need:
- Rich error information: Wasm records the error information during the entire execution process, including Wasm executor errors and host_function errors. The backtrace information of wasmi will be unified with the error information here.
- Execution in the debugging process: The main modification information of
Pallet Contracts, the "contract stack" is used to record the process of contract calling contract, and any information that can assist debugging during the execution of this layer of contract, such as the situation of calling the host_function, selector, and calling contract parameters, etc.
Therefore, in response to such needs, Europa made the following designs and modifications:
1.1.1 rich error information#
1.error on the wasm executor layer:
Europa designed our own ep-sandbox to replace the original sp-sandbox used by Pallet Contracts, and modified ep_sandbox::Error
use patract_wasmi::Error as WasmiError;pub enum Error {Module(WasmiError),OutOfBounds,Execution,WasmiExecution(WasmiError),}Module(WasmiError) carries the original error information of the Wasm layer, and the to_execution_result in frame/contracts/src/wasm/runtime.rs is converted to String to throw an error message.
Europa's own ep-sandbox only has the std version (because Europa has removed all Wasm parts, there is no need for ep-sandbox to support no-std), so in the future, ep-sandbox can be replaced with different wasm executors to support running tests of different wasm executors, and replaced with wasm executors that support debugging and other features.
Currently ep-sandbox uses a forked version of wasmi as the executor, so the error it throws is WasmiError. See the next chapter for errors inwasmi.
2.error of host_functions:
The host function execution error will cause Trap, and will record TrapReason. No modification to the data structure, just record.
1.1.2 Execution during debugging#
The Europa forked version of Pallet Contracts has designed an object to record any information that can help debugging during contract execution:
/// Record the contract execution context.pub struct NestedRuntime { /// Current depth depth: usize, /// The current contract execute result ext_result: ExecResult, /// The value in sandbox successful result sandbox_result_ok: Option<ReturnValue>, /// Who call the current contract caller: AccountId32, /// The account of the current contract self_account: Option<AccountId32>, /// The input selector selector: Option<HexVec>, /// The input arguments args: Option<HexVec>, /// The value in call or the endowment in instantiate value: u128, /// The gas limit when this contract is called gas_limit: Gas, /// The gas left when this contract return gas_left: Gas, /// The host function call stack env_trace: EnvTraceList, /// The error in wasm wasm_error: Option<WasmErrorWrapper>, /// The trap in host function execution trap_reason: Option<TrapReason>, /// Nested contract execution context nest: Vec<NestedRuntime>,}In the model of Pallet Contracts, a contract calling another contract is in the "contract stack" model, so NestedRuntime will track the execution process of the entire contract stack, and use the property of nest to store a list of NestedRuntime to represent other contracts the the contract called.
In the process of executing a contract by Pallet Contracts, Europa records the relevant information in the execution process in the structure of NestedRuntime in the form of a bypass, and will print the NestedRuntime to the log (show the case later) in a certain format after the contract call ends. Contract developers can analyze the information printed by NestedRuntime to obtain various detailed information during the execution of the contract, which can be used in various situations:
- help to locate where the error occurs, including the following situations:
Pallet Contractslayerink!layer- The specific position in the contract layer
- Locate which level of the contract is when a contract calling another contract
- Analyze the information during the execution of the contract at this timing:
- Analyze the consumption of gas execution
- Analyze the call of
get_storageandset_storage, help reconstruct the contract code and analyze the demand ofrent - According to
selector,argsandvalue, analyze and locate whether the transaction parameters of the third-party SDK are legal. - Analyze the execution path of the contract and adjust the contract based on the
nestinformation and combined with theseal_callinformation. - etc.
The process of recording Pallet Contracts executing contract to NestEdRuntime is relatively fine-grained.
The process of logging the information of the execution contract of Pallet Contracts to NestEdRuntime is relatively fine-grained. Take seal_call in define_env! as an example:
pub struct SealCall { callee: Option<HexVec>, gas: u64, value: Option<u128>, input: Option<HexVec>, output: Option<HexVec>,}The attributes are basically Option<>. For example, before calling the contract, the input will be set to Some, and the return value will be set after the calling contract is normal. If there is an error in the calling contract, then output will remain None. Therefore, if input is Some and output is None, it means that there is a problem with the called contract during the process of calling the contract.
The current information of NestedRuntime is only printed in the log. In the future, NestedRuntime will be stored locally and provide corresponding RPC for external access. Therefore, in the future, third-party applications can obtain NestedRuntime for further processing. For example, in our Redspot, a plug-in can be designed to generate a contract call another contract topology based on the information of NestedRuntime, and a visual contract call path can be generated on the web wallet interface, etc.
1.2 on wasmi layer#
We forked wasmi and integrated it into ep-sandbox. Forked Pallet Contracts can obtain the error information of forked wasmi through ep-sandbox, including the backtrace information of wasmi.
If you need to make wasmi can retain the backtrace information during execution, you need to have the following functions:
- The "name section" section is required in the Wasm source file (see the specification of name section))
- Keep the "name section" information in the process of checking the contract by
Pallet Contractsand still have a corresponding relationship with the wasm source file after the process. - During the execution of
wasmi, the execution stack needs to be preserved with the key information of the functions. At the same time, the "name section" needs to be parsed and correspond to the function information reserved by thewasmiexecution stack.
The changes to 2 involve cargo-build and parity-wasm, while the changes to 1 and 3 are mainly in the forked wasmi, and a small part involves pwasm-utils.
1.2.1 Submitted Wasm files contains debug info from "name section"#
Frist of all, we have to submit wasm files which contain the debug info that the on-chain side can parse and get the panic errors.
Currently, parity/cargo-contract trims debug info while building contracts, we can get them back with the following steps.
1. Keep name section from striping#
The name section has been striped at cargo-contract/cmd/build.rs#L247.
2. Keep debug info from wasm-opt#
cargo-contract passes debug_info: false to wasm-opt, so the debug-info will be always optimized when we run wasm-opt, the code is here: cargo-contract/cmd/build.rs#L267.
3. Keep debug info from rustc#
cargo-contract executes realease build by default, here we can enable debug build or modify the opt-level flag of rustc to keep debug infos at cargo-contract/cmd/build.rs#L137.
1.2.2 Save debug info from the scraper of Pallet Contracts#
What happends to the Pallet Contracts while we calling a contract?
- Get the Wasm binary from storage
- Inject gas meter to the contract
- Inject stack height to the contract
- Put the contract into
sp-sandboxand execute it - Get the result from
sp-sandboxand return the result to us
1. Store name section while building Wasm module#
Pallet Contracts builds Wasm modules from storage and drops custom sections by default, here we should get them back.
2. Update function indices in name section while injecting gas meter#
Pallet Contracts reorders the indcies of functions in our Wasm contracts after injecting gas memter to the Wasm contracts at paritytech/wasm-utils/gas/mod.rs#L467, this will mess up the function indecies in name section that we can not get the correct backtraces.
3. Impelment Wasm backtrace to WASMI#
- Source: patractlabs/wasmi
Remember the last two steps in chapter 2, the core part of enabling Wasm backtrace to Pallet Contract is making wasmi support backtrace.
The process of executing a function in the interpreter of wasmi is like:
- Invoke the target function
- call and call and call over again
- Panic if the process breaks.
Add function info field to FuncRef#
FuncRef is the 'function' wasmi interpreter calling directly, so we need to embed the debug info into the FuncRef as the first time, source at wasmi/func.rs#L26.
//! patractlabs/wasmi/src/func.rs#L26/// ...pub struct FuncRef { /// ... /// Function name and index for debug info: Option<(usize, String)>,}Set function info using name section while parsing Wasm modules#
We alread have the info field in FuncRef, now we need to fill this field using name section while parsing Wasm modules, source at wasmi/module#L343.
//! wasmi/src/module.rs#L343// ...if has_name_section { if let Some(name) = function_names.get((index + import_count) as u32) { func_instance = func_instance.set_info(index, name.to_string()); } else { func_instance = func_instance.set_info(index, "<unknown>".to_string()); }}// ...Make the interpreter support trace#
However, we don't need to get infos of every functions but the panicked series in the stack of the interpreter, source at wasmi/runner.rs#L1491.
//! wasmi/src/runner.rs#L1491/// Get the functions of current the stackpub fn trace(&self) -> Vec<Option<&(usize, String)>> { self.buf.iter().map(|f| f.info()).collect::<Vec<_>>()}Gather debug infos when program breaks#
Just gather backtraces when we invoke function failed, source at wasmi/func.rs#L170.
//! wasmi/src/func.rs#L170// ...
let res = interpreter.start_execution(externals);if let Err(trap) = res {let mut stack = interpreter .trace() .iter() .map(|n| { if let Some(info) = n { format!("{:#}[{}]", rustc_demangle::demangle(&info.1), info.0) } else { "<unknown>".to_string() } }) .collect::<Vec<_>>();
// Append the panicing trapstack.append(&mut trap.wasm_trace().clone());stack.reverse();
// Embed this info into the trapErr(trap.set_wasm_trace(stack))
// ...1.3 Contract Log functions#
In the process of contract debugging, you need to know the internal execution of the contract and the intermediate data. In the current lack of debugging conditions (such as using gdb for debugging), log printing is the most convenient way. As mentioned in the Europa v0.2 proposal, the current Pallet Contracts and ink! already support format!+seal_println to format and print strings, but this mode has two defects :
- All the logs of
seal_printlnprinted on the node side aretarget: runtimeand levelDEBUG, but when developing complex contracts, a lot of logs will be printed. If you cannot filter bytargetand log level, then the development process will be full of interference from irrelevant information. - The contract developer wrote
seal_printlnwhen needed during the development process, but allseal_printlnmust be deleted when the contract is released. Although the contract developer can encapsulate a conditionally compiled function to control it, it is more convenient if a tool library already provides such a function.
Therefore, Europa provides a log library patractlabs/ink-log that mimics Rust's log crete to solve the above problems. Its usage is the same as that of Rust. log is completely consistent, which reduces the learning cost of developers.
The ink-log is generally implemented by the ChainExtension of Pallet Contracts, the agreed function_id is 0xfeffff00, and the message is transmitted in the wasm memory through the structure LoggerExt. Therefore this library is divided into the following two parts:
ink_log: In theink-log/contractsdirectory, provideinfo!,debug!,warn!,error!,trace!, same as Rust'sloglibrary in the same macro, and the call method of the macro is also the same. These macros are packaged implementations ofseal_chain_extensionson the ink! side, and are tool library for contract developers. For example, after this library is introduced in the contractCargo.toml, the log can be printed as follows:In
Cargo.toml:[dependencies]ink_log = { version = "0.1", git = "https://github.com/patractlabs/ink-log", default-features = false, features = ["ink-log-chain-extensions"] } [features]default = ["std"]std = [ # ... "ink_log/std"]In the contract, you can use the following methods to print logs in the node:
ink_log::info!(target: "flipper-contract", "latest value is: {}", self.value);
runtime_log: In the ink-log/runtime directory, this library is based on the contents of the function_id and LoggerExt structures passed from ChainExtensions to call the corresponding logs under debug in frame_support to print. It is an implementation library of ink_log prepared for developers of the chain. **For example, chain developers can use it in their own ChainExtensions:
In Cargo.toml:
[dependencies]runtime_log = { version = "0.1", git = "https://github.com/patractlabs/ink-log", default-features = false }
[features]default = ["std"]std = [ # ... "runtime_log/std"] In ChainExtensions's implementation:
pub struct CustomExt;impl ChainExtension for CustomExt { fn call<E: Ext>(func_id: u32, env: Environment<E, InitState>) -> Result<RetVal, DispatchError> where <E::T as SysConfig>::AccountId: UncheckedFrom<<E::T as SysConfig>::Hash> + AsRef<[u8]>, { match func_id { ... => {/* other ChainExtension */ } 0xfeffff00 => { // TODO add other libs runtime_log::logger_ext!(func_id, env); // or use // LoggerExt::call::<E>(func_id, env) Ok(RetVal::Converging(0)) } } }}ink_log corresponds to runtime_log, so if contract developers need to use ink_log, they need to pay attention to the chain corresponding to the debugging contract that needs to implement runtime_log.
On the other hand, after contract developers introduce ink_log, they need to pay attention to features = ["ink-log-chain-extensions"], ink_log will call seal_chain_extensions to interact with the chain only when this feature is enabled. Without this feature, noop will be used to skip the process of contract printing.
Therefore, contract developers can control the contract to print logs in the debugging environment and the production environment through features. The contract compiled in the debugging environment opens the "ink-log-chain-extensions" feature, and the contract compiled in the production environment removes this feature.
2. What Europa can do in v0.2#
2.1 Build#
For contract developers, it is necessary to prepare Europa and cargo-contract tools.
2.1.1 Europa#
The building process for this project is as same as Substrate.
When building finished, current executable file in target directory is named Europa.
git clone --recurse-submodules https://github.com/patractlabs/Europa.git2.1.2 cargo-contract#
If you want to see the backtrace executed by Wasm during the operation of Europa, you must use the cargo-contract version we provide. Because the current paritytech repo cargo-contract uses the highest optimization level when compiling the contract, and discards the "name section" part in Wasm. As mentioned above, if you need to print the call stack information in the wasmi execution contract, the contract file must have the "name section" part, so the use of the cargo-contract provided by paritytech cannot meet the requirements. We completed this function in our forked repo. On the other hand, we think that the function of "name section" in Wasm may not only be needed by Europa, so we submitted pr#131[Enable debug info to the source warehouse with flag in command build] provides this feature.
Before this PR is merged, currently only the cargo-contract version provided by us (Patract Labs) can be used:
cargo install --git https://github.com/patractlabs/cargo-contract --branch cmd/debug --forceIf you do not want this version of cargo-contract to override the version released by paritytech, then it is recommended to compile locally and use the compiled cargo-contract directly:
git clone https://github.com/patractlabs/cargo-contract --branch cmd/debugcd cargo-contractcargo build --releaseNote: Executing the
cargo-contract buildcommand requires thedefault toolchainof the rust tool-chain to benightly, otherwise you can only usecargo +nightly contract build, but usingcargoto callcargo-contractneeds to be executedcargo installinstalls or overwrites the compiled product in the~/.cargo/bindirectory, and cannot co-exist with paritytech'scargo-contract
Execute:
cargo-contract build --help# orcargo +nightly contract build --helpIf you can see:
FLAGS: -d, --debug Emits debug info into wasm fileIt means that you are using the cargo-contract provided by Patract Labs. If you want to see the backtrace of the Wasm contract execution crash while using Europa, you need to add the --debug command when compiling the contract.
Using the --debug command will generate another file besides the normal file in the target/ink directory of the originally compiled contract, ending with *.src.wasm. This *.src.wasm file is the Wasm contract file containing the "name section" part.
If you need to use Europa for testing, the contract deployed to Europa needs to use this *.src.wasm file instead of the originally generated *.wasm file.
example#
We can use one simple case and other cases we have encountered to verify the reliability of Europa's positioning problems.
In the following context, the methods of starting Europa are all used by:
$ Europa --tmp -lruntime=debugEvery time Europa is started in this way, new data is created. If you want to keep Europa's execution data, please refer to Europa's README or Europa v0.1's [Report](https://polkadot.polkassembly.io/post/ 166), you can get more command introduction.
Case 1:Simple case#
For example, we modify the example contract ink/example/erc20 in the ink! project as follows:
#[ink(message)]pub fn transfer(&mut self, to: AccountId, value: Balance) -> Result<()> { let from = self.env().caller(); self.transfer_from_to(from, to, value)?; panic!("123"); Ok(())}Wasm, it corresponds to the code after the macro expansion of the original file, so if you want to compare the errors of the call stack, you need to expand the macro of the original contract:
cargo install expandcd ink/example/erc20cargo expand > tmp.rsAfter reading the tmp.rs file, we can know that Wasm needs to go through when it executes the transfer function:
fn call() -> u32 -> <Erc20 as ::ink_lang::DispatchUsingMode>::dispatch_using_mode(...)-> <<Erc20 as ::ink_lang::ConstructorDispatcher>::Type as ::ink_lang::Execute>::execute(..) # compile selector at here-> ::ink_lang::execute_message_mut-> move |state: &mut Erc20| { ... } # a closure-> <__ink_Msg<[(); 2644567034usize]> as ::ink_lang::MessageMut>::CALLABLE-> transferTherefore, if the panic in transfer is encountered during the contract call, the backtrace of Wasm should be similar to this.
First we start Europa:
$ Europa --tmp -lruntime=debugThen we deploy this erc20 and call transfer to execute.
We can use Polkadot/Substrate Portal or use RedSpot to verify this process. Suppose we use RedSpot to execute a transfer call of this wrong ERC20 contract. Please note that the --debug subcommand must be added in the process of compiling the contract:
$ npx redspot-new erc20$ cd erc20/contracts# add panic in `transfer` function as abrove$ vim lib.rs # notice must add --debug when compile contract# due current cargo-contract is not paritytech, we need to copy compile product into `artifacts` directory. RedSpot would support Europa and PatractLabs's cargo-contract in next version.$ cargo +nightly contract build --debug $ mkdir ../artifacts# notice must cp erc20.src.wasm, not erc20.wasm$ cp ./target/ink/erc20.src.wasm ../artifacts # notice must rename metadata.json to erc20.json$ cp ./target/ink/metadata.json ../artifacts/erc20.json $ cd ../# enter redspot console, use `--no-compile` to deny recompile contract$ npx redspot console --no-compile # in redspot consoleWelcome to Node.js v12.16.1.Type ".help" for more information.> > var factory = await patract.getContractFactory('erc20')# do following command could deploy the erc20 contract> var contract = await factory.deployed('new', '1000000', {value: 20000000000, salt:1})# do a transfer call directly> await contract.transfer("5GcTYx4dPTQfi4udKPvE4VKmbooV7zY6hNYVF9JXHJL4knNF", 100)Then in Europa's log, you can see:
1: NestedRuntime { ext_result: [failed] ExecError { error: DispatchError::Module {index:5, error:17, message: Some("ContractTrapped"), orign: ErrorOrigin::Caller }} caller: d43593c715fdd31c61141abd04a99fd6822...(5GrwvaEF...), self_account: b6484f58b7b939e93fff7dc10a654af7e.... (5GBi41bY...), selector: 0xfae3a09d, args: 0x1cbd2d43530a44705ad088af313e18f80b5...., value: 0, gas_limit: 409568000000, gas_left: 369902872067, env_trace: [ seal_value_transferred(Some(0x00000000000000000000000000000000)), seal_input(Some(0xfae3a09d1cbd.....)), seal_get_storage((Some(0x0100000000000....), Some(0x010000000100000001000000))), # ... seal_caller(Some(0xd43593c715fdd31c61141abd...)), seal_hash_blake256((Some(0x696e6b20686173....), Some(0x0873b31b7a3cf....))), # ... seal_deposit_event((Some([0x45726332303a....00000000000]), Some(0x000..))), ], trap_reason: TrapReason::SupervisorError(DispatchError::Module { index: 5, error: 17, message: Some("ContractTrapped") }), wasm_error: Error::WasmiExecution(Trap(Trap { kind: Unreachable })) wasm backtrace: | core::panicking::panic[28] | erc20::erc20::_::<impl erc20::erc20::Erc20>::transfer[1697] | <erc20::erc20::_::__ink_Msg<[(); 2644567034]> as ink_lang::traits::MessageMut>::CALLABLE::{{closure}}[611] | core::ops::function::FnOnce::call_once[610] | <erc20::erc20::_::_::__ink_MessageDispatchEnum as ink_lang::dispatcher::Execute>::execute::{{closure}}[1675] | ink_lang::dispatcher::execute_message_mut[1674] | <erc20::erc20::_::_::__ink_MessageDispatchEnum as ink_lang::dispatcher::Execute>::execute[1692] | erc20::erc20::_::<impl ink_lang::contract::DispatchUsingMode for erc20::erc20::Erc20>::dispatch_using_mode[1690] | call[1691] ╰─><unknown>[2387] , nest: [],}Let us explain the information printed above:
ext_result: indicates that this contract call is displayed as successful or failed:[success]: indicates the successful execution of this contract (Note: the successful execution of the contract does not mean the successful execution of the business logic of the contract itself. There may be an error return inink!or the business logic of the contract itself, as in case 3 in the following text.) And theExecResultValue {flag:0, data: 0x...}followed by[success]indicates the return value after this contract is executed.[failed]: indicates that the execution of this contract failed, and theExecError {.. }followed by[failed]indicates the cause of this error. The reason for this is the value recorded ineventon the chain, which is the value defined indecl_error!ofPallet Contracts.
1: NestedRuntime&nest: The contract information that represents the current print information is located in the first layer of the contract call stack. If the current contract calls another contract, it will appear in the array of thenestfield.2: NestedRuntimeand1: NestedRuntimehas the same structure. Among them,2indicates that the called contract is in the second layer of the contract call stack. If several contracts are called across contracts in the current contract, there will be severalNestedRuntimein the array ofnest. If there are other contract calls in the second-level contract, the same goes for.For example, if there are contracts A, B, C, if it is the following situation:
After A calls B, it returns to A to continue execution, and then calls contract C
|A|| |->|B|| |<-| |->|C|| |<-Then it will produce a log print similar to the following:
1: NestedRuntime { self_account: A, nest:[ 2: NestedRuntime { self_account: B, nest:[], }, 2: NestedRuntime { self_account: C, nest:[], } ]}After A calls B, B calls contract C again, and finally returns to A
|A|| |->|B|| | | |->|C|| | | |<-| |<-Then it will produce a log print similar to the following:
1: NestedRuntime { self_account: A, nest:[ 2: NestedRuntime { self_account: B, nest:[ 3: NestedRuntime { self_account: C, nest:[], } ], } ]}
caller: who is the caller of the current contract. If the contract calls the contract, the value of the called contract is the address of the upper-level contract.self_account: represents the address of the current contract itself.selector&args&value: Represents theselectorand parameters passed in when calling the current contract. These information can quickly locate whether the calling contract method is correct.gas_limit&gas_left: Represents thegas_limitpassed in when the contract is currently called and the remaining gas after executing this layer. Note here thatgas_leftrefers to the remaining gas after the execution of this layer of contract, so In the contract call contract, the gas consumed by each layer of contract can be determined throughgas_left, not only get the consumption after the execution of the entire contract.env_trace: Indicates that during the execution of the current layer of the contract, each time host_function is called in the contract Wasm execution, a record will be added to the list here. Because all host_functions and the definitions indefine_env!in thePallet Contractsmodule are related, so tracingenv_tracecan trace the process of interacting withPallet Contractsduring the execution of the current Wasm contract.For example, if following thing appears in
env_trace:seal_call: It means that there is a contract call contract situation in the current contract. According to the order in whichseal_callappears inenv_trace, it can correspond tonestto calculate the state before and after the contract calls the contract.seal_get_storage&seal_set_storage: It means that data read and write occurred in the contract. Through these two interfaces, it is possible to intercept and count the data read and write during the execution of the current contract, and the data size calculated byseal_set_storagecan also be used to infer the storage size required byrent.seal_deposit_event: indicates that the event is printed in the contract. Here you can intercept the content of each event separately, instead of getting a unified event at the end. And the following text will use an example to surface that Europa can quickly locate the bug in thehost_function.
On the other hand, the statistics of
env_traceare relatively fine-grained. For example, if there are multiple possible errors inhost_function, when an error occurs, all the information before the error will be retained, so it can be located to the place where the problem occurred during the execution ofhost_function.And if there is an error in
host_functionthat causes the contract to end execution,env_tracerecords the last errorhost_functioncall, so you can directly locate whichhost_functioncaused the contract execution exception.trap_reason: According to the definition ofTrapReasoninPallet Contracts,trap_reasoncan be divided into 2 categories:Return&Termination&Restoration: indicates that the contract exit is the design ofPallet Contracts, not an internal error. This type of trap indicates that the contract is executed normally and is not an error.SupervisorError: Indicates that an error occurred during the execution of the contract calling host_function.
Therefore, the current Europa log printing design is designed to record whenever
trap_reasonappears. On the other hand,trap_reasonmay not always appear during the execution of the contract. Combining the design ofPallet Contractsandink!, there is a case where the successful execution of the contract or the execution failure in theink!layer does not generatetrap_reason. Therefore, in addition to recordingtrap_reason, Europa also records the results returned by the Wasm executor after execution, which is recorded withsandbox_result_ok.
sandbox_result_ok: The value ofsandbox_result_okrepresents the result of the contract after the Wasm executor is executed. This value could have been recorded assandbox_result, including correct and incorrect conditions. However, due to the limitations of Rust and combined with the business logic ofPallet Contracts, only the result ofsandbox_resultis kept asOkhere. For log printing, Europa is designed to printsandbox_result_okonly when trap_reason is the first case, as information to assist in judging contract execution.sandbox_result_okis the Wasm executor result after callinginvokeAfter the processing ofto_execution_result, if there is notrap_reason, the result ofOk(..)is [discarded](https://github.com/paritytech/substrate/blob/712085115cdef4a79a66747338c920d6ba4e479f /frame/contracts/src/wasm/runtime.rs#L366-L368). But in fact there are two situations here:- An error occurred in
ink!: According to the implementation ofink!, before calling the functions wrapped by the contract#[ink(message)]and#[ink(constructor)], the input The process of decoding and matchingselector. If an error occurs during this process, the contract will return error codeDispatchError. But for the Wasm executor, the Wasm code is executed normally, so the result will be returned, including this error code. This contract execution process is an error situation. - The return value of
#[ink(message)]is defined as(): According to the implementation ofink!, if the return value type is(),seal_reasonwill not be called, so it will not Containstrap_reason. This contract execution process is an correct situation.
Since
ink!is only a contract implementation that runs onPallet Contracts, other implementations may have different rules, so currentlysandbox_result_okis only used to assist in determining the execution of theink!contract, the value isReturnValue. Among them, if the<num>part ofReturnValue::Value(<num>)of the log is not 0, it means that there may be an error in the execution ofink!. You can useink!forDispatchErrorThe error code determines the error.- An error occurred in
wasm_error: indicates the backtrace when Wasm executes an error. This part will be printed only whenext_resultisfailed.In the above example, because the execution of
transferwill triggerpanic, you can see that the cause of the error here isWasmiExecution(Trap(Trap {kind: Unreachable })), indicating that this time the failure is due to execution The situation ofUnreacblein the contract process is caused, and the backtrace information below also very accurately describes the function execution call stack when an error is encountered after the expansion of the contract macro discussed above. The following calling process can be clearly found from the backtrace.call -> dispatch_using_mode -> ... -> transfer -> panicThis process is consistent with the original information of the contract.
Case 2:ContractTrap caused by locating duplicate topics#
Some time ago, we (Patract Labs) reported a bug to ink!, see issue:"When set '0' value in contracts event, may cause Error::ContractTrapped and panic in contract #589" . It is very difficult to locate this error before Europa has developed the relevant function. Thank you @athei located the error. Here we reproduce this error and use Europa's log to quickly analyze and locate the place where the bug appears:
checkout
ink!to commit8e8fe09565ca6d2fad7701d68ff13f12deda7eedcd inkgit checkout 8e8fe09565ca6d2fad7701d68ff13f12deda7eed -b tmpGo in
ink/examples/erc20/lib.rs:L90to changevalueto0_u128inTransfer#[ink(constructor)]pub fn new(initial_supply: Balance) -> Self { //... Self::env().emit_event(Transfer { from: None, to: Some(caller), // change this from `initial_supply` to `0_u128` value: 0_u128.into() // initial_supply, }); instance}Execute
cargo +nightly contract build --debugto compile the contractUse RedSpot or
Polkadot/Substrate Portalto deploy this contract ( Note that you must use the erc20.src.wasm file)
You should encounter DuplicateTopics in the deployment phase (before this bug is corrected, the reported error is ContractTrap), and in the Europa log Will show:
1: NestedRuntime { #... env_trace: [ seal_input(Some(0xd183512b0)), #... seal_deposit_event((Some([0x45726332303a3a5472616e736....]), None)), ], trap_reason: TrapReason::SupervisorError(DispatchError::Module { index: 5, error: 23, message: Some("DuplicateTopics") }), wasm_error: Error::WasmiExecution(Trap(Trap { kind: Host(DummyHostError) })) wasm backtrace: | ink_env::engine::on_chain::ext::deposit_event[1623] | ink_env::engine::on_chain::impls::<impl ink_env::backend::TypedEnvBackend for ink_env::engine::on_chain::EnvInstance>::emit_event[1564] | ink_env::api::emit_event::{{closure}}[1563] | <ink_env::engine::on_chain::EnvInstance as ink_env::engine::OnInstance>::on_instance[1562] | ink_env::api::emit_event[1561] | erc20::erc20::_::<impl ink_lang::events::EmitEvent<erc20::erc20::Erc20> for ink_lang::env_access::EnvAccess<<erc20::erc20::Erc20 as ink_lang::env_access::ContractEnv>::Env>>::emit_event[1685]# ...# ... | deploy[1691] ╰─><unknown>[2385] , nest: [],}You can see from the above log:
- The last record of
env_traceisseal_deposit_eventinstead ofseal_return(when the contract is executed correctly, the last record must beseal_return) - The second parameter of
seal_deposit_eventisNoneinstead of an existing value, which indicates that the host_function ofseal_deposit_eventhas not been executed, but an error occurred during the execution (see the forked dependency of Europa) See the [corresponding implementation] (https://github.com/patractlabs/substrate/blob/3624deb47cabe6f6cd44ec2c49c6ae5a29fd2198/frame/contracts/src/wasm/runtime.rs#L1399) for the source code of the version ofPallet Contracts. - Combined with the error stack of wasm backtrace, we can intuitively see that the top call stack of backtrace is
deposit_event.
Therefore, combining the above information, we can directly infer that the host_function of seal_deposit_event has an exception during the execution. (Before the submission of Pallet Contractspull#7762, we recorded the error message in host_function. After the merge, we used trap_reason unified error message.)
Case 3: When error is caused by the chain using type Balance=u64 instead of type Balance=u128#
If the chain uses the definition of Balance=u64, and the definition of Balance in the chain is unknown to ink! (the default definition of Balance is u128). Therefore, when using u128 to define Balance's ink! as a dependency compiled contract, when running on a chain where Balance is defined as u64, it will cause the Pallet Contracts module to transfer values to the contract , The contract internally regards the value of u64 as a decoding error of u128.
Take the example contract of erc20 as an example, after expanding the macro of the contract, you can see:
- When there is an error in the
dispatch_using_modestage of decodinginput, the contract returns with::ink_lang::DispatchError::CouldNotReadInput, but the model design ofPallet Contractsbelieves that the Wasm contract execution is not abnormal. - In the call of
call, sincedeny_paymentis checked before callingdispatch_using_mode, and if an Error is returned when checkingdeny_payment, it will be directlypanic.
Therefore, in this case, the contract for deploying (Instantiate) ERC20 will execute normally, and any method of ERC20 such as transfer will be called with ContractTrap.
Let's look at these two situations separately:
instantiatestage:1: NestedRuntime { ext_result: [success] ExecError { error: DispatchError::Module {index:5, error:17, message: Some("ContractTrapped"), orign: ErrorOrigin::Caller }}#... env_trace: [ seal_input(Some(0xd183512b008cb6611e0100000000000000000000)), seal_caller(Some(0xd43593c715fdd31c61141abd04a99fd682)), //... seal_set_storage((Some(0x030000000100000...), Some(0x000000000000000...))), ], sandbox_result_ok: RuntimeValue::Value(7), nest: [],}From the above log, we can see:
The end of
env_tracedoes not end withseal_return, it means that the contract has not been executed normally. Because it can be seen from the design ofink!that if you enter#[ink(constructor)]normally or enter#[ink(message)], then must be executed to::ink_lang::execute_message(::ink_lang::execute_messagewill callseal_return), and the absence ofseal_returnmeans that the execution has not reached the stage ofexecute.sandbox_result_okindicates that the return value of the execution is7. By queryingink!for the implementation ofDispatchError, you can see that this error code representsCouldNotReadInputDispatchError::CouldNotReadInput => Self(0x07),According to the expanded code of the contract macro, you can see that in the
dispatch_using_modefunction,::ink_env::decode_inputis called before callingexecute, and this function has areturn Errorsituation. Therefore, it is reasonable to guess that an exception occurred when parsinginput. The input parameterargs:0x008cb6611e0100000000000000000000is recorded in the log. Observing this parameter, it can be found that its length is significantly smaller than theu128code. Therefore, it can be inferred fromargsandenv_tracethat an error occurred when decodinginput.// this part code is expanded by erc20 example.::ink_env::decode_input::<<Erc20 as ::ink_lang::ConstructorDispatcher>::Type>().map_err(|_| ::ink_lang::DispatchError::CouldNotReadInput)?
At this point, the contract instantiation is successful, but the constructor to execute the instantiation exists. Therefore, the contract exists on the chain but the process of #[ink(constructor)] is not executed normally.
The
callstage, such as callingtransfer:Calling
transferto the above successfully instantiated function,ContractTrapwill appear, Europa's log shows as follows:1: NestedRuntime { ext_result: [failed] ExecError { error: DispatchError::Module {index:5, error:17, message: Some("ContractTrapped"), orign: ErrorOrigin::Caller }}# ... env_trace: [ seal_value_transferred(Some(0x0000000000000000)), ], wasm_error: Error::WasmiExecution(Trap(Trap { kind: Unreachable })) wasm backtrace: | core::panicking::panic_fmt.60[1743] | core::result::unwrap_failed[914] | core::result::Result<T,E>::expect[915] | ink_lang::dispatcher::deny_payment[1664] | call[1691] ╰─><unknown>[2387] , nest: [],}First notice that the last record of
env_traceis still notseal_return, and the error cause ofwasm_errorisWasmiExecution::Unreachable. Therefore, it can be determined thatpanicorexpectwas encountered during the execution of the contract.From the wasm backtrace, it is very obvious that the execution process is
call -> deny_payment -> expectAccording to the code expanded macro (cd ink/examples/erc20; cargo expand> tmp.rs), we can see:
#[no_mangle]fn call() -> u32 { if true { ::ink_lang::deny_payment::<<Erc20 as ::ink_lang::ContractEnv>::Env>() .expect("caller transferred value even though all ink! message deny payments") } ::ink_lang::DispatchRetCode::from( <Erc20 as ::ink_lang::DispatchUsingMode>::dispatch_using_mode( ::ink_lang::DispatchMode::Call, ), ) .to_u32()} Therefore, it can be judged that an error was returned in deny_payment during the execution of the contract in the process of transfer, and the direct processing of the error as expect resulted in the execution result of wasmi being Unreachable Tracking the code of deny_payment can find that the function returns expect caused by Error
Note,The relevant code is as follows:
In
ink_langhttps://github.com/paritytech/ink/blob/master/crates/lang/src/dispatcher.rs#L140-L150pub fn deny_payment<E>() -> Result<()>where E: Environment,{ let transferred = ink_env::transferred_balance::<E>() .expect("encountered error while querying transferred balance"); if transferred != <E as Environment>::Balance::from(0u32) { return Err(DispatchError::PaidUnpayableMessage) } Ok(())}There will be a difference between the
off_chainpart and theon_chainpart in the ink,off_chainwill think that an error is returned at the stage ofink_env::transferred_balance::<E>(), so it is executingAfter transferred_balance, you will encounterexpectwhich leads topanic, and part ofon_chainis taken from the memory of wasm, it will normally get the characters corresponding to u128 length and decode to gettransferred, which is just decoded The result will not meet expectations, causingtransferred!=0to makedeny_paymentreturn an Error, and the part wheredeny_paymentis called in the macro expansion of the contract triggersexpectif true { ::ink_lang::deny_payment::<<Erc20 as ::ink_lang::ContractEnv>::Env>() .expect("caller transferred value even though all ink! message deny payments")}Therefore, for wasm backtrace,
expectappears whendeny_paymentis called incall, not whentransferred_balanceis called indeny_payment.This example side shows that
ink!currently does not completely correspond to the processing ofoff_chainandon_chain, and may cause difficult-to-check errors for contract users in some casesVerify v0.2#
Construct incorrect contracts and execute logs printing to determine whether it meets expectationsDisplay the call statistics of thedefine_env!interface during contract executionrun test case
instantiate_return_codein patractlabs/substrate branch:europa-contracts$ cd europa/vendor/substrate/frame/contracts$ cargo test --package pallet-contracts --lib tests::instantiate_return_code -- --exact# then you could see1: NestedRuntime { caller: 0101010101010101010101010101010101010101010101010101010101010101 (5C62Ck4U...),# ...} 1: NestedRuntime {# ...} 1: NestedRuntime {# ...}# ...run test case
run_out_of_gasin patractlabs/substrate branch:europa-contracts$ cd europa/vendor/substrate/frame/contracts$ cargo test --package pallet-contracts --lib tests::run_out_of_gas -- --exact1: NestedRuntime {# ...} 1: NestedRuntime {#... gas(None), ], trap_reason: TrapReason::SupervisorError(DispatchError::Module { index: 0, error: 6, message: Some("OutOfGas") }), nest: [],}
Anyone can check whether the printed log matching with the test case.
Execute the log printing function, provide formatted printing examples of different data, and judge whether it meets expectationsUsing
ink-loginink!example could test this part.Construct a contract that crashes under different conditions and record the log after execution. Then judge whether the backtrace information of the contract execution is completely printed, and check whether it matches the actual execution of the collapsed contract.We provide a test case repo europa_contracts_test_templates. Any one could using Polkadot/Substrate Portal or RedSpot to deploy and call this test contract to verify this.