diff --git a/src/HashedObject.cpp b/src/HashedObject.cpp index 69e855ddc6..25bff66268 100644 --- a/src/HashedObject.cpp +++ b/src/HashedObject.cpp @@ -8,6 +8,8 @@ #include "Application.h" #include "Log.h" +SETUP_LOG(); + HashedObjectStore::HashedObjectStore(int cacheSize, int cacheAge) : mCache(cacheSize, cacheAge), mWritePending(false) { @@ -22,9 +24,7 @@ bool HashedObjectStore::store(HashedObjectType type, uint32 index, if (!theApp->getHashNodeDB()) return true; if (mCache.touch(hash)) { -#ifdef HS_DEBUG - Log(lsTRACE) << "HOS: " << hash << " store: incache"; -#endif + cLog(lsTRACE) << "HOS: " << hash << " store: incache"; return false; } @@ -53,7 +53,7 @@ void HashedObjectStore::bulkWrite() mWriteSet.swap(set); mWritePending = false; } - Log(lsINFO) << "HOS: BulkWrite " << set.size(); + cLog(lsINFO) << "HOS: BulkWrite " << set.size(); static boost::format fExists("SELECT ObjType FROM CommittedObjects WHERE Hash = '%s';"); static boost::format @@ -94,7 +94,7 @@ HashedObject::pointer HashedObjectStore::retrieve(const uint256& hash) obj = mCache.fetch(hash); if (obj) { - Log(lsTRACE) << "HOS: " << hash << " fetch: incache"; + cLog(lsTRACE) << "HOS: " << hash << " fetch: incache"; return obj; } } @@ -111,7 +111,7 @@ HashedObject::pointer HashedObjectStore::retrieve(const uint256& hash) if (!db->executeSQL(sql) || !db->startIterRows()) { - Log(lsTRACE) << "HOS: " << hash << " fetch: not in db"; + cLog(lsTRACE) << "HOS: " << hash << " fetch: not in db"; return HashedObject::pointer(); } @@ -136,14 +136,14 @@ HashedObject::pointer HashedObjectStore::retrieve(const uint256& hash) case 'A': htype = hotACCOUNT_NODE; break; case 'N': htype = hotTRANSACTION_NODE; break; default: - Log(lsERROR) << "Invalid hashed object"; + cLog(lsERROR) << "Invalid hashed object"; return HashedObject::pointer(); } obj = boost::make_shared(htype, index, data, hash); mCache.canonicalize(hash, obj); } - Log(lsTRACE) << "HOS: " << hash << " fetch: in db"; + cLog(lsTRACE) << "HOS: " << hash << " fetch: in db"; return obj; } diff --git a/src/Ledger.cpp b/src/Ledger.cpp index 2f3c8cfdf1..ff4dc08aca 100644 --- a/src/Ledger.cpp +++ b/src/Ledger.cpp @@ -19,6 +19,7 @@ #include "HashPrefixes.h" #include "Log.h" +SETUP_LOG(); Ledger::Ledger(const NewcoinAddress& masterID, uint64 startAmount) : mTotCoins(startAmount), mLedgerSeq(1), mCloseTime(0), mParentCloseTime(0), mCloseResolution(LEDGER_TIME_ACCURACY), mCloseFlags(0), @@ -428,11 +429,13 @@ Ledger::pointer Ledger::getSQL(const std::string& sql) closeFlags, closeResolution, ledgerSeq); if (ret->getHash() != ledgerHash) { - Json::StyledStreamWriter ssw; - Log(lsERROR) << "Failed on ledger"; - Json::Value p; - ret->addJson(p, LEDGER_JSON_FULL); - ssw.write(Log(lsERROR).ref(), p); + if (sLog(lsERROR)) + { + Log(lsERROR) << "Failed on ledger"; + Json::Value p; + ret->addJson(p, LEDGER_JSON_FULL); + Log(lsERROR) << p; + } assert(false); return Ledger::pointer(); } diff --git a/src/Ledger.h b/src/Ledger.h index d059f01581..7e2ebb9782 100644 --- a/src/Ledger.h +++ b/src/Ledger.h @@ -140,9 +140,8 @@ public: boost::posix_time::ptime getCloseTime() const; // low level functions - SHAMap::pointer peekTransactionMap() { return mTransactionMap; } - SHAMap::pointer peekAccountStateMap() { return mAccountStateMap; } - Ledger::pointer snapShot(bool isMutable); + SHAMap::ref peekTransactionMap() { return mTransactionMap; } + SHAMap::ref peekAccountStateMap() { return mAccountStateMap; } // ledger sync functions void setAcquiring(void); diff --git a/src/LedgerAcquire.cpp b/src/LedgerAcquire.cpp index 76a43e7276..d9056fdad4 100644 --- a/src/LedgerAcquire.cpp +++ b/src/LedgerAcquire.cpp @@ -146,7 +146,7 @@ void LedgerAcquire::trigger(Peer::ref peer, bool timer) if (mAborted || mComplete || mFailed) return; #ifdef LA_DEBUG - if(peer) Log(lsTRACE) << "Trigger acquiring ledger " << mHash << " from " << peer->getIP(); + if (peer) Log(lsTRACE) << "Trigger acquiring ledger " << mHash << " from " << peer->getIP(); else Log(lsTRACE) << "Trigger acquiring ledger " << mHash; if (mComplete || mFailed) Log(lsTRACE) << "complete=" << mComplete << " failed=" << mFailed; diff --git a/src/LedgerConsensus.cpp b/src/LedgerConsensus.cpp index f5ed0dde0b..bccbd76d14 100644 --- a/src/LedgerConsensus.cpp +++ b/src/LedgerConsensus.cpp @@ -23,6 +23,8 @@ typedef std::pair u160_prop_pair; typedef std::pair u256_lct_pair; +SETUP_LOG(); + TransactionAcquire::TransactionAcquire(const uint256& hash) : PeerSet(hash, TX_ACQUIRE_TIMEOUT), mHaveRoot(false) { mMap = boost::make_shared(hash); @@ -32,7 +34,7 @@ void TransactionAcquire::done() { if (mFailed) { - Log(lsWARNING) << "Failed to acquire TXs " << mHash; + cLog(lsWARNING) << "Failed to acquire TXs " << mHash; theApp->getOPs().mapComplete(mHash, SHAMap::pointer()); } else @@ -51,12 +53,12 @@ void TransactionAcquire::trigger(Peer::ref peer, bool timer) { if (mComplete || mFailed) { - Log(lsINFO) << "complete or failed"; + cLog(lsINFO) << "complete or failed"; return; } if (!mHaveRoot) { - Log(lsINFO) << "have no root"; + cLog(lsINFO) << "have no root"; newcoin::TMGetLedger tmGL; tmGL.set_ledgerhash(mHash.begin(), mHash.size()); tmGL.set_itype(newcoin::liTS_CANDIDATE); @@ -110,7 +112,7 @@ bool TransactionAcquire::takeNodes(const std::list& nodeIDs, { if (mHaveRoot) { - Log(lsWARNING) << "Got root TXS node, already have it"; + cLog(lsWARNING) << "Got root TXS node, already have it"; return false; } if (!mMap->addRootNode(getHash(), *nodeDatait, snfWIRE)) @@ -129,7 +131,7 @@ bool TransactionAcquire::takeNodes(const std::list& nodeIDs, } catch (...) { - Log(lsERROR) << "Peer sends us junky transaction node data"; + cLog(lsERROR) << "Peer sends us junky transaction node data"; return false; } } @@ -143,25 +145,25 @@ void LCTransaction::setVote(const uint160& peer, bool votesYes) { // new vote if (votesYes) { - Log(lsTRACE) << "Peer " << peer << " votes YES on " << mTransactionID; + cLog(lsTRACE) << "Peer " << peer << " votes YES on " << mTransactionID; ++mYays; } else { - Log(lsTRACE) << "Peer " << peer << " votes NO on " << mTransactionID; + cLog(lsTRACE) << "Peer " << peer << " votes NO on " << mTransactionID; ++mNays; } } else if (votesYes && !res.first->second) { // changes vote to yes - Log(lsTRACE) << "Peer " << peer << " now votes YES on " << mTransactionID; + cLog(lsTRACE) << "Peer " << peer << " now votes YES on " << mTransactionID; --mNays; ++mYays; res.first->second = true; } else if (!votesYes && res.first->second) { // changes vote to no - Log(lsTRACE) << "Peer " << peer << " now votes NO on " << mTransactionID; + cLog(lsTRACE) << "Peer " << peer << " now votes NO on " << mTransactionID; ++mNays; --mYays; res.first->second = false; @@ -209,13 +211,13 @@ bool LCTransaction::updateVote(int percentTime, bool proposing) if (newPosition == mOurVote) { #ifdef LC_DEBUG - Log(lsTRACE) << "No change (" << (mOurVote ? "YES" : "NO") << ") : weight " + cLog(lsTRACE) << "No change (" << (mOurVote ? "YES" : "NO") << ") : weight " << weight << ", percent " << percentTime; #endif return false; } mOurVote = newPosition; - Log(lsTRACE) << "We now vote " << (mOurVote ? "YES" : "NO") << " on " << mTransactionID; + cLog(lsTRACE) << "We now vote " << (mOurVote ? "YES" : "NO") << " on " << mTransactionID; return true; } @@ -224,8 +226,8 @@ LedgerConsensus::LedgerConsensus(const uint256& prevLCLHash, Ledger::ref previou mValSeed(theConfig.VALIDATION_SEED), mCurrentMSeconds(0), mClosePercent(0), mHaveCloseTimeConsensus(false), mConsensusStartTime(boost::posix_time::microsec_clock::universal_time()) { - Log(lsDEBUG) << "Creating consensus object"; - Log(lsTRACE) << "LCL:" << previousLedger->getHash() <<", ct=" << closeTime; + cLog(lsDEBUG) << "Creating consensus object"; + cLog(lsTRACE) << "LCL:" << previousLedger->getHash() <<", ct=" << closeTime; mPreviousProposers = theApp->getOPs().getPreviousProposers(); mPreviousMSeconds = theApp->getOPs().getPreviousConvergeTime(); assert(mPreviousMSeconds); @@ -235,21 +237,21 @@ LedgerConsensus::LedgerConsensus(const uint256& prevLCLHash, Ledger::ref previou if (mValSeed.isValid()) { - Log(lsINFO) << "Entering consensus process, validating"; + cLog(lsINFO) << "Entering consensus process, validating"; mValidating = true; mProposing = theApp->getOPs().getOperatingMode() == NetworkOPs::omFULL; } else { - Log(lsINFO) << "Entering consensus process, watching"; + cLog(lsINFO) << "Entering consensus process, watching"; mProposing = mValidating = false; } handleLCL(prevLCLHash); if (!mHaveCorrectLCL) { - Log(lsINFO) << "Entering consensus with: " << previousLedger->getHash(); - Log(lsINFO) << "Correct LCL is: " << prevLCLHash; + cLog(lsINFO) << "Entering consensus with: " << previousLedger->getHash(); + cLog(lsINFO) << "Correct LCL is: " << prevLCLHash; } } @@ -282,13 +284,13 @@ void LedgerConsensus::checkLCL() default: status = "unknown"; } - Log(lsWARNING) << "View of consensus changed during consensus (" << netLgrCount << ") status=" + cLog(lsWARNING) << "View of consensus changed during consensus (" << netLgrCount << ") status=" << status << ", " << (mHaveCorrectLCL ? "CorrectLCL" : "IncorrectLCL"); - Log(lsWARNING) << mPrevLedgerHash << " to " << netLgr; + cLog(lsWARNING) << mPrevLedgerHash << " to " << netLgr; #ifdef DEBUG BOOST_FOREACH(u256_cvc_pair& it, vals) - Log(lsDEBUG) << "V: " << it.first << ", " << it.second.first; + cLog(lsDEBUG) << "V: " << it.first << ", " << it.second.first; #endif if (mHaveCorrectLCL) @@ -310,7 +312,7 @@ void LedgerConsensus::handleLCL(const uint256& lclHash) return; else { - Log(lsWARNING) << "Need consensus ledger " << mPrevLedgerHash; + cLog(lsWARNING) << "Need consensus ledger " << mPrevLedgerHash; mAcquiringLedger = theApp->getMasterLedgerAcquire().findCreate(mPrevLedgerHash); std::vector peerList = theApp->getConnectionPool().getPeerVector(); @@ -333,7 +335,7 @@ void LedgerConsensus::handleLCL(const uint256& lclHash) if (mHaveCorrectLCL && mProposing && mOurPosition) { - Log(lsINFO) << "Bowing out of consensus"; + cLog(lsINFO) << "Bowing out of consensus"; mOurPosition->bowOut(); propose(); } @@ -348,7 +350,7 @@ void LedgerConsensus::handleLCL(const uint256& lclHash) return; } - Log(lsINFO) << "Acquired the consensus ledger " << mPrevLedgerHash; + cLog(lsINFO) << "Acquired the consensus ledger " << mPrevLedgerHash; mHaveCorrectLCL = true; mAcquiringLedger = LedgerAcquire::pointer(); mCloseResolution = ContinuousLedgerTiming::getNextLedgerTimeResolution( @@ -361,7 +363,7 @@ void LedgerConsensus::takeInitialPosition(Ledger& initialLedger) { SHAMap::pointer initialSet = initialLedger.peekTransactionMap()->snapShot(false); uint256 txSet = initialSet->getHash(); - Log(lsINFO) << "initial position " << txSet; + cLog(lsINFO) << "initial position " << txSet; mapComplete(txSet, initialSet, false); if (mValidating) @@ -415,14 +417,13 @@ void LedgerConsensus::createDisputes(SHAMap::ref m1, SHAMap::ref m2) void LedgerConsensus::mapComplete(const uint256& hash, SHAMap::ref map, bool acquired) { - if (acquired) - Log(lsINFO) << "We have acquired TXS " << hash; + tLog(acquired, lsINFO) << "We have acquired TXS " << hash; if (!map) { // this is an invalid/corrupt map mAcquired[hash] = map; mAcquiring.erase(hash); - Log(lsWARNING) << "A trusted node directed us to acquire an invalid TXN map"; + cLog(lsWARNING) << "A trusted node directed us to acquire an invalid TXN map"; return; } assert(hash == map->getHash()); @@ -456,8 +457,7 @@ void LedgerConsensus::mapComplete(const uint256& hash, SHAMap::ref map, bool acq } if (!peers.empty()) adjustCount(map, peers); - else if (acquired) - Log(lsWARNING) << "By the time we got the map " << hash << " no peers were proposing it"; + else tLog(acquired, lsWARNING) << "By the time we got the map " << hash << " no peers were proposing it"; sendHaveTxSet(hash, true); } @@ -496,7 +496,7 @@ void LedgerConsensus::statusChange(newcoin::NodeEvent event, Ledger& ledger) s.set_ledgerhash(hash.begin(), hash.size()); PackedMessage::pointer packet = boost::make_shared(s, newcoin::mtSTATUS_CHANGE); theApp->getConnectionPool().relayMessage(NULL, packet); - Log(lsINFO) << "send status change to peer"; + cLog(lsINFO) << "send status change to peer"; } int LedgerConsensus::startup() @@ -545,12 +545,11 @@ void LedgerConsensus::stateEstablish() updateOurPositions(); if (!mHaveCloseTimeConsensus) { - if (haveConsensus()) - Log(lsINFO) << "We have TX consensus but not CT consensus"; + tLog(haveConsensus(), lsINFO) << "We have TX consensus but not CT consensus"; } else if (haveConsensus()) { - Log(lsINFO) << "Converge cutoff (" << mPeerPositions.size() << " participants)"; + cLog(lsINFO) << "Converge cutoff (" << mPeerPositions.size() << " participants)"; mState = lcsFINISHED; beginAccept(); } @@ -605,7 +604,7 @@ void LedgerConsensus::updateOurPositions() if (it->second->isStale(peerCutoff)) { // proposal is stale uint160 peerID = it->second->getPeerID(); - Log(lsWARNING) << "Removing stale proposal from " << peerID; + cLog(lsWARNING) << "Removing stale proposal from " << peerID; BOOST_FOREACH(u256_lct_pair& it, mDisputes) it.second->unVote(peerID); mPeerPositions.erase(it++); @@ -670,18 +669,17 @@ void LedgerConsensus::updateOurPositions() for (std::map::iterator it = closeTimes.begin(), end = closeTimes.end(); it != end; ++it) { - Log(lsINFO) << "CCTime: " << it->first << " has " << it->second << ", " << thresh << " required"; + cLog(lsINFO) << "CCTime: " << it->first << " has " << it->second << ", " << thresh << " required"; if (it->second > thresh) { - Log(lsINFO) << "Close time consensus reached: " << it->first; + cLog(lsINFO) << "Close time consensus reached: " << it->first; mHaveCloseTimeConsensus = true; closeTime = it->first; thresh = it->second; } } - if (!mHaveCloseTimeConsensus) - Log(lsDEBUG) << "No CT consensus: Proposers:" << mPeerPositions.size() << " Proposing:" << - (mProposing ? "yes" : "no") << " Thresh:" << thresh << " Pos:" << closeTime; + tLog(!mHaveCloseTimeConsensus, lsDEBUG) << "No CT consensus: Proposers:" << mPeerPositions.size() + << " Proposing:" << (mProposing ? "yes" : "no") << " Thresh:" << thresh << " Pos:" << closeTime; } if ((!changes) && @@ -696,7 +694,7 @@ void LedgerConsensus::updateOurPositions() if (changes) { uint256 newHash = ourPosition->getHash(); - Log(lsINFO) << "Position change: CTime " << closeTime << ", tx " << newHash; + cLog(lsINFO) << "Position change: CTime " << closeTime << ", tx " << newHash; if (mOurPosition->changePosition(newHash, closeTime)) { if (mProposing) @@ -724,7 +722,7 @@ bool LedgerConsensus::haveConsensus() int currentValidations = theApp->getValidations().getNodesAfter(mPrevLedgerHash); #ifdef LC_DEBUG - Log(lsINFO) << "Checking for TX consensus: agree=" << agree << ", disagree=" << disagree; + cLog(lsINFO) << "Checking for TX consensus: agree=" << agree << ", disagree=" << disagree; #endif return ContinuousLedgerTiming::haveConsensus(mPreviousProposers, agree + disagree, agree, currentValidations, @@ -742,7 +740,7 @@ SHAMap::pointer LedgerConsensus::getTransactionTree(const uint256& hash, bool do SHAMap::pointer currentMap = theApp->getMasterLedger().getCurrentLedger()->peekTransactionMap(); if (currentMap->getHash() == hash) { - Log(lsINFO) << "node proposes our open transaction set"; + cLog(lsINFO) << "node proposes our open transaction set"; currentMap = currentMap->snapShot(false); mapComplete(hash, currentMap, false); return currentMap; @@ -803,7 +801,7 @@ void LedgerConsensus::startAcquiring(const TransactionAcquire::pointer& acquire) void LedgerConsensus::propose() { - Log(lsTRACE) << "We propose: " << mOurPosition->getCurrentHash(); + cLog(lsTRACE) << "We propose: " << mOurPosition->getCurrentHash(); newcoin::TMProposeSet prop; prop.set_currenttxhash(mOurPosition->getCurrentHash().begin(), 256 / 8); prop.set_proposeseq(mOurPosition->getProposeSeq()); @@ -819,7 +817,7 @@ void LedgerConsensus::propose() void LedgerConsensus::addDisputedTransaction(const uint256& txID, const std::vector& tx) { - Log(lsTRACE) << "Transaction " << txID << " is disputed"; + cLog(lsTRACE) << "Transaction " << txID << " is disputed"; boost::unordered_map::iterator it = mDisputes.find(txID); if (it != mDisputes.end()) return; @@ -861,7 +859,7 @@ bool LedgerConsensus::peerPosition(const LedgerProposal::pointer& newPosition) uint160 peerID = newPosition->getPeerID(); if (mDeadNodes.find(peerID) != mDeadNodes.end()) { - Log(lsINFO) << "Position from dead node"; + cLog(lsINFO) << "Position from dead node"; return false; } @@ -876,7 +874,7 @@ bool LedgerConsensus::peerPosition(const LedgerProposal::pointer& newPosition) if (newPosition->getProposeSeq() == 0) { // new initial close time estimate - Log(lsTRACE) << "Peer reports close time as " << newPosition->getCloseTime(); + cLog(lsTRACE) << "Peer reports close time as " << newPosition->getCloseTime(); ++mCloseTimes[newPosition->getCloseTime()]; } else if (newPosition->getProposeSeq() == LedgerProposal::seqLeave) @@ -889,7 +887,7 @@ bool LedgerConsensus::peerPosition(const LedgerProposal::pointer& newPosition) } - Log(lsINFO) << "Processing peer proposal " << newPosition->getProposeSeq() << "/" << newPosition->getCurrentHash(); + cLog(lsINFO) << "Processing peer proposal " << newPosition->getProposeSeq() << "/" << newPosition->getCurrentHash(); currentPosition = newPosition; SHAMap::pointer set = getTransactionTree(newPosition->getCurrentHash(), true); @@ -899,7 +897,7 @@ bool LedgerConsensus::peerPosition(const LedgerProposal::pointer& newPosition) it.second->setVote(peerID, set->hasItem(it.first)); } else - Log(lsTRACE) << "Don't have that tx set"; + cLog(lsTRACE) << "Don't have that tx set"; return true; } @@ -936,7 +934,7 @@ void LedgerConsensus::beginAccept() SHAMap::pointer consensusSet = mAcquired[mOurPosition->getCurrentHash()]; if (!consensusSet) { - Log(lsFATAL) << "We don't have a consensus set"; + cLog(lsFATAL) << "We don't have a consensus set"; abort(); return; } @@ -970,7 +968,7 @@ void LedgerConsensus::playbackProposals() proposal->setPrevLedger(mPrevLedgerHash); if (proposal->checkSign()) { - Log(lsINFO) << "Applying deferred proposal"; + cLog(lsINFO) << "Applying deferred proposal"; peerPosition(proposal); } } @@ -991,18 +989,18 @@ void LedgerConsensus::applyTransaction(TransactionEngine& engine, const Serializ TER result = engine.applyTransaction(*txn, parms); if (isTerRetry(result)) { - Log(lsINFO) << " retry"; + cLog(lsINFO) << " retry"; assert(!ledger->hasTransaction(txn->getTransactionID())); failedTransactions.push_back(txn); } else if (isTepSuccess(result)) // FIXME: Need to do partial success { - Log(lsTRACE) << " success"; + cLog(lsTRACE) << " success"; assert(ledger->hasTransaction(txn->getTransactionID())); } else if (isTemMalformed(result) || isTefFailure(result)) { - Log(lsINFO) << " hard fail"; + cLog(lsINFO) << " hard fail"; } else assert(false); @@ -1010,7 +1008,7 @@ void LedgerConsensus::applyTransaction(TransactionEngine& engine, const Serializ } catch (...) { - Log(lsWARNING) << " Throws"; + cLog(lsWARNING) << " Throws"; } #endif } @@ -1025,7 +1023,7 @@ void LedgerConsensus::applyTransactions(SHAMap::ref set, Ledger::ref applyLedger { if (!checkLedger->hasTransaction(item->getTag())) { - Log(lsINFO) << "Processing candidate transaction: " << item->getTag(); + cLog(lsINFO) << "Processing candidate transaction: " << item->getTag(); #ifndef TRUST_NETWORK try { @@ -1037,7 +1035,7 @@ void LedgerConsensus::applyTransactions(SHAMap::ref set, Ledger::ref applyLedger } catch (...) { - Log(lsWARNING) << " Throws"; + cLog(lsWARNING) << " Throws"; } #endif } @@ -1065,7 +1063,7 @@ void LedgerConsensus::applyTransactions(SHAMap::ref set, Ledger::ref applyLedger } catch (...) { - Log(lsWARNING) << " Throws"; + cLog(lsWARNING) << " Throws"; it = failedTransactions.erase(it); } } @@ -1083,11 +1081,11 @@ void LedgerConsensus::accept(SHAMap::ref set) uint32 closeTime = roundCloseTime(mOurPosition->getCloseTime()); - Log(lsINFO) << "Computing new LCL based on network consensus"; + cLog(lsINFO) << "Computing new LCL based on network consensus"; if (mHaveCorrectLCL) { - Log(lsINFO) << "CNF tx " << mOurPosition->getCurrentHash() << ", close " << closeTime; - Log(lsINFO) << "CNF mode " << theApp->getOPs().getOperatingMode() << ", oldLCL " << mPrevLedgerHash; + cLog(lsINFO) << "CNF tx " << mOurPosition->getCurrentHash() << ", close " << closeTime; + cLog(lsINFO) << "CNF mode " << theApp->getOPs().getOperatingMode() << ", oldLCL " << mPrevLedgerHash; } Ledger::pointer newLCL = boost::make_shared(false, boost::ref(*mPreviousLedger)); @@ -1102,7 +1100,7 @@ void LedgerConsensus::accept(SHAMap::ref set) { // we agreed to disagree closeTimeCorrect = false; closeTime = mPreviousLedger->getCloseTimeNC() + 1; - Log(lsINFO) << "CNF badclose " << closeTime; + cLog(lsINFO) << "CNF badclose " << closeTime; } newLCL->setAccepted(closeTime, mCloseResolution, closeTimeCorrect); @@ -1120,10 +1118,10 @@ void LedgerConsensus::accept(SHAMap::ref set) val.set_validation(&validation[0], validation.size()); int j = theApp->getConnectionPool().relayMessage(NULL, boost::make_shared(val, newcoin::mtVALIDATION)); - Log(lsINFO) << "CNF Val " << newLCLHash << " to " << j << " peers"; + cLog(lsINFO) << "CNF Val " << newLCLHash << " to " << j << " peers"; } else - Log(lsINFO) << "CNF newLCL " << newLCLHash; + cLog(lsINFO) << "CNF newLCL " << newLCLHash; Ledger::pointer newOL = boost::make_shared(true, boost::ref(*newLCL)); ScopedLock sl = theApp->getMasterLedger().getLock(); @@ -1136,19 +1134,19 @@ void LedgerConsensus::accept(SHAMap::ref set) { // we voted NO try { - Log(lsINFO) << "Test applying disputed transaction that did not get in"; + cLog(lsINFO) << "Test applying disputed transaction that did not get in"; SerializerIterator sit(it.second->peekTransaction()); SerializedTransaction::pointer txn = boost::make_shared(boost::ref(sit)); applyTransaction(engine, txn, newOL, failedTransactions, true); } catch (...) { - Log(lsINFO) << "Failed to apply transaction we voted NO on"; + cLog(lsINFO) << "Failed to apply transaction we voted NO on"; } } } - Log(lsINFO) << "Applying transactions from current ledger"; + cLog(lsINFO) << "Applying transactions from current ledger"; applyTransactions(theApp->getMasterLedger().getCurrentLedger()->peekTransactionMap(), newOL, newLCL, failedTransactions, true); theApp->getMasterLedger().pushLedger(newLCL, newOL); @@ -1158,12 +1156,12 @@ void LedgerConsensus::accept(SHAMap::ref set) if (mValidating) { // see how close our close time is to other node's close time reports - Log(lsINFO) << "We closed at " << boost::lexical_cast(mCloseTime); + cLog(lsINFO) << "We closed at " << boost::lexical_cast(mCloseTime); uint64 closeTotal = mCloseTime; int closeCount = 1; for (std::map::iterator it = mCloseTimes.begin(), end = mCloseTimes.end(); it != end; ++it) { // FIXME: Use median, not average - Log(lsINFO) << boost::lexical_cast(it->second) << " time votes for " + cLog(lsINFO) << boost::lexical_cast(it->second) << " time votes for " << boost::lexical_cast(it->first); closeCount += it->second; closeTotal += static_cast(it->first) * static_cast(it->second); @@ -1171,17 +1169,17 @@ void LedgerConsensus::accept(SHAMap::ref set) closeTotal += (closeCount / 2); closeTotal /= closeCount; int offset = static_cast(closeTotal) - static_cast(mCloseTime); - Log(lsINFO) << "Our close offset is estimated at " << offset << " (" << closeCount << ")"; + cLog(lsINFO) << "Our close offset is estimated at " << offset << " (" << closeCount << ")"; theApp->getOPs().closeTimeOffset(offset); } #ifdef DEBUG + if (sLog(lsTRACE)) { - Json::StyledStreamWriter ssw; Log(lsTRACE) << "newLCL"; Json::Value p; newLCL->addJson(p, LEDGER_JSON_DUMP_TXNS | LEDGER_JSON_DUMP_STATE); - ssw.write(Log(lsTRACE).ref(), p); + Log(lsTRACE) << p; } #endif } diff --git a/src/LedgerEntrySet.cpp b/src/LedgerEntrySet.cpp index bba1a48bf8..d59b920d0b 100644 --- a/src/LedgerEntrySet.cpp +++ b/src/LedgerEntrySet.cpp @@ -5,6 +5,8 @@ #include "Log.h" +SETUP_LOG(); + // #define META_DEBUG // Small for testing, should likely be 32 or 64. @@ -297,7 +299,7 @@ bool LedgerEntrySet::threadTx(const NewcoinAddress& threadTo, Ledger::ref ledger boost::unordered_map& newMods) { #ifdef META_DEBUG - Log(lsTRACE) << "Thread to " << threadTo.getAccountID(); + cLog(lsTRACE) << "Thread to " << threadTo.getAccountID(); #endif SLE::pointer sle = getForMod(Ledger::getAccountRootIndex(threadTo.getAccountID()), ledger, newMods); if (!sle) @@ -326,14 +328,14 @@ bool LedgerEntrySet::threadOwners(SLE::ref node, Ledger::ref ledger, boost::unor if (node->hasOneOwner()) // thread to owner's account { #ifdef META_DEBUG - Log(lsTRACE) << "Thread to single owner"; + cLog(lsTRACE) << "Thread to single owner"; #endif return threadTx(node->getOwner(), ledger, newMods); } else if (node->hasTwoOwners()) // thread to owner's accounts] { #ifdef META_DEBUG - Log(lsTRACE) << "Thread to two owners"; + cLog(lsTRACE) << "Thread to two owners"; #endif return threadTx(node->getFirstOwner(), ledger, newMods) && @@ -358,21 +360,21 @@ void LedgerEntrySet::calcRawMeta(Serializer& s) { case taaMODIFY: #ifdef META_DEBUG - Log(lsTRACE) << "Modified Node " << it->first; + cLog(lsTRACE) << "Modified Node " << it->first; #endif nType = TMNModifiedNode; break; case taaDELETE: #ifdef META_DEBUG - Log(lsTRACE) << "Deleted Node " << it->first; + cLog(lsTRACE) << "Deleted Node " << it->first; #endif nType = TMNDeletedNode; break; case taaCREATE: #ifdef META_DEBUG - Log(lsTRACE) << "Created Node " << it->first; + cLog(lsTRACE) << "Created Node " << it->first; #endif nType = TMNCreatedNode; break; @@ -466,7 +468,7 @@ void LedgerEntrySet::calcRawMeta(Serializer& s) entryModify(it->second); #ifdef META_DEBUG - Log(lsINFO) << "Metadata:" << mSet.getJson(0); + cLog(lsINFO) << "Metadata:" << mSet.getJson(0); #endif mSet.addRaw(s); @@ -557,10 +559,10 @@ TER LedgerEntrySet::dirAdd( svIndexes.peekValue().push_back(uLedgerIndex); // Append entry. sleNode->setFieldV256(sfIndexes, svIndexes); // Save entry. - Log(lsINFO) << "dirAdd: creating: root: " << uRootIndex.ToString(); - Log(lsINFO) << "dirAdd: appending: Entry: " << uLedgerIndex.ToString(); - Log(lsINFO) << "dirAdd: appending: Node: " << strHex(uNodeDir); - // Log(lsINFO) << "dirAdd: appending: PREV: " << svIndexes.peekValue()[0].ToString(); + cLog(lsINFO) << "dirAdd: creating: root: " << uRootIndex.ToString(); + cLog(lsINFO) << "dirAdd: appending: Entry: " << uLedgerIndex.ToString(); + cLog(lsINFO) << "dirAdd: appending: Node: " << strHex(uNodeDir); + // cLog(lsINFO) << "dirAdd: appending: PREV: " << svIndexes.peekValue()[0].ToString(); return tesSUCCESS; } @@ -580,7 +582,7 @@ TER LedgerEntrySet::dirDelete( if (!sleNode) { - Log(lsWARNING) << "dirDelete: no such node"; + cLog(lsWARNING) << "dirDelete: no such node"; return tefBAD_LEDGER; } @@ -596,7 +598,7 @@ TER LedgerEntrySet::dirDelete( { assert(false); - Log(lsWARNING) << "dirDelete: no such entry"; + cLog(lsWARNING) << "dirDelete: no such entry"; return tefBAD_LEDGER; } @@ -688,14 +690,14 @@ TER LedgerEntrySet::dirDelete( if (!slePrevious) { - Log(lsWARNING) << "dirDelete: previous node is missing"; + cLog(lsWARNING) << "dirDelete: previous node is missing"; return tefBAD_LEDGER; } if (!sleNext) { - Log(lsWARNING) << "dirDelete: next node is missing"; + cLog(lsWARNING) << "dirDelete: next node is missing"; return tefBAD_LEDGER; } @@ -789,7 +791,7 @@ bool LedgerEntrySet::dirNext( } uEntryIndex = vuiIndexes[uDirEntry++]; -Log(lsINFO) << boost::str(boost::format("dirNext: uDirEntry=%d uEntryIndex=%s") % uDirEntry % uEntryIndex); + cLog(lsINFO) << boost::str(boost::format("dirNext: uDirEntry=%d uEntryIndex=%s") % uDirEntry % uEntryIndex); return true; } @@ -836,7 +838,7 @@ STAmount LedgerEntrySet::rippleOwed(const uint160& uToAccountID, const uint160& } else { - Log(lsINFO) << "rippleOwed: No credit line between " + cLog(lsINFO) << "rippleOwed: No credit line between " << NewcoinAddress::createHumanAccountID(uFromAccountID) << " and " << NewcoinAddress::createHumanAccountID(uToAccountID) @@ -876,7 +878,7 @@ uint32 LedgerEntrySet::rippleTransferRate(const uint160& uIssuerID) ? sleAccount->getFieldU32(sfTransferRate) : QUALITY_ONE; - Log(lsINFO) << boost::str(boost::format("rippleTransferRate: uIssuerID=%s account_exists=%d transfer_rate=%f") + cLog(lsINFO) << boost::str(boost::format("rippleTransferRate: uIssuerID=%s account_exists=%d transfer_rate=%f") % NewcoinAddress::createHumanAccountID(uIssuerID) % !!sleAccount % (uQuality/1000000000.0)); @@ -920,7 +922,7 @@ uint32 LedgerEntrySet::rippleQualityIn(const uint160& uToAccountID, const uint16 } } - Log(lsINFO) << boost::str(boost::format("rippleQuality: %s uToAccountID=%s uFromAccountID=%s uCurrencyID=%s bLine=%d uQuality=%f") + cLog(lsINFO) << boost::str(boost::format("rippleQuality: %s uToAccountID=%s uFromAccountID=%s uCurrencyID=%s bLine=%d uQuality=%f") % (sfLow == sfLowQualityIn ? "in" : "out") % NewcoinAddress::createHumanAccountID(uToAccountID) % NewcoinAddress::createHumanAccountID(uFromAccountID) @@ -967,7 +969,7 @@ STAmount LedgerEntrySet::accountHolds(const uint160& uAccountID, const uint160& saAmount = rippleHolds(uAccountID, uCurrencyID, uIssuerID); } - Log(lsINFO) << boost::str(boost::format("accountHolds: uAccountID=%s saAmount=%s") + cLog(lsINFO) << boost::str(boost::format("accountHolds: uAccountID=%s saAmount=%s") % NewcoinAddress::createHumanAccountID(uAccountID) % saAmount.getFullText()); @@ -987,7 +989,7 @@ STAmount LedgerEntrySet::accountFunds(const uint160& uAccountID, const STAmount& { saFunds = saDefault; - Log(lsINFO) << boost::str(boost::format("accountFunds: uAccountID=%s saDefault=%s SELF-FUNDED") + cLog(lsINFO) << boost::str(boost::format("accountFunds: uAccountID=%s saDefault=%s SELF-FUNDED") % NewcoinAddress::createHumanAccountID(uAccountID) % saDefault.getFullText()); } @@ -995,7 +997,7 @@ STAmount LedgerEntrySet::accountFunds(const uint160& uAccountID, const STAmount& { saFunds = accountHolds(uAccountID, saDefault.getCurrency(), saDefault.getIssuer()); - Log(lsINFO) << boost::str(boost::format("accountFunds: uAccountID=%s saDefault=%s saFunds=%s") + cLog(lsINFO) << boost::str(boost::format("accountFunds: uAccountID=%s saDefault=%s saFunds=%s") % NewcoinAddress::createHumanAccountID(uAccountID) % saDefault.getFullText() % saFunds.getFullText()); @@ -1038,7 +1040,7 @@ void LedgerEntrySet::rippleCredit(const uint160& uSenderID, const uint160& uRece if (!sleRippleState) { - Log(lsINFO) << "rippleCredit: Creating ripple line: " << uIndex.ToString(); + cLog(lsINFO) << "rippleCredit: Creating ripple line: " << uIndex.ToString(); STAmount saBalance = saAmount; @@ -1122,7 +1124,7 @@ void LedgerEntrySet::accountSend(const uint160& uSenderID, const uint160& uRecei ? entryCache(ltACCOUNT_ROOT, Ledger::getAccountRootIndex(uReceiverID)) : SLE::pointer(); - Log(lsINFO) << boost::str(boost::format("accountSend> %s (%s) -> %s (%s) : %s") + cLog(lsINFO) << boost::str(boost::format("accountSend> %s (%s) -> %s (%s) : %s") % NewcoinAddress::createHumanAccountID(uSenderID) % (sleSender ? (sleSender->getFieldAmount(sfBalance)).getFullText() : "-") % NewcoinAddress::createHumanAccountID(uReceiverID) @@ -1141,7 +1143,7 @@ void LedgerEntrySet::accountSend(const uint160& uSenderID, const uint160& uRecei entryModify(sleReceiver); } - Log(lsINFO) << boost::str(boost::format("accountSend< %s (%s) -> %s (%s) : %s") + cLog(lsINFO) << boost::str(boost::format("accountSend< %s (%s) -> %s (%s) : %s") % NewcoinAddress::createHumanAccountID(uSenderID) % (sleSender ? (sleSender->getFieldAmount(sfBalance)).getFullText() : "-") % NewcoinAddress::createHumanAccountID(uReceiverID) diff --git a/src/Log.cpp b/src/Log.cpp index 948552cbf9..74904c6a3d 100644 --- a/src/Log.cpp +++ b/src/Log.cpp @@ -13,6 +13,8 @@ std::ofstream* Log::outStream = NULL; boost::filesystem::path *Log::pathToLog = NULL; uint32 Log::logRotateCounter = 0; +LogPartition* LogPartition::headLog = NULL; + Log::~Log() { std::string logMsg = boost::posix_time::to_simple_string(boost::posix_time::second_clock::universal_time()); @@ -79,6 +81,7 @@ void Log::setMinSeverity(LogSeverity s) { boost::recursive_mutex::scoped_lock sl(sLock); sMinSeverity = s; + LogPartition::setSeverity(s); } void Log::setLogFile(boost::filesystem::path path) @@ -99,3 +102,19 @@ void Log::setLogFile(boost::filesystem::path path) pathToLog = new boost::filesystem::path(path); } + +void LogPartition::setSeverity(const char *partition, LogSeverity severity) +{ + for (LogPartition *p = headLog; p != NULL; p = p->mNextLog) + if (p->mName == partition) + { + p->mMinSeverity = severity; + return; + } +} + +void LogPartition::setSeverity(LogSeverity severity) +{ + for (LogPartition *p = headLog; p != NULL; p = p->mNextLog) + p->mMinSeverity = severity; +} diff --git a/src/Log.h b/src/Log.h index fd3db13fd3..a71d07ee9c 100644 --- a/src/Log.h +++ b/src/Log.h @@ -2,6 +2,8 @@ #define __LOG__ #include +#include +#include #include #include @@ -10,7 +12,19 @@ #include "../json/json.h" #include "types.h" -#include + +// Put at the beginning of a C++ file that needs its own log partition +#define SETUP_LOG() static LogPartition logPartition(__FILE__) + +// Standard conditional log +#define cLog(x) if (!logPartition.doLog(x)) do {} while (0); else Log(x) + +// Log only if an additional condition 'c' is true. Condition is not computed if not needed +#define tLog(c,x) if (!logPartition.doLog(x) || !(c)) do {} while(0); else Log(x) + +// Check if should log +#define sLog(x) (logPartition.doLog(x)) + enum LogSeverity { @@ -22,6 +36,32 @@ enum LogSeverity lsFATAL = 5 }; +class LogPartition +{ +protected: + static LogPartition* headLog; + + LogPartition* mNextLog; + LogSeverity mMinSeverity; + std::string mName; + +public: + LogPartition(const char *name) : mNextLog(headLog), mMinSeverity(lsWARNING) + { + const char *ptr = strrchr(name, '/'); + mName = (ptr == NULL) ? name : ptr; + headLog = this; + } + + bool doLog(enum LogSeverity s) + { + return s >= mMinSeverity; + } + + static void setSeverity(const char *partition, LogSeverity severity); + static void setSeverity(LogSeverity severity); +}; + class Log { private: diff --git a/src/NetworkOPs.cpp b/src/NetworkOPs.cpp index 27e28d413c..b2b128cd15 100644 --- a/src/NetworkOPs.cpp +++ b/src/NetworkOPs.cpp @@ -23,6 +23,8 @@ // code assumes this node is synched (and will continue to do so until // there's a functional network. +SETUP_LOG(); + NetworkOPs::NetworkOPs(boost::asio::io_service& io_service, LedgerMaster* pLedgerMaster) : mMode(omDISCONNECTED),mNetTimer(io_service), mLedgerMaster(pLedgerMaster), mCloseTimeOffset(0), mLastCloseProposers(0), mLastCloseConvergeTime(1000 * LEDGER_IDLE_INTERVAL), mLastValidationTime(0) @@ -63,8 +65,7 @@ void NetworkOPs::closeTimeOffset(int offset) mCloseTimeOffset += (offset - 3) / 4; else mCloseTimeOffset = (mCloseTimeOffset * 3) / 4; - if (mCloseTimeOffset) - Log(lsINFO) << "Close time offset now " << mCloseTimeOffset; + tLog(mCloseTimeOffset != 0, lsINFO) << "Close time offset now " << mCloseTimeOffset; } uint32 NetworkOPs::getLedgerID(const uint256& hash) @@ -90,9 +91,9 @@ Transaction::pointer NetworkOPs::submitTransaction(const Transaction::pointer& t if(!tpTransNew->getSTransaction()->isEquivalent(*tpTrans->getSTransaction())) { - Log(lsFATAL) << "Transaction reconstruction failure"; - Log(lsFATAL) << tpTransNew->getSTransaction()->getJson(0); - Log(lsFATAL) << tpTrans->getSTransaction()->getJson(0); + cLog(lsFATAL) << "Transaction reconstruction failure"; + cLog(lsFATAL) << tpTransNew->getSTransaction()->getJson(0); + cLog(lsFATAL) << tpTrans->getSTransaction()->getJson(0); assert(false); } @@ -108,7 +109,7 @@ Transaction::pointer NetworkOPs::processTransaction(Transaction::pointer trans, if (!trans->checkSign()) { - Log(lsINFO) << "Transaction has bad signature"; + cLog(lsINFO) << "Transaction has bad signature"; trans->setStatus(INVALID); return trans; } @@ -119,8 +120,7 @@ Transaction::pointer NetworkOPs::processTransaction(Transaction::pointer trans, if (r != tesSUCCESS) { std::string token, human; - if (transResultInfo(r, token, human)) - Log(lsINFO) << "TransactionResult: " << token << ": " << human; + tLog(transResultInfo(r, token, human), lsINFO) << "TransactionResult: " << token << ": " << human; } #endif @@ -129,7 +129,7 @@ Transaction::pointer NetworkOPs::processTransaction(Transaction::pointer trans, if (r == terPRE_SEQ) { // transaction should be held - Log(lsDEBUG) << "Transaction should be held"; + cLog(lsDEBUG) << "Transaction should be held"; trans->setStatus(HELD); theApp->getMasterTransaction().canonicalize(trans, true); mLedgerMaster->addHeldTransaction(trans); @@ -137,14 +137,14 @@ Transaction::pointer NetworkOPs::processTransaction(Transaction::pointer trans, } if ((r == tefPAST_SEQ)) { // duplicate or conflict - Log(lsINFO) << "Transaction is obsolete"; + cLog(lsINFO) << "Transaction is obsolete"; trans->setStatus(OBSOLETE); return trans; } if (r == tesSUCCESS) { - Log(lsINFO) << "Transaction is now included"; + cLog(lsINFO) << "Transaction is now included"; trans->setStatus(INCLUDED); theApp->getMasterTransaction().canonicalize(trans, true); @@ -162,12 +162,12 @@ Transaction::pointer NetworkOPs::processTransaction(Transaction::pointer trans, PackedMessage::pointer packet = boost::make_shared(tx, newcoin::mtTRANSACTION); int sentTo = theApp->getConnectionPool().relayMessage(source, packet); - Log(lsINFO) << "Transaction relayed to " << sentTo << " node(s)"; + cLog(lsINFO) << "Transaction relayed to " << sentTo << " node(s)"; return trans; } - Log(lsDEBUG) << "Status other than success " << r; + cLog(lsDEBUG) << "Status other than success " << r; if ((mMode != omFULL) && (mMode != omTRACKING) && (theApp->isNew(trans->getID()))) { newcoin::TMTransaction tx; @@ -255,21 +255,21 @@ STVector256 NetworkOPs::getDirNodeInfo( if (sleNode) { - Log(lsDEBUG) << "getDirNodeInfo: node index: " << uNodeIndex.ToString(); + cLog(lsDEBUG) << "getDirNodeInfo: node index: " << uNodeIndex.ToString(); - Log(lsTRACE) << "getDirNodeInfo: first: " << strHex(sleNode->getFieldU64(sfIndexPrevious)); - Log(lsTRACE) << "getDirNodeInfo: last: " << strHex(sleNode->getFieldU64(sfIndexNext)); + cLog(lsTRACE) << "getDirNodeInfo: first: " << strHex(sleNode->getFieldU64(sfIndexPrevious)); + cLog(lsTRACE) << "getDirNodeInfo: last: " << strHex(sleNode->getFieldU64(sfIndexNext)); uNodePrevious = sleNode->getFieldU64(sfIndexPrevious); uNodeNext = sleNode->getFieldU64(sfIndexNext); svIndexes = sleNode->getFieldV256(sfIndexes); - Log(lsTRACE) << "getDirNodeInfo: first: " << strHex(uNodePrevious); - Log(lsTRACE) << "getDirNodeInfo: last: " << strHex(uNodeNext); + cLog(lsTRACE) << "getDirNodeInfo: first: " << strHex(uNodePrevious); + cLog(lsTRACE) << "getDirNodeInfo: last: " << strHex(uNodeNext); } else { - Log(lsINFO) << "getDirNodeInfo: node index: NOT FOUND: " << uNodeIndex.ToString(); + cLog(lsINFO) << "getDirNodeInfo: node index: NOT FOUND: " << uNodeIndex.ToString(); uNodePrevious = 0; uNodeNext = 0; @@ -403,7 +403,7 @@ void NetworkOPs::checkState(const boost::system::error_code& result) if (mMode != omDISCONNECTED) { setMode(omDISCONNECTED); - Log(lsWARNING) << "Node count (" << peerList.size() << + cLog(lsWARNING) << "Node count (" << peerList.size() << ") has fallen below quorum (" << theConfig.NETWORK_QUORUM << ")."; } return; @@ -411,7 +411,7 @@ void NetworkOPs::checkState(const boost::system::error_code& result) if (mMode == omDISCONNECTED) { setMode(omCONNECTED); - Log(lsINFO) << "Node count (" << peerList.size() << ") is sufficient."; + cLog(lsINFO) << "Node count (" << peerList.size() << ") is sufficient."; } if (mConsensus) @@ -467,7 +467,7 @@ bool NetworkOPs::checkLastClosedLedger(const std::vector& peerLis // FIXME: We may have a ledger with many recent validations but that no directly-connected // node is using. THis is kind of fundamental. - Log(lsTRACE) << "NetworkOPs::checkLastClosedLedger"; + cLog(lsTRACE) << "NetworkOPs::checkLastClosedLedger"; Ledger::pointer ourClosed = mLedgerMaster->getClosedLedger(); uint256 closedLedger = ourClosed->getHash(); @@ -501,7 +501,7 @@ bool NetworkOPs::checkLastClosedLedger(const std::vector& peerLis { if (!it) { - Log(lsDEBUG) << "NOP::CS Dead pointer in peer list"; + cLog(lsDEBUG) << "NOP::CS Dead pointer in peer list"; } else if (it->isConnected()) { @@ -523,14 +523,13 @@ bool NetworkOPs::checkLastClosedLedger(const std::vector& peerLis for (boost::unordered_map::iterator it = ledgers.begin(), end = ledgers.end(); it != end; ++it) { - Log(lsTRACE) << "L: " << it->first << " t=" << it->second.trustedValidations << + cLog(lsTRACE) << "L: " << it->first << " t=" << it->second.trustedValidations << ", n=" << it->second.nodesUsing; // Temporary logging to make sure tiebreaking isn't broken if (it->second.trustedValidations > 0) - Log(lsTRACE) << " TieBreakTV: " << it->second.highValidation; - else if (it->second.nodesUsing > 0) - Log(lsTRACE) << " TieBreakNU: " << it->second.highNodeUsing; + cLog(lsTRACE) << " TieBreakTV: " << it->second.highValidation; + else tLog(it->second.nodesUsing > 0, lsTRACE) << " TieBreakNU: " << it->second.highNodeUsing; if (it->second > bestVC) { @@ -542,7 +541,7 @@ bool NetworkOPs::checkLastClosedLedger(const std::vector& peerLis if (switchLedgers && (closedLedger == prevClosedLedger)) { // don't switch to our own previous ledger - Log(lsINFO) << "We won't switch to our own previous ledger"; + cLog(lsINFO) << "We won't switch to our own previous ledger"; networkClosed = ourClosed->getHash(); switchLedgers = false; } @@ -560,22 +559,22 @@ bool NetworkOPs::checkLastClosedLedger(const std::vector& peerLis return false; } - Log(lsWARNING) << "We are not running on the consensus ledger"; - Log(lsINFO) << "Our LCL " << ourClosed->getHash(); - Log(lsINFO) << "Net LCL " << closedLedger; + cLog(lsWARNING) << "We are not running on the consensus ledger"; + cLog(lsINFO) << "Our LCL " << ourClosed->getHash(); + cLog(lsINFO) << "Net LCL " << closedLedger; if ((mMode == omTRACKING) || (mMode == omFULL)) setMode(omCONNECTED); Ledger::pointer consensus = mLedgerMaster->getLedgerByHash(closedLedger); if (!consensus) { - Log(lsINFO) << "Acquiring consensus ledger " << closedLedger; + cLog(lsINFO) << "Acquiring consensus ledger " << closedLedger; if (!mAcquiringLedger || (mAcquiringLedger->getHash() != closedLedger)) mAcquiringLedger = theApp->getMasterLedgerAcquire().findCreate(closedLedger); if (!mAcquiringLedger || mAcquiringLedger->isFailed()) { theApp->getMasterLedgerAcquire().dropLedger(closedLedger); - Log(lsERROR) << "Network ledger cannot be acquired"; + cLog(lsERROR) << "Network ledger cannot be acquired"; return true; } if (!mAcquiringLedger->isComplete()) @@ -612,9 +611,9 @@ void NetworkOPs::switchLastClosedLedger(Ledger::pointer newLedger, bool duringCo { // set the newledger as our last closed ledger -- this is abnormal code if (duringConsensus) - Log(lsERROR) << "JUMPdc last closed ledger to " << newLedger->getHash(); + cLog(lsERROR) << "JUMPdc last closed ledger to " << newLedger->getHash(); else - Log(lsERROR) << "JUMP last closed ledger to " << newLedger->getHash(); + cLog(lsERROR) << "JUMP last closed ledger to " << newLedger->getHash(); newLedger->setClosed(); Ledger::pointer openLedger = boost::make_shared(false, boost::ref(*newLedger)); @@ -634,13 +633,13 @@ void NetworkOPs::switchLastClosedLedger(Ledger::pointer newLedger, bool duringCo int NetworkOPs::beginConsensus(const uint256& networkClosed, Ledger::pointer closingLedger) { - Log(lsINFO) << "Consensus time for ledger " << closingLedger->getLedgerSeq(); - Log(lsINFO) << " LCL is " << closingLedger->getParentHash(); + cLog(lsINFO) << "Consensus time for ledger " << closingLedger->getLedgerSeq(); + cLog(lsINFO) << " LCL is " << closingLedger->getParentHash(); Ledger::pointer prevLedger = mLedgerMaster->getLedgerByHash(closingLedger->getParentHash()); if (!prevLedger) { // this shouldn't happen unless we jump ledgers - Log(lsWARNING) << "Don't have LCL, going to tracking"; + cLog(lsWARNING) << "Don't have LCL, going to tracking"; setMode(omTRACKING); return 3; } @@ -654,7 +653,7 @@ int NetworkOPs::beginConsensus(const uint256& networkClosed, Ledger::pointer clo networkClosed, prevLedger, theApp->getMasterLedger().getCurrentLedger()->getCloseTimeNC()); mConsensus->swapDefer(mDeferredProposals); - Log(lsDEBUG) << "Initiating consensus engine"; + cLog(lsDEBUG) << "Initiating consensus engine"; return mConsensus->startup(); } @@ -670,7 +669,7 @@ bool NetworkOPs::haveConsensusObject() bool ledgerChange = checkLastClosedLedger(peerList, networkClosed); if (!ledgerChange) { - Log(lsWARNING) << "Beginning consensus due to peer action"; + cLog(lsWARNING) << "Beginning consensus due to peer action"; beginConsensus(networkClosed, theApp->getMasterLedger().getCurrentLedger()); } return mConsensus; @@ -700,14 +699,14 @@ bool NetworkOPs::recvPropose(uint32 proposeSeq, const uint256& proposeHash, cons if (!haveConsensusObject()) { - Log(lsINFO) << "Received proposal outside consensus window"; + cLog(lsINFO) << "Received proposal outside consensus window"; return mMode != omFULL; } // Is this node on our UNL? if (!theApp->getUNL().nodeInUNL(naPeerPublic)) { - Log(lsINFO) << "Untrusted proposal: " << naPeerPublic.humanNodePublic() << " " << proposeHash; + cLog(lsINFO) << "Untrusted proposal: " << naPeerPublic.humanNodePublic() << " " << proposeHash; return true; } @@ -717,7 +716,7 @@ bool NetworkOPs::recvPropose(uint32 proposeSeq, const uint256& proposeHash, cons boost::make_shared(prevLedger, proposeSeq, proposeHash, closeTime, naPeerPublic); if (!proposal->checkSign(signature)) { - Log(lsWARNING) << "New-style ledger proposal fails signature check"; + cLog(lsWARNING) << "New-style ledger proposal fails signature check"; return false; } if (prevLedger == mConsensus->getLCL()) @@ -730,7 +729,7 @@ bool NetworkOPs::recvPropose(uint32 proposeSeq, const uint256& proposeHash, cons boost::make_shared(mConsensus->getLCL(), proposeSeq, proposeHash, closeTime, naPeerPublic); if (!proposal->checkSign(signature)) { // Note that if the LCL is different, the signature check will fail - Log(lsWARNING) << "Ledger proposal fails signature check"; + cLog(lsWARNING) << "Ledger proposal fails signature check"; proposal->setSignature(signature); mConsensus->deferProposal(proposal, nodePublic); return false; @@ -757,7 +756,7 @@ bool NetworkOPs::hasTXSet(const boost::shared_ptr& peer, const uint256& se { if (!haveConsensusObject()) { - Log(lsINFO) << "Peer has TX set, not during consensus"; + cLog(lsINFO) << "Peer has TX set, not during consensus"; return false; } return mConsensus->peerHasSet(peer, set, status); @@ -776,7 +775,7 @@ void NetworkOPs::endConsensus(bool correctLCL) BOOST_FOREACH(Peer::ref it, peerList) if (it && (it->getClosedLedgerHash() == deadLedger)) { - Log(lsTRACE) << "Killing obsolete peer status"; + cLog(lsTRACE) << "Killing obsolete peer status"; it->cycleStatus(); } mConsensus->swapDefer(mDeferredProposals); @@ -851,7 +850,7 @@ std::vector bool NetworkOPs::recvValidation(const SerializedValidation::pointer& val) { - Log(lsINFO) << "recvValidation " << val->getLedgerHash(); + cLog(lsINFO) << "recvValidation " << val->getLedgerHash(); return theApp->getValidations().addValidation(val); } diff --git a/src/Peer.cpp b/src/Peer.cpp index 2ea4f85f69..585b720d7f 100644 --- a/src/Peer.cpp +++ b/src/Peer.cpp @@ -16,6 +16,8 @@ #include "utils.h" #include "Log.h" +SETUP_LOG(); + // Don't try to run past receiving nonsense from a peer #define TRUST_NETWORK @@ -28,7 +30,7 @@ Peer::Peer(boost::asio::io_service& io_service, boost::asio::ssl::context& ctx) mSocketSsl(io_service, ctx), mVerifyTimer(io_service) { - // Log(lsDEBUG) << "CREATING PEER: " << ADDRESS(this); + // cLog(lsDEBUG) << "CREATING PEER: " << ADDRESS(this); } void Peer::handle_write(const boost::system::error_code& error, size_t bytes_transferred) @@ -47,7 +49,7 @@ void Peer::handle_write(const boost::system::error_code& error, size_t bytes_tra } else if (error) { - Log(lsINFO) << "Peer: Write: Error: " << ADDRESS(this) << ": bytes=" << bytes_transferred << ": " << error.category().name() << ": " << error.message() << ": " << error; + cLog(lsINFO) << "Peer: Write: Error: " << ADDRESS(this) << ": bytes=" << bytes_transferred << ": " << error.category().name() << ": " << error.message() << ": " << error; detach("hw"); } @@ -67,7 +69,7 @@ void Peer::setIpPort(const std::string& strIP, int iPort) { mIpPort = make_pair(strIP, iPort); - Log(lsDEBUG) << "Peer: Set: " + cLog(lsDEBUG) << "Peer: Set: " << ADDRESS(this) << "> " << (mNodePublic.isValid() ? mNodePublic.humanNodePublic() : "-") << " " << getIP() << " " << getPort(); } @@ -78,7 +80,7 @@ void Peer::detach(const char *rsn) { mDetaching = true; // Race is ok. /* - Log(lsDEBUG) << "Peer: Detach: " + cLog(lsDEBUG) << "Peer: Detach: " << ADDRESS(this) << "> " << rsn << ": " << (mNodePublic.isValid() ? mNodePublic.humanNodePublic() : "-") << " " << getIP() << " " << getPort(); @@ -105,7 +107,7 @@ void Peer::detach(const char *rsn) mIpPort.first.clear(); // Be idempotent. } /* - Log(lsDEBUG) << "Peer: Detach: " + cLog(lsDEBUG) << "Peer: Detach: " << ADDRESS(this) << "< " << rsn << ": " << (mNodePublic.isValid() ? mNodePublic.humanNodePublic() : "-") << " " << getIP() << " " << getPort(); @@ -124,14 +126,14 @@ void Peer::handleVerifyTimer(const boost::system::error_code& ecResult) } else if (ecResult) { - Log(lsINFO) << "Peer verify timer error"; + cLog(lsINFO) << "Peer verify timer error"; // Can't do anything sound. abort(); } else { - //Log(lsINFO) << "Peer: Verify: Peer failed to verify in time."; + //cLog(lsINFO) << "Peer: Verify: Peer failed to verify in time."; detach("hvt"); } @@ -157,7 +159,7 @@ void Peer::connect(const std::string& strIp, int iPort) if (err || itrEndpoint == boost::asio::ip::tcp::resolver::iterator()) { - Log(lsWARNING) << "Peer: Connect: Bad IP: " << strIp; + cLog(lsWARNING) << "Peer: Connect: Bad IP: " << strIp; detach("c"); return; } @@ -168,7 +170,7 @@ void Peer::connect(const std::string& strIp, int iPort) if (err) { - Log(lsWARNING) << "Peer: Connect: Failed to set timer."; + cLog(lsWARNING) << "Peer: Connect: Failed to set timer."; detach("c2"); return; } @@ -176,7 +178,7 @@ void Peer::connect(const std::string& strIp, int iPort) if (!err) { - Log(lsINFO) << "Peer: Connect: Outbound: " << ADDRESS(this) << ": " << mIpPort.first << " " << mIpPort.second; + cLog(lsINFO) << "Peer: Connect: Outbound: " << ADDRESS(this) << ": " << mIpPort.first << " " << mIpPort.second; boost::asio::async_connect( getSocket(), @@ -197,7 +199,7 @@ void Peer::handleStart(const boost::system::error_code& error) { if (error) { - Log(lsINFO) << "Peer: Handshake: Error: " << error.category().name() << ": " << error.message() << ": " << error; + cLog(lsINFO) << "Peer: Handshake: Error: " << error.category().name() << ": " << error.message() << ": " << error; detach("hs"); } else @@ -212,7 +214,7 @@ void Peer::handleConnect(const boost::system::error_code& error, boost::asio::ip { if (error) { - Log(lsINFO) << "Peer: Connect: Error: " << error.category().name() << ": " << error.message() << ": " << error; + cLog(lsINFO) << "Peer: Connect: Error: " << error.category().name() << ": " << error.message() << ": " << error; detach("hc"); } else @@ -244,7 +246,7 @@ void Peer::connected(const boost::system::error_code& error) { // Not redundant ip and port, handshake, and start. - Log(lsINFO) << "Peer: Inbound: Accepted: " << ADDRESS(this) << ": " << strIp << " " << iPort; + cLog(lsINFO) << "Peer: Inbound: Accepted: " << ADDRESS(this) << ": " << strIp << " " << iPort; mSocketSsl.set_verify_mode(boost::asio::ssl::verify_none); @@ -253,7 +255,7 @@ void Peer::connected(const boost::system::error_code& error) } else if (!mDetaching) { - Log(lsINFO) << "Peer: Inbound: Error: " << ADDRESS(this) << ": " << strIp << " " << iPort << " : " << error.category().name() << ": " << error.message() << ": " << error; + cLog(lsINFO) << "Peer: Inbound: Error: " << ADDRESS(this) << ": " << strIp << " " << iPort << " : " << error.category().name() << ": " << error.message() << ": " << error; detach("ctd"); } @@ -334,7 +336,7 @@ void Peer::handle_read_header(const boost::system::error_code& error) } else { - Log(lsINFO) << "Peer: Header: Error: " << ADDRESS(this) << ": " << error.category().name() << ": " << error.message() << ": " << error; + cLog(lsINFO) << "Peer: Header: Error: " << ADDRESS(this) << ": " << error.category().name() << ": " << error.message() << ": " << error; detach("hrh2"); } } @@ -353,7 +355,7 @@ void Peer::handle_read_body(const boost::system::error_code& error) } else { - Log(lsINFO) << "Peer: Body: Error: " << ADDRESS(this) << ": " << error.category().name() << ": " << error.message() << ": " << error; + cLog(lsINFO) << "Peer: Body: Error: " << ADDRESS(this) << ": " << error.category().name() << ": " << error.message() << ": " << error; detach("hrb"); } } @@ -370,7 +372,7 @@ void Peer::processReadBuffer() // If connected and get a mtHELLO or if not connected and get a non-mtHELLO, wrong message was sent. if (mHelloed == (type == newcoin::mtHELLO)) { - Log(lsWARNING) << "Wrong message type: " << type; + cLog(lsWARNING) << "Wrong message type: " << type; detach("prb1"); } else @@ -579,36 +581,40 @@ void Peer::recvHello(newcoin::TMHello& packet) { int64 to = ourTime; to -= packet.nettime(); - Log(lsDEBUG) << "Connect: time offset " << to; + cLog(lsDEBUG) << "Connect: time offset " << to; } #endif if (packet.has_nettime() && ((packet.nettime() < minTime) || (packet.nettime() > maxTime))) { if (packet.nettime() > maxTime) - Log(lsINFO) << "Recv(Hello): " << getIP() << " :Clock far off +" << packet.nettime() - ourTime; + { + cLog(lsINFO) << "Recv(Hello): " << getIP() << " :Clock far off +" << packet.nettime() - ourTime; + } else if(packet.nettime() < minTime) - Log(lsINFO) << "Recv(Hello): " << getIP() << " :Clock far off -" << ourTime - packet.nettime(); + { + cLog(lsINFO) << "Recv(Hello): " << getIP() << " :Clock far off -" << ourTime - packet.nettime(); + } } else if (packet.protoversionmin() < MAKE_VERSION_INT(MIN_PROTO_MAJOR, MIN_PROTO_MINOR)) { - Log(lsINFO) << "Recv(Hello): Server requires protocol version " << + cLog(lsINFO) << "Recv(Hello): Server requires protocol version " << GET_VERSION_MAJOR(packet.protoversion()) << "." << GET_VERSION_MINOR(packet.protoversion()) << " we run " << PROTO_VERSION_MAJOR << "." << PROTO_VERSION_MINOR; } else if (!mNodePublic.setNodePublic(packet.nodepublic())) { - Log(lsINFO) << "Recv(Hello): Disconnect: Bad node public key."; + cLog(lsINFO) << "Recv(Hello): Disconnect: Bad node public key."; } else if (!mNodePublic.verifyNodePublic(mCookieHash, packet.nodeproof())) { // Unable to verify they have private key for claimed public key. - Log(lsINFO) << "Recv(Hello): Disconnect: Failed to verify session."; + cLog(lsINFO) << "Recv(Hello): Disconnect: Failed to verify session."; } else { // Successful connection. - Log(lsINFO) << "Recv(Hello): Connect: " << mNodePublic.humanNodePublic(); - if (packet.protoversion() != MAKE_VERSION_INT(PROTO_VERSION_MAJOR, PROTO_VERSION_MINOR)) - Log(lsINFO) << "Peer speaks version " << + cLog(lsINFO) << "Recv(Hello): Connect: " << mNodePublic.humanNodePublic(); + tLog(packet.protoversion() != MAKE_VERSION_INT(PROTO_VERSION_MAJOR, PROTO_VERSION_MINOR), lsINFO) + << "Peer speaks version " << (packet.protoversion() >> 16) << "." << (packet.protoversion() & 0xFF); mHello = packet; @@ -620,7 +626,7 @@ void Peer::recvHello(newcoin::TMHello& packet) if (!theApp->getConnectionPool().peerConnected(shared_from_this(), mNodePublic, getIP(), getPort())) { // Already connected, self, or some other reason. - Log(lsINFO) << "Recv(Hello): Disconnect: Extraneous connection."; + cLog(lsINFO) << "Recv(Hello): Disconnect: Extraneous connection."; } else { @@ -716,7 +722,7 @@ void Peer::recvPropose(newcoin::TMProposeSet& packet) if ((packet.currenttxhash().size() != 32) || (packet.nodepubkey().size() < 28) || (packet.signature().size() < 56)) { - Log(lsWARNING) << "Received proposal is malformed"; + cLog(lsWARNING) << "Received proposal is malformed"; return; } @@ -756,7 +762,7 @@ void Peer::recvValidation(newcoin::TMValidation& packet) { if (packet.validation().size() < 50) { - Log(lsWARNING) << "Too small validation from peer"; + cLog(lsWARNING) << "Too small validation from peer"; punishPeer(PP_UNKNOWN_REQUEST); return; } @@ -774,13 +780,13 @@ void Peer::recvValidation(newcoin::TMValidation& packet) uint256 signingHash = val->getSigningHash(); if (!theApp->isNew(signingHash)) { - Log(lsTRACE) << "Validation is duplicate"; + cLog(lsTRACE) << "Validation is duplicate"; return; } if (!val->isValid(signingHash)) { - Log(lsWARNING) << "Validation is invalid"; + cLog(lsWARNING) << "Validation is invalid"; punishPeer(PP_UNKNOWN_REQUEST); return; } @@ -794,7 +800,7 @@ void Peer::recvValidation(newcoin::TMValidation& packet) //#ifndef TRUST_NETWORK catch (...) { - Log(lsWARNING) << "Exception processing validation"; + cLog(lsWARNING) << "Exception processing validation"; punishPeer(PP_UNKNOWN_REQUEST); } //#endif @@ -837,7 +843,7 @@ void Peer::recvGetPeers(newcoin::TMGetPeers& packet) addr->set_ipv4(inet_addr(strIP.c_str())); addr->set_ipv4port(iPort); - //Log(lsINFO) << "Peer: Teaching: " << ADDRESS(this) << ": " << n << ": " << strIP << " " << iPort; + //cLog(lsINFO) << "Peer: Teaching: " << ADDRESS(this) << ": " << n << ": " << strIP << " " << iPort; } PackedMessage::pointer message = boost::make_shared(peers, newcoin::mtPEERS); @@ -859,7 +865,7 @@ void Peer::recvPeers(newcoin::TMPeers& packet) if (strIP != "0.0.0.0" && strIP != "127.0.0.1") { - //Log(lsINFO) << "Peer: Learning: " << ADDRESS(this) << ": " << i << ": " << strIP << " " << iPort; + //cLog(lsINFO) << "Peer: Learning: " << ADDRESS(this) << ": " << i << ": " << strIP << " " << iPort; theApp->getConnectionPool().savePeer(strIP, iPort, UniqueNodeList::vsTold); } @@ -900,7 +906,7 @@ void Peer::recvAccount(newcoin::TMAccount& packet) void Peer::recvStatus(newcoin::TMStatusChange& packet) { - Log(lsTRACE) << "Received status change from peer " << getIP(); + cLog(lsTRACE) << "Received status change from peer " << getIP(); if (!packet.has_networktime()) packet.set_networktime(theApp->getOPs().getNetworkTimeNC()); @@ -917,7 +923,7 @@ void Peer::recvStatus(newcoin::TMStatusChange& packet) { if (!mClosedLedgerHash.isZero()) { - Log(lsTRACE) << "peer has lost sync " << getIP(); + cLog(lsTRACE) << "peer has lost sync " << getIP(); mClosedLedgerHash.zero(); } mPreviousLedgerHash.zero(); @@ -927,11 +933,11 @@ void Peer::recvStatus(newcoin::TMStatusChange& packet) { // a peer has changed ledgers memcpy(mClosedLedgerHash.begin(), packet.ledgerhash().data(), 256 / 8); addLedger(mClosedLedgerHash); - Log(lsTRACE) << "peer LCL is " << mClosedLedgerHash << " " << getIP(); + cLog(lsTRACE) << "peer LCL is " << mClosedLedgerHash << " " << getIP(); } else { - Log(lsTRACE) << "peer has no ledger hash" << getIP(); + cLog(lsTRACE) << "peer has no ledger hash" << getIP(); mClosedLedgerHash.zero(); } @@ -951,7 +957,7 @@ void Peer::recvGetLedger(newcoin::TMGetLedger& packet) if (packet.itype() == newcoin::liTS_CANDIDATE) { // Request is for a transaction candidate set - Log(lsINFO) << "Received request for TX candidate set data " << getIP(); + cLog(lsINFO) << "Received request for TX candidate set data " << getIP(); if ((!packet.has_ledgerhash() || packet.ledgerhash().size() != 32)) { punishPeer(PP_INVALID_REQUEST); @@ -962,7 +968,7 @@ void Peer::recvGetLedger(newcoin::TMGetLedger& packet) map = theApp->getOPs().getTXMap(txHash); if (!map) { - Log(lsERROR) << "We do not have the map our peer wants"; + cLog(lsERROR) << "We do not have the map our peer wants"; punishPeer(PP_INVALID_REQUEST); return; } @@ -974,7 +980,7 @@ void Peer::recvGetLedger(newcoin::TMGetLedger& packet) } else { // Figure out what ledger they want - Log(lsINFO) << "Received request for ledger data " << getIP(); + cLog(lsINFO) << "Received request for ledger data " << getIP(); Ledger::pointer ledger; if (packet.has_ledgerhash()) { @@ -982,13 +988,12 @@ void Peer::recvGetLedger(newcoin::TMGetLedger& packet) if (packet.ledgerhash().size() != 32) { punishPeer(PP_INVALID_REQUEST); - Log(lsWARNING) << "Invalid request"; + cLog(lsWARNING) << "Invalid request"; return; } memcpy(ledgerhash.begin(), packet.ledgerhash().data(), 32); ledger = theApp->getMasterLedger().getLedgerByHash(ledgerhash); - if (!ledger) - Log(lsINFO) << "Don't have ledger " << ledgerhash; + tLog(!ledger, lsINFO) << "Don't have ledger " << ledgerhash; } else if (packet.has_ledgerseq()) ledger = theApp->getMasterLedger().getLedgerBySeq(packet.ledgerseq()); @@ -1003,14 +1008,14 @@ void Peer::recvGetLedger(newcoin::TMGetLedger& packet) else { punishPeer(PP_INVALID_REQUEST); - Log(lsWARNING) << "Can't figure out what ledger they want"; + cLog(lsWARNING) << "Can't figure out what ledger they want"; return; } if ((!ledger) || (packet.has_ledgerseq() && (packet.ledgerseq() != ledger->getLedgerSeq()))) { punishPeer(PP_UNKNOWN_REQUEST); - Log(lsWARNING) << "Can't find the ledger they want"; + cLog(lsWARNING) << "Can't find the ledger they want"; return; } @@ -1022,14 +1027,14 @@ void Peer::recvGetLedger(newcoin::TMGetLedger& packet) if(packet.itype() == newcoin::liBASE) { // they want the ledger base data - Log(lsTRACE) << "Want ledger base data"; + cLog(lsTRACE) << "Want ledger base data"; Serializer nData(128); ledger->addRaw(nData); reply.add_nodes()->set_nodedata(nData.getDataPtr(), nData.getLength()); if (packet.nodeids().size() != 0) { // new-style root request - Log(lsINFO) << "Ledger root w/map roots request"; + cLog(lsINFO) << "Ledger root w/map roots request"; SHAMap::pointer map = ledger->peekAccountStateMap(); if (map) { // return account state root node if possible @@ -1063,7 +1068,7 @@ void Peer::recvGetLedger(newcoin::TMGetLedger& packet) if ((!map) || (packet.nodeids_size() == 0)) { - Log(lsWARNING) << "Can't find map or empty request"; + cLog(lsWARNING) << "Can't find map or empty request"; punishPeer(PP_INVALID_REQUEST); return; } @@ -1128,7 +1133,7 @@ void Peer::recvLedger(newcoin::TMLedgerData& packet) const newcoin::TMLedgerNode& node = packet.nodes(i); if (!node.has_nodeid() || !node.has_nodedata() || (node.nodeid().size() != 33)) { - Log(lsWARNING) << "LedgerData request with invalid node ID"; + cLog(lsWARNING) << "LedgerData request with invalid node ID"; punishPeer(PP_INVALID_REQUEST); return; } @@ -1288,7 +1293,7 @@ Json::Value Peer::getJson() case newcoin::nsMONITORING: ret["status"] = "monitoring"; break; case newcoin::nsVALIDATING: ret["status"] = "validating"; break; case newcoin::nsSHUTTING: ret["status"] = "shutting"; break; - default: Log(lsWARNING) << "Peer has unknown status: " << mLastStatus.newstatus(); + default: cLog(lsWARNING) << "Peer has unknown status: " << mLastStatus.newstatus(); } } diff --git a/src/RPCServer.cpp b/src/RPCServer.cpp index 4b5de9ef8d..9aa51033c6 100644 --- a/src/RPCServer.cpp +++ b/src/RPCServer.cpp @@ -28,10 +28,12 @@ #include "../json/reader.h" #include "../json/writer.h" +SETUP_LOG(); + RPCServer::RPCServer(boost::asio::io_service& io_service , NetworkOPs* nopNetwork) : mNetOps(nopNetwork), mSocket(io_service) { - mRole=GUEST; + mRole = GUEST; } Json::Value RPCServer::RPCError(int iError) @@ -175,13 +177,12 @@ std::string RPCServer::handleRequest(const std::string& requestStr) else if (!valParams.isArray()) return(HTTPReply(400, "parms unparseable")); - Json::StyledStreamWriter w; - w.write(Log(lsTRACE).ref(), valParams); - Json::Value result(doCommand(strMethod, valParams)); - w.write(Log(lsTRACE).ref(), result); + cLog(lsTRACE) << valParams; + Json::Value result = doCommand(strMethod, valParams); + cLog(lsTRACE) << result; std::string strReply = JSONRPCReply(result, Json::Value(), id); - return( HTTPReply(200, strReply) ); + return HTTPReply(200, strReply); } int RPCServer::getParamCount(const Json::Value& params) diff --git a/src/RippleCalc.cpp b/src/RippleCalc.cpp index 698b2aac56..817660d05b 100644 --- a/src/RippleCalc.cpp +++ b/src/RippleCalc.cpp @@ -8,6 +8,8 @@ #include "../json/writer.h" +SETUP_LOG(); + std::size_t hash_value(const aciSource& asValue) { std::size_t seed = 0; @@ -69,7 +71,7 @@ TER RippleCalc::calcNodeAdvance( bDirectAdvance = !sleDirectDir; bDirectDirDirty = true; - Log(lsINFO) << boost::str(boost::format("calcNodeAdvance: Initialize node: uDirectTip=%s uDirectEnd=%s bDirectAdvance=%d") % uDirectTip % uDirectEnd % bDirectAdvance); + cLog(lsINFO) << boost::str(boost::format("calcNodeAdvance: Initialize node: uDirectTip=%s uDirectEnd=%s bDirectAdvance=%d") % uDirectTip % uDirectEnd % bDirectAdvance); } if (bDirectAdvance) @@ -82,13 +84,13 @@ TER RippleCalc::calcNodeAdvance( if (!!uDirectTip) { // Have another quality directory. - Log(lsINFO) << boost::str(boost::format("calcNodeAdvance: Quality advance: uDirectTip=%s") % uDirectTip); + cLog(lsINFO) << boost::str(boost::format("calcNodeAdvance: Quality advance: uDirectTip=%s") % uDirectTip); sleDirectDir = lesActive.entryCache(ltDIR_NODE, uDirectTip); } else if (bReverse) { - Log(lsINFO) << "calcNodeAdvance: No more offers."; + cLog(lsINFO) << "calcNodeAdvance: No more offers."; uOfferIndex = 0; break; @@ -96,7 +98,7 @@ TER RippleCalc::calcNodeAdvance( else { // No more offers. Should be done rather than fall off end of book. - Log(lsINFO) << "calcNodeAdvance: Unreachable: Fell off end of order book."; + cLog(lsINFO) << "calcNodeAdvance: Unreachable: Fell off end of order book."; assert(false); terResult = tefEXCEPTION; @@ -109,7 +111,7 @@ TER RippleCalc::calcNodeAdvance( uEntry = 0; bEntryAdvance = true; - Log(lsINFO) << boost::str(boost::format("calcNodeAdvance: directory dirty: saOfrRate=%s") % saOfrRate); + cLog(lsINFO) << boost::str(boost::format("calcNodeAdvance: directory dirty: saOfrRate=%s") % saOfrRate); } if (!bEntryAdvance) @@ -122,11 +124,11 @@ TER RippleCalc::calcNodeAdvance( saOfferFunds = lesActive.accountFunds(uOfrOwnerID, saTakerGets); // Funds left. bFundsDirty = false; - Log(lsINFO) << boost::str(boost::format("calcNodeAdvance: directory dirty: saOfrRate=%s") % saOfrRate); + cLog(lsINFO) << boost::str(boost::format("calcNodeAdvance: directory dirty: saOfrRate=%s") % saOfrRate); } else { - Log(lsINFO) << boost::str(boost::format("calcNodeAdvance: as is")); + cLog(lsINFO) << boost::str(boost::format("calcNodeAdvance: as is")); nothing(); } } @@ -139,12 +141,12 @@ TER RippleCalc::calcNodeAdvance( // Do another cur directory iff bMultiQuality if (bMultiQuality) { - Log(lsINFO) << boost::str(boost::format("calcNodeAdvance: next quality")); + cLog(lsINFO) << boost::str(boost::format("calcNodeAdvance: next quality")); bDirectAdvance = true; } else if (!bReverse) { - Log(lsINFO) << boost::str(boost::format("calcNodeAdvance: unreachable: ran out of offers")); + cLog(lsINFO) << boost::str(boost::format("calcNodeAdvance: unreachable: ran out of offers")); assert(false); // Can't run out of offers in forward direction. terResult = tefEXCEPTION; } @@ -157,12 +159,12 @@ TER RippleCalc::calcNodeAdvance( const aciSource asLine = boost::make_tuple(uOfrOwnerID, uCurCurrencyID, uCurIssuerID); - Log(lsINFO) << boost::str(boost::format("calcNodeAdvance: uOfrOwnerID=%s") % NewcoinAddress::createHumanAccountID(uOfrOwnerID)); + cLog(lsINFO) << boost::str(boost::format("calcNodeAdvance: uOfrOwnerID=%s") % NewcoinAddress::createHumanAccountID(uOfrOwnerID)); if (sleOffer->isFieldPresent(sfExpiration) && sleOffer->getFieldU32(sfExpiration) <= lesActive.getLedger()->getParentCloseTimeNC()) { // Offer is expired. - Log(lsINFO) << "calcNodeAdvance: expired offer"; + cLog(lsINFO) << "calcNodeAdvance: expired offer"; assert(musUnfundedFound.find(uOfferIndex) != musUnfundedFound.end()); // Verify reverse found it too. bEntryAdvance = true; @@ -177,7 +179,7 @@ TER RippleCalc::calcNodeAdvance( if (bFoundForward && itForward->second != uIndex) { // Temporarily unfunded. Another node uses this source, ignore in this offer. - Log(lsINFO) << "calcNodeAdvance: temporarily unfunded offer (forward)"; + cLog(lsINFO) << "calcNodeAdvance: temporarily unfunded offer (forward)"; bEntryAdvance = true; continue; @@ -189,7 +191,7 @@ TER RippleCalc::calcNodeAdvance( if (bFoundPast && itPast->second != uIndex) { // Temporarily unfunded. Another node uses this source, ignore in this offer. - Log(lsINFO) << "calcNodeAdvance: temporarily unfunded offer (past)"; + cLog(lsINFO) << "calcNodeAdvance: temporarily unfunded offer (past)"; bEntryAdvance = true; continue; @@ -201,7 +203,7 @@ TER RippleCalc::calcNodeAdvance( if (bFoundReverse && itReverse->second != uIndex) { // Temporarily unfunded. Another node uses this source, ignore in this offer. - Log(lsINFO) << "calcNodeAdvance: temporarily unfunded offer (reverse)"; + cLog(lsINFO) << "calcNodeAdvance: temporarily unfunded offer (reverse)"; bEntryAdvance = true; continue; @@ -215,7 +217,7 @@ TER RippleCalc::calcNodeAdvance( if (!saOfferFunds.isPositive()) { // Offer is unfunded. - Log(lsINFO) << "calcNodeAdvance: unfunded offer"; + cLog(lsINFO) << "calcNodeAdvance: unfunded offer"; if (bReverse && !bFoundReverse && !bFoundPast) { @@ -233,7 +235,7 @@ TER RippleCalc::calcNodeAdvance( && !bFoundReverse) // Not mentioned for pass. { // Consider source mentioned by current path state. - Log(lsINFO) << boost::str(boost::format("calcNodeAdvance: remember=%s/%s/%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeAdvance: remember=%s/%s/%s") % NewcoinAddress::createHumanAccountID(uOfrOwnerID) % STAmount::createHumanCurrency(uCurCurrencyID) % NewcoinAddress::createHumanAccountID(uCurIssuerID)); @@ -249,11 +251,11 @@ TER RippleCalc::calcNodeAdvance( if (tesSUCCESS == terResult) { - Log(lsINFO) << boost::str(boost::format("calcNodeAdvance: uOfferIndex=%s") % uOfferIndex); + cLog(lsINFO) << boost::str(boost::format("calcNodeAdvance: uOfferIndex=%s") % uOfferIndex); } else { - Log(lsINFO) << boost::str(boost::format("calcNodeAdvance: terResult=%s") % transToken(terResult)); + cLog(lsINFO) << boost::str(boost::format("calcNodeAdvance: terResult=%s") % transToken(terResult)); } return terResult; @@ -308,7 +310,7 @@ TER RippleCalc::calcNodeDeliverRev( const STAmount saOutFeeRate = uOfrOwnerID == uCurIssuerID || uOutAccountID == uCurIssuerID // Issuer receiving or sending. ? saOne // No fee. : saTransferRate; // Transfer rate of issuer. - Log(lsINFO) << boost::str(boost::format("calcNodeDeliverRev: uOfrOwnerID=%s uOutAccountID=%s uCurIssuerID=%s saTransferRate=%s saOutFeeRate=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeDeliverRev: uOfrOwnerID=%s uOutAccountID=%s uCurIssuerID=%s saTransferRate=%s saOutFeeRate=%s") % NewcoinAddress::createHumanAccountID(uOfrOwnerID) % NewcoinAddress::createHumanAccountID(uOutAccountID) % NewcoinAddress::createHumanAccountID(uCurIssuerID) @@ -320,14 +322,14 @@ TER RippleCalc::calcNodeDeliverRev( // Set initial rate. saRateMax = saOutFeeRate; - Log(lsINFO) << boost::str(boost::format("calcNodeDeliverRev: Set initial rate: saRateMax=%s saOutFeeRate=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeDeliverRev: Set initial rate: saRateMax=%s saOutFeeRate=%s") % saRateMax % saOutFeeRate); } else if (saRateMax < saOutFeeRate) { // Offer exceeds initial rate. - Log(lsINFO) << boost::str(boost::format("calcNodeDeliverRev: Offer exceeds initial rate: saRateMax=%s saOutFeeRate=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeDeliverRev: Offer exceeds initial rate: saRateMax=%s saOutFeeRate=%s") % saRateMax % saOutFeeRate); @@ -340,14 +342,14 @@ TER RippleCalc::calcNodeDeliverRev( saRateMax = saOutFeeRate; - Log(lsINFO) << boost::str(boost::format("calcNodeDeliverRev: Reducing rate: saRateMax=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeDeliverRev: Reducing rate: saRateMax=%s") % saRateMax); } STAmount saOutPass = std::min(std::min(saOfferFunds, saTakerGets), saOutReq-saOutAct); // Offer maximum out - assuming no out fees. STAmount saOutPlusFees = STAmount::multiply(saOutPass, saOutFeeRate); // Offer out with fees. - Log(lsINFO) << boost::str(boost::format("calcNodeDeliverRev: saOutReq=%s saOutAct=%s saTakerGets=%s saOutPass=%s saOutPlusFees=%s saOfferFunds=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeDeliverRev: saOutReq=%s saOutAct=%s saTakerGets=%s saOutPass=%s saOutPlusFees=%s saOfferFunds=%s") % saOutReq % saOutAct % saTakerGets @@ -362,7 +364,7 @@ TER RippleCalc::calcNodeDeliverRev( saOutPlusFees = saOfferFunds; saOutPass = STAmount::divide(saOutPlusFees, saOutFeeRate); - Log(lsINFO) << boost::str(boost::format("calcNodeDeliverRev: Total exceeds fees: saOutPass=%s saOutPlusFees=%s saOfferFunds=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeDeliverRev: Total exceeds fees: saOutPass=%s saOutPlusFees=%s saOfferFunds=%s") % saOutPass % saOutPlusFees % saOfferFunds); @@ -373,7 +375,7 @@ TER RippleCalc::calcNodeDeliverRev( STAmount saInPassReq = STAmount::multiply(saOutPass, saOfrRate, saTakerPays); STAmount saInPassAct; - Log(lsINFO) << boost::str(boost::format("calcNodeDeliverRev: saInPassReq=%s saOfrRate=%s saOutPass=%s saOutPlusFees=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeDeliverRev: saInPassReq=%s saOfrRate=%s saOutPass=%s saOutPlusFees=%s") % saInPassReq % saOfrRate % saOutPass @@ -390,7 +392,7 @@ TER RippleCalc::calcNodeDeliverRev( saInPassAct = saInPassReq; - Log(lsINFO) << boost::str(boost::format("calcNodeDeliverRev: account --> OFFER --> ? : saInPassAct=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeDeliverRev: account --> OFFER --> ? : saInPassAct=%s") % saPrvDlvReq); } else @@ -405,7 +407,7 @@ TER RippleCalc::calcNodeDeliverRev( saInPassReq, saInPassAct); - Log(lsINFO) << boost::str(boost::format("calcNodeDeliverRev: offer --> OFFER --> ? : saInPassAct=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeDeliverRev: offer --> OFFER --> ? : saInPassAct=%s") % saInPassAct); } @@ -418,7 +420,7 @@ TER RippleCalc::calcNodeDeliverRev( saOutPass = STAmount::divide(saInPassAct, saOfrRate, saTakerGets); saOutPlusFees = STAmount::multiply(saOutPass, saOutFeeRate); - Log(lsINFO) << boost::str(boost::format("calcNodeDeliverRev: adjusted: saOutPass=%s saOutPlusFees=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeDeliverRev: adjusted: saOutPass=%s saOutPlusFees=%s") % saOutPass % saOutPlusFees); } @@ -438,7 +440,7 @@ TER RippleCalc::calcNodeDeliverRev( if (saOutPass == saTakerGets) { // Offer became unfunded. - Log(lsINFO) << boost::str(boost::format("calcNodeDeliverRev: offer became unfunded.")); + cLog(lsINFO) << boost::str(boost::format("calcNodeDeliverRev: offer became unfunded.")); bEntryAdvance = true; } @@ -516,7 +518,7 @@ TER RippleCalc::calcNodeDeliverFwd( STAmount saInPassFees; STAmount saOutPassAct; - Log(lsINFO) << boost::str(boost::format("calcNodeDeliverFwd: saOutFunded=%s saInFunded=%s saInTotal=%s saInSum=%s saInPassAct=%s saOutPassMax=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeDeliverFwd: saOutFunded=%s saInFunded=%s saInTotal=%s saInSum=%s saInPassAct=%s saOutPassMax=%s") % saOutFunded % saInFunded % saInTotal @@ -538,7 +540,7 @@ TER RippleCalc::calcNodeDeliverFwd( saOutPassAct = saOutPassMax; - Log(lsINFO) << boost::str(boost::format("calcNodeDeliverFwd: ? --> OFFER --> account: saOutPassAct=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeDeliverFwd: ? --> OFFER --> account: saOutPassAct=%s") % saOutPassAct); } else @@ -564,7 +566,7 @@ TER RippleCalc::calcNodeDeliverFwd( saInPassFees = STAmount::multiply(saInFunded, saInFeeRate)-saInPassAct; } - Log(lsINFO) << boost::str(boost::format("calcNodeDeliverFwd: saTakerGets=%s saTakerPays=%s saInPassAct=%s saOutPassAct=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeDeliverFwd: saTakerGets=%s saTakerPays=%s saInPassAct=%s saOutPassAct=%s") % saTakerGets.getFullText() % saTakerPays.getFullText() % saInPassAct.getFullText() @@ -696,7 +698,7 @@ void RippleCalc::calcNodeRipple( STAmount& saCurAct, // <-> out limit achieved. uint64& uRateMax) { - Log(lsINFO) << boost::str(boost::format("calcNodeRipple> uQualityIn=%d uQualityOut=%d saPrvReq=%s saCurReq=%s saPrvAct=%s saCurAct=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeRipple> uQualityIn=%d uQualityOut=%d saPrvReq=%s saCurReq=%s saPrvAct=%s saCurAct=%s") % uQualityIn % uQualityOut % saPrvReq.getFullText() @@ -711,7 +713,7 @@ void RippleCalc::calcNodeRipple( const STAmount saCur = saCurReq-saCurAct; #if 0 - Log(lsINFO) << boost::str(boost::format("calcNodeRipple: bPrvUnlimited=%d saPrv=%s saCur=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeRipple: bPrvUnlimited=%d saPrv=%s saCur=%s") % bPrvUnlimited % saPrv.getFullText() % saCur.getFullText()); @@ -720,7 +722,7 @@ void RippleCalc::calcNodeRipple( if (uQualityIn >= uQualityOut) { // No fee. - Log(lsINFO) << boost::str(boost::format("calcNodeRipple: No fees")); + cLog(lsINFO) << boost::str(boost::format("calcNodeRipple: No fees")); if (!uRateMax || STAmount::uRateOne <= uRateMax) { @@ -736,7 +738,7 @@ void RippleCalc::calcNodeRipple( else { // Fee. - Log(lsINFO) << boost::str(boost::format("calcNodeRipple: Fee")); + cLog(lsINFO) << boost::str(boost::format("calcNodeRipple: Fee")); uint64 uRate = STAmount::getRate(STAmount(uQualityIn), STAmount(uQualityOut)); @@ -748,19 +750,19 @@ void RippleCalc::calcNodeRipple( STAmount saCurIn = STAmount::divide(STAmount::multiply(saCur, uQualityOut, uCurrencyID, uCurIssuerID), uQualityIn, uCurrencyID, uCurIssuerID); - Log(lsINFO) << boost::str(boost::format("calcNodeRipple: bPrvUnlimited=%d saPrv=%s saCurIn=%s") % bPrvUnlimited % saPrv.getFullText() % saCurIn.getFullText()); + cLog(lsINFO) << boost::str(boost::format("calcNodeRipple: bPrvUnlimited=%d saPrv=%s saCurIn=%s") % bPrvUnlimited % saPrv.getFullText() % saCurIn.getFullText()); if (bPrvUnlimited || saCurIn <= saPrv) { // All of cur. Some amount of prv. saCurAct += saCur; saPrvAct += saCurIn; - Log(lsINFO) << boost::str(boost::format("calcNodeRipple:3c: saCurReq=%s saPrvAct=%s") % saCurReq.getFullText() % saPrvAct.getFullText()); + cLog(lsINFO) << boost::str(boost::format("calcNodeRipple:3c: saCurReq=%s saPrvAct=%s") % saCurReq.getFullText() % saPrvAct.getFullText()); } else { // A part of cur. All of prv. (cur as driver) STAmount saCurOut = STAmount::divide(STAmount::multiply(saPrv, uQualityIn, uCurrencyID, uCurIssuerID), uQualityOut, uCurrencyID, uCurIssuerID); - Log(lsINFO) << boost::str(boost::format("calcNodeRipple:4: saCurReq=%s") % saCurReq.getFullText()); + cLog(lsINFO) << boost::str(boost::format("calcNodeRipple:4: saCurReq=%s") % saCurReq.getFullText()); saCurAct += saCurOut; saPrvAct = saPrvReq; @@ -771,7 +773,7 @@ void RippleCalc::calcNodeRipple( } } - Log(lsINFO) << boost::str(boost::format("calcNodeRipple< uQualityIn=%d uQualityOut=%d saPrvReq=%s saCurReq=%s saPrvAct=%s saCurAct=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeRipple< uQualityIn=%d uQualityOut=%d saPrvReq=%s saCurReq=%s saPrvAct=%s saCurAct=%s") % uQualityIn % uQualityOut % saPrvReq.getFullText() @@ -819,7 +821,7 @@ TER RippleCalc::calcNodeAccountRev(const unsigned int uIndex, const PathState::p ? lesActive.rippleOwed(uCurAccountID, uNxtAccountID, uCurrencyID) : STAmount(uCurrencyID, uCurAccountID); - Log(lsINFO) << boost::str(boost::format("calcNodeAccountRev> uIndex=%d/%d uPrvAccountID=%s uCurAccountID=%s uNxtAccountID=%s uCurrencyID=%s uQualityIn=%d uQualityOut=%d saPrvOwed=%s saPrvLimit=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeAccountRev> uIndex=%d/%d uPrvAccountID=%s uCurAccountID=%s uNxtAccountID=%s uCurrencyID=%s uQualityIn=%d uQualityOut=%d saPrvOwed=%s saPrvLimit=%s") % uIndex % uLast % NewcoinAddress::createHumanAccountID(uPrvAccountID) @@ -854,13 +856,13 @@ TER RippleCalc::calcNodeAccountRev(const unsigned int uIndex, const PathState::p const STAmount& saCurDeliverReq = pnCur.saRevDeliver; STAmount saCurDeliverAct(saCurDeliverReq.getCurrency(), saCurDeliverReq.getIssuer()); - Log(lsINFO) << boost::str(boost::format("calcNodeAccountRev: saPrvRedeemReq=%s saPrvIssueReq=%s saCurRedeemReq=%s saNxtOwed=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeAccountRev: saPrvRedeemReq=%s saPrvIssueReq=%s saCurRedeemReq=%s saNxtOwed=%s") % saPrvRedeemReq.getFullText() % saPrvIssueReq.getFullText() % saCurRedeemReq.getFullText() % saNxtOwed.getFullText()); - Log(lsINFO) << pspCur->getJson(); + cLog(lsINFO) << pspCur->getJson(); assert(!saCurRedeemReq || (-saNxtOwed) >= saCurRedeemReq); // Current redeem req can't be more than IOUs on hand. assert(!saCurIssueReq // If not issuing, fine. @@ -884,14 +886,14 @@ TER RippleCalc::calcNodeAccountRev(const unsigned int uIndex, const PathState::p : pspCur->saOutReq; // Previous is an offer, no limit: redeem own IOUs. STAmount saCurWantedAct(saCurWantedReq.getCurrency(), saCurWantedReq.getIssuer()); - Log(lsINFO) << boost::str(boost::format("calcNodeAccountRev: account --> ACCOUNT --> $ : saCurWantedReq=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeAccountRev: account --> ACCOUNT --> $ : saCurWantedReq=%s") % saCurWantedReq.getFullText()); // Calculate redeem if (saPrvRedeemReq) // Previous has IOUs to redeem. { // Redeem at 1:1 - Log(lsINFO) << boost::str(boost::format("calcNodeAccountRev: Redeem at 1:1")); + cLog(lsINFO) << boost::str(boost::format("calcNodeAccountRev: Redeem at 1:1")); saCurWantedAct = std::min(saPrvRedeemReq, saCurWantedReq); saPrvRedeemAct = saCurWantedAct; @@ -904,7 +906,7 @@ TER RippleCalc::calcNodeAccountRev(const unsigned int uIndex, const PathState::p && saPrvIssueReq) // Will accept IOUs from prevous. { // Rate: quality in : 1.0 - Log(lsINFO) << boost::str(boost::format("calcNodeAccountRev: Rate: quality in : 1.0")); + cLog(lsINFO) << boost::str(boost::format("calcNodeAccountRev: Rate: quality in : 1.0")); // If we previously redeemed and this has a poorer rate, this won't be included the current increment. calcNodeRipple(uQualityIn, QUALITY_ONE, saPrvIssueReq, saCurWantedReq, saPrvIssueAct, saCurWantedAct, uRateMax); @@ -925,7 +927,7 @@ TER RippleCalc::calcNodeAccountRev(const unsigned int uIndex, const PathState::p && saPrvRedeemReq) // Previous has IOUs to redeem. { // Rate : 1.0 : quality out - Log(lsINFO) << boost::str(boost::format("calcNodeAccountRev: Rate : 1.0 : quality out")); + cLog(lsINFO) << boost::str(boost::format("calcNodeAccountRev: Rate : 1.0 : quality out")); calcNodeRipple(QUALITY_ONE, uQualityOut, saPrvRedeemReq, saCurRedeemReq, saPrvRedeemAct, saCurRedeemAct, uRateMax); } @@ -935,7 +937,7 @@ TER RippleCalc::calcNodeAccountRev(const unsigned int uIndex, const PathState::p && saPrvRedeemAct == saPrvRedeemReq) // Previous has no IOUs to redeem remaining. { // Rate: quality in : quality out - Log(lsINFO) << boost::str(boost::format("calcNodeAccountRev: Rate: quality in : quality out")); + cLog(lsINFO) << boost::str(boost::format("calcNodeAccountRev: Rate: quality in : quality out")); calcNodeRipple(uQualityIn, uQualityOut, saPrvIssueReq, saCurRedeemReq, saPrvIssueAct, saCurRedeemAct, uRateMax); } @@ -946,7 +948,7 @@ TER RippleCalc::calcNodeAccountRev(const unsigned int uIndex, const PathState::p && saPrvRedeemAct != saPrvRedeemReq) // Did not complete redeeming previous IOUs. { // Rate : 1.0 : transfer_rate - Log(lsINFO) << boost::str(boost::format("calcNodeAccountRev: Rate : 1.0 : transfer_rate")); + cLog(lsINFO) << boost::str(boost::format("calcNodeAccountRev: Rate : 1.0 : transfer_rate")); calcNodeRipple(QUALITY_ONE, lesActive.rippleTransferRate(uCurAccountID), saPrvRedeemReq, saCurIssueReq, saPrvRedeemAct, saCurIssueAct, uRateMax); } @@ -957,7 +959,7 @@ TER RippleCalc::calcNodeAccountRev(const unsigned int uIndex, const PathState::p && saPrvRedeemReq == saPrvRedeemAct) // Previously redeemed all owed IOUs. { // Rate: quality in : 1.0 - Log(lsINFO) << boost::str(boost::format("calcNodeAccountRev: Rate: quality in : 1.0")); + cLog(lsINFO) << boost::str(boost::format("calcNodeAccountRev: Rate: quality in : 1.0")); calcNodeRipple(uQualityIn, QUALITY_ONE, saPrvIssueReq, saCurIssueReq, saPrvIssueAct, saCurIssueAct, uRateMax); } @@ -968,7 +970,7 @@ TER RippleCalc::calcNodeAccountRev(const unsigned int uIndex, const PathState::p terResult = tepPATH_DRY; } - Log(lsINFO) << boost::str(boost::format("calcNodeAccountRev: ^|account --> ACCOUNT --> account : saCurRedeemReq=%s saCurIssueReq=%s saPrvOwed=%s saCurRedeemAct=%s saCurIssueAct=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeAccountRev: ^|account --> ACCOUNT --> account : saCurRedeemReq=%s saCurIssueReq=%s saPrvOwed=%s saCurRedeemAct=%s saCurIssueAct=%s") % saCurRedeemReq.getFullText() % saCurIssueReq.getFullText() % saPrvOwed.getFullText() @@ -980,7 +982,7 @@ TER RippleCalc::calcNodeAccountRev(const unsigned int uIndex, const PathState::p { // account --> ACCOUNT --> offer // Note: deliver is always issue as ACCOUNT is the issuer for the offer input. - Log(lsINFO) << boost::str(boost::format("calcNodeAccountRev: account --> ACCOUNT --> offer")); + cLog(lsINFO) << boost::str(boost::format("calcNodeAccountRev: account --> ACCOUNT --> offer")); // redeem -> deliver/issue. if (saPrvOwed.isPositive() // Previous has IOUs to redeem. @@ -1004,7 +1006,7 @@ TER RippleCalc::calcNodeAccountRev(const unsigned int uIndex, const PathState::p terResult = tepPATH_DRY; } - Log(lsINFO) << boost::str(boost::format("calcNodeAccountRev: saCurDeliverReq=%s saCurDeliverAct=%s saPrvOwed=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeAccountRev: saCurDeliverReq=%s saCurDeliverAct=%s saPrvOwed=%s") % saCurDeliverReq.getFullText() % saCurDeliverAct.getFullText() % saPrvOwed.getFullText()); @@ -1019,7 +1021,7 @@ TER RippleCalc::calcNodeAccountRev(const unsigned int uIndex, const PathState::p : pspCur->saOutReq; // Previous is an offer, no limit: redeem own IOUs. STAmount saCurWantedAct(saCurWantedReq.getCurrency(), saCurWantedReq.getIssuer()); - Log(lsINFO) << boost::str(boost::format("calcNodeAccountRev: offer --> ACCOUNT --> $ : saCurWantedReq=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeAccountRev: offer --> ACCOUNT --> $ : saCurWantedReq=%s") % saCurWantedReq.getFullText()); // Rate: quality in : 1.0 @@ -1035,7 +1037,7 @@ TER RippleCalc::calcNodeAccountRev(const unsigned int uIndex, const PathState::p { // offer --> ACCOUNT --> account // Note: offer is always delivering(redeeming) as account is issuer. - Log(lsINFO) << boost::str(boost::format("calcNodeAccountRev: offer --> ACCOUNT --> account")); + cLog(lsINFO) << boost::str(boost::format("calcNodeAccountRev: offer --> ACCOUNT --> account")); // deliver -> redeem if (saCurRedeemReq) // Next wants us to redeem. @@ -1052,7 +1054,7 @@ TER RippleCalc::calcNodeAccountRev(const unsigned int uIndex, const PathState::p calcNodeRipple(QUALITY_ONE, lesActive.rippleTransferRate(uCurAccountID), saPrvDeliverReq, saCurIssueReq, saPrvDeliverAct, saCurIssueAct, uRateMax); } - Log(lsINFO) << boost::str(boost::format("calcNodeAccountRev: saCurRedeemReq=%s saCurIssueAct=%s saCurIssueReq=%s saPrvDeliverAct=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeAccountRev: saCurRedeemReq=%s saCurIssueAct=%s saCurIssueReq=%s saPrvDeliverAct=%s") % saCurRedeemReq.getFullText() % saCurRedeemAct.getFullText() % saCurIssueReq.getFullText() @@ -1069,7 +1071,7 @@ TER RippleCalc::calcNodeAccountRev(const unsigned int uIndex, const PathState::p { // offer --> ACCOUNT --> offer // deliver/redeem -> deliver/issue. - Log(lsINFO) << boost::str(boost::format("calcNodeAccountRev: offer --> ACCOUNT --> offer")); + cLog(lsINFO) << boost::str(boost::format("calcNodeAccountRev: offer --> ACCOUNT --> offer")); // Rate : 1.0 : transfer_rate calcNodeRipple(QUALITY_ONE, lesActive.rippleTransferRate(uCurAccountID), saPrvDeliverReq, saCurDeliverReq, saPrvDeliverAct, saCurDeliverAct, uRateMax); @@ -1138,7 +1140,7 @@ TER RippleCalc::calcNodeAccountFwd( const STAmount& saCurDeliverReq = pnCur.saRevDeliver; STAmount& saCurDeliverAct = pnCur.saFwdDeliver; - Log(lsINFO) << boost::str(boost::format("calcNodeAccountFwd> uIndex=%d/%d saPrvRedeemReq=%s saPrvIssueReq=%s saPrvDeliverReq=%s saCurRedeemReq=%s saCurIssueReq=%s saCurDeliverReq=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeAccountFwd> uIndex=%d/%d saPrvRedeemReq=%s saPrvIssueReq=%s saPrvDeliverReq=%s saCurRedeemReq=%s saCurIssueReq=%s saCurDeliverReq=%s") % uIndex % uLast % saPrvRedeemReq.getFullText() @@ -1194,7 +1196,7 @@ TER RippleCalc::calcNodeAccountFwd( } saCurSendMaxAct += saCurIssueAct; - Log(lsINFO) << boost::str(boost::format("calcNodeAccountFwd: ^ --> ACCOUNT --> account : saCurSendMaxReq=%s saCurRedeemAct=%s saCurIssueReq=%s saCurIssueAct=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeAccountFwd: ^ --> ACCOUNT --> account : saCurSendMaxReq=%s saCurRedeemAct=%s saCurIssueReq=%s saCurIssueAct=%s") % saCurSendMaxReq.getFullText() % saCurRedeemAct.getFullText() % saCurIssueReq.getFullText() @@ -1203,7 +1205,7 @@ TER RippleCalc::calcNodeAccountFwd( else if (uIndex == uLast) { // account --> ACCOUNT --> $ - Log(lsINFO) << boost::str(boost::format("calcNodeAccountFwd: account --> ACCOUNT --> $ : uPrvAccountID=%s uCurAccountID=%s saPrvRedeemReq=%s saPrvIssueReq=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeAccountFwd: account --> ACCOUNT --> $ : uPrvAccountID=%s uCurAccountID=%s saPrvRedeemReq=%s saPrvIssueReq=%s") % NewcoinAddress::createHumanAccountID(uPrvAccountID) % NewcoinAddress::createHumanAccountID(uCurAccountID) % saPrvRedeemReq.getFullText() @@ -1226,7 +1228,7 @@ TER RippleCalc::calcNodeAccountFwd( else { // account --> ACCOUNT --> account - Log(lsINFO) << boost::str(boost::format("calcNodeAccountFwd: account --> ACCOUNT --> account")); + cLog(lsINFO) << boost::str(boost::format("calcNodeAccountFwd: account --> ACCOUNT --> account")); // Previous redeem part 1: redeem -> redeem if (saPrvRedeemReq != saPrvRedeemAct) // Previous wants to redeem. To next must be ok. @@ -1269,7 +1271,7 @@ TER RippleCalc::calcNodeAccountFwd( else if (bPrvAccount && !bNxtAccount) { // account --> ACCOUNT --> offer - Log(lsINFO) << boost::str(boost::format("calcNodeAccountFwd: account --> ACCOUNT --> offer")); + cLog(lsINFO) << boost::str(boost::format("calcNodeAccountFwd: account --> ACCOUNT --> offer")); // redeem -> issue. // wants to redeem and current would and can issue. @@ -1297,7 +1299,7 @@ TER RippleCalc::calcNodeAccountFwd( if (uIndex == uLast) { // offer --> ACCOUNT --> $ - Log(lsINFO) << boost::str(boost::format("calcNodeAccountFwd: offer --> ACCOUNT --> $")); + cLog(lsINFO) << boost::str(boost::format("calcNodeAccountFwd: offer --> ACCOUNT --> $")); STAmount& saCurReceive = pspCur->saOutAct; @@ -1309,7 +1311,7 @@ TER RippleCalc::calcNodeAccountFwd( else { // offer --> ACCOUNT --> account - Log(lsINFO) << boost::str(boost::format("calcNodeAccountFwd: offer --> ACCOUNT --> account")); + cLog(lsINFO) << boost::str(boost::format("calcNodeAccountFwd: offer --> ACCOUNT --> account")); // deliver -> redeem if (saPrvDeliverReq) // Previous wants to deliver. @@ -1335,7 +1337,7 @@ TER RippleCalc::calcNodeAccountFwd( { // offer --> ACCOUNT --> offer // deliver/redeem -> deliver/issue. - Log(lsINFO) << boost::str(boost::format("calcNodeAccountFwd: offer --> ACCOUNT --> offer")); + cLog(lsINFO) << boost::str(boost::format("calcNodeAccountFwd: offer --> ACCOUNT --> offer")); if (saPrvDeliverReq // Previous wants to deliver && saCurIssueReq) // Current wants issue. @@ -1379,7 +1381,7 @@ TER PathState::pushImply( const PaymentNode& pnPrv = vpnNodes.back(); TER terResult = tesSUCCESS; - Log(lsINFO) << "pushImply> " + cLog(lsINFO) << "pushImply> " << NewcoinAddress::createHumanAccountID(uAccountID) << " " << STAmount::createHumanCurrency(uCurrencyID) << " " << NewcoinAddress::createHumanAccountID(uIssuerID); @@ -1412,7 +1414,7 @@ TER PathState::pushImply( uIssuerID); } - Log(lsINFO) << "pushImply< " << terResult; + cLog(lsINFO) << "pushImply< " << terResult; return terResult; } @@ -1425,7 +1427,7 @@ TER PathState::pushNode( const uint160& uCurrencyID, const uint160& uIssuerID) { - Log(lsINFO) << "pushNode> " + cLog(lsINFO) << "pushNode> " << NewcoinAddress::createHumanAccountID(uAccountID) << " " << STAmount::createHumanCurrency(uCurrencyID) << "/" << NewcoinAddress::createHumanAccountID(uIssuerID); @@ -1445,7 +1447,7 @@ TER PathState::pushNode( if (iType & ~STPathElement::typeValidBits) { - Log(lsINFO) << "pushNode: bad bits."; + cLog(lsINFO) << "pushNode: bad bits."; terResult = temBAD_PATH; } @@ -1479,7 +1481,7 @@ TER PathState::pushNode( if (!sleRippleState) { - Log(lsINFO) << "pushNode: No credit line between " + cLog(lsINFO) << "pushNode: No credit line between " << NewcoinAddress::createHumanAccountID(pnBck.uAccountID) << " and " << NewcoinAddress::createHumanAccountID(pnCur.uAccountID) @@ -1487,13 +1489,13 @@ TER PathState::pushNode( << STAmount::createHumanCurrency(pnPrv.uCurrencyID) << "." ; - Log(lsINFO) << getJson(); + cLog(lsINFO) << getJson(); terResult = terNO_LINE; } else { - Log(lsINFO) << "pushNode: Credit line found between " + cLog(lsINFO) << "pushNode: Credit line found between " << NewcoinAddress::createHumanAccountID(pnBck.uAccountID) << " and " << NewcoinAddress::createHumanAccountID(pnCur.uAccountID) @@ -1533,7 +1535,7 @@ TER PathState::pushNode( vpnNodes.push_back(pnCur); } } - Log(lsINFO) << "pushNode< " << terResult; + cLog(lsINFO) << "pushNode< " << terResult; return terResult; } @@ -1610,7 +1612,7 @@ PathState::PathState( else if (!umForward.insert(std::make_pair(boost::make_tuple(pnCur.uAccountID, pnCur.uCurrencyID, pnCur.uIssuerID), uIndex)).second) { // Failed to insert. Have a loop. - Log(lsINFO) << boost::str(boost::format("PathState: loop detected: %s") + cLog(lsINFO) << boost::str(boost::format("PathState: loop detected: %s") % getJson()); terStatus = temBAD_PATH_LOOP; @@ -1618,7 +1620,7 @@ PathState::PathState( } } - Log(lsINFO) << boost::str(boost::format("PathState: in=%s/%s out=%s/%s %s") + cLog(lsINFO) << boost::str(boost::format("PathState: in=%s/%s out=%s/%s %s") % STAmount::createHumanCurrency(uInCurrencyID) % NewcoinAddress::createHumanAccountID(uInIssuerID) % STAmount::createHumanCurrency(uOutCurrencyID) @@ -1699,7 +1701,7 @@ TER RippleCalc::calcNodeFwd(const unsigned int uIndex, const PathState::pointer& const PaymentNode& pnCur = pspCur->vpnNodes[uIndex]; const bool bCurAccount = isSetBit(pnCur.uFlags, STPathElement::typeAccount); - Log(lsINFO) << boost::str(boost::format("calcNodeFwd> uIndex=%d") % uIndex); + cLog(lsINFO) << boost::str(boost::format("calcNodeFwd> uIndex=%d") % uIndex); TER terResult = bCurAccount ? calcNodeAccountFwd(uIndex, pspCur, bMultiQuality) @@ -1710,7 +1712,7 @@ TER RippleCalc::calcNodeFwd(const unsigned int uIndex, const PathState::pointer& terResult = calcNodeFwd(uIndex+1, pspCur, bMultiQuality); } - Log(lsINFO) << boost::str(boost::format("calcNodeFwd< uIndex=%d terResult=%d") % uIndex % terResult); + cLog(lsINFO) << boost::str(boost::format("calcNodeFwd< uIndex=%d terResult=%d") % uIndex % terResult); return terResult; } @@ -1736,7 +1738,7 @@ TER RippleCalc::calcNodeRev(const unsigned int uIndex, const PathState::pointer& saTransferRate = STAmount::saFromRate(lesActive.rippleTransferRate(uCurIssuerID)); - Log(lsINFO) << boost::str(boost::format("calcNodeRev> uIndex=%d uIssuerID=%s saTransferRate=%s") + cLog(lsINFO) << boost::str(boost::format("calcNodeRev> uIndex=%d uIssuerID=%s saTransferRate=%s") % uIndex % NewcoinAddress::createHumanAccountID(uCurIssuerID) % saTransferRate.getFullText()); @@ -1758,7 +1760,7 @@ TER RippleCalc::calcNodeRev(const unsigned int uIndex, const PathState::pointer& terResult = calcNodeRev(uIndex-1, pspCur, bMultiQuality); } - Log(lsINFO) << boost::str(boost::format("calcNodeRev< uIndex=%d terResult=%s/%d") % uIndex % transToken(terResult) % terResult); + cLog(lsINFO) << boost::str(boost::format("calcNodeRev< uIndex=%d terResult=%s/%d") % uIndex % transToken(terResult) % terResult); return terResult; } @@ -1773,7 +1775,7 @@ void RippleCalc::pathNext(const PathState::pointer& pspCur, const int iPaths, co const bool bMultiQuality = iPaths == 1; const unsigned int uLast = pspCur->vpnNodes.size() - 1; - Log(lsINFO) << "Path In: " << pspCur->getJson(); + cLog(lsINFO) << "Path In: " << pspCur->getJson(); assert(pspCur->vpnNodes.size() >= 2); @@ -1785,7 +1787,7 @@ void RippleCalc::pathNext(const PathState::pointer& pspCur, const int iPaths, co pspCur->terStatus = calcNodeRev(uLast, pspCur, bMultiQuality); - Log(lsINFO) << "Path after reverse: " << pspCur->getJson(); + cLog(lsINFO) << "Path after reverse: " << pspCur->getJson(); if (tesSUCCESS == pspCur->terStatus) { @@ -1799,7 +1801,7 @@ void RippleCalc::pathNext(const PathState::pointer& pspCur, const int iPaths, co ? STAmount::getRate(pspCur->saOutAct, pspCur->saInAct) // Calculate relative quality. : 0; // Mark path as inactive. - Log(lsINFO) << "Path after forward: " << pspCur->getJson(); + cLog(lsINFO) << "Path after forward: " << pspCur->getJson(); } } @@ -1826,7 +1828,7 @@ TER RippleCalc::rippleCalc( if (bNoRippleDirect && spsPaths.isEmpty()) { - Log(lsINFO) << "doPayment: Invalid transaction: No paths and direct ripple not allowed."; + cLog(lsINFO) << "doPayment: Invalid transaction: No paths and direct ripple not allowed."; return temRIPPLE_EMPTY; } @@ -1838,7 +1840,7 @@ TER RippleCalc::rippleCalc( { // Direct path. // XXX Might also make a stamp bridge by default. - Log(lsINFO) << "doPayment: Build direct:"; + cLog(lsINFO) << "doPayment: Build direct:"; PathState::pointer pspDirect = PathState::createPathState( vpsPaths.size(), @@ -1865,11 +1867,11 @@ TER RippleCalc::rippleCalc( } } - Log(lsINFO) << "doPayment: Paths in set: " << spsPaths.getPathCount(); + cLog(lsINFO) << "doPayment: Paths in set: " << spsPaths.getPathCount(); BOOST_FOREACH(const STPath& spPath, spsPaths) { - Log(lsINFO) << "doPayment: Build path:"; + cLog(lsINFO) << "doPayment: Build path:"; PathState::pointer pspExpanded = PathState::createPathState( vpsPaths.size(), @@ -2101,7 +2103,7 @@ void TransactionEngine::calcOfferBridgeNext( if (sleOffer->isFieldPresent(sfExpiration) && sleOffer->getFieldU32(sfExpiration) <= mLedger->getParentCloseTimeNC()) { // Offer is expired. - Log(lsINFO) << "calcOfferFirst: encountered expired offer"; + cLog(lsINFO) << "calcOfferFirst: encountered expired offer"; } else { @@ -2135,7 +2137,7 @@ void TransactionEngine::calcOfferBridgeNext( if (!saOfferFunds.isPositive()) { // Offer is unfunded. - Log(lsINFO) << "calcOfferFirst: offer unfunded: delete"; + cLog(lsINFO) << "calcOfferFirst: offer unfunded: delete"; } else if (saOfferFunds >= saOfferPays) { diff --git a/src/RippleLines.cpp b/src/RippleLines.cpp index e9a8ad25fa..46b88d75fa 100644 --- a/src/RippleLines.cpp +++ b/src/RippleLines.cpp @@ -1,7 +1,11 @@ #include "RippleLines.h" + +#include + #include "Application.h" #include "Log.h" -#include + +SETUP_LOG(); RippleLines::RippleLines(const uint160& accountID, Ledger::pointer ledger) { @@ -47,7 +51,7 @@ void RippleLines::fillLines(const uint160& accountID, Ledger::pointer ledger) } else { - Log(lsWARNING) << "doRippleLinesGet: Bad index: " << uNode.ToString(); + cLog(lsWARNING) << "doRippleLinesGet: Bad index: " << uNode.ToString(); } } } diff --git a/src/SHAMap.cpp b/src/SHAMap.cpp index 652326f177..5dd31f5651 100644 --- a/src/SHAMap.cpp +++ b/src/SHAMap.cpp @@ -15,6 +15,8 @@ #include "SHAMap.h" #include "Application.h" +SETUP_LOG(); + std::size_t hash_value(const SHAMapNode& mn) { std::size_t seed = theApp->getNonceST(); @@ -662,7 +664,7 @@ bool SHAMap::updateGiveItem(const SHAMapItem::pointer& item, bool isTransaction, if (!node->setItem(item, !isTransaction ? SHAMapTreeNode::tnACCOUNT_STATE : (hasMeta ? SHAMapTreeNode::tnTRANSACTION_MD : SHAMapTreeNode::tnTRANSACTION_NM))) { - Log(lsWARNING) << "SHAMap setItem, no change"; + cLog(lsWARNING) << "SHAMap setItem, no change"; return true; } @@ -695,7 +697,7 @@ SHAMapTreeNode::pointer SHAMap::fetchNodeExternal(const SHAMapNode& id, const ui } catch (...) { - Log(lsWARNING) << "fetchNodeExternal gets an invalid node: " << hash; + cLog(lsWARNING) << "fetchNodeExternal gets an invalid node: " << hash; throw SHAMapMissingNode(id, hash); } } @@ -792,7 +794,7 @@ BOOST_AUTO_TEST_SUITE(SHAMap_suite) BOOST_AUTO_TEST_CASE( SHAMap_test ) { // h3 and h4 differ only in the leaf, same terminal node (level 19) - Log(lsTRACE) << "SHAMap test"; + cLog(lsTRACE) << "SHAMap test"; uint256 h1, h2, h3, h4, h5; h1.SetHex("092891fe4ef6cee585fdc6fda0e09eb4d386363158ec3321b8123e5a772c6ca7"); h2.SetHex("436ccbac3347baa1f1e53baeef1f43334da88f1f6d70d963b833afd6dfa289fe"); @@ -828,7 +830,7 @@ BOOST_AUTO_TEST_CASE( SHAMap_test ) i = sMap.peekNextItem(i->getTag()); if (i) BOOST_FAIL("bad traverse"); - Log(lsTRACE) << "SHAMap snap test"; + cLog(lsTRACE) << "SHAMap snap test"; uint256 mapHash = sMap.getHash(); SHAMap::pointer map2 = sMap.snapShot(false); if (sMap.getHash() != mapHash) BOOST_FAIL("bad snapshot"); diff --git a/src/SHAMap.h b/src/SHAMap.h index e7f5046d5c..c239bad307 100644 --- a/src/SHAMap.h +++ b/src/SHAMap.h @@ -23,10 +23,6 @@ class SHAMap; class SHAMapNode { // Identifies a node in a SHA256 hash -public: - typedef boost::shared_ptr pointer; - typedef const boost::shared_ptr& ref; - private: static uint256 smMasks[65]; // AND with hash to get node id @@ -84,7 +80,8 @@ inline std::ostream& operator<<(std::ostream& out, const SHAMapNode& node) { ret class SHAMapItem { // an item stored in a SHAMap public: - typedef boost::shared_ptr pointer; + typedef boost::shared_ptr pointer; + typedef const boost::shared_ptr& ref; private: uint256 mTag; @@ -136,7 +133,8 @@ class SHAMapTreeNode : public SHAMapNode friend class SHAMap; public: - typedef boost::shared_ptr pointer; + typedef boost::shared_ptr pointer; + typedef const boost::shared_ptr& ref; enum TNType { @@ -163,7 +161,7 @@ private: public: SHAMapTreeNode(uint32 seq, const SHAMapNode& nodeID); // empty node SHAMapTreeNode(const SHAMapTreeNode& node, uint32 seq); // copy node from older tree - SHAMapTreeNode(const SHAMapNode& nodeID, const SHAMapItem::pointer& item, TNType type, uint32 seq); + SHAMapTreeNode(const SHAMapNode& nodeID, SHAMapItem::ref item, TNType type, uint32 seq); // raw node functions SHAMapTreeNode(const SHAMapNode& id, const std::vector& data, uint32 seq, SHANodeFormat format); @@ -200,7 +198,7 @@ public: // item node function bool hasItem() const { return !!mItem; } - SHAMapItem::pointer peekItem() { return mItem; } + SHAMapItem::ref peekItem() { return mItem; } SHAMapItem::pointer getItem() const; bool setItem(const SHAMapItem::pointer& i, TNType type); const uint256& getTag() const { return mItem->getTag(); } @@ -292,7 +290,7 @@ protected: SHAMapItem::pointer onlyBelow(SHAMapTreeNode*); void eraseChildren(SHAMapTreeNode::pointer); - bool walkBranch(SHAMapTreeNode* node, SHAMapItem::pointer otherMapItem, bool isFirstMap, + bool walkBranch(SHAMapTreeNode* node, SHAMapItem::ref otherMapItem, bool isFirstMap, SHAMapDiff& differences, int& maxCount); public: @@ -321,8 +319,8 @@ public: uint256 getHash() { return root->getNodeHash(); } // save a copy if you have a temporary anyway - bool updateGiveItem(const SHAMapItem::pointer&, bool isTransaction, bool hasMeta); - bool addGiveItem(const SHAMapItem::pointer&, bool isTransaction, bool hasMeta); + bool updateGiveItem(SHAMapItem::ref, bool isTransaction, bool hasMeta); + bool addGiveItem(SHAMapItem::ref, bool isTransaction, bool hasMeta); // save a copy if you only need a temporary SHAMapItem::pointer peekItem(const uint256& id); diff --git a/src/SHAMapDiff.cpp b/src/SHAMapDiff.cpp index 3f5adb3e0d..fa1ae6a642 100644 --- a/src/SHAMapDiff.cpp +++ b/src/SHAMapDiff.cpp @@ -20,13 +20,15 @@ class SHAMapDiffNode mNodeID(id), mOurHash(ourHash), mOtherHash(otherHash) { ; } }; -bool SHAMap::walkBranch(SHAMapTreeNode* node, SHAMapItem::pointer otherMapItem, bool isFirstMap, +bool SHAMap::walkBranch(SHAMapTreeNode* node, SHAMapItem::ref otherMapItem, bool isFirstMap, SHAMapDiff& differences, int& maxCount) { // Walk a branch of a SHAMap that's matched by an empty branch or single item in the other map std::stack nodeStack; nodeStack.push(node); - + + bool emptyBranch = !otherMapItem; + while (!nodeStack.empty()) { SHAMapTreeNode* node = nodeStack.top(); @@ -41,7 +43,7 @@ bool SHAMap::walkBranch(SHAMapTreeNode* node, SHAMapItem::pointer otherMapItem, { // This is a leaf node, process its item SHAMapItem::pointer item = node->getItem(); - if (otherMapItem && (otherMapItem->getTag() < item->getTag())) + if (!emptyBranch && (otherMapItem->getTag() < item->getTag())) { // this item comes after the item from the other map, so add the other item if (isFirstMap) // this is first map, so other item is from second differences.insert(std::make_pair(otherMapItem->getTag(), @@ -49,11 +51,12 @@ bool SHAMap::walkBranch(SHAMapTreeNode* node, SHAMapItem::pointer otherMapItem, else differences.insert(std::make_pair(otherMapItem->getTag(), std::make_pair(otherMapItem, SHAMapItem::pointer()))); - if (--maxCount <= 0) return false; - otherMapItem = SHAMapItem::pointer(); + if (--maxCount <= 0) + return false; + emptyBranch = true; } - if ((!otherMapItem) || (item->getTag() < otherMapItem->getTag())) + if (emptyBranch || (item->getTag() < otherMapItem->getTag())) { // unmatched if (isFirstMap) differences.insert(std::make_pair(item->getTag(), std::make_pair(item, SHAMapItem::pointer()))); @@ -77,7 +80,7 @@ bool SHAMap::walkBranch(SHAMapTreeNode* node, SHAMapItem::pointer otherMapItem, } } - if (otherMapItem) + if (!emptyBranch) { // otherMapItem was unmatched, must add if (isFirstMap) // this is first map, so other item is from second differences.insert(std::make_pair(otherMapItem->getTag(), diff --git a/src/SHAMapSync.cpp b/src/SHAMapSync.cpp index 5ae0af44c5..fef3cf04ad 100644 --- a/src/SHAMapSync.cpp +++ b/src/SHAMapSync.cpp @@ -11,6 +11,8 @@ #include "Log.h" +SETUP_LOG(); + void SHAMap::getMissingNodes(std::vector& nodeIDs, std::vector& hashes, int max, SHAMapSyncFilter* filter) { @@ -26,7 +28,7 @@ void SHAMap::getMissingNodes(std::vector& nodeIDs, std::vectorisInner()) { - Log(lsWARNING) << "synching empty tree"; + cLog(lsWARNING) << "synching empty tree"; return; } @@ -61,12 +63,12 @@ void SHAMap::getMissingNodes(std::vector& nodeIDs, std::vector(childID, nodeData, mSeq, snfPREFIX); if (childHash != d->getNodeHash()) { - Log(lsERROR) << "Wrong hash from cached object"; + cLog(lsERROR) << "Wrong hash from cached object"; d = SHAMapTreeNode::pointer(); } else { - Log(lsTRACE) << "Got sync node from cache: " << *d; + cLog(lsTRACE) << "Got sync node from cache: " << *d; mTNByID[*d] = d; } } @@ -136,7 +138,7 @@ bool SHAMap::addRootNode(const std::vector& rootNode, SHANodeForm // we already have a root node if (root->getNodeHash().isNonZero()) { - Log(lsTRACE) << "got root node, already have one"; + cLog(lsTRACE) << "got root node, already have one"; return true; } @@ -168,7 +170,7 @@ bool SHAMap::addRootNode(const uint256& hash, const std::vector& // we already have a root node if (root->getNodeHash().isNonZero()) { - Log(lsTRACE) << "got root node, already have one"; + cLog(lsTRACE) << "got root node, already have one"; assert(root->getNodeHash() == hash); return true; } @@ -216,15 +218,15 @@ bool SHAMap::addKnownNode(const SHAMapNode& node, const std::vectorisLeaf() || (iNode->getDepth() == node.getDepth())) { - Log(lsTRACE) << "got inner node, already had it (late)"; + cLog(lsTRACE) << "got inner node, already had it (late)"; return true; } if (iNode->getDepth() != (node.getDepth() - 1)) { // Either this node is broken or we didn't request it (yet) - Log(lsINFO) << "unable to hook node " << node; - Log(lsINFO) << " stuck at " << *iNode; - Log(lsINFO) << "got depth=" << node.getDepth() << ", walked to= " << iNode->getDepth(); + cLog(lsINFO) << "unable to hook node " << node; + cLog(lsINFO) << " stuck at " << *iNode; + cLog(lsINFO) << "got depth=" << node.getDepth() << ", walked to= " << iNode->getDepth(); return false; } @@ -295,16 +297,16 @@ bool SHAMap::deepCompare(SHAMap& other) if (!otherNode) { - Log(lsINFO) << "unable to fetch node"; + cLog(lsINFO) << "unable to fetch node"; return false; } else if (otherNode->getNodeHash() != node->getNodeHash()) { - Log(lsWARNING) << "node hash mismatch"; + cLog(lsWARNING) << "node hash mismatch"; return false; } -// Log(lsTRACE) << "Comparing inner nodes " << *node; +// cLog(lsTRACE) << "Comparing inner nodes " << *node; if (node->getNodeHash() != otherNode->getNodeHash()) return false; @@ -329,7 +331,7 @@ bool SHAMap::deepCompare(SHAMap& other) SHAMapTreeNode::pointer next = getNode(node->getChildNodeID(i), node->getChildHash(i), false); if (!next) { - Log(lsWARNING) << "unable to fetch inner node"; + cLog(lsWARNING) << "unable to fetch inner node"; return false; } stack.push(next); @@ -365,7 +367,7 @@ static bool confuseMap(SHAMap &map, int count) items.push_back(item->getTag()); if (!map.addItem(*item, false, false)) { - Log(lsFATAL) << "Unable to add item to map"; + cLog(lsFATAL) << "Unable to add item to map"; return false; } } @@ -374,14 +376,14 @@ static bool confuseMap(SHAMap &map, int count) { if (!map.delItem(*it)) { - Log(lsFATAL) << "Unable to remove item from map"; + cLog(lsFATAL) << "Unable to remove item from map"; return false; } } if (beforeHash != map.getHash()) { - Log(lsFATAL) << "Hashes do not match"; + cLog(lsFATAL) << "Hashes do not match"; return false; } @@ -412,26 +414,26 @@ BOOST_AUTO_TEST_SUITE( SHAMapSync ) BOOST_AUTO_TEST_CASE( SHAMapSync_test ) { - Log(lsTRACE) << "being sync test"; + cLog(lsTRACE) << "being sync test"; unsigned int seed; RAND_pseudo_bytes(reinterpret_cast(&seed), sizeof(seed)); srand(seed); - Log(lsTRACE) << "Constructing maps"; + cLog(lsTRACE) << "Constructing maps"; SHAMap source, destination; // add random data to the source map - Log(lsTRACE) << "Adding random data"; + cLog(lsTRACE) << "Adding random data"; int items = 10000; for (int i = 0; i < items; ++i) source.addItem(*makeRandomAS(), false, false); - Log(lsTRACE) << "Adding items, then removing them"; + cLog(lsTRACE) << "Adding items, then removing them"; if (!confuseMap(source, 500)) BOOST_FAIL("ConfuseMap"); source.setImmutable(); - Log(lsTRACE) << "SOURCE COMPLETE, SYNCHING"; + cLog(lsTRACE) << "SOURCE COMPLETE, SYNCHING"; std::vector nodeIDs, gotNodeIDs; std::list< std::vector > gotNodes; @@ -447,23 +449,23 @@ BOOST_AUTO_TEST_CASE( SHAMapSync_test ) if (!source.getNodeFat(SHAMapNode(), nodeIDs, gotNodes, (rand() % 2) == 0, (rand() % 2) == 0)) { - Log(lsFATAL) << "GetNodeFat(root) fails"; + cLog(lsFATAL) << "GetNodeFat(root) fails"; BOOST_FAIL("GetNodeFat"); } if (gotNodes.size() < 1) { - Log(lsFATAL) << "Didn't get root node " << gotNodes.size(); + cLog(lsFATAL) << "Didn't get root node " << gotNodes.size(); BOOST_FAIL("NodeSize"); } if (!destination.addRootNode(*gotNodes.begin(), snfWIRE)) { - Log(lsFATAL) << "AddRootNode fails"; + cLog(lsFATAL) << "AddRootNode fails"; BOOST_FAIL("AddRootNode"); } nodeIDs.clear(); gotNodes.clear(); - Log(lsINFO) << "ROOT COMPLETE, INNER SYNCHING"; + cLog(lsINFO) << "ROOT COMPLETE, INNER SYNCHING"; #ifdef SMS_DEBUG int bytes = 0; #endif @@ -477,14 +479,14 @@ BOOST_AUTO_TEST_CASE( SHAMapSync_test ) destination.getMissingNodes(nodeIDs, hashes, 2048, NULL); if (nodeIDs.empty()) break; - Log(lsINFO) << nodeIDs.size() << " needed nodes"; + cLog(lsINFO) << nodeIDs.size() << " needed nodes"; // get as many nodes as possible based on this information for (nodeIDIterator = nodeIDs.begin(); nodeIDIterator != nodeIDs.end(); ++nodeIDIterator) { if (!source.getNodeFat(*nodeIDIterator, gotNodeIDs, gotNodes, (rand() % 2) == 0, (rand() % 2) == 0)) { - Log(lsFATAL) << "GetNodeFat fails"; + cLog(lsFATAL) << "GetNodeFat fails"; BOOST_FAIL("GetNodeFat"); } } @@ -494,11 +496,11 @@ BOOST_AUTO_TEST_CASE( SHAMapSync_test ) if (gotNodeIDs.empty()) { - Log(lsFATAL) << "No nodes gotten"; + cLog(lsFATAL) << "No nodes gotten"; BOOST_FAIL("Got Node ID"); } - Log(lsTRACE) << gotNodeIDs.size() << " found nodes"; + cLog(lsTRACE) << gotNodeIDs.size() << " found nodes"; for (nodeIDIterator = gotNodeIDs.begin(), rawNodeIterator = gotNodes.begin(); nodeIDIterator != gotNodeIDs.end(); ++nodeIDIterator, ++rawNodeIterator) { @@ -508,7 +510,7 @@ BOOST_AUTO_TEST_CASE( SHAMapSync_test ) #endif if (!destination.addKnownNode(*nodeIDIterator, *rawNodeIterator, NULL)) { - Log(lsTRACE) << "AddKnownNode fails"; + cLog(lsTRACE) << "AddKnownNode fails"; BOOST_FAIL("AddKnownNode"); } } @@ -520,18 +522,18 @@ BOOST_AUTO_TEST_CASE( SHAMapSync_test ) destination.clearSynching(); #ifdef SMS_DEBUG - Log(lsINFO) << "SYNCHING COMPLETE " << items << " items, " << nodes << " nodes, " << + cLog(lsINFO) << "SYNCHING COMPLETE " << items << " items, " << nodes << " nodes, " << bytes / 1024 << " KB"; #endif if (!source.deepCompare(destination)) { - Log(lsFATAL) << "DeepCompare fails"; + cLog(lsFATAL) << "DeepCompare fails"; BOOST_FAIL("Deep Compare"); } #ifdef SMS_DEBUG - Log(lsINFO) << "SHAMapSync test passed: " << items << " items, " << + cLog(lsINFO) << "SHAMapSync test passed: " << items << " items, " << passes << " passes, " << nodes << " nodes"; #endif diff --git a/src/TransactionEngine.cpp b/src/TransactionEngine.cpp index 2994034c89..38dbeb5610 100644 --- a/src/TransactionEngine.cpp +++ b/src/TransactionEngine.cpp @@ -13,6 +13,8 @@ #include "TransactionFormats.h" #include "utils.h" +SETUP_LOG(); + void TransactionEngine::txnWrite() { // Write back the account states @@ -32,7 +34,7 @@ void TransactionEngine::txnWrite() case taaCREATE: { - Log(lsINFO) << "applyTransaction: taaCREATE: " << sleEntry->getText(); + cLog(lsINFO) << "applyTransaction: taaCREATE: " << sleEntry->getText(); if (mLedger->writeBack(lepCREATE, sleEntry) & lepERROR) assert(false); @@ -41,7 +43,7 @@ void TransactionEngine::txnWrite() case taaMODIFY: { - Log(lsINFO) << "applyTransaction: taaMODIFY: " << sleEntry->getText(); + cLog(lsINFO) << "applyTransaction: taaMODIFY: " << sleEntry->getText(); if (mLedger->writeBack(lepNONE, sleEntry) & lepERROR) assert(false); @@ -50,7 +52,7 @@ void TransactionEngine::txnWrite() case taaDELETE: { - Log(lsINFO) << "applyTransaction: taaDELETE: " << sleEntry->getText(); + cLog(lsINFO) << "applyTransaction: taaDELETE: " << sleEntry->getText(); if (!mLedger->peekAccountStateMap()->delItem(it->first)) assert(false); @@ -62,7 +64,7 @@ void TransactionEngine::txnWrite() TER TransactionEngine::applyTransaction(const SerializedTransaction& txn, TransactionEngineParams params) { - Log(lsTRACE) << "applyTransaction>"; + cLog(lsTRACE) << "applyTransaction>"; assert(mLedger); mNodes.init(mLedger, txn.getTransactionID(), mLedger->getLedgerSeq()); @@ -75,10 +77,10 @@ TER TransactionEngine::applyTransaction(const SerializedTransaction& txn, Transa SerializedTransaction s2(sit); if (!s2.isEquivalent(txn)) { - Log(lsFATAL) << "Transaction serdes mismatch"; + cLog(lsFATAL) << "Transaction serdes mismatch"; Json::StyledStreamWriter ssw; - ssw.write(Log(lsINFO).ref(), txn.getJson(0)); - ssw.write(Log(lsFATAL).ref(), s2.getJson(0)); + cLog(lsINFO) << txn.getJson(0); + cLog(lsFATAL) << s2.getJson(0); assert(false); } } @@ -88,7 +90,7 @@ TER TransactionEngine::applyTransaction(const SerializedTransaction& txn, Transa uint256 txID = txn.getTransactionID(); if (!txID) { - Log(lsWARNING) << "applyTransaction: invalid transaction id"; + cLog(lsWARNING) << "applyTransaction: invalid transaction id"; terResult = temINVALID; } @@ -110,7 +112,7 @@ TER TransactionEngine::applyTransaction(const SerializedTransaction& txn, Transa // Consistency: really signed. if ((tesSUCCESS == terResult) && !isSetBit(params, tapNO_CHECK_SIGN) && !txn.checkSign(naSigningPubKey)) { - Log(lsWARNING) << "applyTransaction: Invalid transaction: bad signature"; + cLog(lsWARNING) << "applyTransaction: Invalid transaction: bad signature"; terResult = temINVALID; } @@ -153,12 +155,12 @@ TER TransactionEngine::applyTransaction(const SerializedTransaction& txn, Transa break; case ttINVALID: - Log(lsWARNING) << "applyTransaction: Invalid transaction: ttINVALID transaction type"; + cLog(lsWARNING) << "applyTransaction: Invalid transaction: ttINVALID transaction type"; terResult = temINVALID; break; default: - Log(lsWARNING) << "applyTransaction: Invalid transaction: unknown transaction type"; + cLog(lsWARNING) << "applyTransaction: Invalid transaction: unknown transaction type"; terResult = temUNKNOWN; break; } @@ -173,7 +175,7 @@ TER TransactionEngine::applyTransaction(const SerializedTransaction& txn, Transa // Only check fee is sufficient when the ledger is open. if (isSetBit(params, tapOPEN_LEDGER) && saPaid < saCost) { - Log(lsINFO) << "applyTransaction: insufficient fee"; + cLog(lsINFO) << "applyTransaction: insufficient fee"; terResult = telINSUF_FEE_P; } @@ -183,7 +185,7 @@ TER TransactionEngine::applyTransaction(const SerializedTransaction& txn, Transa if (saPaid) { // Transaction is malformed. - Log(lsWARNING) << "applyTransaction: fee not allowed"; + cLog(lsWARNING) << "applyTransaction: fee not allowed"; terResult = temINSUF_FEE_P; } @@ -194,7 +196,7 @@ TER TransactionEngine::applyTransaction(const SerializedTransaction& txn, Transa mTxnAccountID = txn.getSourceAccount().getAccountID(); if (tesSUCCESS == terResult && !mTxnAccountID) { - Log(lsWARNING) << "applyTransaction: bad source id"; + cLog(lsWARNING) << "applyTransaction: bad source id"; terResult = temINVALID; } @@ -215,7 +217,7 @@ TER TransactionEngine::applyTransaction(const SerializedTransaction& txn, Transa if (!mTxnAccount) { - Log(lsTRACE) << boost::str(boost::format("applyTransaction: Delay transaction: source account does not exist: %s") % + cLog(lsTRACE) << boost::str(boost::format("applyTransaction: Delay transaction: source account does not exist: %s") % txn.getSourceAccount().humanAccountID()); terResult = terNO_ACCOUNT; @@ -234,7 +236,7 @@ TER TransactionEngine::applyTransaction(const SerializedTransaction& txn, Transa case ttCLAIM: if (bHaveAuthKey) { - Log(lsWARNING) << "applyTransaction: Account already claimed."; + cLog(lsWARNING) << "applyTransaction: Account already claimed."; terResult = tefCLAIMED; } @@ -257,8 +259,8 @@ TER TransactionEngine::applyTransaction(const SerializedTransaction& txn, Transa if (naSigningPubKey.getAccountID() != mTxnAccountID) { // Signing Pub Key must be for Source Account ID. - Log(lsWARNING) << "sourceAccountID: " << naSigningPubKey.humanAccountID(); - Log(lsWARNING) << "txn accountID: " << txn.getSourceAccount().humanAccountID(); + cLog(lsWARNING) << "sourceAccountID: " << naSigningPubKey.humanAccountID(); + cLog(lsWARNING) << "txn accountID: " << txn.getSourceAccount().humanAccountID(); terResult = tefBAD_CLAIM_ID; } @@ -270,8 +272,8 @@ TER TransactionEngine::applyTransaction(const SerializedTransaction& txn, Transa if (naSigningPubKey.getAccountID() != mTxnAccountID) { // Signing Pub Key must be for Source Account ID. - Log(lsWARNING) << "sourceAccountID: " << naSigningPubKey.humanAccountID(); - Log(lsWARNING) << "txn accountID: " << txn.getSourceAccount().humanAccountID(); + cLog(lsWARNING) << "sourceAccountID: " << naSigningPubKey.humanAccountID(); + cLog(lsWARNING) << "txn accountID: " << txn.getSourceAccount().humanAccountID(); terResult = temBAD_SET_ID; } @@ -291,13 +293,13 @@ TER TransactionEngine::applyTransaction(const SerializedTransaction& txn, Transa } else if (bHaveAuthKey) { - Log(lsINFO) << "applyTransaction: Delay: Not authorized to use account."; + cLog(lsINFO) << "applyTransaction: Delay: Not authorized to use account."; terResult = tefBAD_AUTH; } else { - Log(lsINFO) << "applyTransaction: Invalid: Not authorized to use account."; + cLog(lsINFO) << "applyTransaction: Invalid: Not authorized to use account."; terResult = temBAD_AUTH_MASTER; } @@ -313,7 +315,7 @@ TER TransactionEngine::applyTransaction(const SerializedTransaction& txn, Transa } else if (saSrcBalance < saPaid) { - Log(lsINFO) + cLog(lsINFO) << boost::str(boost::format("applyTransaction: Delay: insufficient balance: balance=%s paid=%s") % saSrcBalance.getText() % saPaid.getText()); @@ -334,13 +336,13 @@ TER TransactionEngine::applyTransaction(const SerializedTransaction& txn, Transa { uint32 a_seq = mTxnAccount->getFieldU32(sfSequence); - Log(lsTRACE) << "Aseq=" << a_seq << ", Tseq=" << t_seq; + cLog(lsTRACE) << "Aseq=" << a_seq << ", Tseq=" << t_seq; if (t_seq != a_seq) { if (a_seq < t_seq) { - Log(lsINFO) << "applyTransaction: future sequence number"; + cLog(lsINFO) << "applyTransaction: future sequence number"; terResult = terPRE_SEQ; } @@ -348,7 +350,7 @@ TER TransactionEngine::applyTransaction(const SerializedTransaction& txn, Transa terResult = tefALREADY; else { - Log(lsWARNING) << "applyTransaction: past sequence number"; + cLog(lsWARNING) << "applyTransaction: past sequence number"; terResult = tefPAST_SEQ; } @@ -360,11 +362,11 @@ TER TransactionEngine::applyTransaction(const SerializedTransaction& txn, Transa } else { - Log(lsINFO) << "applyTransaction: Zero cost transaction"; + cLog(lsINFO) << "applyTransaction: Zero cost transaction"; if (t_seq) { - Log(lsINFO) << "applyTransaction: bad sequence for pre-paid transaction"; + cLog(lsINFO) << "applyTransaction: bad sequence for pre-paid transaction"; terResult = tefPAST_SEQ; } @@ -389,7 +391,7 @@ TER TransactionEngine::applyTransaction(const SerializedTransaction& txn, Transa break; case ttINVALID: - Log(lsINFO) << "applyTransaction: invalid type"; + cLog(lsINFO) << "applyTransaction: invalid type"; terResult = temINVALID; break; @@ -443,7 +445,7 @@ TER TransactionEngine::applyTransaction(const SerializedTransaction& txn, Transa transResultInfo(terResult, strToken, strHuman); - Log(lsINFO) << "applyTransaction: terResult=" << strToken << " : " << terResult << " : " << strHuman; + cLog(lsINFO) << "applyTransaction: terResult=" << strToken << " : " << terResult << " : " << strHuman; if (isTepPartial(terResult) && isSetBit(params, tapRETRY)) { diff --git a/src/UniqueNodeList.cpp b/src/UniqueNodeList.cpp index 96ca1b7d7d..d51baaa30f 100644 --- a/src/UniqueNodeList.cpp +++ b/src/UniqueNodeList.cpp @@ -42,6 +42,8 @@ #define MIN(x,y) ((x)<(y)?(x):(y)) #endif +SETUP_LOG(); + UniqueNodeList::UniqueNodeList(boost::asio::io_service& io_service) : mdtScoreTimer(io_service), mFetchActive(0), @@ -612,7 +614,7 @@ void UniqueNodeList::processIps(const std::string& strSite, const NewcoinAddress std::string strEscNodePublic = sqlEscape(naNodePublic.humanNodePublic()); - Log(lsINFO) + cLog(lsDEBUG) << str(boost::format("Validator: '%s' processing %d ips.") % strSite % ( pmtVecStrIps ? pmtVecStrIps->size() : 0)); @@ -716,7 +718,7 @@ int UniqueNodeList::processValidators(const std::string& strSite, const std::str if (!boost::regex_match(strReferral, smMatch, reReferral)) { - Log(lsWARNING) << str(boost::format("Bad validator: syntax error: %s: %s") % strSite % strReferral); + cLog(lsWARNING) << str(boost::format("Bad validator: syntax error: %s: %s") % strSite % strReferral); } else { @@ -727,7 +729,7 @@ int UniqueNodeList::processValidators(const std::string& strSite, const std::str if (naValidator.setSeedGeneric(strRefered)) { - Log(lsWARNING) << str(boost::format("Bad validator: domain or public key required: %s %s") % strRefered % strComment); + cLog(lsWARNING) << str(boost::format("Bad validator: domain or public key required: %s %s") % strRefered % strComment); } else if (naValidator.setNodePublic(strRefered)) { @@ -735,7 +737,7 @@ int UniqueNodeList::processValidators(const std::string& strSite, const std::str // XXX Schedule for CAS lookup. nodeAddPublic(naValidator, vsWhy, strComment); - Log(lsINFO) << str(boost::format("Node Public: %s %s") % strRefered % strComment); + cLog(lsINFO) << str(boost::format("Node Public: %s %s") % strRefered % strComment); if (naNodePublic.isValid()) vstrValues.push_back(str(boost::format("('%s',%d,'%s')") % strNodePublic % iValues % naValidator.humanNodePublic())); @@ -747,7 +749,7 @@ int UniqueNodeList::processValidators(const std::string& strSite, const std::str // A domain: need to look it up. nodeAddDomain(strRefered, vsWhy, strComment); - Log(lsINFO) << str(boost::format("Node Domain: %s %s") % strRefered % strComment); + cLog(lsINFO) << str(boost::format("Node Domain: %s %s") % strRefered % strComment); if (naNodePublic.isValid()) vstrValues.push_back(str(boost::format("('%s',%d,%s)") % strNodePublic % iValues % sqlEscape(strRefered))); @@ -1577,7 +1579,7 @@ void UniqueNodeList::nodeBootstrap() // Always merge in the file specified in the config. if (!theConfig.UNL_DEFAULT.empty()) { - Log(lsINFO) << "Bootstrapping UNL: loading from unl_default."; + cLog(lsINFO) << "Bootstrapping UNL: loading from unl_default."; bLoaded = nodeLoad(theConfig.UNL_DEFAULT); } @@ -1585,7 +1587,7 @@ void UniqueNodeList::nodeBootstrap() // If never loaded anything try the current directory. if (!bLoaded && theConfig.UNL_DEFAULT.empty()) { - Log(lsINFO) << "Bootstrapping UNL: loading from '" VALIDATORS_FILE_NAME "'."; + cLog(lsINFO) << "Bootstrapping UNL: loading from '" VALIDATORS_FILE_NAME "'."; bLoaded = nodeLoad(VALIDATORS_FILE_NAME); } @@ -1595,7 +1597,7 @@ void UniqueNodeList::nodeBootstrap() { NewcoinAddress naInvalid; // Don't want a referrer on added entries. - Log(lsINFO) << "Bootstrapping UNL: loading from " CONFIG_FILE_NAME "."; + cLog(lsINFO) << "Bootstrapping UNL: loading from " CONFIG_FILE_NAME "."; if (processValidators("local", CONFIG_FILE_NAME, naInvalid, vsConfig, &theConfig.VALIDATORS)) bLoaded = true; @@ -1603,7 +1605,7 @@ void UniqueNodeList::nodeBootstrap() if (!bLoaded) { - Log(lsINFO) << "Bootstrapping UNL: loading from " << theConfig.VALIDATORS_SITE << "."; + cLog(lsINFO) << "Bootstrapping UNL: loading from " << theConfig.VALIDATORS_SITE << "."; nodeNetwork(); } diff --git a/src/ValidationCollection.cpp b/src/ValidationCollection.cpp index 0e356c7151..5f5fc17a5f 100644 --- a/src/ValidationCollection.cpp +++ b/src/ValidationCollection.cpp @@ -7,7 +7,7 @@ #include "LedgerTiming.h" #include "Log.h" -// #define VC_DEBUG +SETUP_LOG(); bool ValidationCollection::addValidation(const SerializedValidation::pointer& val) { @@ -21,9 +21,14 @@ bool ValidationCollection::addValidation(const SerializedValidation::pointer& va if ((now > (valClose - LEDGER_EARLY_INTERVAL)) && (now < (valClose + LEDGER_VAL_INTERVAL))) isCurrent = true; else - Log(lsWARNING) << "Received stale validation now=" << now << ", close=" << valClose; + { + cLog(lsWARNING) << "Received stale validation now=" << now << ", close=" << valClose; + } + } + else + { + cLog(lsINFO) << "Node " << signer.humanNodePublic() << " not in UNL"; } - else Log(lsINFO) << "Node " << signer.humanNodePublic() << " not in UNL"; uint256 hash = val->getLedgerHash(); uint160 node = signer.getNodeID(); @@ -49,7 +54,7 @@ bool ValidationCollection::addValidation(const SerializedValidation::pointer& va } } - Log(lsINFO) << "Val for " << hash << " from " << signer.humanNodePublic() + cLog(lsINFO) << "Val for " << hash << " from " << signer.humanNodePublic() << " added " << (val->isTrusted() ? "trusted/" : "UNtrusted/") << (isCurrent ? "current" : "stale"); return isCurrent; } @@ -84,9 +89,7 @@ void ValidationCollection::getValidationCount(const uint256& ledger, bool curren isTrusted = false; else { -#ifdef VC_DEBUG - Log(lsINFO) << "VC: Untrusted due to time " << ledger; -#endif + cLog(lsTRACE) << "VC: Untrusted due to time " << ledger; } } if (isTrusted) @@ -95,9 +98,7 @@ void ValidationCollection::getValidationCount(const uint256& ledger, bool curren ++untrusted; } } -#ifdef VC_DEBUG - Log(lsINFO) << "VC: " << ledger << "t:" << trusted << " u:" << untrusted; -#endif + cLog(lsTRACE) << "VC: " << ledger << "t:" << trusted << " u:" << untrusted; } int ValidationCollection::getTrustedValidationCount(const uint256& ledger)