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

This blindly changes logging to nim-chronicles - issues that ensue: * absurd amounts of logs in gas computation, slows down tests by orders of magnitude (lacking trace level) - the problem is further exacerbated by chronicles' default multi-line output * unclear if logScope is practical - for example, since vm is split over many files, topics get lost when using simple top-level per-module topics * when passing named object around, scope should incliude the name of the object but this is caught neither by logScope nor by dynamicLogScope
status-im · Aug 23, 2018 · 273ea85 · 273ea85
1 parent 986cba5
commit 273ea85
Show file tree

Hide file tree

Showing 18 changed files with 60 additions and 98 deletions.
diff --git a/nimbus/block_types.nim b/nimbus/block_types.nim
@@ -7,7 +7,7 @@
 
 import
  eth_common,
- ./logging, ./constants
+ ./constants
 
 type
  Block* = ref object of RootObj

diff --git a/nimbus/db/state_db.nim b/nimbus/db/state_db.nim
@@ -7,8 +7,11 @@
 
 import
  sequtils, tables,
- eth_common, nimcrypto, rlp, eth_trie/[hexary, memdb],
- ../constants, ../errors, ../validation, ../account, ../logging
+ chronicles, eth_common, nimcrypto, rlp, eth_trie/[hexary, memdb],
+ ../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

diff --git a/nimbus/logging.nim b/nimbus/logging.nim
diff --git a/nimbus/rpc/common.nim b/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
 
 proc setupCommonRPC*(server: RpcServer) =

diff --git a/nimbus/vm/code_stream.nim b/nimbus/vm/code_stream.nim
@@ -6,17 +6,19 @@
 # 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
  bytes*: seq[byte]
  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))

diff --git a/nimbus/vm/computation.nim b/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

diff --git a/nimbus/vm/interpreter/gas_meter.nim b/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
- ../../logging, ../../errors, ../../vm_types
+ chronicles, strformat, eth_common, # GasInt
+ ../../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,23 +26,24 @@ 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})")
+
+ debug(
+ "GAS CONSUMPTION", total = gasMeter.gasRemaining + amount, amount, remaining = gasMeter.gasRemaining, reason)
 
 proc returnGas*(gasMeter: var GasMeter; amount: GasInt) =
  #if amount < 0.int256:
  # raise newException(ValidationError, "Gas return amount must be positive")
  # 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(
- &"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:
  # raise newException(ValidationError, "Gas refund amount must be positive")
  # 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(
- &"GAS REFUND: {gasMeter.gasRemaining - amount} + {amount} -> {gasMeter.gasRefunded}")
+ debug(
+ "GAS REFUND", consumed = gasMeter.gasRemaining - amount, amount, refunded = gasMeter.gasRefunded)
diff --git a/nimbus/vm/interpreter/opcodes_impl.nim b/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(
- "SELFDESTRUCT: %s (%s) -> %s" &
- computation.msg.storage_address.toHex &
- local_balance.toString &
- beneficiary.toHex)
+ debug(
+ "SELFDESTRUCT",
+ storage_address = computation.msg.storage_address.toHex,
+ local_balance = local_balance.toString,
+ beneficiary = beneficiary.toHex)
diff --git a/nimbus/vm/interpreter_dispatch.nim b/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 =

diff --git a/nimbus/vm/memory.nim b/nimbus/vm/memory.nim
@@ -7,19 +7,20 @@
 
 import
  sequtils,
- eth_common/eth_types,
- ../constants, ../errors, ../logging, ../validation,
+ chronicles, eth_common/eth_types,
+ ../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

diff --git a/nimbus/vm/message.nim b/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

diff --git a/nimbus/vm/stack.nim b/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,
- ../errors, ../validation, ./interpreter/utils/utils_numeric, ../constants, ../logging
+ chronicles, strformat, strutils, sequtils, macros, rlp, eth_common, nimcrypto,
+ ../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) =

diff --git a/nimbus/vm_state.nim b/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
 

diff --git a/nimbus/vm_state_transactions.nim b/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.}=

diff --git a/nimbus/vm_types.nim b/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

diff --git a/tests/test_gas_meter.nim b/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

diff --git a/tests/test_opcode.nim b/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)