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
This commit is contained in:
Jacek Sieka 2018-08-22 21:38:00 -06:00
parent 055b169e86
commit db202dc35f
No known key found for this signature in database
GPG Key ID: 6299FEB3EB6FA465
18 changed files with 63 additions and 98 deletions

View File

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

View File

@ -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

View File

@ -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

View File

@ -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) =

View File

@ -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))

View File

@ -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

View File

@ -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)

View File

@ -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)

View File

@ -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 =

View File

@ -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

View File

@ -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

View File

@ -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) =

View File

@ -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

View File

@ -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.}=

View File

@ -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

View File

@ -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

View File

@ -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)

View File

@ -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)