logging changes

- port some "echo" logging to "chronicles"
- change the logging level of messages that should not appear by default
  to TRACE instead of DEBUG
- remove the "nimbusTrace" define
- suppress logging for messages below the ERROR level in "nimble test"

nimbus.nimble

@@ -28,8 +28,9 @@ proc buildBinary(name: string, srcDir = ".", lang = "c") =
   setCommand lang, srcDir & name & ".nim"
 
 proc test(name: string, lang = "c") =
-  buildBinary name, "tests/"
+  --define: "chronicles_log_level=ERROR"
   --run
+  buildBinary name, "tests/"
 
 task test, "Run tests":
   test "all_tests"

nimbus/nimbus.nim

@@ -9,7 +9,7 @@
 
 import
   os, strutils, net, eth_common, db/[storage_types, db_chain],
-  asyncdispatch2, json_rpc/rpcserver, eth_keys,
+  asyncdispatch2, json_rpc/rpcserver, eth_keys, chronicles,
   eth_p2p, eth_p2p/rlpx_protocols/[eth_protocol, les_protocol],
   eth_p2p/blockchain_sync,
   config, genesis, rpc/[common, p2p, debug, whisper], p2p/chain,
@@ -43,7 +43,7 @@ type
     state*: NimbusState
 
 proc initializeEmptyDb(db: BaseChainDB) =
-  echo "Writing genesis to DB"
+  trace "Writing genesis to DB"
   let networkId = getConfiguration().net.networkId.toPublicNetwork()
   if networkId == CustomNet:
     raise newException(Exception, "Custom genesis not implemented")
@@ -108,13 +108,13 @@ proc start(): NimbusObject =
   # TODO: temp code until the CLI/RPC interface is fleshed out
   let status = waitFor nimbus.ethNode.fastBlockchainSync()
   if status != syncSuccess:
-    echo "Block sync failed: ", status
+    debug "Block sync failed: ", status
 
   nimbus.state = Running
   result = nimbus
 
 proc stop*(nimbus: NimbusObject) {.async.} =
-  echo "Graceful shutdown"
+  trace "Graceful shutdown"
   nimbus.rpcServer.stop()
 
 proc process*(nimbus: NimbusObject) =

nimbus/p2p/chain.nim

@@ -39,7 +39,7 @@ method persistBlocks*(c: Chain, headers: openarray[BlockHeader], bodies: openarr
   let transaction = c.db.db.beginTransaction()
   defer: transaction.dispose()
 
-  echo "Persisting blocks: ", headers[0].blockNumber, " - ", headers[^1].blockNumber
+  trace "Persisting blocks", range = headers[0].blockNumber & " - " & headers[^1].blockNumber
   for i in 0 ..< headers.len:
     let head = c.db.getCanonicalHead()
     assert(head.blockNumber == headers[i].blockNumber - 1)
@@ -54,8 +54,7 @@ method persistBlocks*(c: Chain, headers: openarray[BlockHeader], bodies: openarr
       assert(bodies[i].transactions.len != 0)
 
       if bodies[i].transactions.len != 0:
-        echo "block: ", headers[i].blockNumber
+        trace "Has transactions", blockNumber = headers[i].blockNumber, blockHash = headers[i].blockHash
-        echo "h: ", headers[i].blockHash
 
         for t in bodies[i].transactions:
           var sender: EthAddress
@@ -82,10 +81,9 @@ method persistBlocks*(c: Chain, headers: openarray[BlockHeader], bodies: openarr
     stateDb.addBalance(headers[i].coinbase, mainReward)
 
     if headers[i].stateRoot != stateDb.rootHash:
-      echo "Wrong state root in block ", headers[i].blockNumber, ". Expected: ", headers[i].stateRoot, ", Actual: ", stateDb.rootHash, " arrived from ", c.db.getCanonicalHead().stateRoot
+      debug "Wrong state root in block", blockNumber = headers[i].blockNumber, expected = headers[i].stateRoot, actual = stateDb.rootHash, arrivedFrom = c.db.getCanonicalHead().stateRoot
-      let trace = traceTransaction(c.db, headers[i], bodies[i], bodies[i].transactions.len - 1, {})
+      let ttrace = traceTransaction(c.db, headers[i], bodies[i], bodies[i].transactions.len - 1, {})
-      echo "NIMBUS TRACE"
+      trace "NIMBUS TRACE", transactionTrace=ttrace.pretty()
-      echo trace.pretty()
 
     assert(headers[i].stateRoot == stateDb.rootHash)
 

nimbus/p2p/executor.nim

@@ -5,8 +5,8 @@ import ../db/[db_chain, state_db], ../transaction, eth_common,
 proc processTransaction*(db: var AccountStateDB, t: Transaction, sender: EthAddress, vmState: BaseVMState): UInt256 =
   ## Process the transaction, write the results to db.
   ## Returns amount of ETH to be rewarded to miner
-  echo "Sender: ", sender
+  trace "Sender", sender
-  echo "txHash: ", t.rlpHash
+  trace "txHash", rlpHash = t.rlpHash
   # Inct nonce:
   db.setNonce(sender, db.getNonce(sender) + 1)
   var transactionFailed = false
@@ -35,7 +35,7 @@ proc processTransaction*(db: var AccountStateDB, t: Transaction, sender: EthAddr
   var gasUsed = t.payload.intrinsicGas.GasInt # += 32000 appears in Homestead when contract create
 
   if gasUsed > t.gasLimit:
-    echo "Transaction failed. Out of gas."
+    debug "Transaction failed. Out of gas."
     transactionFailed = true
   else:
     if t.isContractCreation:
@@ -46,14 +46,13 @@ proc processTransaction*(db: var AccountStateDB, t: Transaction, sender: EthAddr
       let code = db.getCode(t.to)
       if code.len == 0:
         # Value transfer
-        echo "Transfer ", t.value, " from ", sender, " to ", t.to
+        trace "Transfer", value = t.value, sender, to = t.to
 
         db.addBalance(t.to, t.value)
       else:
         # Contract call
-        echo "Contract call"
+        trace "Contract call"
-
+        trace "Transaction", sender, to = t.to, value = t.value, hasCode = code.len != 0
-        debug "Transaction", sender, to = t.to, value = t.value, hasCode = code.len != 0
         let msg = newMessage(t.gasLimit, t.gasPrice, t.to, sender, t.value, t.payload, code.toSeq)
         # TODO: Run the vm
 

nimbus/vm/computation.nim

@@ -130,7 +130,7 @@ proc applyMessage(computation: var BaseComputation, opCode: static[Op]) =
         db.setBalance(computation.msg.sender, newBalance)
         db.addBalance(computation.msg.storage_address, computation.msg.value)
 
-      debug "Value transferred",
+      trace "Value transferred",
         source = computation.msg.sender,
         dest = computation.msg.storage_address,
         value = computation.msg.value,
@@ -139,7 +139,7 @@ proc applyMessage(computation: var BaseComputation, opCode: static[Op]) =
         gasPrice = computation.msg.gasPrice,
         gas = computation.msg.gas
 
-    debug "Apply message",
+    trace "Apply message",
       value = computation.msg.value,
       senderBalance = newBalance,
       sender = computation.msg.sender.toHex,
@@ -154,7 +154,7 @@ proc applyMessage(computation: var BaseComputation, opCode: static[Op]) =
     computation.opcodeExec(computation)
 
   if not computation.isError:
-    debug "Computation committed"
+    trace "Computation committed"
     transaction.commit()
   else:
     debug "Computation rolled back due to error"
@@ -182,7 +182,7 @@ proc applyCreateMessage(fork: Fork, computation: var BaseComputation, opCode: st
           reason = "Write contract code for CREATE")
 
         let storageAddr = computation.msg.storage_address
-        debug "SETTING CODE",
+        trace "SETTING CODE",
           address = storageAddr.toHex,
           length = len(contract_code),
           hash = contractCode.rlpHash

nimbus/vm/interpreter/gas_meter.nim

@@ -22,19 +22,12 @@ 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
-
+  trace "GAS CONSUMPTION", total = gasMeter.gasRemaining + amount, amount, remaining = 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) =
   gasMeter.gasRemaining += amount
-  when defined(nimbusTrace): # XXX: https://github.com/status-im/nim-chronicles/issues/26
+  trace "GAS RETURNED", consumed = gasMeter.gasRemaining - amount, amount, remaining = gasMeter.gasRemaining
-    debug(
-      "GAS RETURNED", consumed = gasMeter.gasRemaining - amount, amount, remaining = gasMeter.gasRemaining)
 
 proc refundGas*(gasMeter: var GasMeter; amount: GasInt) =
   gasMeter.gasRefunded += amount
-  when defined(nimbusTrace): # XXX: https://github.com/status-im/nim-chronicles/issues/26
+  trace "GAS REFUND", consumed = gasMeter.gasRemaining - amount, amount, refunded = gasMeter.gasRefunded
-    debug(
-      "GAS REFUND", consumed = gasMeter.gasRemaining - amount, amount, refunded = gasMeter.gasRefunded)

nimbus/vm/interpreter/opcodes_impl.nim

@@ -569,7 +569,7 @@ op create, inline = false, value, startPosition, size:
     isCollision = db.hasCodeOrNonce(contractAddress)
 
   if isCollision:
-    debug("Address collision while creating contract", address = contractAddress.toHex)
+    debug "Address collision while creating contract", address = contractAddress.toHex
     push: 0
     raise newException(ValidationError, "Contract creation failed, address already in use")
 
@@ -699,7 +699,7 @@ template genCall(callName: untyped, opCode: Op): untyped =
                 c_memOffset: 0, # TODO make sure if we pass the largest mem requested
                 c_memLength: 0  # or an addition of mem requested
       ))
-    debug "Call (" & callName.astToStr & ")", gasCost = gasCost, childCost = childMsgGas
+    trace "Call (" & callName.astToStr & ")", gasCost = gasCost, childCost = childMsgGas
     computation.gasMeter.consumeGas(gasCost, reason = $opCode)
 
     computation.memory.extend(memInPos, memInLen)
@@ -798,8 +798,7 @@ op selfDestruct, inline = false:
     let RefundSelfDestruct = 24_000
     computation.gasMeter.refundGas(RefundSelfDestruct)
 
-    debug(
+    trace "SELFDESTRUCT",
-      "SELFDESTRUCT",
       storage_address = computation.msg.storage_address.toHex,
       local_balance = local_balance.toString,
-      beneficiary = beneficiary.toHex)
+      beneficiary = beneficiary.toHex

nimbus/vm/message.nim

@@ -47,7 +47,7 @@ proc newMessage*(
 
   validateGte(options.depth, minimum=0, title="Message.depth")
 
-  debug "New message",
+  trace "New message",
     gas = gas,
     gasPrice = gasPrice,
     destination = to,

nimbus/vm/precompiles.nim

@@ -71,7 +71,7 @@ proc ecRecover*(computation: var BaseComputation) =
 
   computation.rawOutput.setLen(32)
   computation.rawOutput[12..31] = pubKey.toCanonicalAddress()
-  debug "ECRecover precompile", derivedKey = pubKey.toCanonicalAddress()
+  trace "ECRecover precompile", derivedKey = pubKey.toCanonicalAddress()
 
 proc sha256*(computation: var BaseComputation) =
   let
@@ -80,7 +80,7 @@ proc sha256*(computation: var BaseComputation) =
 
   computation.gasMeter.consumeGas(gasFee, reason="SHA256 Precompile")
   computation.rawOutput = @(nimcrypto.sha_256.digest(computation.msg.data).data)
-  debug "SHA256 precompile", output = computation.rawOutput.toHex
+  trace "SHA256 precompile", output = computation.rawOutput.toHex
 
 proc ripemd160*(computation: var BaseComputation) =
   let
@@ -90,7 +90,7 @@ proc ripemd160*(computation: var BaseComputation) =
   computation.gasMeter.consumeGas(gasFee, reason="RIPEMD160 Precompile")
   computation.rawOutput.setLen(32)
   computation.rawOutput[12..31] = @(nimcrypto.ripemd160.digest(computation.msg.data).data)
-  debug "RIPEMD160 precompile", output = computation.rawOutput.toHex
+  trace "RIPEMD160 precompile", output = computation.rawOutput.toHex
 
 proc identity*(computation: var BaseComputation) =
   let
@@ -99,7 +99,7 @@ proc identity*(computation: var BaseComputation) =
 
   computation.gasMeter.consumeGas(gasFee, reason="Identity Precompile")
   computation.rawOutput = computation.msg.data
-  debug "Identity precompile", output = computation.rawOutput.toHex
+  trace "Identity precompile", output = computation.rawOutput.toHex
 
 proc modExpInternal(computation: var BaseComputation, base_len, exp_len, mod_len: int, T: type StUint) =
   template rawMsg: untyped {.dirty.} =
@@ -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)
-    debug "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)

nimbus/vm_state_transactions.nim

@@ -7,7 +7,7 @@
 
 import
   ranges/typedranges, sequtils, strformat, tables,
-  eth_common,
+  eth_common, chronicles,
   ./constants, ./errors, ./vm/computation,
   ./transaction, ./vm_types, ./vm_state, ./block_types, ./db/[db_chain, state_db], ./utils/header,
   ./vm/interpreter, ./utils/addresses
@@ -62,7 +62,7 @@ proc execComputation*(computation: var BaseComputation): bool =
 proc applyCreateTransaction*(db: var AccountStateDB, t: Transaction, vmState: BaseVMState, sender: EthAddress, useHomestead: bool = false): UInt256 =
   doAssert t.isContractCreation
   # TODO: clean up params
-  echo "Contract creation"
+  trace "Contract creation"
 
   let gasUsed = t.payload.intrinsicGas.GasInt + (if useHomestead: 32000 else: 0)
 
@@ -107,7 +107,7 @@ proc applyCreateTransaction*(db: var AccountStateDB, t: Transaction, vmState: Ba
     # the if transactionfailed at end is what is supposed to pick it up
     # especially when it's cross-function, it's ugly/fragile
     db.addBalance(sender, t.value)
-    echo "isError: ", c.isError
+    debug "execComputation() error", isError = c.isError
     if c.tracingEnabled:
       c.traceError()
     return t.gasLimit.u256 * t.gasPrice.u256