Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Reduce logging messages on info level #418

Merged
merged 2 commits into from
Jan 22, 2018
Merged

Reduce logging messages on info level #418

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
e95d140
logs demoted on many clasess and minor logging fixes
lsebrie Jan 15, 2018
a21a8fa
Improvements based on sonar and peer review
lsebrie Jan 15, 2018
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
28 changes: 14 additions & 14 deletions rskj-core/src/main/java/co/rsk/core/bc/BlockChainImpl.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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) {
Expand All @@ -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) {
Expand All @@ -255,19 +255,19 @@ 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());
} else {
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;
Expand All @@ -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();
Expand Down Expand Up @@ -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());
}
Expand Down Expand Up @@ -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);
}

Expand Down Expand Up @@ -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();
Expand Down
14 changes: 7 additions & 7 deletions rskj-core/src/main/java/co/rsk/core/bc/BlockExecutor.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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);

Expand All @@ -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);

Expand All @@ -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;
Expand All @@ -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);
Expand Down
18 changes: 9 additions & 9 deletions rskj-core/src/main/java/co/rsk/core/bc/PendingStateImpl.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -166,19 +166,19 @@ public synchronized List<Transaction> addWireTransactions(List<Transaction> tran
List<Transaction> 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;
}

Expand All @@ -197,7 +197,7 @@ public synchronized List<Transaction> addWireTransactions(List<Transaction> 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;
}
Expand Down Expand Up @@ -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());
Expand All @@ -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());
}
Expand All @@ -348,7 +348,7 @@ public synchronized void clearPendingState(List<Transaction> 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));
}
}

Expand All @@ -358,7 +358,7 @@ public synchronized void clearWire(List<Transaction> 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));
}
}

Expand All @@ -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();

Expand Down
4 changes: 2 additions & 2 deletions rskj-core/src/main/java/co/rsk/db/RepositoryImpl.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -320,7 +320,7 @@ public void reset() {
@Override
public synchronized void updateBatch(Map<RskAddress, AccountState> stateCache,
Map<RskAddress, ContractDetails> detailsCache) {
logger.info("updatingBatch: detailsCache.size: {}", detailsCache.size());
logger.debug("updatingBatch: detailsCache.size: {}", detailsCache.size());

for (Map.Entry<RskAddress, AccountState> entry : stateCache.entrySet()) {
RskAddress addr = entry.getKey();
Expand Down Expand Up @@ -357,7 +357,7 @@ public synchronized void updateBatch(Map<RskAddress, AccountState> stateCache,
}
}

logger.info("updated: detailsCache.size: {}", detailsCache.size());
logger.debug("updated: detailsCache.size: {}", detailsCache.size());

stateCache.clear();
detailsCache.clear();
Expand Down
11 changes: 4 additions & 7 deletions rskj-core/src/main/java/co/rsk/mine/MinerServerImpl.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
Expand Down Expand Up @@ -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<BlockHeader> uncles;
if (blockStore != null) {
Expand Down Expand Up @@ -711,7 +708,7 @@ public long increaseTime(long seconds) {
private void removePendingTransactions(List<Transaction> transactions) {
if (transactions != null) {
for (Transaction tx : transactions) {
logger.info("Removing transaction {}", Hex.toHexString(tx.getHash()));
logger.debug("Removing transaction {}", Hex.toHexString(tx.getHash()));
}
}

Expand All @@ -721,7 +718,7 @@ private void removePendingTransactions(List<Transaction> transactions) {

private List<Transaction> getTransactions(List<Transaction> txsToRemove, Block parent, BigInteger minGasPrice) {

logger.info("Starting getTransactions");
logger.debug("Starting getTransactions");

List<Transaction> txs = new MinerUtils().getAllTransactions(pendingState);
logger.debug("txsList size {}", txs.size());
Expand Down
8 changes: 4 additions & 4 deletions rskj-core/src/main/java/co/rsk/mine/MinerUtils.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -154,10 +154,10 @@ public List<org.ethereum.core.Transaction> filterTransactions(List<org.ethereum.
List<org.ethereum.core.Transaction> 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());

Expand All @@ -183,7 +183,7 @@ public List<org.ethereum.core.Transaction> filterTransactions(List<org.ethereum.

accountNonces.put(txSender, txNonce);

logger.info("Accepted transaction {} sender: {} value: {} nonce: {}", Hex.toHexString(tx.getHash()), txSender, Hex.toHexString(tx.getValue()), Hex.toHexString(tx.getNonce()));
logger.debug("Accepted transaction {} sender: {} value: {} nonce: {}", Hex.toHexString(tx.getHash()), txSender, Hex.toHexString(tx.getValue()), Hex.toHexString(tx.getNonce()));
} catch (Exception e) {
// Txs that can't be selected by any reason should be removed from pending state
String hash = null == tx.getHash() ? "" : Hex.toHexString(tx.getHash());
Expand All @@ -199,7 +199,7 @@ public List<org.ethereum.core.Transaction> filterTransactions(List<org.ethereum.
txsResult.add(tx);
}

logger.info("Ending getTransactions {}", txsResult.size());
logger.debug("Ending getTransactions {}", txsResult.size());

return txsResult;
}
Expand Down
2 changes: 1 addition & 1 deletion rskj-core/src/main/java/co/rsk/net/Metrics.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -153,7 +153,7 @@ public static void messageBytes(@Nonnull final NodeID sender, int length) {
}

private static void logEvent(@Nonnull final String event) {
logger.info("{} at: {} nano: {} | {} ", nodeID, currentTimeMillis(), nanoTime(), event);
logger.debug("{} at: {} nano: {} | {} ", nodeID, currentTimeMillis(), nanoTime(), event);
}

public static void registerNodeID(byte[] bytes) {
Expand Down
8 changes: 7 additions & 1 deletion rskj-core/src/main/java/co/rsk/net/eth/RskWireProtocol.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -157,14 +157,20 @@ protected void processStatus(org.ethereum.net.eth.message.StatusMessage msg, Cha
if (!Arrays.equals(msg.getGenesisHash(), genesis.getHash())
|| msg.getProtocolVersion() != version.getCode()) {
loggerNet.info("Removing EthHandler for {} due to protocol incompatibility", ctx.channel().remoteAddress());
if (msg.getProtocolVersion() != version.getCode()){
loggerNet.info("Protocol version {} - message protocol version {}", version.getCode(), msg.getProtocolVersion());
} else {
loggerNet.info("Config genesis hash {} - message genesis hash {}", genesis.getHash(), msg.getGenesisHash());
}
ethState = EthState.STATUS_FAILED;
recordEvent(EventType.INCOMPATIBLE_PROTOCOL);
disconnect(ReasonCode.INCOMPATIBLE_PROTOCOL);
ctx.pipeline().remove(this); // Peer is not compatible for the 'eth' sub-protocol
return;
}

if (msg.getNetworkId() != config.networkId()) {
if (config.networkId() != msg.getNetworkId()) {
loggerNet.info("Different network received: config network ID {} - message network ID {}", config.networkId(), msg.getNetworkId());
ethState = EthState.STATUS_FAILED;
recordEvent(EventType.INVALID_NETWORK);
disconnect(ReasonCode.NULL_IDENTITY);
Expand Down
2 changes: 1 addition & 1 deletion rskj-core/src/main/java/org/ethereum/core/Transaction.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -249,7 +249,7 @@ public void rlpParse() {
byte[] s = transaction.get(8).getRLPData();
this.signature = ECDSASignature.fromComponents(r, s, getRealV(v));
} else {
logger.debug("RLP encoded tx is not signed!");
logger.trace("RLP encoded tx is not signed!");
}
this.parsed = true;
this.hash = getHash();
Expand Down
Loading