From f91e69f7c761870535ca6037bea9deccf10dca31 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?=C8=98tefan=20Talpalaru?= <stefantalpalaru@yahoo.com>
Date: Wed, 12 Dec 2018 00:26:08 +0100
Subject: [PATCH] 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 |  7 ++++++-
 nimbus/vm/precompiles.nim          |  2 +-
 nimbus/vm/transaction_tracer.nim   | 12 ++++++++++--
 tests/nim.cfg                      |  3 +++
 tests/test_generalstate_json.nim   |  8 ++++++--
 5 files changed, 26 insertions(+), 6 deletions(-)
 create mode 100644 tests/nim.cfg

diff --git a/nimbus/vm/interpreter_dispatch.nim b/nimbus/vm/interpreter_dispatch.nim
index 0394e790a..2b7a2123c 100644
--- a/nimbus/vm/interpreter_dispatch.nim
+++ b/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:
diff --git a/nimbus/vm/precompiles.nim b/nimbus/vm/precompiles.nim
index a36f4f3a1..90a2a1109 100644
--- a/nimbus/vm/precompiles.nim
+++ b/nimbus/vm/precompiles.nim
@@ -277,7 +277,7 @@ proc execPrecompiles*(computation: var BaseComputation): bool {.inline.} =
   if lb in PrecompileAddresses.low.byte .. PrecompileAddresses.high.byte:
     result = true
     let precompile = PrecompileAddresses(lb)
-    trace "Call precompile ", precompile = precompile, codeAddr = computation.msg.codeAddress
+    trace "Call precompile", precompile = precompile, codeAddr = computation.msg.codeAddress
     case precompile
     of paEcRecover: ecRecover(computation)
     of paSha256: sha256(computation)
diff --git a/nimbus/vm/transaction_tracer.nim b/nimbus/vm/transaction_tracer.nim
index aaea7b33a..664292102 100644
--- a/nimbus/vm/transaction_tracer.nim
+++ b/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()
diff --git a/tests/nim.cfg b/tests/nim.cfg
new file mode 100644
index 000000000..ee64291c7
--- /dev/null
+++ b/tests/nim.cfg
@@ -0,0 +1,3 @@
+-d:chronicles_line_numbers
+-d:"chronicles_sinks=textblocks"
+
diff --git a/tests/test_generalstate_json.nim b/tests/test_generalstate_json.nim
index aec3cbd4d..a63983a87 100644
--- a/tests/test_generalstate_json.nim
+++ b/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)