diff --git a/rskj-core/src/main/java/co/rsk/core/bc/BlockChainImpl.java b/rskj-core/src/main/java/co/rsk/core/bc/BlockChainImpl.java index c0557203397..ca76a9036ee 100644 --- a/rskj-core/src/main/java/co/rsk/core/bc/BlockChainImpl.java +++ b/rskj-core/src/main/java/co/rsk/core/bc/BlockChainImpl.java @@ -180,12 +180,12 @@ public ImportResult tryToConnect(Block block) { } try { - logger.info("Try connect block hash: {}, number: {}", + logger.trace("Try connect block hash: {}, number: {}", Hex.toHexString(block.getHash()).substring(0, 6), block.getNumber()); synchronized (connectLock) { - logger.info("Start try connect"); + logger.trace("Start try connect"); long saveTime = System.nanoTime(); ImportResult result = internalTryToConnect(block); long totalTime = System.nanoTime() - saveTime; @@ -211,7 +211,7 @@ private ImportResult internalTryToConnect(Block block) { Block bestBlock; BigInteger bestTotalDifficulty; - logger.info("get current state"); + logger.trace("get current state"); // get current state synchronized (accessLock) { @@ -229,7 +229,7 @@ private ImportResult internalTryToConnect(Block block) { } // else, Get parent AND total difficulty else { - logger.info("get parent and total difficulty"); + logger.trace("get parent and total difficulty"); parent = blockStore.getBlockByHash(block.getParentHash()); if (parent == null) { @@ -255,7 +255,7 @@ private ImportResult internalTryToConnect(Block block) { if (parent != null) { long saveTime = System.nanoTime(); - logger.info("execute start"); + logger.trace("execute start"); if (this.noValidation) { result = blockExecutor.executeAll(block, parent.getStateRoot()); @@ -263,11 +263,11 @@ private ImportResult internalTryToConnect(Block block) { result = blockExecutor.execute(block, parent.getStateRoot(), false); } - logger.info("execute done"); + logger.trace("execute done"); boolean isValid = noValidation ? true : blockExecutor.validate(block, result); - logger.info("validate done"); + logger.trace("validate done"); if (!isValid) { return ImportResult.INVALID_BLOCK; @@ -279,17 +279,17 @@ private ImportResult internalTryToConnect(Block block) { adminInfo.addBlockExecTime(totalTime); } - logger.info("block: num: [{}] hash: [{}], executed after: [{}]nano", block.getNumber(), block.getShortHash(), totalTime); + logger.trace("block: num: [{}] hash: [{}], executed after: [{}]nano", block.getNumber(), block.getShortHash(), totalTime); } // the new accumulated difficulty BigInteger totalDifficulty = parentTotalDifficulty.add(block.getCumulativeDifficulty()); - logger.info("TD: updated to {}", totalDifficulty); + logger.trace("TD: updated to {}", totalDifficulty); // It is the new best block if (SelectionRule.shouldWeAddThisBlock(totalDifficulty, status.getTotalDifficulty(),block, bestBlock)) { if (bestBlock != null && !bestBlock.isParentOf(block)) { - logger.info("Rebranching: {} ~> {} From block {} ~> {} Difficulty {} Challenger difficulty {}", + logger.trace("Rebranching: {} ~> {} From block {} ~> {} Difficulty {} Challenger difficulty {}", bestBlock.getShortHash(), block.getShortHash(), bestBlock.getNumber(), block.getNumber(), status.getTotalDifficulty().toString(), totalDifficulty.toString()); BlockFork fork = new BlockFork(); @@ -321,7 +321,7 @@ private ImportResult internalTryToConnect(Block block) { // It is not the new best block else { if (bestBlock != null && !bestBlock.isParentOf(block)) { - logger.info("No rebranch: {} ~> {} From block {} ~> {} Difficulty {} Challenger difficulty {}", + logger.trace("No rebranch: {} ~> {} From block {} ~> {} Difficulty {} Challenger difficulty {}", bestBlock.getShortHash(), block.getShortHash(), bestBlock.getNumber(), block.getNumber(), status.getTotalDifficulty().toString(), totalDifficulty.toString()); } @@ -509,7 +509,7 @@ private void extendAlternativeBlockChain(Block block, BigInteger totalDifficulty private void storeBlock(Block block, BigInteger totalDifficulty, boolean inBlockChain) { blockStore.saveBlock(block, totalDifficulty, inBlockChain); - logger.info("Block saved: number: {}, hash: {}, TD: {}", + logger.trace("Block saved: number: {}, hash: {}, TD: {}", block.getNumber(), block.getShortHash(), totalDifficulty); } @@ -553,11 +553,11 @@ private void flushData() { long saveTime = System.nanoTime(); repository.flush(); long totalTime = System.nanoTime() - saveTime; - logger.info("repository flush: [{}]nano", totalTime); + logger.trace("repository flush: [{}]nano", totalTime); saveTime = System.nanoTime(); blockStore.flush(); totalTime = System.nanoTime() - saveTime; - logger.info("blockstore flush: [{}]nano", totalTime); + logger.trace("blockstore flush: [{}]nano", totalTime); } nFlush++; nFlush = nFlush % config.flushNumberOfBlocks(); diff --git a/rskj-core/src/main/java/co/rsk/core/bc/BlockExecutor.java b/rskj-core/src/main/java/co/rsk/core/bc/BlockExecutor.java index 92ab568a052..c9b4b962ed0 100644 --- a/rskj-core/src/main/java/co/rsk/core/bc/BlockExecutor.java +++ b/rskj-core/src/main/java/co/rsk/core/bc/BlockExecutor.java @@ -186,7 +186,7 @@ public BlockResult executeAll(Block block, byte[] stateRoot) { } private BlockResult execute(Block block, byte[] stateRoot, boolean discardInvalidTxs, boolean ignoreReadyToExecute) { - logger.info("applyBlock: block: [{}] tx.list: [{}]", block.getNumber(), block.getTransactionsList().size()); + logger.trace("applyBlock: block: [{}] tx.list: [{}]", block.getNumber(), block.getTransactionsList().size()); Repository initialRepository = repository.getSnapshotTo(stateRoot); @@ -202,7 +202,7 @@ private BlockResult execute(Block block, byte[] stateRoot, boolean discardInvali int txindex = 0; for (Transaction tx : block.getTransactionsList()) { - logger.info("apply block: [{}] tx: [{}] ", block.getNumber(), i); + logger.trace("apply block: [{}] tx: [{}] ", block.getNumber(), i); TransactionExecutor txExecutor = new TransactionExecutor(config, tx, txindex++, block.getCoinbase(), track, blockStore, blockChain.getReceiptStore(), programInvokeFactory, block, listener, totalGasUsed); @@ -224,11 +224,11 @@ private BlockResult execute(Block block, byte[] stateRoot, boolean discardInvali txExecutor.go(); txExecutor.finalization(); - logger.info("tx executed"); + logger.trace("tx executed"); track.commit(); - logger.info("track commit"); + logger.trace("track commit"); long gasUsed = txExecutor.getGasUsed(); totalGasUsed += gasUsed; @@ -246,16 +246,16 @@ private BlockResult execute(Block block, byte[] stateRoot, boolean discardInvali receipt.setLogInfoList(txExecutor.getVMLogs()); receipt.setStatus(txExecutor.getReceipt().getStatus()); - logger.info("block: [{}] executed tx: [{}] state: [{}]", block.getNumber(), Hex.toHexString(tx.getHash()), + logger.trace("block: [{}] executed tx: [{}] state: [{}]", block.getNumber(), Hex.toHexString(tx.getHash()), Hex.toHexString(lastStateRootHash)); - logger.info("tx[{}].receipt", i); + logger.trace("tx[{}].receipt", i); i++; receipts.add(receipt); - logger.info("tx done"); + logger.trace("tx done"); } return new BlockResult(executedTransactions, receipts, lastStateRootHash, totalGasUsed, totalPaidFees); diff --git a/rskj-core/src/main/java/co/rsk/core/bc/PendingStateImpl.java b/rskj-core/src/main/java/co/rsk/core/bc/PendingStateImpl.java index 6c2d55d95de..9db6e15a493 100644 --- a/rskj-core/src/main/java/co/rsk/core/bc/PendingStateImpl.java +++ b/rskj-core/src/main/java/co/rsk/core/bc/PendingStateImpl.java @@ -166,19 +166,19 @@ public synchronized List addWireTransactions(List tran List added = new ArrayList<>(); Long bnumber = Long.valueOf(getCurrentBestBlockNumber()); - logger.info("Trying add {} wire transactions using block {} {}", transactions.size(), bnumber, getBestBlock().getShortHash()); + logger.trace("Trying add {} wire transactions using block {} {}", transactions.size(), bnumber, getBestBlock().getShortHash()); for (Transaction tx : transactions) { if (!shouldAcceptTx(tx)) { continue; } - logger.info("Trying add wire transaction nonce {} hash {}", tx.getHash(), toBI(tx.getNonce())); + logger.trace("Trying add wire transaction nonce {} hash {}", tx.getHash(), toBI(tx.getNonce())); ByteArrayWrapper hash = new ByteArrayWrapper(tx.getHash()); if (pendingTransactions.containsKey(hash) || wireTransactions.containsKey(hash)) { - logger.info("TX already exists: {} ", tx); + logger.trace("TX already exists: {} ", tx); continue; } @@ -197,7 +197,7 @@ public synchronized List addWireTransactions(List tran }); } - logger.info("Wire transaction list added: {} new, {} valid of received {}, #of known txs: {}", added.size(), added.size(), transactions.size(), transactions.size()); + logger.trace("Wire transaction list added: {} new, {} valid of received {}, #of known txs: {}", added.size(), added.size(), transactions.size(), transactions.size()); return added; } @@ -301,7 +301,7 @@ public void removeObsoleteTransactions(long currentBlock, int depth, int timeout if (block < currentBlock - depth) { toremove.add(entry.getKey()); - logger.info( + logger.trace( "Clear outdated transaction, block.number: [{}] hash: [{}]", block, entry.getKey().toString()); @@ -324,7 +324,7 @@ public synchronized void removeObsoleteTransactions(long timeSeconds) { if (txtime <= timeSeconds) { toremove.add(entry.getKey()); - logger.info( + logger.trace( "Clear outdated transaction, hash: [{}]", entry.getKey().toString()); } @@ -348,7 +348,7 @@ public synchronized void clearPendingState(List txs) { byte[] bhash = tx.getHash(); ByteArrayWrapper hash = new ByteArrayWrapper(bhash); pendingTransactions.remove(hash); - logger.info("Clear pending transaction, hash: [{}]", Hex.toHexString(bhash)); + logger.trace("Clear pending transaction, hash: [{}]", Hex.toHexString(bhash)); } } @@ -358,7 +358,7 @@ public synchronized void clearWire(List txs) { byte[] bhash = tx.getHash(); ByteArrayWrapper hash = new ByteArrayWrapper(bhash); wireTransactions.remove(hash); - logger.info("Clear wire transaction, hash: [{}]", Hex.toHexString(bhash)); + logger.trace("Clear wire transaction, hash: [{}]", Hex.toHexString(bhash)); } } @@ -384,7 +384,7 @@ public synchronized void updateState() { } private void executeTransaction(Transaction tx) { - logger.info("Apply pending state tx: {} {}", toBI(tx.getNonce()), Hex.toHexString(tx.getHash())); + logger.trace("Apply pending state tx: {} {}", toBI(tx.getNonce()), Hex.toHexString(tx.getHash())); Block best = blockChain.getBestBlock(); diff --git a/rskj-core/src/main/java/co/rsk/db/RepositoryImpl.java b/rskj-core/src/main/java/co/rsk/db/RepositoryImpl.java index 63827cae2ba..6ffbb32d634 100644 --- a/rskj-core/src/main/java/co/rsk/db/RepositoryImpl.java +++ b/rskj-core/src/main/java/co/rsk/db/RepositoryImpl.java @@ -320,7 +320,7 @@ public void reset() { @Override public synchronized void updateBatch(Map stateCache, Map detailsCache) { - logger.info("updatingBatch: detailsCache.size: {}", detailsCache.size()); + logger.debug("updatingBatch: detailsCache.size: {}", detailsCache.size()); for (Map.Entry entry : stateCache.entrySet()) { RskAddress addr = entry.getKey(); @@ -357,7 +357,7 @@ public synchronized void updateBatch(Map stateCache, } } - logger.info("updated: detailsCache.size: {}", detailsCache.size()); + logger.debug("updated: detailsCache.size: {}", detailsCache.size()); stateCache.clear(); detailsCache.clear(); diff --git a/rskj-core/src/main/java/co/rsk/mine/MinerServerImpl.java b/rskj-core/src/main/java/co/rsk/mine/MinerServerImpl.java index 1752ac0f89e..7cf5dc385bb 100644 --- a/rskj-core/src/main/java/co/rsk/mine/MinerServerImpl.java +++ b/rskj-core/src/main/java/co/rsk/mine/MinerServerImpl.java @@ -469,14 +469,11 @@ public SubmitBlockResult submitBitcoinBlock(String blockHashForMergedMining, co. private boolean isValid(Block block) { try { - if (!powRule.isValid(block)) { - return false; - } + return powRule.isValid(block); } catch (Exception e) { logger.error("Failed to validate PoW from block {}: {}", block.getShortHash(), e); return false; } - return true; } public static byte[] compressCoinbase(byte[] bitcoinMergedMiningCoinbaseTransactionSerialized) { @@ -607,7 +604,7 @@ public void buildBlockToMine(@Nonnull Block newBlockParent, boolean createCompet newBlockParent = blockchain.getBlockByHash(newBlockParent.getParentHash()); } - logger.info("Starting block to mine from parent {}", newBlockParent.getNumber() + " " + Hex.toHexString(newBlockParent.getHash())); + logger.info("Starting block to mine from parent {} {}", newBlockParent.getNumber(), Hex.toHexString(newBlockParent.getHash())); List uncles; if (blockStore != null) { @@ -711,7 +708,7 @@ public long increaseTime(long seconds) { private void removePendingTransactions(List transactions) { if (transactions != null) { for (Transaction tx : transactions) { - logger.info("Removing transaction {}", Hex.toHexString(tx.getHash())); + logger.debug("Removing transaction {}", Hex.toHexString(tx.getHash())); } } @@ -721,7 +718,7 @@ private void removePendingTransactions(List transactions) { private List getTransactions(List txsToRemove, Block parent, BigInteger minGasPrice) { - logger.info("Starting getTransactions"); + logger.debug("Starting getTransactions"); List txs = new MinerUtils().getAllTransactions(pendingState); logger.debug("txsList size {}", txs.size()); diff --git a/rskj-core/src/main/java/co/rsk/mine/MinerUtils.java b/rskj-core/src/main/java/co/rsk/mine/MinerUtils.java index 7c0adbe46b0..6368ba63da0 100644 --- a/rskj-core/src/main/java/co/rsk/mine/MinerUtils.java +++ b/rskj-core/src/main/java/co/rsk/mine/MinerUtils.java @@ -154,10 +154,10 @@ public List filterTransactions(List txsResult = new ArrayList<>(); for (org.ethereum.core.Transaction tx : txs) { try { - logger.info("Pending transaction {} {}", toBI(tx.getNonce()), Hex.toHexString(tx.getHash())); + logger.debug("Pending transaction {} {}", toBI(tx.getNonce()), Hex.toHexString(tx.getHash())); RskAddress txSender = tx.getSender(); - logger.info("Examining transaction {} sender: {} value: {} nonce: {}", Hex.toHexString(tx.getHash()), txSender, Hex.toHexString(tx.getValue()), Hex.toHexString(tx.getNonce())); + logger.debug("Examining transaction {} sender: {} value: {} nonce: {}", Hex.toHexString(tx.getHash()), txSender, Hex.toHexString(tx.getValue()), Hex.toHexString(tx.getNonce())); BigInteger txNonce = new BigInteger(1, tx.getNonce()); @@ -183,7 +183,7 @@ public List filterTransactions(List filterTransactions(List Constants.getMaxAddressByteLength()) { - if (logger.isWarnEnabled()) { - logger.warn("Receiver address to long: size: {}, tx {}", receiveAddress.length, Hex.toHexString(tx.getHash())); - logger.warn("Transaction Data: {}", tx); - logger.warn("Tx Included in the following block: {}", this.executionBlock); - } + logger.warn("Receiver address to long: size: {}, tx {}", receiveAddress.length, Hex.toHexString(tx.getHash())); + logger.warn("Transaction Data: {}", tx); + logger.warn("Tx Included in the following block: {}", this.executionBlock); return false; } if (!tx.acceptTransactionSignature(config.getBlockchainConfig().getCommonConstants().getChainId())) { - if (logger.isWarnEnabled()) { - logger.warn("Transaction {} signature not accepted: {}", Hex.toHexString(tx.getHash()), tx.getSignature()); - logger.warn("Transaction Data: {}", tx); - logger.warn("Tx Included in the following block: {}", this.executionBlock); - } + logger.warn("Transaction {} signature not accepted: {}", Hex.toHexString(tx.getHash()), tx.getSignature()); + logger.warn("Transaction Data: {}", tx); + logger.warn("Tx Included in the following block: {}", this.executionBlock); panicProcessor.panic("invalidsignature", String.format("Transaction %s signature not accepted: %s", Hex.toHexString(tx.getHash()), tx.getSignature().toString())); - execError("Transaction signature not accepted: " + tx.getSignature()); + execError(String.format("Transaction signature not accepted: %s", tx.getSignature().toString())); return false; } @@ -217,7 +211,7 @@ public void execute() { return; } - logger.info("Execute transaction {} {}", toBI(tx.getNonce()), Hex.toHexString(tx.getHash())); + logger.trace("Execute transaction {} {}", toBI(tx.getNonce()), Hex.toHexString(tx.getHash())); if (!localCall) { @@ -227,8 +221,8 @@ public void execute() { BigInteger txGasCost = toBI(tx.getGasPrice()).multiply(txGasLimit); track.addBalance(tx.getSender(), txGasCost.negate()); - if (logger.isInfoEnabled()) { - logger.info("Paying: txGasCost: [{}], gasPrice: [{}], gasLimit: [{}]", txGasCost, toBI(tx.getGasPrice()), txGasLimit); + if (logger.isTraceEnabled()){ + logger.trace("Paying: txGasCost: [{}], gasPrice: [{}], gasLimit: [{}]", txGasCost, toBI(tx.getGasPrice()), txGasLimit); } } @@ -244,7 +238,7 @@ private void call() { return; } - logger.info("Call transaction {} {}", toBI(tx.getNonce()), Hex.toHexString(tx.getHash())); + logger.trace("Call transaction {} {}", toBI(tx.getNonce()), Hex.toHexString(tx.getHash())); RskAddress targetAddress = tx.getReceiveAddress(); @@ -262,8 +256,8 @@ private void call() { if (!localCall && txGasLimit.compareTo(BigInteger.valueOf(requiredGas)) < 0) { // no refund // no endowment - execError("Out of Gas calling precompiled contract 0x" + targetAddress.toString() + - ", required: " + (requiredGas + basicTxCost) + ", left: " + mEndGas); + execError(String.format("Out of Gas calling precompiled contract 0x%s, required: %d, left: %s ", + targetAddress.toString(), (requiredGas + basicTxCost), mEndGas)); mEndGas = BigInteger.ZERO; return; } else { @@ -323,6 +317,11 @@ private void create() { transfer(cacheTrack, tx.getSender(), newContractAddress, endowment); } + private void execError(Throwable err) { + logger.warn("execError: ", err); + executionError = err.getMessage(); + } + private void execError(String err) { logger.warn(err); executionError = err; @@ -339,7 +338,7 @@ public void go() { return; } - logger.info("Go transaction {} {}", toBI(tx.getNonce()), Hex.toHexString(tx.getHash())); + logger.trace("Go transaction {} {}", toBI(tx.getNonce()), Hex.toHexString(tx.getHash())); try { @@ -397,7 +396,7 @@ public void go() { // https://github.com/ethereum/cpp-ethereum/blob/develop/libethereum/Executive.cpp#L241 cacheTrack.rollback(); mEndGas = BigInteger.ZERO; - execError(e.getMessage()); + execError(e); } } @@ -426,7 +425,7 @@ public void finalization() { return; } - logger.info("Finalize transaction {} {}", toBI(tx.getNonce()), Hex.toHexString(tx.getHash())); + logger.trace("Finalize transaction {} {}", toBI(tx.getNonce()), Hex.toHexString(tx.getHash())); cacheTrack.commit(); @@ -464,20 +463,20 @@ public void finalization() { } } - logger.info("Building transaction execution summary"); + logger.trace("Building transaction execution summary"); TransactionExecutionSummary summary = summaryBuilder.build(); // Refund for gas leftover track.addBalance(tx.getSender(), summary.getLeftover().add(summary.getRefund())); - logger.info("Pay total refund to sender: [{}], refund val: [{}]", tx.getSender(), summary.getRefund()); + logger.trace("Pay total refund to sender: [{}], refund val: [{}]", tx.getSender(), summary.getRefund()); // Transfer fees to miner BigInteger summaryFee = summary.getFee(); //TODO: REMOVE THIS WHEN THE LocalBLockTests starts working with REMASC if(config.isRemascEnabled()) { - logger.info("Adding fee to remasc contract account"); + logger.trace("Adding fee to remasc contract account"); track.addBalance(PrecompiledContracts.REMASC_ADDR, summaryFee); } else { track.addBalance(coinbase, summaryFee); @@ -486,7 +485,7 @@ public void finalization() { this.paidFees = summaryFee; if (result != null) { - logger.info("Processing result"); + logger.trace("Processing result"); logs = notRejectedLogInfos; result.getCodeChanges().forEach((key, value) -> track.saveCode(new RskAddress(key), value)); @@ -498,7 +497,7 @@ public void finalization() { listener.onTransactionExecuted(summary); } - logger.info("tx listener done"); + logger.trace("tx listener done"); if (config.vmTrace() && program != null && result != null) { ProgramTrace trace = program.getTrace().result(result.getHReturn()).error(result.getException()); @@ -509,13 +508,13 @@ public void finalization() { listener.onVMTraceCreated(txHash, trace); } } catch (IOException e) { - String errorMessage = "Cannot write trace to file"; - panicProcessor.panic("executor", errorMessage + ": " + e); - logger.error(errorMessage, e); + String errorMessage = String.format("Cannot write trace to file: %s", e.getMessage()); + panicProcessor.panic("executor", errorMessage); + logger.error(errorMessage); } } - logger.info("tx finalization done"); + logger.trace("tx finalization done"); } public TransactionExecutor setLocalCall(boolean localCall) { diff --git a/rskj-core/src/main/java/org/ethereum/datasource/LevelDbDataSource.java b/rskj-core/src/main/java/org/ethereum/datasource/LevelDbDataSource.java index 323ba50ff74..ae6ef110cd9 100644 --- a/rskj-core/src/main/java/org/ethereum/datasource/LevelDbDataSource.java +++ b/rskj-core/src/main/java/org/ethereum/datasource/LevelDbDataSource.java @@ -65,7 +65,7 @@ public class LevelDbDataSource implements KeyValueDataSource { public LevelDbDataSource(RskSystemProperties config, String name) { this.config = config; this.name = name; - logger.info("New LevelDbDataSource: {}", name); + logger.debug("New LevelDbDataSource: {}", name); } @Override diff --git a/rskj-core/src/main/java/org/ethereum/net/rlpx/FrameCodecHandler.java b/rskj-core/src/main/java/org/ethereum/net/rlpx/FrameCodecHandler.java index dcd35bd1675..ab72d41129b 100644 --- a/rskj-core/src/main/java/org/ethereum/net/rlpx/FrameCodecHandler.java +++ b/rskj-core/src/main/java/org/ethereum/net/rlpx/FrameCodecHandler.java @@ -39,8 +39,8 @@ public class FrameCodecHandler extends ByteToMessageCodec { private static final Logger loggerWire = LoggerFactory.getLogger("wire"); private static final Logger loggerNet = LoggerFactory.getLogger("net"); - public FrameCodec frameCodec; - public Channel channel; + protected final FrameCodec frameCodec; + protected final Channel channel; public FrameCodecHandler(FrameCodec frameCodec, Channel channel) { this.frameCodec = frameCodec; @@ -63,8 +63,7 @@ protected void decode(ChannelHandlerContext ctx, ByteBuf in, List out) t } for (int i = 0; i < frames.size(); i++) { - FrameCodec.Frame frame = frames.get(i); - + frames.get(i); channel.getNodeStatistics().rlpxInMessages.add(); } @@ -85,8 +84,7 @@ public void exceptionCaught(ChannelHandlerContext ctx, Throwable cause) throws E loggerNet.debug("FrameCodec failed: ", cause); } else { if (cause instanceof IOException) { - loggerNet.info("FrameCodec failed: " + ctx.channel().remoteAddress() + "(" + cause.getMessage() + ")"); - loggerNet.debug("FrameCodec failed: " + ctx.channel().remoteAddress(), cause); + loggerNet.info(String.format("FrameCodec failed: %s", ctx.channel().remoteAddress()), cause); } else { loggerNet.error("FrameCodec failed: ", cause); } diff --git a/rskj-core/src/main/java/org/ethereum/net/rlpx/HandshakeHandler.java b/rskj-core/src/main/java/org/ethereum/net/rlpx/HandshakeHandler.java index 6f17d94919e..f7d86612347 100644 --- a/rskj-core/src/main/java/org/ethereum/net/rlpx/HandshakeHandler.java +++ b/rskj-core/src/main/java/org/ethereum/net/rlpx/HandshakeHandler.java @@ -24,7 +24,6 @@ import co.rsk.scoring.PeerScoringManager; import com.google.common.io.ByteStreams; import io.netty.buffer.ByteBuf; -import io.netty.channel.ChannelHandler; import io.netty.channel.ChannelHandlerContext; import io.netty.handler.codec.ByteToMessageDecoder; import org.ethereum.config.SystemProperties; @@ -41,10 +40,7 @@ import org.spongycastle.crypto.InvalidCipherTextException; import org.spongycastle.math.ec.ECPoint; import org.spongycastle.util.encoders.Hex; -import org.springframework.context.annotation.Scope; -import org.springframework.stereotype.Component; -import javax.annotation.PostConstruct; import java.io.IOException; import java.net.InetAddress; import java.net.InetSocketAddress; @@ -112,7 +108,7 @@ protected void decode(ChannelHandlerContext ctx, ByteBuf in, List out) t public void initiate(ChannelHandlerContext ctx) throws Exception { - loggerNet.info("RLPX protocol activated"); + loggerNet.trace("RLPX protocol activated"); nodeId = myKey.getNodeId(); @@ -139,9 +135,7 @@ public void initiate(ChannelHandlerContext ctx) throws Exception { channel.getNodeStatistics().rlpxAuthMessagesSent.add(); - if (loggerNet.isInfoEnabled()) { - loggerNet.info("To: \t{} \tSend: \t{}", ctx.channel().remoteAddress(), msg); - } + loggerNet.trace("To: \t{} \tSend: \t{}", ctx.channel().remoteAddress(), msg); } // consume handshake, producing no resulting message to upper layers @@ -161,7 +155,7 @@ private void decodeHandshake(final ChannelHandlerContext ctx, ByteBuf buffer) th // trying to decode as pre-EIP-8 AuthResponseMessage response = handshake.handleAuthResponse(myKey, initiatePacket, responsePacket); - loggerNet.info("From: \t{} \tRecv: \t{}", ctx.channel().remoteAddress(), response); + loggerNet.trace("From: \t{} \tRecv: \t{}", ctx.channel().remoteAddress(), response); } catch (Throwable t) { @@ -174,16 +168,16 @@ private void decodeHandshake(final ChannelHandlerContext ctx, ByteBuf buffer) th } AuthResponseMessageV4 response = handshake.handleAuthResponseV4(myKey, initiatePacket, responsePacket); - loggerNet.info("From: \t{} \tRecv: \t{}", ctx.channel().remoteAddress(), response); + loggerNet.trace("From: \t{} \tRecv: \t{}", ctx.channel().remoteAddress(), response); } EncryptionHandshake.Secrets secrets = this.handshake.getSecrets(); this.frameCodec = new FrameCodec(secrets); - loggerNet.info("auth exchange done"); + loggerNet.trace("auth exchange done"); channel.sendHelloMessage(ctx, frameCodec, Hex.toHexString(nodeId), null); } else { - loggerWire.info("MessageCodec: Buffer bytes: " + buffer.readableBytes()); + loggerWire.debug("MessageCodec: Buffer bytes: " + buffer.readableBytes()); List frames = frameCodec.readFrames(buffer); if (frames == null || frames.isEmpty()) { return; @@ -192,17 +186,13 @@ private void decodeHandshake(final ChannelHandlerContext ctx, ByteBuf buffer) th byte[] payload = ByteStreams.toByteArray(frame.getStream()); if (frame.getType() == P2pMessageCodes.HELLO.asByte()) { HelloMessage helloMessage = new HelloMessage(payload); - if (loggerNet.isInfoEnabled()) { - loggerNet.info("From: \t{} \tRecv: \t{}", ctx.channel().remoteAddress(), helloMessage); - } + loggerNet.trace("From: \t{} \tRecv: \t{}", ctx.channel().remoteAddress(), helloMessage); isHandshakeDone = true; this.channel.publicRLPxHandshakeFinished(ctx, frameCodec, helloMessage); recordSuccessfulHandshake(ctx); } else { DisconnectMessage message = new DisconnectMessage(payload); - if (loggerNet.isInfoEnabled()) { - loggerNet.info("From: \t{} \tRecv: \t{}", channel, message); - } + loggerNet.trace("From: \t{} \tRecv: \t{}", channel, message); channel.getNodeStatistics().nodeDisconnectedRemote(message.getReason()); } } @@ -224,10 +214,10 @@ private void decodeHandshake(final ChannelHandlerContext ctx, ByteBuf buffer) th // trying to decode as pre-EIP-8 AuthInitiateMessage initiateMessage = handshake.decryptAuthInitiate(authInitPacket, myKey); - loggerNet.info("From: \t{} \tRecv: \t{}", ctx.channel().remoteAddress(), initiateMessage); + loggerNet.trace("From: \t{} \tRecv: \t{}", ctx.channel().remoteAddress(), initiateMessage); AuthResponseMessage response = handshake.makeAuthInitiate(initiateMessage, myKey); - loggerNet.info("To: \t{} \tSend: \t{}", ctx.channel().remoteAddress(), response); + loggerNet.trace("To: \t{} \tSend: \t{}", ctx.channel().remoteAddress(), response); responsePacket = handshake.encryptAuthResponse(response); } catch (Throwable t) { @@ -242,10 +232,10 @@ private void decodeHandshake(final ChannelHandlerContext ctx, ByteBuf buffer) th } AuthInitiateMessageV4 initiateMessage = handshake.decryptAuthInitiateV4(authInitPacket, myKey); - loggerNet.info("From: \t{} \tRecv: \t{}", ctx.channel().remoteAddress(), initiateMessage); + loggerNet.trace("From: \t{} \tRecv: \t{}", ctx.channel().remoteAddress(), initiateMessage); AuthResponseMessageV4 response = handshake.makeAuthInitiateV4(initiateMessage, myKey); - loggerNet.info("To: \t{} \tSend: \t{}", ctx.channel().remoteAddress(), response); + loggerNet.trace("To: \t{} \tSend: \t{}", ctx.channel().remoteAddress(), response); responsePacket = handshake.encryptAuthResponseV4(response); } catch (InvalidCipherTextException ce) { @@ -280,7 +270,7 @@ private void decodeHandshake(final ChannelHandlerContext ctx, ByteBuf buffer) th Message message = new P2pMessageFactory().create((byte) frame.getType(), ByteStreams.toByteArray(frame.getStream())); - loggerNet.info("From: \t{} \tRecv: \t{}", ctx.channel().remoteAddress(), message); + loggerNet.trace("From: \t{} \tRecv: \t{}", ctx.channel().remoteAddress(), message); if (frame.getType() == P2pMessageCodes.DISCONNECT.asByte()) { loggerNet.info("Active remote peer disconnected right after handshake."); @@ -347,13 +337,12 @@ public byte[] getRemoteId() { public void exceptionCaught(ChannelHandlerContext ctx, Throwable cause) throws Exception { recordFailedHandshake(ctx); if (channel.isDiscoveryMode()) { - loggerNet.debug("Handshake failed: " + ctx.channel().remoteAddress() + "(" + cause.getMessage() + ")"); + loggerNet.debug(String.format("Handshake failed: %s (%s)", ctx.channel().remoteAddress(), cause.getMessage())); } else { if (cause instanceof IOException) { - loggerNet.info("Handshake failed: " + ctx.channel().remoteAddress() + "(" + cause.getMessage() + ")"); - loggerNet.debug("Handshake failed: " + ctx.channel().remoteAddress(), cause); + loggerNet.info(String.format("Handshake failed: %s", ctx.channel().remoteAddress(), cause)); } else { - loggerNet.error("Handshake failed: " + ctx.channel().remoteAddress() + "(" + cause.getMessage() + ")"); + loggerNet.error("Handshake failed: ", cause); } } ctx.close(); diff --git a/rskj-core/src/main/java/org/ethereum/net/rlpx/MessageCodec.java b/rskj-core/src/main/java/org/ethereum/net/rlpx/MessageCodec.java index deab63c1f2a..ed24732f6a9 100644 --- a/rskj-core/src/main/java/org/ethereum/net/rlpx/MessageCodec.java +++ b/rskj-core/src/main/java/org/ethereum/net/rlpx/MessageCodec.java @@ -78,7 +78,6 @@ public MessageCodec(EthereumListener ethereumListener, SystemProperties config) @Override protected void decode(ChannelHandlerContext ctx, Frame frame, List out) throws Exception { - Frame completeFrame = null; if (frame.isChunked()) { if (!supportChunkedFrames && frame.totalFrameSize > 0) { throw new RuntimeException("Faming is not supported in this configuration."); @@ -88,7 +87,7 @@ protected void decode(ChannelHandlerContext ctx, Frame frame, List out) if (frameParts == null) { if (frame.totalFrameSize < 0) { // TODO: refactor this logic (Cpp sends non-chunked frames with context-id) - Message message = decodeMessage(ctx, Collections.singletonList(frame)); + Message message = decodeMessage(Collections.singletonList(frame)); out.add(message); return; } else { @@ -116,17 +115,17 @@ protected void decode(ChannelHandlerContext ctx, Frame frame, List out) return; } if (curSize == frameParts.getLeft().get(0).totalFrameSize) { - Message message = decodeMessage(ctx, frameParts.getLeft()); + Message message = decodeMessage(frameParts.getLeft()); incompleteFrames.remove(frame.contextId); out.add(message); } } else { - Message message = decodeMessage(ctx, Collections.singletonList(frame)); + Message message = decodeMessage(Collections.singletonList(frame)); out.add(message); } } - private Message decodeMessage(ChannelHandlerContext ctx, List frames) throws IOException { + private Message decodeMessage(List frames) throws IOException { long frameType = frames.get(0).getType(); byte[] payload = new byte[frames.size() == 1 ? frames.get(0).getSize() : frames.get(0).totalFrameSize]; @@ -141,9 +140,7 @@ private Message decodeMessage(ChannelHandlerContext ctx, List frames) thr Message msg = createMessage((byte) frameType, payload); - if (loggerNet.isInfoEnabled()) { - loggerNet.info("From: \t{} \tRecv: \t{}", channel, msg.toString()); - } + loggerNet.trace("From: \t{} \tRecv: \t{}", channel, msg); ethereumListener.onRecvMessage(channel, msg); @@ -156,9 +153,7 @@ protected void encode(ChannelHandlerContext ctx, Message msg, List out) String output = String.format("To: \t%s \tSend: \t%s", ctx.channel().remoteAddress(), msg); ethereumListener.trace(output); - if (loggerNet.isInfoEnabled()) { - loggerNet.info("To: \t{} \tSend: \t{}", channel, msg); - } + loggerNet.trace("To: \t{} \tSend: \t{}", channel, msg); byte[] encoded = msg.getEncoded(); diff --git a/rskj-core/src/main/java/org/ethereum/net/server/ChannelManagerImpl.java b/rskj-core/src/main/java/org/ethereum/net/server/ChannelManagerImpl.java index 79707f8f1a0..0bf1993c908 100644 --- a/rskj-core/src/main/java/org/ethereum/net/server/ChannelManagerImpl.java +++ b/rskj-core/src/main/java/org/ethereum/net/server/ChannelManagerImpl.java @@ -59,7 +59,6 @@ public class ChannelManagerImpl implements ChannelManager { private static final Logger logger = LoggerFactory.getLogger("net"); - private static final Logger mlogger = LoggerFactory.getLogger("metrics"); // If the inbound peer connection was dropped by us with a reason message // then we ban that peer IP on any connections for some time to protect from @@ -327,8 +326,7 @@ public void notifyDisconnect(Channel channel) { syncPool.onDisconnect(channel); activePeers.values().remove(channel); if(newPeers.remove(channel)) { - logger.debug("Peer removed from active peers: {}", channel); - mlogger.info("Peer removed from active peers: {}", channel); + logger.info("Peer removed from active peers: {}", channel.getPeerId()); } } diff --git a/rskj-core/src/main/java/org/ethereum/net/submit/TransactionTask.java b/rskj-core/src/main/java/org/ethereum/net/submit/TransactionTask.java index 0578ee29376..15a286590e3 100644 --- a/rskj-core/src/main/java/org/ethereum/net/submit/TransactionTask.java +++ b/rskj-core/src/main/java/org/ethereum/net/submit/TransactionTask.java @@ -59,7 +59,7 @@ public TransactionTask(List tx, ChannelManager channelManager, Chan public List call() throws Exception { try { - logger.info("submit tx: {}", tx.toString()); + logger.trace("submit tx: {}", tx.toString()); channelManager.sendTransaction(tx, receivedFrom); return tx;