EVMC: Improve host call tracing and fix nested call C stack usage

This combines two things, a C stack usage change with EVM nested calls
via EVMC, and changes to host call tracing.

Feature-wise, the tracing is improved:

- Storage keys and values are make more sense.
- The message/result/context objects are shown with all relevant fields.
- `call` trace is split into entry/exit, so these can be shown around the
  called contract's operations, instead of only showing the `call` parameters
  after the nested call is finished.
- Nested calls are indented, which helps to highlight the flow.
- C stack usage considerably reduced in nested calls when more functionality
  is enabled (either tracing here, or other things to come).

This will seem like a minor patch, but C stack usage was the real motivation,
after plenty of time in the debugger.

Nobody cares about stack when `showTxCalls` (you can just use a big stack when
debugging).  But these subtle changes around the `call` path were found to be
necessary for passing all tests when the EVMC nested call code is completed,
and that's a prerequisite for many things: async EVM, dynamic EVM, Beam Sync,
and to fix https://github.com/status-im/nimbus-eth1/issues/345.

Signed-off-by: Jamie Lokier <jamie@shareable.org>

nimbus/transaction/evmc_host_glue.nim

@@ -100,13 +100,16 @@ proc evmc_create_nimbus_evm(): ptr evmc_vm {.cdecl, importc.}
 # a separate library yet.
 import ./evmc_vm_glue
 
-# This must be named `call` to show as "call" when traced by the `show` macro.
-proc call(host: TransactionHost): EvmcResult {.show, inline.} =
+proc evmcExecComputation*(host: TransactionHost): EvmcResult {.inline.} =
+  host.showCallEntry(host.msg)
+
   let vm = evmc_create_nimbus_evm()
   if vm.isNil:
     echo "Warning: No EVM"
     # Nim defaults are fine for all other fields in the result object.
-    return EvmcResult(status_code: EVMC_INTERNAL_ERROR)
+    result = EvmcResult(status_code: EVMC_INTERNAL_ERROR)
+    host.showCallReturn(result)
+    return
 
   let hostInterface = evmcGetHostInterface()
   let hostContext = cast[evmc_host_context](host)
@@ -128,10 +131,9 @@ proc call(host: TransactionHost): EvmcResult {.show, inline.} =
   # TODO: But wait: Why does the Nim EVMC test program compile fine without
   # any `gcsafe`, even with `--threads:on`?
   {.gcsafe.}:
-    vm.execute(vm, hostInterface[].addr, hostContext,
-               evmc_revision(host.vmState.fork), host.msg,
-               if host.code.len > 0: host.code[0].unsafeAddr else: nil,
-               host.code.len.csize_t)
+    result = vm.execute(vm, hostInterface[].addr, hostContext,
+                        evmc_revision(host.vmState.fork), host.msg,
+                        if host.code.len > 0: host.code[0].unsafeAddr else: nil,
+                        host.code.len.csize_t)
 
-proc evmcExecComputation*(host: TransactionHost): EvmcResult =
-  call(host)
+  host.showCallReturn(result)

nimbus/transaction/host_call_nested.nim

@@ -12,7 +12,7 @@ import
   sets, stint, chronicles, stew/ranges/ptr_arith,
   eth/common/eth_types,
   ".."/[vm_types, vm_computation, utils],
-  ./host_types
+  ./host_types, ./host_trace
 
 proc evmcResultRelease(res: var EvmcResult) {.cdecl, gcsafe.} =
   dealloc(res.output_data)
@@ -111,6 +111,7 @@ proc beforeExecEvmcNested(host: TransactionHost, msg: EvmcMessage): Computation
     # This function must be declared with `{.noinline.}` to make sure it doesn't
     # contribute to the stack frame of `callEvmcNested` below.
     {.noinline.} =
+  host.showCallEntry(msg)
   if msg.kind == EVMC_CREATE or msg.kind == EVMC_CREATE2:
     return beforeExecCreateEvmcNested(host, msg)
   else:
@@ -125,6 +126,7 @@ proc afterExecEvmcNested(host: TransactionHost, child: Computation,
     afterExecCreateEvmcNested(host, child, result)
   else:
     afterExecCallEvmcNested(host, child, result)
+  host.showCallReturn(result, kind.isCreate)
 
 template callEvmcNested*(host: TransactionHost, msg: EvmcMessage): EvmcResult =
   # This function must be declared `template` to ensure it is inlined at Nim

nimbus/transaction/host_services.nim

@@ -232,8 +232,13 @@ proc selfDestruct(host: TransactionHost, address, beneficiary: HostAddress) {.sh
   #host.touchedAccounts.incl(beneficiary)
   #host.selfDestructs.incl(address)
 
-proc call(host: TransactionHost, msg: EvmcMessage): EvmcResult {.show.} =
-  return host.callEvmcNested(msg)
+template call(host: TransactionHost, msg: EvmcMessage): EvmcResult =
+  # `call` is special.  The C stack usage must be kept small for deeply nested
+  # EVM calls.  To ensure small stack, `{.show.}` must be handled at
+  # `host_call_nested`, not here, and this function must use `template` to
+  # inline at Nim level (same for `callEvmcNested`).  `{.inline.}` is not good
+  # enough.  Due to object return it ends up using a lot more stack.
+  host.callEvmcNested(msg)
 
 proc getTxContext(host: TransactionHost): EvmcTxContext {.show.} =
   if not host.cachedTxContext:

nimbus/transaction/host_trace.nim

@@ -1,4 +1,4 @@
-# Nimbus - Services available to EVM code that is run for a transaction
+# Nimbus - Trace EVMC host calls when EVM code is run for a transaction
 #
 # Copyright (c) 2021 Status Research & Development GmbH
 # Licensed under either of
@@ -6,23 +6,93 @@
 #  * MIT license ([LICENSE-MIT](LICENSE-MIT) or http://opensource.org/licenses/MIT)
 # at your option. This file may not be copied, modified, or distributed except according to those terms.
 
-import macros, strformat, stew/byteutils, stint, ./host_types
+import
+  macros, strformat, strutils, stint, chronicles,
+  stew/byteutils, stew/ranges/ptr_arith,
+  ./host_types
 
-const show_tx_calls = false
+# Set `true` or `false` to control host call tracing.
+const showTxCalls  = false
+const showTxNested = true
+
+proc `$`(val: EvmcCallKind | EvmcStatusCode |
+         EvmcStorageStatus | EvmcAccessStatus): string =
+  result = val.repr
+  result.removePrefix("EVMC_")
+
+proc `$`(address: HostAddress): string = toHex(address)
 
 # Don't use both types in the overload, as Nim <= 1.2.x gives "ambiguous call".
 #func `$`(n: HostKey | HostValue): string = toHex(n)
-func `$`(n: HostKey): string = toHex(n)
+proc `$`(n: HostKey): string =
+  # Show small keys and values as decimal, and large ones as "0x"-prefix hex.
+  # These are often small numbers despite the 256-bit type, so low digits is
+  # helpful.  But "key=d" looks odd.  Hex must be used for large values as they
+  # are sometimes 256-bit hashes, and then decimal is unhelpful.
+  if n <= 65535.u256.HostKey:
+    $n.truncate(uint16)
+  else:
+    "0x" & n.toHex
 
-func `$`(address: HostAddress): string = toHex(address)
-func `$`(txc: EvmcTxContext): string = &"gas_price={txc.tx_gas_price.fromEvmc}"
-func `$`(n: typeof(EvmcMessage().sender)): string = $n.fromEvmc
-func `$`(n: typeof(EvmcMessage().value)): string = $n.fromEvmc
-func `$`(host: TransactionHost): string = &"(fork={host.vmState.fork} message=${host.msg})"
+proc depthPrefix(host: TransactionHost): string =
+  let depth = host.depth
+  if depth <= 20:
+    return spaces(depth * 2)
+  else:
+    let num = '(' & $depth & ')'
+    return num & spaces(42 - num.len)
 
-macro show*(fn: untyped): auto =
-  if not show_tx_calls:
-    return fn
+proc showEvmcMessage(msg: EvmcMessage): string =
+  let kindStr =
+    if msg.flags == {}: $msg.kind
+    elif msg.flags == {EVMC_STATIC} and msg.kind == EVMC_CALL: "CALL_STATIC"
+    else: &"{$msg.kind} flags={$msg.flags}"
+  var inputStr = "(" & $msg.input_size & ")"
+  if msg.input_size > 0:
+    inputStr.add toHex(makeOpenArray(msg.input_data,
+                                     min(msg.input_size, 256).int))
+    if msg.input_size > 256:
+      inputStr.add "..."
+  result = &"kind={kindStr}" &
+    &" depth={$msg.depth}" &
+    &" gas={$msg.gas}" &
+    &" value={$msg.value.fromEvmc}" &
+    &" sender={$msg.sender.fromEvmc}" &
+    &" destination={$msg.destination.fromEvmc}" &
+    &" input_data={inputStr}"
+  if msg.kind == EVMC_CREATE2:
+    result.add &" create2_salt={$msg.create2_salt.fromEvmc}"
+
+proc showEvmcResult(res: EvmcResult, withCreateAddress = true): string =
+  if res.status_code != EVMC_SUCCESS and res.status_code != EVMC_REVERT and
+     res.gas_left == 0 and res.output_size == 0:
+    return &"status={$res.status_code}"
+
+  var outputStr = "(" & $res.output_size & ")"
+  if res.output_size > 0:
+    outputStr.add toHex(makeOpenArray(res.output_data,
+                                      min(res.output_size, 256).int))
+    if res.output_size > 256:
+      outputStr.add "..."
+
+  result = &"status={$res.status_code}" &
+    &" gas_left={$res.gas_left}" &
+    &" output_data={outputStr}"
+  if withCreateAddress:
+    result.add &" create_address={$res.create_address.fromEvmc}"
+
+proc showEvmcTxContext(txc: EvmcTxContext): string =
+  return &"tx_gas_price={$txc.tx_gas_price.fromEvmc}" &
+    &" tx_origin={$txc.tx_origin.fromEvmc}" &
+    &" block_coinbase={$txc.block_coinbase.fromEvmc}" &
+    &" block_number={$txc.block_number}" &
+    &" block_timestamp={$txc.block_timestamp}" &
+    &" block_gas_limit={$txc.block_gas_limit}" &
+    &" block_difficulty={$txc.block_difficulty.fromEvmc}" &
+    &" chain_id={$txc.chain_id.fromEvmc}" &
+    &" block_base_fee={$txc.block_base_fee.fromEvmc}"
+
+proc showEvmcArgsExpr(fn: NimNode, callName: string): auto =
   var args: seq[NimNode] = newSeq[NimNode]()
   var types: seq[NimNode] = newSeq[NimNode]()
   for i in 1 ..< fn.params.len:
@@ -30,11 +100,9 @@ macro show*(fn: untyped): auto =
     for j in 0 ..< idents.len-2:
       args.add idents[j]
       types.add idents[^2]
-
-  let procName = $fn.name
-  let msgVar = genSym(nskLet, "msg")
+  let hostExpr = args[0]
   var msgExpr = quote do:
-    "tx." & `procName`
+    `depthPrefix`(`hostExpr`) & "evmc." & `callName` & ":"
   var skip = 0
   for i in 1 ..< args.len:
     if i == skip:
@@ -47,19 +115,47 @@ macro show*(fn: untyped): auto =
       arg = newPar(args[i], args[i+1])
     msgExpr = quote do:
       `msgExpr` & `argNameString` & $(`arg`)
-  let call = newCall(fn.name, args)
+  return (msgExpr, args)
 
-  let wrapFn = newProc(name = fn.name)
-  wrapFn.params = fn.params.copy
-  wrapFn.body.add fn
+macro show*(fn: untyped): auto =
+  if not showTxCalls:
+    return fn
+
+  let (msgExpr, args) = showEvmcArgsExpr(fn, $fn.name)
+  let hostExpr = args[0]
   if fn.params[0].kind == nnkEmpty:
-    wrapFn.body.add quote do:
-      echo `msgExpr`
-      `call`
+    fn.body.insert 0, quote do:
+      if showTxNested or `hostExpr`.depth > 1:
+        echo `msgExpr`
   else:
-    wrapFn.body.add quote do:
+    let innerFn = newProc(name = fn.name, body = fn.body)
+    innerFn.params = fn.params.copy
+    innerFn.addPragma(newIdentNode("inline"))
+    fn.body = newStmtList(innerFn)
+    let call = newCall(fn.name, args)
+    let msgVar = genSym(nskLet, "msg")
+    fn.body.add quote do:
+      if not (showTxNested or `hostExpr`.depth > 1):
+        return `call`
       let `msgVar` = `msgExpr`
-      let res = `call`
-      echo `msgVar` & " -> result=" & $res
-      res
-  return wrapFn
+      result = `call`
+    if fn.params[0].repr == "EvmcTxContext":
+      fn.body.add quote do:
+        echo `msgVar` & " -> " & showEvmcTxContext(result)
+    else:
+      fn.body.add quote do:
+        echo `msgVar` & " -> result=" & $result
+  return fn
+
+template showCallEntry*(host: TransactionHost, msg: EvmcMessage) =
+  if showTxCalls and (showTxNested or host.depth > 0):
+    echo depthPrefix(host) & "evmc.call: " &
+      showEvmcMessage(msg)
+    inc host.depth
+
+template showCallReturn*(host: TransactionHost, res: EvmcResult,
+                         forNestedCreate = false) =
+  if showTxCalls and (showTxNested or host.depth > 1):
+    echo depthPrefix(host) & "evmc.return -> " &
+      showEvmcResult(res, forNestedCreate)
+    dec host.depth

nimbus/transaction/host_types.nim

@@ -62,6 +62,7 @@ type
     logEntries*:      seq[Log]
     touchedAccounts*: HashSet[EthAddress]
     selfDestructs*:   HashSet[EthAddress]
+    depth*:           int
 
 # These versions of `toEvmc` and `fromEvmc` don't flip big/little-endian like
 # the older functions in `evmc_helpers`.  New code only flips with _explicit_