improve runtime logging (#529)

* improve runtime logging * use log::info instead * lint * fix level
AcalaNetwork · Nov 9, 2023 · 9e45639 · 9e45639
1 parent d6278ba
commit 9e45639
Show file tree

Hide file tree

Showing 6 changed files with 48 additions and 60 deletions.
diff --git a/executor/src/task.rs b/executor/src/task.rs
@@ -299,34 +299,56 @@ pub async fn run_task(task: TaskCall, js: crate::JsCallback) -> Result<TaskRespo
 
                 RuntimeHostVm::LogEmit(req) => {
                     {
-                        let info = req.info();
-                        let log = match info {
-                            LogEmitInfo::Num(v) => LogInfo {
-                                message: v.to_string(),
-                                level: None,
-                                target: None,
-                            },
-                            LogEmitInfo::Utf8(v) => LogInfo {
-                                message: v.to_string(),
-                                level: None,
-                                target: None,
-                            },
-                            LogEmitInfo::Hex(v) => LogInfo {
-                                message: v.to_string(),
-                                level: None,
-                                target: None,
-                            },
+                        match req.info() {
+                            LogEmitInfo::Num(v) => {
+                                log::info!("{}", v);
+                                runtime_logs.push(LogInfo {
+                                    message: format!("{}", v),
+                                    level: None,
+                                    target: None,
+                                });
+                            }
+                            LogEmitInfo::Utf8(v) => {
+                                log::info!("{}", v.to_string());
+                                runtime_logs.push(LogInfo {
+                                    message: v.to_string(),
+                                    level: None,
+                                    target: None,
+                                });
+                            }
+                            LogEmitInfo::Hex(v) => {
+                                log::info!("{}", v.to_string());
+                                runtime_logs.push(LogInfo {
+                                    message: v.to_string(),
+                                    level: None,
+                                    target: None,
+                                });
+                            }
                             LogEmitInfo::Log {
                                 log_level,
                                 target,
                                 message,
-                            } => LogInfo {
-                                message: message.to_string(),
-                                level: Some(log_level),
-                                target: Some(target.to_string()),
-                            },
+                            } => {
+                                let level = match log_level {
+                                    0 => "ERROR".to_string(),
+                                    1 => "WARN".to_string(),
+                                    2 => "INFO".to_string(),
+                                    3 => "DEBUG".to_string(),
+                                    4 => "TRACE".to_string(),
+                                    l => format!("_{l}_"),
+                                };
+                                log::info!(
+                                    "{}: {}",
+                                    format!("{:<28}{:>6}", target.to_string(), level),
+                                    message.to_string()
+                                );
+                                runtime_logs.push(LogInfo {
+                                    message: message.to_string(),
+                                    level: Some(log_level),
+                                    target: Some(target.to_string()),
+                                });
+                            }
                         };
-                        runtime_logs.push(log);
                     }
                     req.resume()
                 }

diff --git a/packages/chopsticks/src/plugins/dry-run/dry-run-preimage.ts b/packages/chopsticks/src/plugins/dry-run/dry-run-preimage.ts
@@ -5,7 +5,7 @@ import { hexToU8a } from '@polkadot/util'
 import { Config } from '../../schema/index.js'
 import { defaultLogger } from '../../logger.js'
 import { generateHtmlDiffPreviewFile } from '../../utils/generate-html-diff.js'
-import { newHeader, printRuntimeLogs, runTask, setStorage, taskHandler } from '@acala-network/chopsticks-core'
+import { newHeader, runTask, setStorage, taskHandler } from '@acala-network/chopsticks-core'
 import { openHtml } from '../../utils/open-html.js'
 import { setupContext } from '../../context.js'
 
@@ -85,8 +85,6 @@ export const dryRunPreimage = async (argv: Config) => {
     throw new Error(result.Error)
   }
 
-  printRuntimeLogs(result.Call.runtimeLogs)
-
   const filePath = await generateHtmlDiffPreviewFile(block, result.Call.storageDiff, hash)
   console.log(`Generated preview ${filePath}`)
   if (argv['open']) {

diff --git a/packages/chopsticks/src/plugins/follow-chain/index.ts b/packages/chopsticks/src/plugins/follow-chain/index.ts
@@ -1,4 +1,4 @@
-import { Block, defaultLogger, printRuntimeLogs, runTask, taskHandler } from '@acala-network/chopsticks-core'
+import { Block, defaultLogger, runTask, taskHandler } from '@acala-network/chopsticks-core'
 import { Header } from '@polkadot/types/interfaces'
 import { HexString } from '@polkadot/util/types'
 import _ from 'lodash'
@@ -79,8 +79,6 @@ export const cli = (y: Argv) => {
             if ('Error' in result) {
               throw new Error(result.Error)
             }
-
-            printRuntimeLogs(result.Call.runtimeLogs)
           } catch (e) {
             logger.error(e, 'Error when processing new head')
             await close()

diff --git a/packages/chopsticks/src/plugins/run-block/index.ts b/packages/chopsticks/src/plugins/run-block/index.ts
@@ -13,7 +13,6 @@ import {
   RuntimeLog,
   compactHex,
   decodeKeyValue,
-  printRuntimeLogs,
   runTask,
   taskHandler,
 } from '@acala-network/chopsticks-core'
@@ -75,8 +74,6 @@ export const cli = (y: Argv) => {
         throw new Error(result.Error)
       }
 
-      printRuntimeLogs(result.Call.runtimeLogs)
-
       if (argv.html) {
         const filePath = await generateHtmlDiffPreviewFile(parent, result.Call.storageDiff, block.hash)
         console.log(`Generated preview ${filePath}`)

diff --git a/packages/core/src/blockchain/block.ts b/packages/core/src/blockchain/block.ts
@@ -16,7 +16,7 @@ import {
   StorageValue,
   StorageValueKind,
 } from './storage-layer.js'
-import { compactHex, printRuntimeLogs } from '../utils/index.js'
+import { compactHex } from '../utils/index.js'
 import { getRuntimeVersion, runTask, taskHandler } from '../wasm-executor/index.js'
 import type { RuntimeVersion, TaskCallResponse } from '../wasm-executor/index.js'
 
@@ -320,8 +320,6 @@ export class Block {
       taskHandler(this),
     )
     if ('Call' in response) {
-      printRuntimeLogs(response.Call.runtimeLogs)
-
       if (this.chain.offchainWorker) {
         // apply offchain storage
         for (const [key, value] of response.Call.offchainStorageDiff) {

diff --git a/packages/core/src/utils/index.ts b/packages/core/src/utils/index.ts
@@ -4,7 +4,6 @@ import { compactStripLength, u8aToHex } from '@polkadot/util'
 import { hexAddPrefix, hexStripPrefix } from '@polkadot/util/hex'
 
 import { Blockchain } from '../blockchain/index.js'
-import { RuntimeLog } from '../wasm-executor/index.js'
 
 export * from './set-storage.js'
 export * from './time-travel.js'
@@ -108,27 +107,3 @@ export const stripChildPrefix = (key: HexString) => {
   if (!child) return key
   return storageKey
 }
-
-const logLevels = ['OFF', 'ERROR', 'WARN', 'INFO', 'DEBUG', 'TRACE']
-
-export const formatRuntimeLog = (log: RuntimeLog) => {
-  let msg = ''
-  if (log.level != null) {
-    msg += `${logLevels[log.level]}\t `
-  }
-  if (log.target) {
-    msg += `[${log.target}]:\t `
-  }
-  msg += log.message
-  return msg
-}
-
-export const printRuntimeLogs = (logs: RuntimeLog[]) => {
-  if (!logs.length) return
-
-  console.group('RuntimeLogs:')
-  for (const log of logs) {
-    console.log(formatRuntimeLog(log))
-  }
-  console.groupEnd()
-}