From 19efa3bf9b34d05466bf2d1053a8dd8ecd32ee51 Mon Sep 17 00:00:00 2001 From: JoelKatz Date: Fri, 19 Oct 2012 11:51:44 -0700 Subject: [PATCH 01/11] Make sure we properly handle receiving our own proposals and validations. --- src/LedgerConsensus.cpp | 5 ++++- src/LedgerConsensus.h | 4 +++- src/NetworkOPs.cpp | 6 ++++++ src/Peer.cpp | 10 ++++------ src/SerializedValidation.cpp | 5 +++-- src/SerializedValidation.h | 3 ++- 6 files changed, 22 insertions(+), 11 deletions(-) diff --git a/src/LedgerConsensus.cpp b/src/LedgerConsensus.cpp index f241934ed..09b91aee7 100644 --- a/src/LedgerConsensus.cpp +++ b/src/LedgerConsensus.cpp @@ -239,6 +239,7 @@ LedgerConsensus::LedgerConsensus(const uint256& prevLCLHash, Ledger::ref previou cLog(lsINFO) << "Entering consensus process, validating"; mValidating = true; mProposing = theApp->getOPs().getOperatingMode() == NetworkOPs::omFULL; + mValPublic = NewcoinAddress::createNodePublic(mValSeed); } else { @@ -1139,9 +1140,11 @@ void LedgerConsensus::accept(SHAMap::ref set) statusChange(ripple::neACCEPTED_LEDGER, *newLCL); if (mValidating) { + uint256 signingHash; SerializedValidation::pointer v = boost::make_shared - (newLCLHash, theApp->getOPs().getValidationTimeNC(), mValSeed, mProposing); + (newLCLHash, theApp->getOPs().getValidationTimeNC(), mValSeed, mProposing, boost::ref(signingHash)); v->setTrusted(); + theApp->isNew(signingHash); // suppress it if we receive it theApp->getValidations().addValidation(v); std::vector validation = v->getSigned(); ripple::TMValidation val; diff --git a/src/LedgerConsensus.h b/src/LedgerConsensus.h index a88aee079..4ab27866b 100644 --- a/src/LedgerConsensus.h +++ b/src/LedgerConsensus.h @@ -87,7 +87,7 @@ protected: Ledger::pointer mPreviousLedger; LedgerAcquire::pointer mAcquiringLedger; LedgerProposal::pointer mOurPosition; - NewcoinAddress mValSeed; + NewcoinAddress mValSeed, mValPublic; bool mProposing, mValidating, mHaveCorrectLCL; int mCurrentMSeconds, mClosePercent, mCloseResolution; @@ -183,6 +183,8 @@ public: bool peerGaveNodes(Peer::ref peer, const uint256& setHash, const std::list& nodeIDs, const std::list< std::vector >& nodeData); + bool isOurPubKey(const NewcoinAddress &k) { return k == mValPublic; } + // test/debug void simulate(); }; diff --git a/src/NetworkOPs.cpp b/src/NetworkOPs.cpp index c5059ee6a..bdf97d4d9 100644 --- a/src/NetworkOPs.cpp +++ b/src/NetworkOPs.cpp @@ -712,6 +712,12 @@ bool NetworkOPs::recvPropose(uint32 proposeSeq, const uint256& proposeHash, cons return mMode != omFULL; } + if (mConsensus->isOurPubKey(naPeerPublic)) + { + cLog(lsTRACE) << "Received our own validation"; + return false; + } + // Is this node on our UNL? if (!theApp->getUNL().nodeInUNL(naPeerPublic)) { diff --git a/src/Peer.cpp b/src/Peer.cpp index 99558dd84..506aad80a 100644 --- a/src/Peer.cpp +++ b/src/Peer.cpp @@ -758,11 +758,9 @@ void Peer::recvValidation(ripple::TMValidation& packet) return; } -// The four #ifndef/#endif's are commented out temporarily to avoid -// an update hassle. They can be removed once all nodes are running this code -//#ifndef TRUST_NETWORK +#ifndef TRUST_NETWORK try -//#endif +#endif { Serializer s(packet.validation()); SerializerIterator sit(s); @@ -788,13 +786,13 @@ void Peer::recvValidation(ripple::TMValidation& packet) theApp->getConnectionPool().relayMessage(this, message); } } -//#ifndef TRUST_NETWORK +#ifndef TRUST_NETWORK catch (...) { cLog(lsWARNING) << "Exception processing validation"; punishPeer(PP_UNKNOWN_REQUEST); } -//#endif +#endif } void Peer::recvGetValidation(ripple::TMGetValidations& packet) diff --git a/src/SerializedValidation.cpp b/src/SerializedValidation.cpp index f95866a51..85f4048d0 100644 --- a/src/SerializedValidation.cpp +++ b/src/SerializedValidation.cpp @@ -37,7 +37,7 @@ SerializedValidation::SerializedValidation(SerializerIterator& sit, bool checkSi } SerializedValidation::SerializedValidation(const uint256& ledgerHash, uint32 signTime, - const NewcoinAddress& naSeed, bool isFull) + const NewcoinAddress& naSeed, bool isFull, uint256& signingHash) : STObject(sValidationFormat, sfValidation), mTrusted(false) { setFieldH256(sfLedgerHash, ledgerHash); @@ -52,8 +52,9 @@ SerializedValidation::SerializedValidation(const uint256& ledgerHash, uint32 sig if (!isFull) setFlag(sFullFlag); + signingHash = getSigningHash(); std::vector signature; - NewcoinAddress::createNodePrivate(naSeed).signNodePrivate(getSigningHash(), signature); + NewcoinAddress::createNodePrivate(naSeed).signNodePrivate(signingHash, signature); setFieldVL(sfSignature, signature); // XXX Check if this can fail. // if (!NewcoinAddress::createNodePrivate(naSeed).signNodePrivate(getSigningHash(), mSignature.peekValue())) diff --git a/src/SerializedValidation.h b/src/SerializedValidation.h index 9ce8fb6a2..139850edf 100644 --- a/src/SerializedValidation.h +++ b/src/SerializedValidation.h @@ -21,7 +21,8 @@ public: // These throw if the object is not valid SerializedValidation(SerializerIterator& sit, bool checkSignature = true); - SerializedValidation(const uint256& ledgerHash, uint32 signTime, const NewcoinAddress& naSeed, bool isFull); + SerializedValidation(const uint256& ledgerHash, uint32 signTime, const NewcoinAddress& naSeed, bool isFull, + uint256& signingHash); uint256 getLedgerHash() const; uint32 getSignTime() const; From ec0376533f6bd3b79e75a81b1f21db648703edf7 Mon Sep 17 00:00:00 2001 From: JoelKatz Date: Fri, 19 Oct 2012 12:28:12 -0700 Subject: [PATCH 02/11] Change "logseverity" command to "log_level". --- src/RPCServer.cpp | 7 ++----- src/RPCServer.h | 2 +- 2 files changed, 3 insertions(+), 6 deletions(-) diff --git a/src/RPCServer.cpp b/src/RPCServer.cpp index 046a8946d..35c74bbdc 100644 --- a/src/RPCServer.cpp +++ b/src/RPCServer.cpp @@ -2647,7 +2647,7 @@ Json::Value RPCServer::doLogin(const Json::Value& params) } } -Json::Value RPCServer::doLogSeverity(const Json::Value& params) +Json::Value RPCServer::doLogLevel(const Json::Value& params) { if (params.size() == 0) { // get log severities @@ -2666,10 +2666,7 @@ Json::Value RPCServer::doLogSeverity(const Json::Value& params) { // set base log severity LogSeverity sv = Log::stringToSeverity(params[0u].asString()); if (sv == lsINVALID) - { - Log(lsWARNING) << "Unable to parse severity: " << params[0u].asString(); return RPCError(rpcINVALID_PARAMS); - } Log::setMinSeverity(sv); return RPCError(rpcSUCCESS); } @@ -2721,8 +2718,8 @@ Json::Value RPCServer::doCommand(const std::string& command, Json::Value& params { "data_fetch", &RPCServer::doDataFetch, 1, 1, true }, { "data_store", &RPCServer::doDataStore, 2, 2, true }, { "ledger", &RPCServer::doLedger, 0, 2, false, optNetwork }, + { "log_level", &RPCServer::doLogLevel, 0, 2, true }, { "logrotate", &RPCServer::doLogRotate, 0, 0, true }, - { "logseverity", &RPCServer::doLogSeverity, 0, 2, true }, { "nickname_info", &RPCServer::doNicknameInfo, 1, 1, false, optCurrent }, { "nickname_set", &RPCServer::doNicknameSet, 2, 3, false, optCurrent }, { "offer_create", &RPCServer::doOfferCreate, 9, 10, false, optCurrent }, diff --git a/src/RPCServer.h b/src/RPCServer.h index 7d7695599..af8c6d754 100644 --- a/src/RPCServer.h +++ b/src/RPCServer.h @@ -155,7 +155,7 @@ private: Json::Value doServerInfo(const Json::Value& params); Json::Value doSessionClose(const Json::Value& params); Json::Value doSessionOpen(const Json::Value& params); - Json::Value doLogSeverity(const Json::Value& params); + Json::Value doLogLevel(const Json::Value& params); Json::Value doStop(const Json::Value& params); Json::Value doTransitSet(const Json::Value& params); Json::Value doTx(const Json::Value& params); From bd2b4daae41b947c70c0c66a3e108de8175c4858 Mon Sep 17 00:00:00 2001 From: JoelKatz Date: Fri, 19 Oct 2012 12:33:11 -0700 Subject: [PATCH 03/11] If a debug logfile is set, don't suppress INFO/DEBUG logging. --- src/Application.cpp | 3 +++ 1 file changed, 3 insertions(+) diff --git a/src/Application.cpp b/src/Application.cpp index ec56e6b91..0d777f518 100644 --- a/src/Application.cpp +++ b/src/Application.cpp @@ -70,7 +70,10 @@ void Application::run() { assert(mTxnDB == NULL); if (!theConfig.DEBUG_LOGFILE.empty()) + { Log::setLogFile(theConfig.DEBUG_LOGFILE); + LogPartition::setSeverity(lsDEBUG); + } boost::thread auxThread(boost::bind(&boost::asio::io_service::run, &mAuxService)); auxThread.detach(); From 887a87081f6cb3c0cd7181b818389c1db18b7501 Mon Sep 17 00:00:00 2001 From: JoelKatz Date: Fri, 19 Oct 2012 12:51:06 -0700 Subject: [PATCH 04/11] Move to new logging. --- src/ConnectionPool.cpp | 57 ++++++++++++++++++++++-------------------- 1 file changed, 30 insertions(+), 27 deletions(-) diff --git a/src/ConnectionPool.cpp b/src/ConnectionPool.cpp index 6285d4555..e592d000e 100644 --- a/src/ConnectionPool.cpp +++ b/src/ConnectionPool.cpp @@ -14,6 +14,7 @@ #include "utils.h" #include "Log.h" +SETUP_LOG(); // How often to enforce policies. #define POLICY_INTERVAL_SECONDS 5 @@ -164,7 +165,7 @@ void ConnectionPool::policyLowWater() if (mConnectedMap.size() > theConfig.PEER_CONNECT_LOW_WATER) { // Above low water mark, don't need more connections. - Log(lsTRACE) << "Pool: Low water: sufficient connections: " << mConnectedMap.size() << "/" << theConfig.PEER_CONNECT_LOW_WATER; + cLog(lsTRACE) << "Pool: Low water: sufficient connections: " << mConnectedMap.size() << "/" << theConfig.PEER_CONNECT_LOW_WATER; nothing(); } @@ -178,7 +179,7 @@ void ConnectionPool::policyLowWater() else if (!peerAvailable(strIp, iPort)) { // No more connections available to start. - Log(lsTRACE) << "Pool: Low water: no peers available."; + cLog(lsTRACE) << "Pool: Low water: no peers available."; // XXX Might ask peers for more ips. nothing(); @@ -186,10 +187,12 @@ void ConnectionPool::policyLowWater() else { // Try to start connection. - Log(lsTRACE) << "Pool: Low water: start connection."; + cLog(lsTRACE) << "Pool: Low water: start connection."; if (!peerConnect(strIp, iPort)) - Log(lsINFO) << "Pool: Low water: already connected."; + { + cLog(lsINFO) << "Pool: Low water: already connected."; + } // Check if we need more. policyLowWater(); @@ -303,11 +306,11 @@ Peer::pointer ConnectionPool::peerConnect(const std::string& strIp, int iPort) if (ppResult) { - //Log(lsINFO) << "Pool: Connecting: " << ADDRESS_SHARED(ppResult) << ": " << strIp << " " << iPort; + //cLog(lsINFO) << "Pool: Connecting: " << ADDRESS_SHARED(ppResult) << ": " << strIp << " " << iPort; } else { - //Log(lsINFO) << "Pool: Already connected: " << strIp << " " << iPort; + //cLog(lsINFO) << "Pool: Already connected: " << strIp << " " << iPort; } return ppResult; @@ -355,7 +358,7 @@ bool ConnectionPool::peerConnected(Peer::ref peer, const NewcoinAddress& naPeer, if (naPeer == theApp->getWallet().getNodePublic()) { - Log(lsINFO) << "Pool: Connected: self: " << ADDRESS_SHARED(peer) << ": " << naPeer.humanNodePublic() << " " << strIP << " " << iPort; + cLog(lsINFO) << "Pool: Connected: self: " << ADDRESS_SHARED(peer) << ": " << naPeer.humanNodePublic() << " " << strIP << " " << iPort; } else { @@ -365,7 +368,7 @@ bool ConnectionPool::peerConnected(Peer::ref peer, const NewcoinAddress& naPeer, if (itCm == mConnectedMap.end()) { // New connection. - //Log(lsINFO) << "Pool: Connected: new: " << ADDRESS_SHARED(peer) << ": " << naPeer.humanNodePublic() << " " << strIP << " " << iPort; + //cLog(lsINFO) << "Pool: Connected: new: " << ADDRESS_SHARED(peer) << ": " << naPeer.humanNodePublic() << " " << strIP << " " << iPort; mConnectedMap[naPeer] = peer; bNew = true; @@ -378,7 +381,7 @@ bool ConnectionPool::peerConnected(Peer::ref peer, const NewcoinAddress& naPeer, if (itCm->second->getIP().empty()) { // Old peer did not know it's IP. - //Log(lsINFO) << "Pool: Connected: redundant: outbound: " << ADDRESS_SHARED(peer) << " discovered: " << ADDRESS_SHARED(itCm->second) << ": " << strIP << " " << iPort; + //cLog(lsINFO) << "Pool: Connected: redundant: outbound: " << ADDRESS_SHARED(peer) << " discovered: " << ADDRESS_SHARED(itCm->second) << ": " << strIP << " " << iPort; itCm->second->setIpPort(strIP, iPort); @@ -388,14 +391,14 @@ bool ConnectionPool::peerConnected(Peer::ref peer, const NewcoinAddress& naPeer, else { // Old peer knew its IP. Do nothing. - //Log(lsINFO) << "Pool: Connected: redundant: outbound: rediscovered: " << ADDRESS_SHARED(peer) << " " << strIP << " " << iPort; + //cLog(lsINFO) << "Pool: Connected: redundant: outbound: rediscovered: " << ADDRESS_SHARED(peer) << " " << strIP << " " << iPort; nothing(); } } else { - //Log(lsINFO) << "Pool: Connected: redundant: inbound: " << ADDRESS_SHARED(peer) << " " << strIP << " " << iPort; + //cLog(lsINFO) << "Pool: Connected: redundant: inbound: " << ADDRESS_SHARED(peer) << " " << strIP << " " << iPort; nothing(); } @@ -418,12 +421,12 @@ void ConnectionPool::peerDisconnected(Peer::ref peer, const NewcoinAddress& naPe if (itCm == mConnectedMap.end()) { // Did not find it. Not already connecting or connected. - Log(lsWARNING) << "Pool: disconnected: Internal Error: mConnectedMap was inconsistent."; + cLog(lsWARNING) << "Pool: disconnected: Internal Error: mConnectedMap was inconsistent."; // XXX Maybe bad error, considering we have racing connections, may not so bad. } else if (itCm->second != peer) { - Log(lsWARNING) << "Pool: disconected: non canonical entry"; + cLog(lsWARNING) << "Pool: disconected: non canonical entry"; nothing(); } @@ -432,12 +435,12 @@ void ConnectionPool::peerDisconnected(Peer::ref peer, const NewcoinAddress& naPe // Found it. Delete it. mConnectedMap.erase(itCm); - //Log(lsINFO) << "Pool: disconnected: " << naPeer.humanNodePublic() << " " << peer->getIP() << " " << peer->getPort(); + //cLog(lsINFO) << "Pool: disconnected: " << naPeer.humanNodePublic() << " " << peer->getIP() << " " << peer->getPort(); } } else { - //Log(lsINFO) << "Pool: disconnected: anonymous: " << peer->getIP() << " " << peer->getPort(); + //cLog(lsINFO) << "Pool: disconnected: anonymous: " << peer->getIP() << " " << peer->getPort(); } } @@ -463,7 +466,7 @@ bool ConnectionPool::peerScanSet(const std::string& strIp, int iPort) boost::posix_time::ptime tpNow = boost::posix_time::second_clock::universal_time(); boost::posix_time::ptime tpNext = tpNow + boost::posix_time::seconds(iInterval); - //Log(lsINFO) << str(boost::format("Pool: Scan: schedule create: %s %s (next %s, delay=%d)") + //cLog(lsINFO) << str(boost::format("Pool: Scan: schedule create: %s %s (next %s, delay=%d)") // % mScanIp % mScanPort % tpNext % (tpNext-tpNow).total_seconds()); db->executeSQL(str(boost::format("UPDATE PeerIps SET ScanNext=%d,ScanInterval=%d WHERE IpPort=%s;") @@ -479,13 +482,13 @@ bool ConnectionPool::peerScanSet(const std::string& strIp, int iPort) // boost::posix_time::ptime tpNow = boost::posix_time::second_clock::universal_time(); // boost::posix_time::ptime tpNext = ptFromSeconds(db->getInt("ScanNext")); - //Log(lsINFO) << str(boost::format("Pool: Scan: schedule exists: %s %s (next %s, delay=%d)") + //cLog(lsINFO) << str(boost::format("Pool: Scan: schedule exists: %s %s (next %s, delay=%d)") // % mScanIp % mScanPort % tpNext % (tpNext-tpNow).total_seconds()); } } else { - //Log(lsWARNING) << "Pool: Scan: peer wasn't in PeerIps: " << strIp << " " << iPort; + //cLog(lsWARNING) << "Pool: Scan: peer wasn't in PeerIps: " << strIp << " " << iPort; } return bScanDirty; @@ -500,7 +503,7 @@ void ConnectionPool::peerClosed(Peer::ref peer, const std::string& strIp, int iP // If the connection was our scan, we are no longer scanning. if (mScanning && mScanning == peer) { - //Log(lsINFO) << "Pool: Scan: scan fail: " << strIp << " " << iPort; + //cLog(lsINFO) << "Pool: Scan: scan fail: " << strIp << " " << iPort; mScanning = Peer::pointer(); // No longer scanning. bScanRefresh = true; // Look for more to scan. @@ -517,13 +520,13 @@ void ConnectionPool::peerClosed(Peer::ref peer, const std::string& strIp, int iP if (itIp == mIpMap.end()) { // Did not find it. Not already connecting or connected. - Log(lsWARNING) << "Pool: Closed: UNEXPECTED: " << ADDRESS_SHARED(peer) << ": " << strIp << " " << iPort; + cLog(lsWARNING) << "Pool: Closed: UNEXPECTED: " << ADDRESS_SHARED(peer) << ": " << strIp << " " << iPort; // XXX Internal error. } else if (mIpMap[ipPeer] == peer) { // We were the identified connection. - //Log(lsINFO) << "Pool: Closed: identified: " << ADDRESS_SHARED(peer) << ": " << strIp << " " << iPort; + //cLog(lsINFO) << "Pool: Closed: identified: " << ADDRESS_SHARED(peer) << ": " << strIp << " " << iPort; // Delete our entry. mIpMap.erase(itIp); @@ -533,7 +536,7 @@ void ConnectionPool::peerClosed(Peer::ref peer, const std::string& strIp, int iP else { // Found it. But, we were redundant. - //Log(lsINFO) << "Pool: Closed: redundant: " << ADDRESS_SHARED(peer) << ": " << strIp << " " << iPort; + //cLog(lsINFO) << "Pool: Closed: redundant: " << ADDRESS_SHARED(peer) << ": " << strIp << " " << iPort; } } @@ -557,7 +560,7 @@ void ConnectionPool::peerVerified(Peer::ref peer) std::string strIpPort = str(boost::format("%s %d") % strIp % iPort); - //Log(lsINFO) << str(boost::format("Pool: Scan: connected: %s %s %s (scanned)") % ADDRESS_SHARED(peer) % strIp % iPort); + //cLog(lsINFO) << str(boost::format("Pool: Scan: connected: %s %s %s (scanned)") % ADDRESS_SHARED(peer) % strIp % iPort); if (peer->getNodePublic() == theApp->getWallet().getNodePublic()) { @@ -604,7 +607,7 @@ void ConnectionPool::scanRefresh() if (mScanning) { // Currently scanning, will scan again after completion. - Log(lsTRACE) << "Pool: Scan: already scanning"; + cLog(lsTRACE) << "Pool: Scan: already scanning"; nothing(); } @@ -641,7 +644,7 @@ void ConnectionPool::scanRefresh() if (tpNow.is_not_a_date_time()) { - //Log(lsINFO) << "Pool: Scan: stop."; + //cLog(lsINFO) << "Pool: Scan: stop."; (void) mScanTimer.cancel(); } @@ -656,7 +659,7 @@ void ConnectionPool::scanRefresh() tpNext = tpNow + boost::posix_time::seconds(iInterval); - //Log(lsINFO) << str(boost::format("Pool: Scan: Now: %s %s (next %s, delay=%d)") + //cLog(lsINFO) << str(boost::format("Pool: Scan: Now: %s %s (next %s, delay=%d)") // % mScanIp % mScanPort % tpNext % (tpNext-tpNow).total_seconds()); iInterval *= 2; @@ -681,7 +684,7 @@ void ConnectionPool::scanRefresh() } else { - //Log(lsINFO) << str(boost::format("Pool: Scan: Next: %s (next %s, delay=%d)") + //cLog(lsINFO) << str(boost::format("Pool: Scan: Next: %s (next %s, delay=%d)") // % strIpPort % tpNext % (tpNext-tpNow).total_seconds()); mScanTimer.expires_at(tpNext); From d3e91345c9d85f4c5090d188620856af70ee550b Mon Sep 17 00:00:00 2001 From: JoelKatz Date: Fri, 19 Oct 2012 14:24:32 -0700 Subject: [PATCH 05/11] Begin cleaning up the handling of ledger changes during the consensus window. --- src/LedgerConsensus.cpp | 13 +++++++++---- 1 file changed, 9 insertions(+), 4 deletions(-) diff --git a/src/LedgerConsensus.cpp b/src/LedgerConsensus.cpp index 09b91aee7..fe61a0a83 100644 --- a/src/LedgerConsensus.cpp +++ b/src/LedgerConsensus.cpp @@ -247,11 +247,16 @@ LedgerConsensus::LedgerConsensus(const uint256& prevLCLHash, Ledger::ref previou mProposing = mValidating = false; } - handleLCL(prevLCLHash); + mHaveCorrectLCL = (mPreviousLedger->getHash() == mPrevLedgerHash); if (!mHaveCorrectLCL) { - cLog(lsINFO) << "Entering consensus with: " << previousLedger->getHash(); - cLog(lsINFO) << "Correct LCL is: " << prevLCLHash; + handleLCL(mPrevLedgerHash); + if (!mHaveCorrectLCL) + { + mProposing = mValidating = false; + cLog(lsINFO) << "Entering consensus with: " << previousLedger->getHash(); + cLog(lsINFO) << "Correct LCL is: " << prevLCLHash; + } } } @@ -357,7 +362,7 @@ void LedgerConsensus::handleLCL(const uint256& lclHash) } } - cLog(lsINFO) << "Acquired the consensus ledger " << mPrevLedgerHash; + cLog(lsINFO) << "Have the consensus ledger " << mPrevLedgerHash; mHaveCorrectLCL = true; mAcquiringLedger = LedgerAcquire::pointer(); theApp->getOPs().clearNeedNetworkLedger(); From 7ee9a20f40e946edac0729cccf32f0e1b9dc1db6 Mon Sep 17 00:00:00 2001 From: JoelKatz Date: Fri, 19 Oct 2012 14:30:09 -0700 Subject: [PATCH 06/11] Some logging cleanups. --- src/LedgerConsensus.cpp | 13 +++++++------ 1 file changed, 7 insertions(+), 6 deletions(-) diff --git a/src/LedgerConsensus.cpp b/src/LedgerConsensus.cpp index fe61a0a83..4c3c3d8e6 100644 --- a/src/LedgerConsensus.cpp +++ b/src/LedgerConsensus.cpp @@ -155,14 +155,14 @@ void LCTransaction::setVote(const uint160& peer, bool votesYes) } else if (votesYes && !res.first->second) { // changes vote to yes - cLog(lsTRACE) << "Peer " << peer << " now votes YES on " << mTransactionID; + cLog(lsDEBUG) << "Peer " << peer << " now votes YES on " << mTransactionID; --mNays; ++mYays; res.first->second = true; } else if (!votesYes && res.first->second) { // changes vote to no - cLog(lsTRACE) << "Peer " << peer << " now votes NO on " << mTransactionID; + cLog(lsDEBUG) << "Peer " << peer << " now votes NO on " << mTransactionID; ++mNays; --mYays; res.first->second = false; @@ -216,7 +216,7 @@ bool LCTransaction::updateVote(int percentTime, bool proposing) return false; } mOurVote = newPosition; - cLog(lsTRACE) << "We now vote " << (mOurVote ? "YES" : "NO") << " on " << mTransactionID; + cLog(lsDEBUG) << "We now vote " << (mOurVote ? "YES" : "NO") << " on " << mTransactionID; return true; } @@ -818,7 +818,8 @@ void LedgerConsensus::startAcquiring(const TransactionAcquire::pointer& acquire) void LedgerConsensus::propose() { - cLog(lsTRACE) << "We propose: " << mOurPosition->getCurrentHash(); + cLog(lsTRACE) << "We propose: " << + (mOurPosition->isBowOut() ? std::string("bowOut") : mOurPosition->getCurrentHash().GetHex()); ripple::TMProposeSet prop; prop.set_currenttxhash(mOurPosition->getCurrentHash().begin(), 256 / 8); @@ -836,7 +837,7 @@ void LedgerConsensus::propose() void LedgerConsensus::addDisputedTransaction(const uint256& txID, const std::vector& tx) { - cLog(lsTRACE) << "Transaction " << txID << " is disputed"; + cLog(lsDEBUG) << "Transaction " << txID << " is disputed"; boost::unordered_map::iterator it = mDisputes.find(txID); if (it != mDisputes.end()) return; @@ -916,7 +917,7 @@ bool LedgerConsensus::peerPosition(const LedgerProposal::pointer& newPosition) it.second->setVote(peerID, set->hasItem(it.first)); } else - cLog(lsTRACE) << "Don't have that tx set"; + cLog(lsDEBUG) << "Don't have that tx set"; return true; } From 81170d78119003c7d73f030f01fa7cd83d32e5ba Mon Sep 17 00:00:00 2001 From: JoelKatz Date: Fri, 19 Oct 2012 16:37:39 -0700 Subject: [PATCH 07/11] Logging improvements. --- src/LedgerConsensus.cpp | 8 ++++---- src/LedgerConsensus.h | 2 +- src/LedgerTiming.cpp | 23 +++++++++++++---------- src/LedgerTiming.h | 3 ++- 4 files changed, 20 insertions(+), 16 deletions(-) diff --git a/src/LedgerConsensus.cpp b/src/LedgerConsensus.cpp index 4c3c3d8e6..df3764830 100644 --- a/src/LedgerConsensus.cpp +++ b/src/LedgerConsensus.cpp @@ -562,9 +562,9 @@ void LedgerConsensus::stateEstablish() updateOurPositions(); if (!mHaveCloseTimeConsensus) { - tLog(haveConsensus(), lsINFO) << "We have TX consensus but not CT consensus"; + tLog(haveConsensus(false), lsINFO) << "We have TX consensus but not CT consensus"; } - else if (haveConsensus()) + else if (haveConsensus(true)) { cLog(lsINFO) << "Converge cutoff (" << mPeerPositions.size() << " participants)"; mState = lcsFINISHED; @@ -721,7 +721,7 @@ void LedgerConsensus::updateOurPositions() } } -bool LedgerConsensus::haveConsensus() +bool LedgerConsensus::haveConsensus(bool forReal) { // FIXME: Should check for a supermajority on each disputed transaction // counting unacquired TX sets as disagreeing int agree = 0, disagree = 0; @@ -743,7 +743,7 @@ bool LedgerConsensus::haveConsensus() #endif return ContinuousLedgerTiming::haveConsensus(mPreviousProposers, agree + disagree, agree, currentValidations, - mPreviousMSeconds, mCurrentMSeconds); + mPreviousMSeconds, mCurrentMSeconds, forReal); } SHAMap::pointer LedgerConsensus::getTransactionTree(const uint256& hash, bool doAcquire) diff --git a/src/LedgerConsensus.h b/src/LedgerConsensus.h index 4ab27866b..23582e071 100644 --- a/src/LedgerConsensus.h +++ b/src/LedgerConsensus.h @@ -174,7 +174,7 @@ public: void stateFinished(); void stateAccepted(); - bool haveConsensus(); + bool haveConsensus(bool forReal); bool peerPosition(const LedgerProposal::pointer&); diff --git a/src/LedgerTiming.cpp b/src/LedgerTiming.cpp index 9ce760fc4..10ef38b62 100644 --- a/src/LedgerTiming.cpp +++ b/src/LedgerTiming.cpp @@ -6,6 +6,7 @@ #include #include "Log.h" +SETUP_LOG(); // NOTE: First and last times must be repeated int ContinuousLedgerTiming::LedgerTimeResolution[] = { 10, 10, 20, 30, 60, 90, 120, 120 }; @@ -23,7 +24,7 @@ bool ContinuousLedgerTiming::shouldClose( if ((previousMSeconds < -1000) || (previousMSeconds > 600000) || (currentMSeconds < -1000) || (currentMSeconds > 600000)) { - Log(lsWARNING) << + cLog(lsWARNING) << boost::str(boost::format("CLC::shouldClose range Trans=%s, Prop: %d/%d, Secs: %d (last:%d)") % (anyTransactions ? "yes" : "no") % previousProposers % proposersClosed % currentMSeconds % previousMSeconds); @@ -34,14 +35,14 @@ bool ContinuousLedgerTiming::shouldClose( { // no transactions so far this interval if (proposersClosed > (previousProposers / 4)) // did we miss a transaction? { - Log(lsTRACE) << "no transactions, many proposers: now (" << proposersClosed << " closed, " + cLog(lsTRACE) << "no transactions, many proposers: now (" << proposersClosed << " closed, " << previousProposers << " before)"; return true; } #if 0 // This false triggers on the genesis ledger if (previousMSeconds > (1000 * (LEDGER_IDLE_INTERVAL + 2))) // the last ledger was very slow to close { - Log(lsTRACE) << "was slow to converge (p=" << (previousMSeconds) << ")"; + cLog(lsTRACE) << "was slow to converge (p=" << (previousMSeconds) << ")"; if (previousMSeconds < 2000) return previousMSeconds; return previousMSeconds - 1000; @@ -61,10 +62,12 @@ bool ContinuousLedgerTiming::haveConsensus( int currentAgree, // proposers who agree with us int currentClosed, // proposers who have currently closed their ledgers int previousAgreeTime, // how long it took to agree on the last ledger - int currentAgreeTime) // how long we've been trying to agree + int currentAgreeTime, // how long we've been trying to agree + bool forReal) // deciding whether to stop consensus process { - Log(lsTRACE) << boost::str(boost::format("CLC::haveConsensus: prop=%d/%d agree=%d closed=%d time=%d/%d") % - currentProposers % previousProposers % currentAgree % currentClosed % currentAgreeTime % previousAgreeTime); + cLog(lsTRACE) << boost::str(boost::format("CLC::haveConsensus: prop=%d/%d agree=%d closed=%d time=%d/%d%s") % + currentProposers % previousProposers % currentAgree % currentClosed % currentAgreeTime % previousAgreeTime % + (forReal ? "" : "X")); if (currentAgreeTime <= LEDGER_MIN_CONSENSUS) return false; @@ -73,7 +76,7 @@ bool ContinuousLedgerTiming::haveConsensus( { // Less than 3/4 of the last ledger's proposers are present, we may need more time if (currentAgreeTime < (previousAgreeTime + LEDGER_MIN_CONSENSUS)) { - Log(lsTRACE) << "too fast, not enough proposers"; + tLog(forReal, lsTRACE) << "too fast, not enough proposers"; return false; } } @@ -81,19 +84,19 @@ bool ContinuousLedgerTiming::haveConsensus( // If 80% of current proposers (plus us) agree on a set, we have consensus if (((currentAgree * 100 + 100) / (currentProposers + 1)) > 80) { - Log(lsTRACE) << "normal consensus"; + tLog(forReal, lsTRACE) << "normal consensus"; return true; } // If 50% of the nodes on your UNL (minus us) have closed, you should close if (((currentClosed * 100 - 100) / (currentProposers + 1)) > 50) { - Log(lsTRACE) << "many closers"; + tLog(forReal, lsTRACE) << "many closers"; return true; } // no consensus yet - Log(lsTRACE) << "no consensus"; + tLog(forReal, lsTRACE) << "no consensus"; return false; } diff --git a/src/LedgerTiming.h b/src/LedgerTiming.h index 551c9bfce..6cf535c40 100644 --- a/src/LedgerTiming.h +++ b/src/LedgerTiming.h @@ -65,7 +65,8 @@ public: static bool haveConsensus( int previousProposers, int currentProposers, int currentAgree, int currentClosed, - int previousAgreeTime, int currentAgreeTime); + int previousAgreeTime, int currentAgreeTime, + bool forReal); static int getNextLedgerTimeResolution(int previousResolution, bool previousAgree, int ledgerSeq); }; From aa4a1b599492539b847f532200d699fcc046c435 Mon Sep 17 00:00:00 2001 From: JoelKatz Date: Fri, 19 Oct 2012 16:49:47 -0700 Subject: [PATCH 08/11] Simplifications. --- src/ValidationCollection.cpp | 26 ++++++++++++-------------- 1 file changed, 12 insertions(+), 14 deletions(-) diff --git a/src/ValidationCollection.cpp b/src/ValidationCollection.cpp index 5f5fc17a5..65e861e8d 100644 --- a/src/ValidationCollection.cpp +++ b/src/ValidationCollection.cpp @@ -9,6 +9,8 @@ SETUP_LOG(); +typedef std::pair u160_val_pair; + bool ValidationCollection::addValidation(const SerializedValidation::pointer& val) { NewcoinAddress signer = val->getSignerPublic(); @@ -121,10 +123,9 @@ int ValidationCollection::getNodesAfter(const uint256& ledger) { // Number of trusted nodes that have moved past this ledger int count = 0; boost::mutex::scoped_lock sl(mValidationLock); - for (boost::unordered_map::iterator it = mCurrentValidations.begin(), - end = mCurrentValidations.end(); it != end; ++it) + BOOST_FOREACH(u160_val_pair& it, mCurrentValidations) { - if (it->second->isTrusted() && it->second->isPreviousHash(ledger)) + if (it.second->isTrusted() && it.second->isPreviousHash(ledger)) ++count; } return count; @@ -136,12 +137,11 @@ int ValidationCollection::getLoadRatio(bool overLoaded) int badNodes = overLoaded ? 0 : 1; { boost::mutex::scoped_lock sl(mValidationLock); - for (boost::unordered_map::iterator it = mCurrentValidations.begin(), - end = mCurrentValidations.end(); it != end; ++it) + BOOST_FOREACH(u160_val_pair& it, mCurrentValidations) { - if (it->second->isTrusted()) + if (it.second->isTrusted()) { - if (it->second->isFull()) + if (it.second->isFull()) ++goodNodes; else ++badNodes; @@ -190,14 +190,13 @@ ValidationCollection::getCurrentValidations(uint256 currentLedger) void ValidationCollection::flush() { - boost::mutex::scoped_lock sl(mValidationLock); - boost::unordered_map::iterator it = mCurrentValidations.begin(); bool anyNew = false; - while (it != mCurrentValidations.end()) + + boost::mutex::scoped_lock sl(mValidationLock); + BOOST_FOREACH(u160_val_pair& it, mCurrentValidations) { - if (it->second) - mStaleValidations.push_back(it->second); - ++it; + if (it.second) + mStaleValidations.push_back(it.second); anyNew = true; } mCurrentValidations.clear(); @@ -243,7 +242,6 @@ void ValidationCollection::doWrite() % db->escape(strCopy(it->getSignature())))); db->executeSQL("END TRANSACTION;"); } - sl.lock(); } mWriting = false; From a98aa82f3a5ebb458c297893e9fc6e6cdb997aed Mon Sep 17 00:00:00 2001 From: JoelKatz Date: Fri, 19 Oct 2012 16:49:56 -0700 Subject: [PATCH 09/11] Fix some broken logic in the way we detect when other nodes have declared consensus. --- src/LedgerTiming.cpp | 14 +++++++------- 1 file changed, 7 insertions(+), 7 deletions(-) diff --git a/src/LedgerTiming.cpp b/src/LedgerTiming.cpp index 10ef38b62..6119123a4 100644 --- a/src/LedgerTiming.cpp +++ b/src/LedgerTiming.cpp @@ -60,13 +60,13 @@ bool ContinuousLedgerTiming::haveConsensus( int previousProposers, // proposers in the last closing (not including us) int currentProposers, // proposers in this closing so far (not including us) int currentAgree, // proposers who agree with us - int currentClosed, // proposers who have currently closed their ledgers + int currentFinished, // proposers who have validated a ledger after this one int previousAgreeTime, // how long it took to agree on the last ledger int currentAgreeTime, // how long we've been trying to agree bool forReal) // deciding whether to stop consensus process { - cLog(lsTRACE) << boost::str(boost::format("CLC::haveConsensus: prop=%d/%d agree=%d closed=%d time=%d/%d%s") % - currentProposers % previousProposers % currentAgree % currentClosed % currentAgreeTime % previousAgreeTime % + cLog(lsTRACE) << boost::str(boost::format("CLC::haveConsensus: prop=%d/%d agree=%d validated=%d time=%d/%d%s") % + currentProposers % previousProposers % currentAgree % currentFinished % currentAgreeTime % previousAgreeTime % (forReal ? "" : "X")); if (currentAgreeTime <= LEDGER_MIN_CONSENSUS) @@ -84,14 +84,14 @@ bool ContinuousLedgerTiming::haveConsensus( // If 80% of current proposers (plus us) agree on a set, we have consensus if (((currentAgree * 100 + 100) / (currentProposers + 1)) > 80) { - tLog(forReal, lsTRACE) << "normal consensus"; + tLog(forReal, lsINFO) << "normal consensus"; return true; } - // If 50% of the nodes on your UNL (minus us) have closed, you should close - if (((currentClosed * 100 - 100) / (currentProposers + 1)) > 50) + // If 50% of the nodes on your UNL have moved on, you should declare consensus + if (((currentFinished * 100) / (currentProposers + 1)) > 50) { - tLog(forReal, lsTRACE) << "many closers"; + tLog(forReal, lsWARNING) << "We see no consensus, but 50% of nodes have moved on"; return true; } From 90d061529b1dc2305e56f0f6d01f523419dfc8d5 Mon Sep 17 00:00:00 2001 From: JoelKatz Date: Fri, 19 Oct 2012 16:50:14 -0700 Subject: [PATCH 10/11] Tiny fix. --- src/LedgerConsensus.cpp | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/src/LedgerConsensus.cpp b/src/LedgerConsensus.cpp index df3764830..2bd8e5744 100644 --- a/src/LedgerConsensus.cpp +++ b/src/LedgerConsensus.cpp @@ -738,9 +738,7 @@ bool LedgerConsensus::haveConsensus(bool forReal) } int currentValidations = theApp->getValidations().getNodesAfter(mPrevLedgerHash); -#ifdef LC_DEBUG - cLog(lsINFO) << "Checking for TX consensus: agree=" << agree << ", disagree=" << disagree; -#endif + cLog(lsDEBUG) << "Checking for TX consensus: agree=" << agree << ", disagree=" << disagree; return ContinuousLedgerTiming::haveConsensus(mPreviousProposers, agree + disagree, agree, currentValidations, mPreviousMSeconds, mCurrentMSeconds, forReal); From 17437784d6bbe95c56fe11472f2f24f8f7978abe Mon Sep 17 00:00:00 2001 From: JoelKatz Date: Fri, 19 Oct 2012 16:53:32 -0700 Subject: [PATCH 11/11] If these are going to be in the repo, they should be correct. --- validators.txt | 7 +++---- 1 file changed, 3 insertions(+), 4 deletions(-) diff --git a/validators.txt b/validators.txt index 335d5d5ad..cde2a6711 100644 --- a/validators.txt +++ b/validators.txt @@ -20,7 +20,6 @@ # [validators] -n9LQC4xFSWXNv1SU1sKtjrW6TZpBZSwp1nRWej8saGs155x42YFZ first -n9LFzWuhKNvXStHAuemfRKFVECLApowncMAM5chSCL9R5ECHGN4V second -n9KXAZxiHkWuVGxDEE8boW7WmcycpZNmWei4vxVaywLZ391Nbuqx third -n94365hzFKikgCULeJwczs3kwzpir3KVHkfhUWGT4MjmbEbC5xBy +n9KPnVLn7ewVzHvn218DcEYsnWLzKerTDwhpofhk4Ym1RUq4TeGw first +n9LFzWuhKNvXStHAuemfRKFVECLApowncMAM5chSCL9R5ECHGN4V second +n94rSdgTyBNGvYg8pZXGuNt59Y5bGAZGxbxyvjDaqD9ceRAgD85P third