From db202dc35f6815aa42c2c1d7a71a0504a2d9d4fe Mon Sep 17 00:00:00 2001 From: Jacek Sieka Date: Wed, 22 Aug 2018 21:38:00 -0600 Subject: [PATCH] replace logging module with nim-chronicles (fixes #38) This blindly changes logging to nim-chronicles - issues that ensue: * keeps gas cost computation logs hidden behind flag * 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 --- nimbus/block_types.nim | 2 +- nimbus/db/state_db.nim | 10 +++--- nimbus/logging.nim | 42 -------------------------- nimbus/rpc/common.nim | 2 +- nimbus/vm/code_stream.nim | 9 +++--- nimbus/vm/computation.nim | 10 +++--- nimbus/vm/interpreter/gas_meter.nim | 24 +++++++++------ nimbus/vm/interpreter/opcodes_impl.nim | 16 +++++----- nimbus/vm/interpreter_dispatch.nim | 6 ++-- nimbus/vm/memory.nim | 9 +++--- nimbus/vm/message.nim | 2 +- nimbus/vm/stack.nim | 9 +++--- nimbus/vm_state.nim | 5 +-- nimbus/vm_state_transactions.nim | 2 +- nimbus/vm_types.nim | 3 +- tests/test_gas_meter.nim | 2 +- tests/test_opcode.nim | 4 +-- tests/test_vm_json.nim | 4 +-- 18 files changed, 63 insertions(+), 98 deletions(-) delete mode 100644 nimbus/logging.nim diff --git a/nimbus/block_types.nim b/nimbus/block_types.nim index 4bc101ad9..f7d298b00 100644 --- 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 index b1e036bca..efb3f1579 100644 --- 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 deleted file mode 100644 index 737eaf89d..000000000 --- a/nimbus/logging.nim +++ /dev/null @@ -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 diff --git a/nimbus/rpc/common.nim b/nimbus/rpc/common.nim index 507a50ed1..602ec9873 100644 --- 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, hexstrings proc setupCommonRPC*(server: RpcServer) = diff --git a/nimbus/vm/code_stream.nim b/nimbus/vm/code_stream.nim index 4bcd20e2a..eebbf9d72 100644 --- a/nimbus/vm/code_stream.nim +++ b/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)) diff --git a/nimbus/vm/computation.nim b/nimbus/vm/computation.nim index ca10a5ea6..1d41423b3 100644 --- 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 index 68abd71bf..8a5f553de 100644 --- 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,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( - &"GAS RETURNED: {gasMeter.gasRemaining - amount} + {amount} -> {gasMeter.gasRemaining}") + when defined(nimbusTrace): # XXX: https://github.com/status-im/nim-chronicles/issues/26 + 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( - &"GAS REFUND: {gasMeter.gasRemaining - amount} + {amount} -> {gasMeter.gasRefunded}") + when defined(nimbusTrace): # XXX: https://github.com/status-im/nim-chronicles/issues/26 + 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 index e7bceb8c0..dace995f4 100644 --- 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 index 03e41d43f..46d529024 100644 --- 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 index 22ec7edbe..0418258e9 100644 --- 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 index 3f49840ce..7f936b8ff 100644 --- 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 index 7f45e69a1..442c3a836 100644 --- 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 index d29734578..e2b1999c6 100644 --- 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 index 5322bc178..81bf79162 100644 --- 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 index bc2ca01e3..0ac106f08 100644 --- 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 index fc4f67039..74f580dbf 100644 --- 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 index 33821ee9f..bb7688388 100644 --- 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) diff --git a/tests/test_vm_json.nim b/tests/test_vm_json.nim index fba5faa16..900fed383 100644 --- a/tests/test_vm_json.nim +++ b/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)