Merge pull request #117 from status-im/logging-to-chronicles

replace logging module with nim-chronicles (fixes #38)

nimbus/block_types.nim

@@ -7,7 +7,7 @@
 
 import
   eth_common,
-  ./logging, ./constants
+  ./constants
 
 type
   Block* = ref object of RootObj

nimbus/db/state_db.nim

@@ -7,8 +7,11 @@
 
 import
   sequtils, tables,
-  eth_common, nimcrypto, rlp, eth_trie/[hexary, memdb],
+  chronicles, eth_common, nimcrypto, rlp, eth_trie/[hexary, memdb],
-  ../constants, ../errors, ../validation, ../account, ../logging
+  ../constants, ../errors, ../validation, ../account
+
+logScope:
+  topics = "state_db"
 
 type
   AccountStateDB* = ref object
@@ -25,9 +28,6 @@ proc newAccountStateDB*(backingStore: TrieDatabaseRef,
   result.new()
   result.trie = initSecureHexaryTrie(backingStore, root)
 
-proc logger*(db: AccountStateDB): Logger =
-  logging.getLogger("db.State")
-
 template createRangeFromAddress(address: EthAddress): ByteRange =
   ## XXX: The name of this proc is intentionally long, because it
   ## performs a memory allocation and data copying that may be eliminated

nimbus/logging.nim

@@ -1,42 +0,0 @@
-# Nimbus
-# Copyright (c) 2018 Status Research & Development GmbH
-# Licensed under either of
-#  * Apache License, version 2.0, ([LICENSE-APACHE](LICENSE-APACHE) or http://www.apache.org/licenses/LICENSE-2.0)
-#  * 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 strformat, terminal
-
-# TODO replace by nim-chronicles
-
-type
-  Logger* = object
-    name*: string
-
-const DEBUG* = defined(nimbusdebug)
-
-# Note: to make logging costless:
-#  - DEBUG should be a const and dispatch should use `when` for compile-time specialization
-#  - Passing a string to a proc, even a const string and inline proc, might trigger a heap allocation
-#    use a template instead.
-
-template log*(l: Logger, msg: string, color: ForegroundColor = fgBlack) =
-  when DEBUG:
-    styledWriteLine(stdout, color, &"#{l.name}: {msg}", resetStyle)
-
-template debug*(l: Logger, msg: string) =
-  when DEBUG:
-    l.log(msg)
-
-template trace*(l: Logger, msg: string) =
-  when DEBUG:
-    l.log(msg, fgBlue)
-
-proc getLogger*(name: string): Logger {.inline.}=
-  result = Logger(name: name)
-
-# proc disableLogging* =
-#   DEBUG = false
-
-# proc enableLogging* =
-#   DEBUG = true

nimbus/rpc/common.nim

@@ -8,7 +8,7 @@
 # those terms.
 import strutils, nimcrypto, eth_common, stint, eth_trie/[memdb, types]
 import
-  json_rpc/server, ../vm_state, ../logging, ../db/[db_chain, state_db],
+  json_rpc/server, ../vm_state, ../db/[db_chain, state_db],
   ../constants, ../config, hexstrings
 
 proc setupCommonRPC*(server: RpcServer) =

nimbus/vm/code_stream.nim

@@ -6,9 +6,12 @@
 # at your option. This file may not be copied, modified, or distributed except according to those terms.
 
 import
-  strformat, strutils, sequtils, parseutils, sets, macros,
+  chronicles, strformat, strutils, sequtils, parseutils, sets, macros,
   eth_common,
-  ../logging, ../constants, ./interpreter/opcode_values
+  ../constants, ./interpreter/opcode_values
+
+logScope:
+  topics = "vm code_stream"
 
 type
   CodeStream* = ref object
@@ -16,7 +19,6 @@ type
     depthProcessed: int
     invalidPositions: HashSet[int]
     pc*: int
-    logger: Logger
     cached: seq[(int, Op, string)]
 
 proc `$`*(b: byte): string =
@@ -29,7 +31,6 @@ proc newCodeStream*(codeBytes: seq[byte]): CodeStream =
   result.invalidPositions = initSet[int]()
   result.depthProcessed = 0
   result.cached = @[]
-  result.logger = logging.getLogger("vm.code_stream")
 
 proc newCodeStream*(codeBytes: string): CodeStream =
   newCodeStream(codeBytes.mapIt(it.byte))

nimbus/vm/computation.nim

@@ -6,12 +6,15 @@
 # at your option. This file may not be copied, modified, or distributed except according to those terms.
 
 import
-  strformat, strutils, sequtils, macros, terminal, math, tables,
+  chronicles, strformat, strutils, sequtils, macros, terminal, math, tables,
   eth_common,
-  ../constants, ../errors, ../validation, ../vm_state, ../logging, ../vm_types,
+  ../constants, ../errors, ../validation, ../vm_state, ../vm_types,
   ./interpreter/[opcode_values, gas_meter, gas_costs, vm_forks],
   ./code_stream, ./memory, ./message, ./stack
 
+logScope:
+  topics = "vm computation"
+
 proc newBaseComputation*(vmState: BaseVMState, blockNumber: UInt256, message: Message): BaseComputation =
   new result
   result.vmState = vmState
@@ -26,9 +29,6 @@ proc newBaseComputation*(vmState: BaseVMState, blockNumber: UInt256, message: Me
   # result.rawOutput = "0x"
   result.gasCosts = blockNumber.toFork.forkToSchedule
 
-proc logger*(computation: BaseComputation): Logger =
-  logging.getLogger("vm.computation.BaseComputation")
-
 proc isOriginComputation*(c: BaseComputation): bool =
   # Is this computation the computation initiated by a transaction
   c.msg.isOrigin

nimbus/vm/interpreter/gas_meter.nim

@@ -6,14 +6,16 @@
 # at your option. This file may not be copied, modified, or distributed except according to those terms.
 
 import
-  strformat, eth_common, # GasInt
+  chronicles, strformat, eth_common, # GasInt
-  ../../logging, ../../errors, ../../vm_types
+  ../../errors, ../../vm_types
+
+logScope:
+  topics = "vm gas"
 
 proc init*(m: var GasMeter, startGas: GasInt) =
   m.startGas = startGas
   m.gasRemaining = m.startGas
   m.gasRefunded = 0
-  m.logger = logging.getLogger("gas")
 
 proc consumeGas*(gasMeter: var GasMeter; amount: GasInt; reason: string) =
   #if amount < 0.u256:
@@ -24,8 +26,10 @@ proc consumeGas*(gasMeter: var GasMeter; amount: GasInt; reason: string) =
     raise newException(OutOfGas,
       &"Out of gas: Needed {amount} - Remaining {gasMeter.gasRemaining} - Reason: {reason}")
   gasMeter.gasRemaining -= amount
-  gasMeter.logger.trace(
+
-    &"GAS CONSUMPTION: {gasMeter.gasRemaining + amount} - {amount} -> {gasMeter.gasRemaining} ({reason})")
+  when defined(nimbusTrace): # XXX: https://github.com/status-im/nim-chronicles/issues/26
+    debug(
+      "GAS CONSUMPTION", total = gasMeter.gasRemaining + amount, amount, remaining = gasMeter.gasRemaining, reason)
 
 proc returnGas*(gasMeter: var GasMeter; amount: GasInt) =
   #if amount < 0.int256:
@@ -33,8 +37,9 @@ proc returnGas*(gasMeter: var GasMeter; amount: GasInt) =
   # Alternatively: use a range type `range[0'i64 .. high(int64)]`
   #   https://github.com/status-im/nimbus/issues/35#issuecomment-391726518
   gasMeter.gasRemaining += amount
-  gasMeter.logger.trace(
+  when defined(nimbusTrace): # XXX: https://github.com/status-im/nim-chronicles/issues/26
-    &"GAS RETURNED: {gasMeter.gasRemaining - amount} + {amount} -> {gasMeter.gasRemaining}")
+    debug(
+      "GAS RETURNED", consumed = gasMeter.gasRemaining - amount, amount, remaining = gasMeter.gasRemaining)
 
 proc refundGas*(gasMeter: var GasMeter; amount: GasInt) =
   #if amount < 0.int256:
@@ -42,5 +47,6 @@ proc refundGas*(gasMeter: var GasMeter; amount: GasInt) =
   # Alternatively: use a range type `range[0'i64 .. high(int64)]`
   #   https://github.com/status-im/nimbus/issues/35#issuecomment-391726518
   gasMeter.gasRefunded += amount
-  gasMeter.logger.trace(
+  when defined(nimbusTrace): # XXX: https://github.com/status-im/nim-chronicles/issues/26
-    &"GAS REFUND: {gasMeter.gasRemaining - amount} + {amount} -> {gasMeter.gasRefunded}")
+    debug(
+      "GAS REFUND", consumed = gasMeter.gasRemaining - amount, amount, refunded = gasMeter.gasRefunded)

nimbus/vm/interpreter/opcodes_impl.nim

@@ -7,11 +7,11 @@
 
 import
   strformat, times, ranges,
-  stint, nimcrypto, ranges/typedranges, eth_common,
+  chronicles, stint, nimcrypto, ranges/typedranges, eth_common,
   ./utils/[macros_procs_opcodes, utils_numeric],
   ./gas_meter, ./gas_costs, ./opcode_values, ./vm_forks,
   ../memory, ../message, ../stack, ../code_stream, ../computation,
-  ../../vm_state, ../../errors, ../../constants, ../../vm_types, ../../logging,
+  ../../vm_state, ../../errors, ../../constants, ../../vm_types,
   ../../db/[db_chain, state_db]
 
 # ##################################
@@ -555,7 +555,7 @@ op create, inline = false, value, startPosition, size:
   let isCollision = false # TODO: db.accountHasCodeOrNonce ...
 
   if isCollision:
-    computation.vmState.logger.debug("Address collision while creating contract: " & contractAddress.toHex)
+    debug("Address collision while creating contract", address = contractAddress.toHex)
     push: 0
     return
 
@@ -806,8 +806,8 @@ op selfDestruct, inline = false:
     # Register the account to be deleted
     computation.registerAccountForDeletion(beneficiary)
 
-    computation.vm_state.logger.debug(
+    debug(
-      "SELFDESTRUCT: %s (%s) -> %s" &
+      "SELFDESTRUCT",
-      computation.msg.storage_address.toHex &
+      storage_address = computation.msg.storage_address.toHex,
-      local_balance.toString &
+      local_balance = local_balance.toString,
-      beneficiary.toHex)
+      beneficiary = beneficiary.toHex)

nimbus/vm/interpreter_dispatch.nim

@@ -7,10 +7,11 @@
 
 import
   tables, macros,
+  chronicles,
   ./interpreter/[opcode_values, opcodes_impl, vm_forks, gas_costs, gas_meter, utils/macros_gen_opcodes],
   ./code_stream,
   ../vm_types, ../errors,
-  ../logging, ./stack, ./computation, terminal # Those are only needed for logging
+  ./stack, ./computation, terminal # Those are only needed for logging
 
 func invalidInstruction*(computation: var BaseComputation) {.inline.} =
   raise newException(ValueError, "Invalid instruction, received an opcode not implemented in the current fork.")
@@ -211,7 +212,8 @@ proc opTableToCaseStmt(opTable: array[Op, NimNode], computation: NimNode): NimNo
     var `instr` = `computation`.code.next()
     while true:
       {.computedGoto.}
-      `computation`.logger.log($`computation`.stack & "\n\n", fgGreen)
+      # TODO lots of macro magic here to unravel, with chronicles...
+      # `computation`.logger.log($`computation`.stack & "\n\n", fgGreen)
       `result`
 
 macro genFrontierDispatch(computation: BaseComputation): untyped =

nimbus/vm/memory.nim

@@ -7,19 +7,20 @@
 
 import
   sequtils,
-  eth_common/eth_types,
+  chronicles, eth_common/eth_types,
-  ../constants, ../errors, ../logging, ../validation,
+  ../constants, ../errors, ../validation,
   ./interpreter/utils/utils_numeric
 
+logScope:
+  topics = "vm memory"
+
 type
   Memory* = ref object
-    logger*: Logger
     bytes*:  seq[byte]
 
 proc newMemory*: Memory =
   new(result)
   result.bytes = @[]
-  result.logger = logging.getLogger("memory.Memory")
 
 proc len*(memory: Memory): int =
   result = memory.bytes.len

nimbus/vm/message.nim

@@ -7,7 +7,7 @@
 
 import
   eth_common,
-  ../logging, ../constants, ../validation, ../vm_types
+  ../constants, ../validation, ../vm_types
 
 proc `origin=`*(message: var Message, value: EthAddress) =
   message.internalOrigin = value

nimbus/vm/stack.nim

@@ -6,12 +6,14 @@
 # at your option. This file may not be copied, modified, or distributed except according to those terms.
 
 import
-  strformat, strutils, sequtils, macros, rlp, eth_common, nimcrypto,
+  chronicles, strformat, strutils, sequtils, macros, rlp, eth_common, nimcrypto,
-  ../errors, ../validation, ./interpreter/utils/utils_numeric, ../constants, ../logging
+  ../errors, ../validation, ./interpreter/utils/utils_numeric, ../constants
+
+logScope:
+  topics = "vm stack"
 
 type
   Stack* = ref object of RootObj
-    logger*: Logger
     values*: seq[StackElement]
 
   StackElement = UInt256
@@ -87,7 +89,6 @@ proc popAddress*(stack: var Stack): EthAddress {.inline.} =
 
 proc newStack*(): Stack =
   new(result)
-  result.logger = logging.getLogger("stack.Stack")
   result.values = @[]
 
 proc swap*(stack: var Stack, position: int) =

nimbus/vm_state.nim

@@ -8,7 +8,7 @@
 import
   macros, strformat, tables,
   eth_common,
-  ./logging, ./constants, ./errors, ./transaction, ./db/[db_chain, state_db],
+  ./constants, ./errors, ./transaction, ./db/[db_chain, state_db],
   ./utils/header
 
 type
@@ -45,9 +45,6 @@ proc newBaseVMState*(header: BlockHeader, chainDB: BaseChainDB): BaseVMState =
   result.blockHeader = header
   result.chaindb = chainDB
 
-method logger*(vmState: BaseVMState): Logger =
-  logging.getLogger(&"evm.vmState.{vmState.name}")
-
 method blockhash*(vmState: BaseVMState): Hash256 =
   vmState.blockHeader.hash
 

nimbus/vm_state_transactions.nim

@@ -7,7 +7,7 @@
 
 import
   strformat, tables,
-  ./logging, ./constants, ./errors, ./vm/computation,
+  ./constants, ./errors, ./vm/computation,
   ./transaction, ./vm_types, ./vm_state, ./block_types, ./db/db_chain, ./utils/header
 
 method executeTransaction(vmState: var BaseVMState, transaction: BaseTransaction): (BaseComputation, BlockHeader) {.base.}=

nimbus/vm_types.nim

@@ -8,7 +8,7 @@
 import
   tables,
   eth_common,
-  ./constants, ./vm_state, ./logging,
+  ./constants, ./vm_state,
   ./vm/[memory, stack, code_stream],
   ./vm/interpreter/[gas_costs, opcode_values] # TODO - will be hidden at a lower layer
 
@@ -46,7 +46,6 @@ type
     runLogic*:  proc(computation: var BaseComputation)
 
   GasMeter* = object
-    logger*: Logger
     gasRefunded*: GasInt
     startGas*: GasInt
     gasRemaining*: GasInt

tests/test_gas_meter.nim

@@ -8,7 +8,7 @@
 import
   unittest, macros, strformat,
   eth_common/eth_types,
-  ../nimbus/[vm_types, errors, logging, vm/interpreter]
+  ../nimbus/[vm_types, errors, vm/interpreter]
 
 # TODO: quicktest
 # PS: parametrize can be easily immitated, but still quicktests would be even more useful

tests/test_opcode.nim

@@ -8,7 +8,7 @@
 import
   unittest, tables, parseutils,
   eth_trie/[types, memdb], eth_common/eth_types,
-  ../nimbus/[constants, vm_types, logging, vm_state],
+  ../nimbus/[constants, vm_types, vm_state],
   ../nimbus/vm/interpreter,
   ../nimbus/utils/header,
   ../nimbus/db/[db_chain, state_db],
@@ -40,7 +40,7 @@ proc testCode(code: string, initialGas: GasInt, blockNum: UInt256): BaseComputat
 
   #echo fixture{"exec"}
   var c = newCodeStreamFromUnescaped(code)
-  if DEBUG:
+  when defined(nimbusdebug):
     c.displayDecompiled()
 
   result = newBaseComputation(vmState, blockNum, message)

tests/test_vm_json.nim

@@ -10,7 +10,7 @@ import
   byteutils, ranges/typedranges, nimcrypto/[keccak, hash],
   rlp, eth_trie/[types, memdb], eth_common,
   ./test_helpers,
-  ../nimbus/[constants, errors, logging],
+  ../nimbus/[constants, errors],
   ../nimbus/[vm_state, vm_types],
   ../nimbus/utils/header,
   ../nimbus/vm/interpreter,
@@ -68,7 +68,7 @@ proc testFixture(fixtures: JsonNode, testStatusIMPL: var TestStatus) =
 
   #echo fixture{"exec"}
   var c = newCodeStreamFromUnescaped(code)
-  if DEBUG:
+  when defined(nimbusdebug):
     c.displayDecompiled()
 
   var computation = newBaseComputation(vmState, header.blockNumber, message)