get runtime logs from vm (#244)

executor/pkg/package.json

@@ -1,7 +1,7 @@
 {
   "name": "@acala-network/chopsticks-executor",
   "description": "Chopsticks executor",
-  "version": "0.5.3",
+  "version": "0.5.10",
   "license": "Apache-2.0",
   "repository": {
     "type": "git",

executor/src/proof.rs

@@ -4,7 +4,7 @@ use smoldot::{
         bytes_to_nibbles,
         proof_decode::{decode_and_verify_proof, Config},
         proof_encode::ProofBuilder,
-        proof_node_codec, trie_structure, Nibble,
+        trie_node, trie_structure, Nibble,
     },
 };
 use std::collections::BTreeMap;
@@ -63,10 +63,10 @@ pub fn create_proof(
     }
 
     for (key, value) in decoded.iter_ordered() {
-        let decoded_value = proof_node_codec::decode(value.node_value).unwrap();
+        let decoded_value = trie_node::decode(value.node_value).unwrap();
 
         if let trie_structure::Entry::Vacant(vacant) = trie.node(key.iter().map(|x| x.to_owned())) {
-            if let proof_node_codec::StorageValue::Unhashed(value) = decoded_value.storage_value {
+            if let trie_node::StorageValue::Unhashed(value) = decoded_value.storage_value {
                 vacant.insert_storage_value().insert(value.to_vec(), vec![]);
             }
         }
@@ -100,7 +100,7 @@ pub fn create_proof(
             vec![]
         };
 
-        let decoded = proof_node_codec::Decoded {
+        let decoded = trie_node::Decoded {
             children: std::array::from_fn(|nibble| {
                 let nibble = Nibble::try_from(u8::try_from(nibble).unwrap()).unwrap();
                 if trie
@@ -121,13 +121,13 @@ pub fn create_proof(
                 .collect::<Vec<_>>()
                 .into_iter(),
             storage_value: if has_storage_value {
-                proof_node_codec::StorageValue::Unhashed(&storage_value[..])
+                trie_node::StorageValue::Unhashed(&storage_value[..])
             } else {
-                proof_node_codec::StorageValue::None
+                trie_node::StorageValue::None
             },
         };
 
-        let node_value = proof_node_codec::encode_to_vec(decoded)
+        let node_value = trie_node::encode_to_vec(decoded)
             .map_err(|e| format!("Failed to encode node proof {:?}", e.to_string()))?;
 
         proof_builder.set_node_value(&key, &node_value, None)

executor/src/task.rs

@@ -64,13 +64,15 @@ pub struct TaskCall {
     storage: Vec<(HexString, Option<HexString>)>,
     mock_signature_host: bool,
     allow_unresolved_imports: bool,
+    runtime_log_level: u32,
 }
 
 #[derive(Serialize, Deserialize, Debug)]
 #[serde(rename_all = "camelCase")]
 pub struct CallResponse {
     result: HexString,
     storage_diff: Vec<(HexString, Option<HexString>)>,
+    runtime_logs: Vec<String>,
 }
 
 #[derive(Serialize, Deserialize, Debug)]
@@ -100,6 +102,7 @@ pub async fn run_task(task: TaskCall, js: crate::JsCallback) -> Result<TaskRespo
     })
     .unwrap();
     let mut ret: Result<Vec<u8>, String> = Ok(Vec::new());
+    let mut runtime_logs: Vec<String> = vec![];
 
     for (call, params) in task.calls {
         let mut vm = runtime_host::run(runtime_host::Config {
@@ -109,6 +112,7 @@ pub async fn run_task(task: TaskCall, js: crate::JsCallback) -> Result<TaskRespo
             top_trie_root_calculation_cache: None,
             storage_top_trie_changes,
             offchain_storage_changes,
+            max_log_level: task.runtime_log_level,
         })
         .unwrap();
 
@@ -186,6 +190,10 @@ pub async fn run_task(task: TaskCall, js: crate::JsCallback) -> Result<TaskRespo
 
                 storage_top_trie_changes = success.storage_top_trie_changes;
                 offchain_storage_changes = success.offchain_storage_changes;
+
+                if !success.logs.is_empty() {
+                    runtime_logs.push(success.logs);
+                }
             }
             Err(err) => {
                 ret = Err(err.to_string());
@@ -204,6 +212,7 @@ pub async fn run_task(task: TaskCall, js: crate::JsCallback) -> Result<TaskRespo
         TaskResponse::Call(CallResponse {
             result: HexString(ret),
             storage_diff: diff,
+            runtime_logs,
         })
     }))
 }

package.json

@@ -14,7 +14,7 @@
 		"prepare": "husky install",
 		"clean": "yarn workspaces foreach run clean",
 		"build": "yarn workspaces foreach run build",
-		"build-wasm": "wasm-pack build executor --target nodejs --scope acala-network",
+		"build-wasm": "wasm-pack build executor --target nodejs --scope acala-network && echo '' >> executor/pkg/package.json",
 		"build-wasm-logging": "yarn build-wasm --features=logging",
 		"check": "cd executor && cargo check --locked",
 		"test": "vitest run",

packages/chopsticks/src/blockchain/block.ts

@@ -10,12 +10,14 @@ import type { HexString } from '@polkadot/util/types'
 import { Blockchain } from '.'
 import { RemoteStorageLayer, StorageLayer, StorageLayerProvider, StorageValue, StorageValueKind } from './storage-layer'
 import { compactHex } from '../utils'
+import { defaultLogger } from '../logger'
 import { getRuntimeVersion, runTask, taskHandler } from '../executor'
 import type { RuntimeVersion } from '../executor'
 
 export type TaskCallResponse = {
   result: HexString
   storageDiff: [HexString, HexString | null][]
+  runtimeLogs: string[]
 }
 
 export class Block {
@@ -233,10 +235,16 @@ export class Block {
         storage,
         mockSignatureHost: this.#chain.mockSignatureHost,
         allowUnresolvedImports: this.#chain.allowUnresolvedImports,
+        runtimeLogLevel: this.#chain.runtimeLogLevel,
       },
       taskHandler(this)
     )
-    if (response.Call) return response.Call
+    if (response.Call) {
+      for (const log of response.Call.runtimeLogs) {
+        defaultLogger.info(`RuntimeLogs:\n${log}`)
+      }
+      return response.Call
+    }
     if (response.Error) throw Error(response.Error)
     throw Error('Unexpected response')
   }

packages/chopsticks/src/blockchain/index.ts

@@ -26,6 +26,7 @@ export interface Options {
   header: { number: number; hash: HexString }
   mockSignatureHost?: boolean
   allowUnresolvedImports?: boolean
+  runtimeLogLevel?: number
   registeredTypes: RegisteredTypes
 }
 
@@ -35,6 +36,7 @@ export class Blockchain {
   readonly db: DataSource | undefined
   readonly mockSignatureHost: boolean
   readonly allowUnresolvedImports: boolean
+  readonly runtimeLogLevel: number
   readonly registeredTypes: RegisteredTypes
 
   readonly #txpool: TxPool
@@ -55,12 +57,14 @@ export class Blockchain {
     header,
     mockSignatureHost = false,
     allowUnresolvedImports = false,
+    runtimeLogLevel = 0,
     registeredTypes = {},
   }: Options) {
     this.api = api
     this.db = db
     this.mockSignatureHost = mockSignatureHost
     this.allowUnresolvedImports = allowUnresolvedImports
+    this.runtimeLogLevel = runtimeLogLevel
     this.registeredTypes = registeredTypes
 
     this.#head = new Block(this, header.number, header.hash)

packages/chopsticks/src/cli.ts

@@ -54,6 +54,10 @@ const defaultOptions = {
     desc: 'Path to config file',
     string: true,
   },
+  'runtime-log-level': {
+    desc: 'Runtime maximum log level [off = 0; error = 1; warn = 2; info = 3; debug = 4; trace = 5]',
+    number: true,
+  },
 }
 
 yargs(hideBin(process.argv))

packages/chopsticks/src/dry-run-preimage.ts

@@ -79,6 +79,7 @@ export const dryRunPreimage = async (argv: Config) => {
       storage: [],
       mockSignatureHost: false,
       allowUnresolvedImports: false,
+      runtimeLogLevel: argv['runtime-log-level'] || 0,
     },
     taskHandler(block)
   )
@@ -87,6 +88,10 @@ export const dryRunPreimage = async (argv: Config) => {
     throw new Error(result.Error)
   }
 
+  for (const logs of result.Call.runtimeLogs) {
+    defaultLogger.info(`RuntimeLogs:\n${logs}`)
+  }
+
   const filePath = await generateHtmlDiffPreviewFile(block, result.Call.storageDiff, hash)
   console.log(`Generated preview ${filePath}`)
   if (argv['open']) {
@@ -101,10 +106,10 @@ export const dryRunPreimage = async (argv: Config) => {
     const { outcome, storageDiff } = await context.chain.dryRunExtrinsic(input)
     if (outcome.isErr) {
       throw new Error(outcome.asErr.toString())
-    } else {
-      defaultLogger.info(outcome.toHuman(), 'dry_run_outcome')
     }
 
+    defaultLogger.info(outcome.toHuman(), 'dry_run_outcome')
+
     const filePath = await generateHtmlDiffPreviewFile(
       context.chain.head,
       storageDiff,

packages/chopsticks/src/dry-run.ts

@@ -15,10 +15,10 @@ export const dryRun = async (argv: Config) => {
 
   if (outcome.isErr) {
     throw new Error(outcome.asErr.toString())
-  } else {
-    defaultLogger.info(outcome.toHuman(), 'dry_run_outcome')
   }
 
+  defaultLogger.info(outcome.toHuman(), 'dry_run_outcome')
+
   if (argv['html']) {
     const filePath = await generateHtmlDiffPreviewFile(
       context.chain.head,

packages/chopsticks/src/executor.ts

@@ -68,6 +68,7 @@ export const runTask = async (
     storage: [HexString, HexString | null][]
     mockSignatureHost: boolean
     allowUnresolvedImports: boolean
+    runtimeLogLevel: number
   },
   callback: JsCallback = emptyTaskHandler
 ) => {
@@ -115,6 +116,7 @@ export const getAuraSlotDuration = _.memoize(async (wasm: HexString, registry: R
     storage: [],
     mockSignatureHost: false,
     allowUnresolvedImports: false,
+    runtimeLogLevel: 0,
   })
 
   if (!result.Call) throw new Error(result.Error)

packages/chopsticks/src/genesis-provider.ts

@@ -153,6 +153,7 @@ export class GenesisProvider implements ProviderInterface {
             storage: [],
             mockSignatureHost: false,
             allowUnresolvedImports: true,
+            runtimeLogLevel: 0,
           },
           this._jsCallback
         )

packages/chopsticks/src/run-block.ts

@@ -2,6 +2,7 @@ import { HexString } from '@polkadot/util/types'
 import { writeFileSync } from 'node:fs'
 
 import { Config } from './schema'
+import { defaultLogger } from './logger'
 import { generateHtmlDiffPreviewFile } from './utils/generate-html-diff'
 import { openHtml } from './utils/open-html'
 import { runTask, taskHandler } from './executor'
@@ -31,6 +32,7 @@ export const runBlock = async (argv: Config) => {
       storage: [],
       mockSignatureHost: false,
       allowUnresolvedImports: false,
+      runtimeLogLevel: argv['runtime-log-level'] || 0,
     },
     taskHandler(parent)
   )
@@ -39,6 +41,10 @@ export const runBlock = async (argv: Config) => {
     throw new Error(result.Error)
   }
 
+  for (const logs of result.Call.runtimeLogs) {
+    defaultLogger.info(`RuntimeLogs:\n${logs}`)
+  }
+
   if (argv['html']) {
     const filePath = await generateHtmlDiffPreviewFile(parent, result.Call.storageDiff, block.hash)
     console.log(`Generated preview ${filePath}`)

packages/chopsticks/src/schema/index.ts

@@ -27,6 +27,7 @@ export const configSchema = z
     genesis: z.union([z.string(), genesisSchema]).optional(),
     timestamp: z.number().optional(),
     'registered-types': z.any().optional(),
+    'runtime-log-level': z.number().min(0).max(5).optional(),
   })
   .strict()
 

packages/chopsticks/src/setup.ts

@@ -73,6 +73,7 @@ export const setup = async (argv: Config, runBlock = false) => {
     },
     mockSignatureHost: argv['mock-signature-host'],
     allowUnresolvedImports: argv['allow-unresolved-imports'],
+    runtimeLogLevel: argv['runtime-log-level'],
     registeredTypes: argv['registered-types'],
   })