Use simple logging system to timestamp/filter log messages.

This commit is contained in:
JoelKatz
2012-05-31 17:00:15 -07:00
parent 7d0b17ba88
commit f8219061b6
2 changed files with 48 additions and 68 deletions

View File

@@ -7,6 +7,7 @@
#include "NetworkOPs.h"
#include "LedgerTiming.h"
#include "SerializedValidation.h"
#include "Log.h"
TransactionAcquire::TransactionAcquire(const uint256& hash) : PeerSet(hash, 1), mHaveRoot(false)
{
@@ -151,8 +152,8 @@ int LCTransaction::getAgreeLevel()
LedgerConsensus::LedgerConsensus(Ledger::pointer previousLedger, uint32 closeTime)
: mState(lcsPRE_CLOSE), mCloseTime(closeTime), mPreviousLedger(previousLedger)
{
std::cerr << "Creating consensus object" << std::endl;
std::cerr << "LCL:" << previousLedger->getHash().GetHex() <<", ct=" << closeTime << std::endl;
Log(lsDEBUG) << "Creating consensus object";
Log(lsTRACE) << "LCL:" << previousLedger->getHash().GetHex() <<", ct=" << closeTime;
}
void LedgerConsensus::takeInitialPosition(Ledger::pointer initialLedger)
@@ -251,7 +252,7 @@ void LedgerConsensus::statusChange(newcoin::NodeEvent event, Ledger::pointer led
void LedgerConsensus::abort()
{
std::cerr << "consensus aborted" << std::endl;
Log(lsWARNING) << "consensus aborted";
mState = lcsABORTED;
}
@@ -274,7 +275,7 @@ int LedgerConsensus::statePostClose(int secondsSinceClose)
{ // we are in the transaction wobble time
if (secondsSinceClose > LEDGER_WOBBLE_TIME)
{
std::cerr << "Wobble is over, it's consensus time" << std::endl;
Log(lsINFO) << "Wobble is over, it's consensus time";
mState = lcsESTABLISH;
}
return 1;
@@ -285,7 +286,7 @@ int LedgerConsensus::stateEstablish(int secondsSinceClose)
updateOurPositions(secondsSinceClose);
if (secondsSinceClose > LEDGER_CONVERGE)
{
std::cerr << "Converge cutoff" << std::endl;
Log(lsINFO) << "Converge cutoff";
mState = lcsCUTOFF;
}
return 1;
@@ -296,7 +297,7 @@ int LedgerConsensus::stateCutoff(int secondsSinceClose)
bool haveConsensus = updateOurPositions(secondsSinceClose);
if (haveConsensus || (secondsSinceClose > LEDGER_FORCE_CONVERGE))
{
std::cerr << "Consensus complete (" << haveConsensus << ")" << std::endl;
Log(lsINFO) << "Consensus complete (" << haveConsensus << ")";
mState = lcsFINISHED;
beginAccept();
}
@@ -369,7 +370,7 @@ bool LedgerConsensus::updateOurPositions(int sinceClose)
if (changes)
{
std::cerr << "We change our position" << std::endl;
Log(lsINFO) << "We change our position";
uint256 newHash = ourPosition->getHash();
mOurPosition->changePosition(newHash);
propose(addedTx, removedTx);
@@ -402,7 +403,7 @@ SHAMap::pointer LedgerConsensus::getTransactionTree(const uint256& hash, bool do
void LedgerConsensus::closeLedger()
{
std::cerr << "Closing ledger" << std::endl;
Log(lsINFO) << "Closing ledger";
Ledger::pointer initial = theApp->getMasterLedger().getCurrentLedger();
statusChange(newcoin::neCLOSING_LEDGER, initial);
takeInitialPosition(initial);
@@ -435,7 +436,7 @@ void LedgerConsensus::startAcquiring(TransactionAcquire::pointer acquire)
void LedgerConsensus::propose(const std::vector<uint256>& added, const std::vector<uint256>& removed)
{
std::cerr << "We propose: " << mOurPosition->getCurrentHash().GetHex() << std::endl;
Log(lsDEBUG) << "We propose: " << mOurPosition->getCurrentHash().GetHex();
newcoin::TMProposeSet prop;
prop.set_currenttxhash(mOurPosition->getCurrentHash().begin(), 256 / 8);
prop.set_prevclosedhash(mOurPosition->getPrevLedger().begin(), 256 / 8);
@@ -479,9 +480,7 @@ bool LedgerConsensus::peerPosition(LedgerProposal::pointer newPosition)
{
if (newPosition->getPrevLedger() != mPreviousLedger->getHash())
{
#ifdef DEBUG
std::cerr << "Peer sends proposal with wrong previous ledger" << std::endl;
#endif
Log(lsWARNING) << "Peer sends proposal with wrong previous ledger";
return false;
}
LedgerProposal::pointer& currentPosition = mPeerPositions[newPosition->getPeerID()];
@@ -496,7 +495,7 @@ bool LedgerConsensus::peerPosition(LedgerProposal::pointer newPosition)
return true;
}
}
std::cerr << "Peer changes position" << std::endl;
Log(lsINFO) << "Peer changes position";
currentPosition = newPosition;
SHAMap::pointer set = getTransactionTree(newPosition->getCurrentHash(), true);
if (set)
@@ -542,7 +541,7 @@ void LedgerConsensus::beginAccept()
SHAMap::pointer consensusSet = mComplete[mOurPosition->getCurrentHash()];
if (!consensusSet)
{
std::cerr << "We don't have our own set" << std::endl;
Log(lsFATAL) << "We don't have our own set";
assert(false);
abort();
return;
@@ -565,7 +564,7 @@ void LedgerConsensus::applyTransactions(SHAMap::pointer set, Ledger::pointer led
SHAMapItem::pointer item = set->peekFirstItem();
while (item)
{
std::cerr << "Processing candidate transaction: " << item->getTag().GetHex() << std::endl;
Log(lsINFO) << "Processing candidate transaction: " << item->getTag().GetHex();
try
{
SerializerIterator sit(item->peekSerializer());
@@ -573,24 +572,24 @@ void LedgerConsensus::applyTransactions(SHAMap::pointer set, Ledger::pointer led
TransactionEngineResult result = engine.applyTransaction(*txn, tepNO_CHECK_FEE);
if (result > 0)
{
std::cerr << " retry" << std::endl;
Log(lsINFO) << " retry";
assert(!ledger->hasTransaction(item->getTag()));
failedTransactions.push_back(txn);
}
else if (result == 0)
{
std::cerr << " success" << std::endl;
Log(lsDEBUG) << " success";
assert(ledger->hasTransaction(item->getTag()));
}
else
{
std::cerr << " hard fail" << std::endl;
Log(lsINFO) << " hard fail";
assert(!ledger->hasTransaction(item->getTag()));
}
}
catch (...)
{
std::cerr << " Throws" << std::endl;
Log(lsWARNING) << " Throws";
}
item = set->peekNextItem(item->getTag());
}
@@ -617,7 +616,7 @@ void LedgerConsensus::applyTransactions(SHAMap::pointer set, Ledger::pointer led
}
catch (...)
{
std::cerr << " Throws" << std::endl;
Log(lsWARNING) << " Throws";
failedTransactions.erase(it++);
}
}
@@ -626,7 +625,7 @@ void LedgerConsensus::applyTransactions(SHAMap::pointer set, Ledger::pointer led
void LedgerConsensus::accept(SHAMap::pointer set)
{
std::cerr << "Computing new LCL based on network consensus" << std::endl;
Log(lsINFO) << "Computing new LCL based on network consensus";
Ledger::pointer newLCL = boost::make_shared<Ledger>(mPreviousLedger);
std::deque<SerializedTransaction::pointer> failedTransactions;
@@ -651,7 +650,7 @@ void LedgerConsensus::accept(SHAMap::pointer set)
newcoin::TMValidation val;
val.set_validation(&validation[0], validation.size());
theApp->getConnectionPool().relayMessage(NULL, boost::make_shared<PackedMessage>(val, newcoin::mtVALIDATION));
std::cerr << "Validation sent" << std::endl;
Log(lsINFO) << "Validation sent";
}
void LedgerConsensus::endConsensus()

View File

@@ -9,6 +9,7 @@
#include "Transaction.h"
#include "LedgerConsensus.h"
#include "LedgerTiming.h"
#include "Log.h"
// This is the primary interface into the "client" portion of the program.
// Code that wants to do normal operations on the network such as
@@ -50,9 +51,7 @@ Transaction::pointer NetworkOPs::processTransaction(Transaction::pointer trans,
if (!trans->checkSign())
{
#ifdef DEBUG
std::cerr << "Transaction has bad signature" << std::endl;
#endif
Log(lsINFO) << "Transaction has bad signature";
trans->setStatus(INVALID);
return trans;
}
@@ -62,9 +61,7 @@ Transaction::pointer NetworkOPs::processTransaction(Transaction::pointer trans,
if (r == terPRE_SEQ)
{ // transaction should be held
#ifdef DEBUG
std::cerr << "Transaction should be held" << std::endl;
#endif
Log(lsDEBUG) << "Transaction should be held";
trans->setStatus(HELD);
theApp->getMasterTransaction().canonicalize(trans, true);
mLedgerMaster->addHeldTransaction(trans);
@@ -72,18 +69,14 @@ Transaction::pointer NetworkOPs::processTransaction(Transaction::pointer trans,
}
if ((r == terPAST_SEQ) || (r == terPAST_LEDGER))
{ // duplicate or conflict
#ifdef DEBUG
std::cerr << "Transaction is obsolete" << std::endl;
#endif
Log(lsINFO) << "Transaction is obsolete";
trans->setStatus(OBSOLETE);
return trans;
}
if (r == terSUCCESS)
{
#ifdef DEBUG
std::cerr << "Transaction is now included, synching to wallet" << std::endl;
#endif
Log(lsINFO) << "Transaction is now included";
trans->setStatus(INCLUDED);
theApp->getMasterTransaction().canonicalize(trans, true);
@@ -106,9 +99,7 @@ Transaction::pointer NetworkOPs::processTransaction(Transaction::pointer trans,
return trans;
}
#ifdef DEBUG
std::cerr << "Status other than success " << r << std::endl;
#endif
Log(lsDEBUG) << "Status other than success " << r ;
trans->setStatus(INVALID);
return trans;
@@ -182,19 +173,19 @@ bool NetworkOPs::getDirInfo(
if (sleRoot)
{
std::cerr << "getDirInfo: root index: " << uRootIndex.ToString() << std::endl;
Log(lsDEBUG) << "getDirInfo: root index: " << uRootIndex.ToString() ;
std::cerr << "getDirInfo: first: " << strHex(sleRoot->getIFieldU64(sfFirstNode)) << std::endl;
std::cerr << "getDirInfo: last: " << strHex(sleRoot->getIFieldU64(sfLastNode)) << std::endl;
Log(lsTRACE) << "getDirInfo: first: " << strHex(sleRoot->getIFieldU64(sfFirstNode)) ;
Log(lsTRACE) << "getDirInfo: last: " << strHex(sleRoot->getIFieldU64(sfLastNode)) ;
uDirLineNodeFirst = Ledger::getDirIndex(uBase, letKind, sleRoot->getIFieldU64(sfFirstNode));
uDirLineNodeLast = Ledger::getDirIndex(uBase, letKind, sleRoot->getIFieldU64(sfLastNode));
std::cerr << "getDirInfo: first: " << uDirLineNodeFirst.ToString() << std::endl;
std::cerr << "getDirInfo: last: " << uDirLineNodeLast.ToString() << std::endl;
Log(lsTRACE) << "getDirInfo: first: " << uDirLineNodeFirst.ToString() ;
Log(lsTRACE) << "getDirInfo: last: " << uDirLineNodeLast.ToString() ;
}
else
{
std::cerr << "getDirInfo: root index: NOT FOUND: " << uRootIndex.ToString() << std::endl;
Log(lsINFO) << "getDirInfo: root index: NOT FOUND: " << uRootIndex.ToString() ;
}
return !!sleRoot;
@@ -209,13 +200,13 @@ STVector256 NetworkOPs::getDirNode(const uint256& uLedger, const uint256& uDirLi
if (sleNode)
{
std::cerr << "getDirNode: node index: " << uDirLineNode.ToString() << std::endl;
Log(lsWARNING) << "getDirNode: node index: " << uDirLineNode.ToString() ;
svIndexes = sleNode->getIFieldV256(sfIndexes);
}
else
{
std::cerr << "getDirNode: node index: NOT FOUND: " << uDirLineNode.ToString() << std::endl;
Log(lsINFO) << "getDirNode: node index: NOT FOUND: " << uDirLineNode.ToString() ;
}
return svIndexes;
@@ -281,8 +272,8 @@ void NetworkOPs::checkState(const boost::system::error_code& result)
if (mMode != omDISCONNECTED)
{
mMode = omDISCONNECTED;
std::cerr << "Node count (" << peerList.size() <<
") has fallen below quorum (" << theConfig.NETWORK_QUORUM << ")." << std::endl;
Log(lsWARNING) << "Node count (" << peerList.size() <<
") has fallen below quorum (" << theConfig.NETWORK_QUORUM << ").";
}
setStateTimer(5);
return;
@@ -290,7 +281,7 @@ void NetworkOPs::checkState(const boost::system::error_code& result)
if (mMode == omDISCONNECTED)
{
mMode = omCONNECTED;
std::cerr << "Node count (" << peerList.size() << ") is sufficient." << std::endl;
Log(lsINFO) << "Node count (" << peerList.size() << ") is sufficient.";
}
// Do we have sufficient validations for our last closed ledger? Or do sufficient nodes
@@ -302,7 +293,7 @@ void NetworkOPs::checkState(const boost::system::error_code& result)
{
if (!*it)
{
std::cerr << "NOP::CS Dead pointer in peer list" << std::endl;
Log(lsDEBUG) << "NOP::CS Dead pointer in peer list";
}
else
{
@@ -347,23 +338,19 @@ void NetworkOPs::checkState(const boost::system::error_code& result)
if (switchLedgers)
{
std::cerr << "We are not running on the consensus ledger" << std::endl;
#ifdef DEBUG
std::cerr << "Our LCL " << currentClosed->getHash().GetHex() << std::endl;
std::cerr << "Net LCL " << closedLedger.GetHex() << std::endl;
#endif
Log(lsWARNING) << "We are not running on the consensus ledger";
Log(lsINFO) << "Our LCL " << currentClosed->getHash().GetHex() ;
Log(lsINFO) << "Net LCL " << closedLedger.GetHex() ;
if ((mMode == omTRACKING) || (mMode == omFULL)) mMode = omTRACKING;
Ledger::pointer consensus = mLedgerMaster->getLedgerByHash(closedLedger);
if (!consensus)
{
#ifdef DEBUG
std::cerr << "Acquiring consensus ledger" << std::endl;
#endif
Log(lsINFO) << "Acquiring consensus ledger";
LedgerAcquire::pointer acq = theApp->getMasterLedgerAcquire().findCreate(closedLedger);
if (!acq || acq->isFailed())
{
theApp->getMasterLedgerAcquire().dropLedger(closedLedger);
std::cerr << "Network ledger cannot be acquired" << std::endl;
Log(lsERROR) << "Network ledger cannot be acquired";
setStateTimer(10);
return;
}
@@ -410,10 +397,8 @@ void NetworkOPs::checkState(const boost::system::error_code& result)
void NetworkOPs::switchLastClosedLedger(Ledger::pointer newLedger)
{ // set the newledger as our last closed ledger -- this is abnormal code
#ifdef DEBUG
assert(false);
std::cerr << "ABNORMAL Switching last closed ledger to " << newLedger->getHash().GetHex() << std::endl;
#endif
Log(lsERROR) << "ABNORMAL Switching last closed ledger to " << newLedger->getHash().GetHex() ;
if (mConsensus)
{
@@ -434,9 +419,7 @@ void NetworkOPs::switchLastClosedLedger(Ledger::pointer newLedger)
int NetworkOPs::beginConsensus(Ledger::pointer closingLedger)
{
#ifdef DEBUG
std::cerr << "Ledger close time for ledger " << closingLedger->getLedgerSeq() << std::endl;
#endif
Log(lsINFO) << "Ledger close time for ledger " << closingLedger->getLedgerSeq() ;
Ledger::pointer prevLedger = mLedgerMaster->getLedgerByHash(closingLedger->getParentHash());
if (!prevLedger)
{ // this shouldn't happen if we jump ledgers
@@ -449,9 +432,7 @@ int NetworkOPs::beginConsensus(Ledger::pointer closingLedger)
mConsensus = boost::make_shared<LedgerConsensus>
(prevLedger, theApp->getMasterLedger().getCurrentLedger()->getCloseTimeNC());
#ifdef DEBUG
std::cerr << "Broadcasting ledger close" << std::endl;
#endif
Log(lsDEBUG) << "Broadcasting ledger close";
return mConsensus->startup();
}
@@ -465,7 +446,7 @@ bool NetworkOPs::recvPropose(const uint256& prevLgr, uint32 proposeSeq, const ui
boost::make_shared<LedgerProposal>(prevLgr, proposeSeq, proposeHash, pubKey);
if (!proposal->checkSign(signature))
{
std::cerr << "Ledger proposal fails signature check" << std::endl;
Log(lsWARNING) << "Ledger proposal fails signature check";
return false;
}