diff --git a/src/LedgerConsensus.cpp b/src/LedgerConsensus.cpp index 3a1662b273..4a065bf330 100644 --- a/src/LedgerConsensus.cpp +++ b/src/LedgerConsensus.cpp @@ -7,6 +7,7 @@ #include "NetworkOPs.h" #include "LedgerTiming.h" #include "SerializedValidation.h" +#include "Log.h" TransactionAcquire::TransactionAcquire(const uint256& hash) : PeerSet(hash, 1), mHaveRoot(false) { @@ -151,8 +152,8 @@ int LCTransaction::getAgreeLevel() LedgerConsensus::LedgerConsensus(Ledger::pointer previousLedger, uint32 closeTime) : mState(lcsPRE_CLOSE), mCloseTime(closeTime), mPreviousLedger(previousLedger) { - std::cerr << "Creating consensus object" << std::endl; - std::cerr << "LCL:" << previousLedger->getHash().GetHex() <<", ct=" << closeTime << std::endl; + Log(lsDEBUG) << "Creating consensus object"; + Log(lsTRACE) << "LCL:" << previousLedger->getHash().GetHex() <<", ct=" << closeTime; } void LedgerConsensus::takeInitialPosition(Ledger::pointer initialLedger) @@ -251,7 +252,7 @@ void LedgerConsensus::statusChange(newcoin::NodeEvent event, Ledger::pointer led void LedgerConsensus::abort() { - std::cerr << "consensus aborted" << std::endl; + Log(lsWARNING) << "consensus aborted"; mState = lcsABORTED; } @@ -274,7 +275,7 @@ int LedgerConsensus::statePostClose(int secondsSinceClose) { // we are in the transaction wobble time if (secondsSinceClose > LEDGER_WOBBLE_TIME) { - std::cerr << "Wobble is over, it's consensus time" << std::endl; + Log(lsINFO) << "Wobble is over, it's consensus time"; mState = lcsESTABLISH; } return 1; @@ -285,7 +286,7 @@ int LedgerConsensus::stateEstablish(int secondsSinceClose) updateOurPositions(secondsSinceClose); if (secondsSinceClose > LEDGER_CONVERGE) { - std::cerr << "Converge cutoff" << std::endl; + Log(lsINFO) << "Converge cutoff"; mState = lcsCUTOFF; } return 1; @@ -296,7 +297,7 @@ int LedgerConsensus::stateCutoff(int secondsSinceClose) bool haveConsensus = updateOurPositions(secondsSinceClose); if (haveConsensus || (secondsSinceClose > LEDGER_FORCE_CONVERGE)) { - std::cerr << "Consensus complete (" << haveConsensus << ")" << std::endl; + Log(lsINFO) << "Consensus complete (" << haveConsensus << ")"; mState = lcsFINISHED; beginAccept(); } @@ -369,7 +370,7 @@ bool LedgerConsensus::updateOurPositions(int sinceClose) if (changes) { - std::cerr << "We change our position" << std::endl; + Log(lsINFO) << "We change our position"; uint256 newHash = ourPosition->getHash(); mOurPosition->changePosition(newHash); propose(addedTx, removedTx); @@ -402,7 +403,7 @@ SHAMap::pointer LedgerConsensus::getTransactionTree(const uint256& hash, bool do void LedgerConsensus::closeLedger() { - std::cerr << "Closing ledger" << std::endl; + Log(lsINFO) << "Closing ledger"; Ledger::pointer initial = theApp->getMasterLedger().getCurrentLedger(); statusChange(newcoin::neCLOSING_LEDGER, initial); takeInitialPosition(initial); @@ -435,7 +436,7 @@ void LedgerConsensus::startAcquiring(TransactionAcquire::pointer acquire) void LedgerConsensus::propose(const std::vector& added, const std::vector& removed) { - std::cerr << "We propose: " << mOurPosition->getCurrentHash().GetHex() << std::endl; + Log(lsDEBUG) << "We propose: " << mOurPosition->getCurrentHash().GetHex(); newcoin::TMProposeSet prop; prop.set_currenttxhash(mOurPosition->getCurrentHash().begin(), 256 / 8); prop.set_prevclosedhash(mOurPosition->getPrevLedger().begin(), 256 / 8); @@ -479,9 +480,7 @@ bool LedgerConsensus::peerPosition(LedgerProposal::pointer newPosition) { if (newPosition->getPrevLedger() != mPreviousLedger->getHash()) { -#ifdef DEBUG - std::cerr << "Peer sends proposal with wrong previous ledger" << std::endl; -#endif + Log(lsWARNING) << "Peer sends proposal with wrong previous ledger"; return false; } LedgerProposal::pointer& currentPosition = mPeerPositions[newPosition->getPeerID()]; @@ -496,7 +495,7 @@ bool LedgerConsensus::peerPosition(LedgerProposal::pointer newPosition) return true; } } - std::cerr << "Peer changes position" << std::endl; + Log(lsINFO) << "Peer changes position"; currentPosition = newPosition; SHAMap::pointer set = getTransactionTree(newPosition->getCurrentHash(), true); if (set) @@ -542,7 +541,7 @@ void LedgerConsensus::beginAccept() SHAMap::pointer consensusSet = mComplete[mOurPosition->getCurrentHash()]; if (!consensusSet) { - std::cerr << "We don't have our own set" << std::endl; + Log(lsFATAL) << "We don't have our own set"; assert(false); abort(); return; @@ -565,7 +564,7 @@ void LedgerConsensus::applyTransactions(SHAMap::pointer set, Ledger::pointer led SHAMapItem::pointer item = set->peekFirstItem(); while (item) { - std::cerr << "Processing candidate transaction: " << item->getTag().GetHex() << std::endl; + Log(lsINFO) << "Processing candidate transaction: " << item->getTag().GetHex(); try { SerializerIterator sit(item->peekSerializer()); @@ -573,24 +572,24 @@ void LedgerConsensus::applyTransactions(SHAMap::pointer set, Ledger::pointer led TransactionEngineResult result = engine.applyTransaction(*txn, tepNO_CHECK_FEE); if (result > 0) { - std::cerr << " retry" << std::endl; + Log(lsINFO) << " retry"; assert(!ledger->hasTransaction(item->getTag())); failedTransactions.push_back(txn); } else if (result == 0) { - std::cerr << " success" << std::endl; + Log(lsDEBUG) << " success"; assert(ledger->hasTransaction(item->getTag())); } else { - std::cerr << " hard fail" << std::endl; + Log(lsINFO) << " hard fail"; assert(!ledger->hasTransaction(item->getTag())); } } catch (...) { - std::cerr << " Throws" << std::endl; + Log(lsWARNING) << " Throws"; } item = set->peekNextItem(item->getTag()); } @@ -617,7 +616,7 @@ void LedgerConsensus::applyTransactions(SHAMap::pointer set, Ledger::pointer led } catch (...) { - std::cerr << " Throws" << std::endl; + Log(lsWARNING) << " Throws"; failedTransactions.erase(it++); } } @@ -626,7 +625,7 @@ void LedgerConsensus::applyTransactions(SHAMap::pointer set, Ledger::pointer led void LedgerConsensus::accept(SHAMap::pointer set) { - std::cerr << "Computing new LCL based on network consensus" << std::endl; + Log(lsINFO) << "Computing new LCL based on network consensus"; Ledger::pointer newLCL = boost::make_shared(mPreviousLedger); std::deque failedTransactions; @@ -651,7 +650,7 @@ void LedgerConsensus::accept(SHAMap::pointer set) newcoin::TMValidation val; val.set_validation(&validation[0], validation.size()); theApp->getConnectionPool().relayMessage(NULL, boost::make_shared(val, newcoin::mtVALIDATION)); - std::cerr << "Validation sent" << std::endl; + Log(lsINFO) << "Validation sent"; } void LedgerConsensus::endConsensus() diff --git a/src/NetworkOPs.cpp b/src/NetworkOPs.cpp index 01e8266f5e..d18841b88c 100644 --- a/src/NetworkOPs.cpp +++ b/src/NetworkOPs.cpp @@ -9,6 +9,7 @@ #include "Transaction.h" #include "LedgerConsensus.h" #include "LedgerTiming.h" +#include "Log.h" // This is the primary interface into the "client" portion of the program. // Code that wants to do normal operations on the network such as @@ -50,9 +51,7 @@ Transaction::pointer NetworkOPs::processTransaction(Transaction::pointer trans, if (!trans->checkSign()) { -#ifdef DEBUG - std::cerr << "Transaction has bad signature" << std::endl; -#endif + Log(lsINFO) << "Transaction has bad signature"; trans->setStatus(INVALID); return trans; } @@ -62,9 +61,7 @@ Transaction::pointer NetworkOPs::processTransaction(Transaction::pointer trans, if (r == terPRE_SEQ) { // transaction should be held -#ifdef DEBUG - std::cerr << "Transaction should be held" << std::endl; -#endif + Log(lsDEBUG) << "Transaction should be held"; trans->setStatus(HELD); theApp->getMasterTransaction().canonicalize(trans, true); mLedgerMaster->addHeldTransaction(trans); @@ -72,18 +69,14 @@ Transaction::pointer NetworkOPs::processTransaction(Transaction::pointer trans, } if ((r == terPAST_SEQ) || (r == terPAST_LEDGER)) { // duplicate or conflict -#ifdef DEBUG - std::cerr << "Transaction is obsolete" << std::endl; -#endif + Log(lsINFO) << "Transaction is obsolete"; trans->setStatus(OBSOLETE); return trans; } if (r == terSUCCESS) { -#ifdef DEBUG - std::cerr << "Transaction is now included, synching to wallet" << std::endl; -#endif + Log(lsINFO) << "Transaction is now included"; trans->setStatus(INCLUDED); theApp->getMasterTransaction().canonicalize(trans, true); @@ -106,9 +99,7 @@ Transaction::pointer NetworkOPs::processTransaction(Transaction::pointer trans, return trans; } -#ifdef DEBUG - std::cerr << "Status other than success " << r << std::endl; -#endif + Log(lsDEBUG) << "Status other than success " << r ; trans->setStatus(INVALID); return trans; @@ -182,19 +173,19 @@ bool NetworkOPs::getDirInfo( if (sleRoot) { - std::cerr << "getDirInfo: root index: " << uRootIndex.ToString() << std::endl; + Log(lsDEBUG) << "getDirInfo: root index: " << uRootIndex.ToString() ; - std::cerr << "getDirInfo: first: " << strHex(sleRoot->getIFieldU64(sfFirstNode)) << std::endl; - std::cerr << "getDirInfo: last: " << strHex(sleRoot->getIFieldU64(sfLastNode)) << std::endl; + Log(lsTRACE) << "getDirInfo: first: " << strHex(sleRoot->getIFieldU64(sfFirstNode)) ; + Log(lsTRACE) << "getDirInfo: last: " << strHex(sleRoot->getIFieldU64(sfLastNode)) ; uDirLineNodeFirst = Ledger::getDirIndex(uBase, letKind, sleRoot->getIFieldU64(sfFirstNode)); uDirLineNodeLast = Ledger::getDirIndex(uBase, letKind, sleRoot->getIFieldU64(sfLastNode)); - std::cerr << "getDirInfo: first: " << uDirLineNodeFirst.ToString() << std::endl; - std::cerr << "getDirInfo: last: " << uDirLineNodeLast.ToString() << std::endl; + Log(lsTRACE) << "getDirInfo: first: " << uDirLineNodeFirst.ToString() ; + Log(lsTRACE) << "getDirInfo: last: " << uDirLineNodeLast.ToString() ; } else { - std::cerr << "getDirInfo: root index: NOT FOUND: " << uRootIndex.ToString() << std::endl; + Log(lsINFO) << "getDirInfo: root index: NOT FOUND: " << uRootIndex.ToString() ; } return !!sleRoot; @@ -209,13 +200,13 @@ STVector256 NetworkOPs::getDirNode(const uint256& uLedger, const uint256& uDirLi if (sleNode) { - std::cerr << "getDirNode: node index: " << uDirLineNode.ToString() << std::endl; + Log(lsWARNING) << "getDirNode: node index: " << uDirLineNode.ToString() ; svIndexes = sleNode->getIFieldV256(sfIndexes); } else { - std::cerr << "getDirNode: node index: NOT FOUND: " << uDirLineNode.ToString() << std::endl; + Log(lsINFO) << "getDirNode: node index: NOT FOUND: " << uDirLineNode.ToString() ; } return svIndexes; @@ -281,8 +272,8 @@ void NetworkOPs::checkState(const boost::system::error_code& result) if (mMode != omDISCONNECTED) { mMode = omDISCONNECTED; - std::cerr << "Node count (" << peerList.size() << - ") has fallen below quorum (" << theConfig.NETWORK_QUORUM << ")." << std::endl; + Log(lsWARNING) << "Node count (" << peerList.size() << + ") has fallen below quorum (" << theConfig.NETWORK_QUORUM << ")."; } setStateTimer(5); return; @@ -290,7 +281,7 @@ void NetworkOPs::checkState(const boost::system::error_code& result) if (mMode == omDISCONNECTED) { mMode = omCONNECTED; - std::cerr << "Node count (" << peerList.size() << ") is sufficient." << std::endl; + Log(lsINFO) << "Node count (" << peerList.size() << ") is sufficient."; } // Do we have sufficient validations for our last closed ledger? Or do sufficient nodes @@ -302,7 +293,7 @@ void NetworkOPs::checkState(const boost::system::error_code& result) { if (!*it) { - std::cerr << "NOP::CS Dead pointer in peer list" << std::endl; + Log(lsDEBUG) << "NOP::CS Dead pointer in peer list"; } else { @@ -347,23 +338,19 @@ void NetworkOPs::checkState(const boost::system::error_code& result) if (switchLedgers) { - std::cerr << "We are not running on the consensus ledger" << std::endl; -#ifdef DEBUG - std::cerr << "Our LCL " << currentClosed->getHash().GetHex() << std::endl; - std::cerr << "Net LCL " << closedLedger.GetHex() << std::endl; -#endif + Log(lsWARNING) << "We are not running on the consensus ledger"; + Log(lsINFO) << "Our LCL " << currentClosed->getHash().GetHex() ; + Log(lsINFO) << "Net LCL " << closedLedger.GetHex() ; if ((mMode == omTRACKING) || (mMode == omFULL)) mMode = omTRACKING; Ledger::pointer consensus = mLedgerMaster->getLedgerByHash(closedLedger); if (!consensus) { -#ifdef DEBUG - std::cerr << "Acquiring consensus ledger" << std::endl; -#endif + Log(lsINFO) << "Acquiring consensus ledger"; LedgerAcquire::pointer acq = theApp->getMasterLedgerAcquire().findCreate(closedLedger); if (!acq || acq->isFailed()) { theApp->getMasterLedgerAcquire().dropLedger(closedLedger); - std::cerr << "Network ledger cannot be acquired" << std::endl; + Log(lsERROR) << "Network ledger cannot be acquired"; setStateTimer(10); return; } @@ -410,10 +397,8 @@ void NetworkOPs::checkState(const boost::system::error_code& result) void NetworkOPs::switchLastClosedLedger(Ledger::pointer newLedger) { // set the newledger as our last closed ledger -- this is abnormal code -#ifdef DEBUG assert(false); - std::cerr << "ABNORMAL Switching last closed ledger to " << newLedger->getHash().GetHex() << std::endl; -#endif + Log(lsERROR) << "ABNORMAL Switching last closed ledger to " << newLedger->getHash().GetHex() ; if (mConsensus) { @@ -434,9 +419,7 @@ void NetworkOPs::switchLastClosedLedger(Ledger::pointer newLedger) int NetworkOPs::beginConsensus(Ledger::pointer closingLedger) { -#ifdef DEBUG - std::cerr << "Ledger close time for ledger " << closingLedger->getLedgerSeq() << std::endl; -#endif + Log(lsINFO) << "Ledger close time for ledger " << closingLedger->getLedgerSeq() ; Ledger::pointer prevLedger = mLedgerMaster->getLedgerByHash(closingLedger->getParentHash()); if (!prevLedger) { // this shouldn't happen if we jump ledgers @@ -449,9 +432,7 @@ int NetworkOPs::beginConsensus(Ledger::pointer closingLedger) mConsensus = boost::make_shared (prevLedger, theApp->getMasterLedger().getCurrentLedger()->getCloseTimeNC()); -#ifdef DEBUG - std::cerr << "Broadcasting ledger close" << std::endl; -#endif + Log(lsDEBUG) << "Broadcasting ledger close"; return mConsensus->startup(); } @@ -465,7 +446,7 @@ bool NetworkOPs::recvPropose(const uint256& prevLgr, uint32 proposeSeq, const ui boost::make_shared(prevLgr, proposeSeq, proposeHash, pubKey); if (!proposal->checkSign(signature)) { - std::cerr << "Ledger proposal fails signature check" << std::endl; + Log(lsWARNING) << "Ledger proposal fails signature check"; return false; }