more VM tracing

The existing vmState tracing is plugged into chronicles, at the TRACE
level, to facilitate state test debugging.

Some useful chronicles defines are added to "tests/nim.cfg" to simplify
the compile-and-run command for individual tests.

nimbus/vm/interpreter_dispatch.nim

@@ -13,6 +13,9 @@ import
   ../vm_types, ../errors, precompiles,
   ./stack, ./computation, terminal # Those are only needed for logging
 
+logScope:
+  topics = "vm opcode"
+
 func invalidInstruction*(computation: var BaseComputation) {.inline.} =
   raise newException(ValueError, "Invalid instruction, received an opcode not implemented in the current fork.")
 
@@ -186,7 +189,9 @@ proc opTableToCaseStmt(opTable: array[Op, NimNode], computation: NimNode): NimNo
   for op, opImpl in opTable.pairs:
     let branchStmt = block:
       if op == Stop:
-        quote do: break
+        quote do:
+          trace "op: Stop"
+          break
       else:
         let asOp = quote do: Op(`op`) # TODO: unfortunately when passing to runtime, ops are transformed into int
         if BaseGasCosts[op].kind == GckFixed:

nimbus/vm/transaction_tracer.nim

@@ -1,8 +1,12 @@
 import
-  json, strutils, nimcrypto, eth_common, stint,
+  json, strutils,
+  chronicles, nimcrypto, eth_common, stint,
   ../vm_types, memory, stack, ../db/[db_chain, state_db],
   eth_trie/hexary, ./message, ranges/typedranges
 
+logScope:
+  topics = "vm opcode"
+
 proc initTracer*(tracer: var TransactionTracer, flags: set[TracerFlags] = {}) =
   tracer.trace = newJObject()
 
@@ -47,7 +51,7 @@ proc traceOpCodeEnded*(tracer: var TransactionTracer, c: BaseComputation) =
   let j = tracer.trace["structLogs"].elems[^1]
 
   # TODO: figure out how to get storage
-  # when contract excecution interrupted by exception
+  # when contract execution interrupted by exception
   if TracerFlags.DisableStorage notin tracer.flags:
     var storage = newJObject()
     var stateDB = c.vmState.chaindb.getStateDb(c.vmState.blockHeader.stateRoot, readOnly = true)
@@ -62,6 +66,8 @@ proc traceOpCodeEnded*(tracer: var TransactionTracer, c: BaseComputation) =
     j["returnValue"] = returnValue
     tracer.trace["returnValue"] = returnValue
 
+  trace "Op", json = j.pretty()
+
 proc traceError*(tracer: var TransactionTracer, c: BaseComputation) =
   let j = tracer.trace["structLogs"].elems[^1]
 
@@ -72,3 +78,5 @@ proc traceError*(tracer: var TransactionTracer, c: BaseComputation) =
 
   j["error"] = %(c.error.info)
   tracer.trace["failed"] = %true
+
+  trace "Error", json = j.pretty()

tests/nim.cfg

@@ -0,0 +1,3 @@
+-d:chronicles_line_numbers
+-d:"chronicles_sinks=textblocks"
+

tests/test_generalstate_json.nim

@@ -9,7 +9,7 @@ import
   unittest, strformat, strutils, tables, json, ospaths, times,
   byteutils, ranges/typedranges, nimcrypto/[keccak, hash], options,
   rlp, eth_trie/db, eth_common,
-  eth_keys,
+  eth_keys, chronicles,
   ./test_helpers,
   ../nimbus/[constants, errors],
   ../nimbus/[vm_state, vm_types, vm_state_transactions],
@@ -24,7 +24,11 @@ suite "generalstate json tests":
 
 
 proc testFixtureIndexes(header: BlockHeader, pre: JsonNode, transaction: Transaction, sender: EthAddress, expectedHash: string, testStatusIMPL: var TestStatus, fork: Fork) =
-  var vmState = newBaseVMState(header, newBaseChainDB(newMemoryDb()))
+  when enabledLogLevel <= TRACE:
+    let tracerFlags = {TracerFlags.EnableTracing}
+  else:
+    let tracerFlags: set[TracerFlags] = {}
+  var vmState = newBaseVMState(header, newBaseChainDB(newMemoryDb()), tracerFlags)
   vmState.mutateStateDB:
     setupStateDB(pre, db)