From 03ec65487d7d28e0d5495298a62243a1698ed474 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?=C8=98tefan=20Talpalaru?= Date: Fri, 7 Dec 2018 00:16:34 +0100 Subject: [PATCH] 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 | 3 ++- nimbus/nimbus.nim | 8 ++++---- nimbus/p2p/chain.nim | 12 +++++------- nimbus/p2p/executor.nim | 13 ++++++------- nimbus/vm/computation.nim | 8 ++++---- nimbus/vm/interpreter/gas_meter.nim | 13 +++---------- nimbus/vm/interpreter/opcodes_impl.nim | 9 ++++----- nimbus/vm/message.nim | 2 +- nimbus/vm/precompiles.nim | 10 +++++----- nimbus/vm_state_transactions.nim | 6 +++--- 10 files changed, 37 insertions(+), 47 deletions(-) diff --git a/nimbus.nimble b/nimbus.nimble index 9e898d043..e4ee07a15 100644 --- a/nimbus.nimble +++ b/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" diff --git a/nimbus/nimbus.nim b/nimbus/nimbus.nim index 8a3f9fe13..5e02158d5 100644 --- a/nimbus/nimbus.nim +++ b/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) = diff --git a/nimbus/p2p/chain.nim b/nimbus/p2p/chain.nim index f0bc7bd5a..8fd656f86 100644 --- a/nimbus/p2p/chain.nim +++ b/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 - echo "h: ", headers[i].blockHash + trace "Has transactions", blockNumber = headers[i].blockNumber, blockHash = 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 - let trace = traceTransaction(c.db, headers[i], bodies[i], bodies[i].transactions.len - 1, {}) - echo "NIMBUS TRACE" - echo trace.pretty() + debug "Wrong state root in block", blockNumber = headers[i].blockNumber, expected = headers[i].stateRoot, actual = stateDb.rootHash, arrivedFrom = c.db.getCanonicalHead().stateRoot + let ttrace = traceTransaction(c.db, headers[i], bodies[i], bodies[i].transactions.len - 1, {}) + trace "NIMBUS TRACE", transactionTrace=ttrace.pretty() assert(headers[i].stateRoot == stateDb.rootHash) diff --git a/nimbus/p2p/executor.nim b/nimbus/p2p/executor.nim index b87f95be3..d54f5df41 100644 --- a/nimbus/p2p/executor.nim +++ b/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 - echo "txHash: ", t.rlpHash + trace "Sender", sender + 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" - - debug "Transaction", sender, to = t.to, value = t.value, hasCode = code.len != 0 + trace "Contract call" + trace "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 diff --git a/nimbus/vm/computation.nim b/nimbus/vm/computation.nim index 083927374..aa2aae959 100644 --- a/nimbus/vm/computation.nim +++ b/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 diff --git a/nimbus/vm/interpreter/gas_meter.nim b/nimbus/vm/interpreter/gas_meter.nim index 69a1644ea..0e2f49de6 100644 --- a/nimbus/vm/interpreter/gas_meter.nim +++ b/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 - - 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) + trace "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 - debug( - "GAS RETURNED", consumed = gasMeter.gasRemaining - amount, amount, remaining = gasMeter.gasRemaining) + trace "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 - debug( - "GAS REFUND", consumed = gasMeter.gasRemaining - amount, amount, refunded = gasMeter.gasRefunded) + trace "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 b501621f5..c699c9cfe 100644 --- a/nimbus/vm/interpreter/opcodes_impl.nim +++ b/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( - "SELFDESTRUCT", + trace "SELFDESTRUCT", storage_address = computation.msg.storage_address.toHex, local_balance = local_balance.toString, - beneficiary = beneficiary.toHex) + beneficiary = beneficiary.toHex diff --git a/nimbus/vm/message.nim b/nimbus/vm/message.nim index c3f215b54..9d2733029 100644 --- a/nimbus/vm/message.nim +++ b/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, diff --git a/nimbus/vm/precompiles.nim b/nimbus/vm/precompiles.nim index 0dd2aed07..a36f4f3a1 100644 --- a/nimbus/vm/precompiles.nim +++ b/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) diff --git a/nimbus/vm_state_transactions.nim b/nimbus/vm_state_transactions.nim index 17e6475d3..07d108ce0 100644 --- a/nimbus/vm_state_transactions.nim +++ b/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