Merge pull request #942 from MonsieurNicolas/dumpSCPStateTimeout

SCP diagnostics improvements

Reviewed-by: graydon

src/herder/HerderImpl.cpp

@@ -1485,7 +1485,7 @@ HerderImpl::dumpInfo(Json::Value& ret, size_t limit)
 
     mSCP.dumpInfo(ret, limit);
 
-    mPendingEnvelopes.dumpInfo(ret);
+    mPendingEnvelopes.dumpInfo(ret, limit);
 }
 
 void
@@ -1665,6 +1665,12 @@ void
 HerderImpl::herderOutOfSync()
 {
     CLOG(INFO, "Herder") << "Lost track of consensus";
+
+    Json::Value v;
+    dumpInfo(v, 20);
+    std::string s = v.toStyledString();
+    CLOG(INFO, "Herder") << "Out of sync context: " << s;
+
     mSCPMetrics.mLostSync.Mark();
     stateChanged();
 

src/herder/PendingEnvelopes.cpp

@@ -286,22 +286,41 @@ PendingEnvelopes::getQSet(Hash const& hash)
 }
 
 void
-PendingEnvelopes::dumpInfo(Json::Value& ret)
+PendingEnvelopes::dumpInfo(Json::Value& ret, size_t limit)
 {
-    /* TODO.1
-    int count = 0;
-    for(auto& entry : mFetching)
+    Json::Value& q = ret["queue"];
+
     {
-        for(auto& fRecord : entry.second)
+        auto it = mFetchingEnvelopes.rbegin();
+        size_t l = limit;
+        while (it != mFetchingEnvelopes.rend() && l-- != 0)
         {
-            auto & envelope = fRecord->env;
-            ostringstream output;
-            output << "i:" << entry.first
-                << " n:" << binToHex(envelope->nodeID).substr(0, 6);
-
-            ret["pending"][count++] = output.str();
+            if (it->second.size() != 0)
+            {
+                Json::Value& slot = q[std::to_string(it->first)]["fetching"];
+                for (auto const& e : it->second)
+                {
+                    slot.append(mHerder.getSCP().envToStr(e));
+                }
+            }
+            it++;
+        }
+    }
+    {
+        auto it = mPendingEnvelopes.rbegin();
+        size_t l = limit;
+        while (it != mPendingEnvelopes.rend() && l-- != 0)
+        {
+            if (it->second.size() != 0)
+            {
+                Json::Value& slot = q[std::to_string(it->first)]["pending"];
+                for (auto const& e : it->second)
+                {
+                    slot.append(mHerder.getSCP().envToStr(e));
+                }
+            }
+            it++;
         }
     }
-    */
-}
 }
+}

src/herder/PendingEnvelopes.h

@@ -70,7 +70,7 @@ class PendingEnvelopes
 
     std::vector<uint64> readySlots();
 
-    void dumpInfo(Json::Value& ret);
+    void dumpInfo(Json::Value& ret, size_t limit);
 
     TxSetFramePtr getTxSet(Hash const& hash);
     SCPQuorumSetPtr getQSet(Hash const& hash);

src/main/Config.cpp

@@ -628,7 +628,8 @@ Config::validateConfig()
     }
 
     // calculates nodes that would break quorum
-    auto r = LocalNode::findClosestVBlocking(QUORUM_SET, nodes);
+    auto selfID = NODE_SEED.getPublicKey();
+    auto r = LocalNode::findClosestVBlocking(QUORUM_SET, nodes, &selfID);
 
     if (FAILURE_SAFETY == -1)
     {

src/scp/BallotProtocol.cpp

@@ -352,7 +352,7 @@ BallotProtocol::bumpState(Value const& value, uint32 n)
 
     CLOG(DEBUG, "SCP") << "BallotProtocol::bumpState"
                        << " i: " << mSlot.getSlotIndex()
-                       << " v: " << mSlot.ballotToStr(newb);
+                       << " v: " << mSlot.getSCP().ballotToStr(newb);
 
     bool updated = updateCurrentValue(newb);
 
@@ -429,7 +429,7 @@ BallotProtocol::bumpToBallot(SCPBallot const& ballot, bool check)
 {
     CLOG(DEBUG, "SCP") << "BallotProtocol::bumpToBallot"
                        << " i: " << mSlot.getSlotIndex()
-                       << " b: " << mSlot.ballotToStr(ballot);
+                       << " b: " << mSlot.getSCP().ballotToStr(ballot);
 
     // `bumpToBallot` should be never called once we committed.
     dbgAssert(mPhase != SCP_PHASE_EXTERNALIZE);
@@ -835,7 +835,7 @@ BallotProtocol::setPreparedAccept(SCPBallot const& ballot)
 {
     CLOG(DEBUG, "SCP") << "BallotProtocol::setPreparedAccept"
                        << " i: " << mSlot.getSlotIndex()
-                       << " b: " << mSlot.ballotToStr(ballot);
+                       << " b: " << mSlot.getSCP().ballotToStr(ballot);
 
     // update our state
     bool didWork = setPrepared(ballot);
@@ -982,7 +982,7 @@ BallotProtocol::setPreparedConfirmed(SCPBallot const& newC,
 {
     CLOG(DEBUG, "SCP") << "BallotProtocol::setPreparedConfirmed"
                        << " i: " << mSlot.getSlotIndex()
-                       << " h: " << mSlot.ballotToStr(newH);
+                       << " h: " << mSlot.getSCP().ballotToStr(newH);
 
     bool didWork = false;
 
@@ -1231,8 +1231,8 @@ BallotProtocol::setAcceptCommit(SCPBallot const& c, SCPBallot const& h)
 {
     CLOG(DEBUG, "SCP") << "BallotProtocol::setAcceptCommit"
                        << " i: " << mSlot.getSlotIndex()
-                       << " new c: " << mSlot.ballotToStr(c)
-                       << " new h: " << mSlot.ballotToStr(h);
+                       << " new c: " << mSlot.getSCP().ballotToStr(c)
+                       << " new h: " << mSlot.getSCP().ballotToStr(h);
 
     bool didWork = false;
 
@@ -1437,8 +1437,8 @@ BallotProtocol::setConfirmCommit(SCPBallot const& c, SCPBallot const& h)
 {
     CLOG(DEBUG, "SCP") << "BallotProtocol::setConfirmCommit"
                        << " i: " << mSlot.getSlotIndex()
-                       << " new c: " << mSlot.ballotToStr(c)
-                       << " new h: " << mSlot.ballotToStr(h);
+                       << " new c: " << mSlot.getSCP().ballotToStr(c)
+                       << " new h: " << mSlot.getSCP().ballotToStr(h);
 
     mCommit = make_unique<SCPBallot>(c);
     mHighBallot = make_unique<SCPBallot>(h);
@@ -1911,7 +1911,7 @@ BallotProtocol::dumpInfo(Json::Value& ret)
 {
     Json::Value state;
     state["heard"] = mHeardFromQuorum;
-    state["ballot"] = mSlot.ballotToStr(mCurrentBallot);
+    state["ballot"] = mSlot.getSCP().ballotToStr(mCurrentBallot);
     state["phase"] = phaseNames[mPhase];
 
     state["state"] = getLocalState();
@@ -2000,10 +2000,12 @@ BallotProtocol::dumpQuorumInfo(Json::Value& ret, NodeID const& id, bool summary)
         }
 
         auto f = LocalNode::findClosestVBlocking(
-            *qSet, mLatestEnvelopes, [&](SCPStatement const& st)
+            *qSet, mLatestEnvelopes,
+            [&](SCPStatement const& st)
             {
                 return areBallotsCompatible(getWorkingBallot(st), b);
-            });
+            },
+            &id);
         ret["fail_at"] = static_cast<int>(f.size());
 
         if (!summary)
@@ -2027,11 +2029,11 @@ BallotProtocol::getLocalState() const
     std::ostringstream oss;
 
     oss << "i: " << mSlot.getSlotIndex() << " | " << phaseNames[mPhase]
-        << " | b: " << mSlot.ballotToStr(mCurrentBallot)
-        << " | p: " << mSlot.ballotToStr(mPrepared)
-        << " | p': " << mSlot.ballotToStr(mPreparedPrime)
-        << " | h: " << mSlot.ballotToStr(mHighBallot)
-        << " | c: " << mSlot.ballotToStr(mCommit)
+        << " | b: " << mSlot.getSCP().ballotToStr(mCurrentBallot)
+        << " | p: " << mSlot.getSCP().ballotToStr(mPrepared)
+        << " | p': " << mSlot.getSCP().ballotToStr(mPreparedPrime)
+        << " | h: " << mSlot.getSCP().ballotToStr(mHighBallot)
+        << " | c: " << mSlot.getSCP().ballotToStr(mCommit)
         << " | M: " << mLatestEnvelopes.size();
     return oss.str();
 }

src/scp/LocalNode.cpp

@@ -414,7 +414,8 @@ LocalNode::isQuorum(
 std::vector<NodeID>
 LocalNode::findClosestVBlocking(
     SCPQuorumSet const& qset, std::map<NodeID, SCPEnvelope> const& map,
-    std::function<bool(SCPStatement const&)> const& filter)
+    std::function<bool(SCPStatement const&)> const& filter,
+    NodeID const* excluded)
 {
     std::set<NodeID> s;
     for (auto const& n : map)
@@ -424,12 +425,13 @@ LocalNode::findClosestVBlocking(
             s.emplace(n.first);
         }
     }
-    return findClosestVBlocking(qset, s);
+    return findClosestVBlocking(qset, s, excluded);
 }
 
 std::vector<NodeID>
 LocalNode::findClosestVBlocking(SCPQuorumSet const& qset,
-                                std::set<NodeID> const& nodes)
+                                std::set<NodeID> const& nodes,
+                                NodeID const* excluded)
 {
     size_t leftTillBlock =
         ((1 + qset.validators.size() + qset.innerSets.size()) - qset.threshold);
@@ -439,20 +441,23 @@ LocalNode::findClosestVBlocking(SCPQuorumSet const& qset,
     // first, compute how many top level items need to be blocked
     for (auto const& validator : qset.validators)
     {
-        auto it = nodes.find(validator);
-        if (it == nodes.end())
+        if (!excluded || !(validator == *excluded))
         {
-            leftTillBlock--;
-            if (leftTillBlock == 0)
+            auto it = nodes.find(validator);
+            if (it == nodes.end())
             {
-                // already blocked
-                return std::vector<NodeID>();
+                leftTillBlock--;
+                if (leftTillBlock == 0)
+                {
+                    // already blocked
+                    return std::vector<NodeID>();
+                }
+            }
+            else
+            {
+                // save this for later
+                res.emplace_back(validator);
             }
-        }
-        else
-        {
-            // save this for later
-            res.emplace_back(validator);
         }
     }
 
@@ -469,7 +474,7 @@ LocalNode::findClosestVBlocking(SCPQuorumSet const& qset,
 
     for (auto const& inner : qset.innerSets)
     {
-        auto v = findClosestVBlocking(inner, nodes);
+        auto v = findClosestVBlocking(inner, nodes, excluded);
         if (v.size() == 0)
         {
             leftTillBlock--;

src/scp/LocalNode.h

@@ -103,17 +103,21 @@ class LocalNode
                  return true;
              });
 
-    // computes the distance to the set of v-blocking sets given a set of nodes
+    // computes the distance to the set of v-blocking sets given
+    // a set of nodes that agree (but can fail)
+    // excluded, if set will be skipped altogether
     static std::vector<NodeID>
     findClosestVBlocking(SCPQuorumSet const& qset,
-                         std::set<NodeID> const& nodes);
+                         std::set<NodeID> const& nodes, NodeID const* excluded);
+
     static std::vector<NodeID> findClosestVBlocking(
         SCPQuorumSet const& qset, std::map<NodeID, SCPEnvelope> const& map,
         std::function<bool(SCPStatement const&)> const& filter =
             [](SCPStatement const&)
         {
             return true;
-        });
+        },
+        NodeID const* excluded = nullptr);
 
     void toJson(SCPQuorumSet const& qSet, Json::Value& value) const;
     std::string to_string(SCPQuorumSet const& qSet) const;

src/scp/NominationProtocol.cpp

@@ -442,7 +442,7 @@ NominationProtocol::nominate(Value const& value, Value const& previousValue,
                              bool timedout)
 {
     CLOG(DEBUG, "SCP") << "NominationProtocol::nominate "
-                       << mSlot.getValueString(value);
+                       << mSlot.getSCP().getValueString(value);
 
     bool updated = false;
 
@@ -530,31 +530,21 @@ NominationProtocol::dumpInfo(Json::Value& ret)
     int counter = 0;
     for (auto const& v : mVotes)
     {
-        nomState["X"][counter] = mSlot.getValueString(v);
+        nomState["X"][counter] = mSlot.getSCP().getValueString(v);
         counter++;
     }
 
     counter = 0;
     for (auto const& v : mAccepted)
     {
-        nomState["Y"][counter] = mSlot.getValueString(v);
+        nomState["Y"][counter] = mSlot.getSCP().getValueString(v);
         counter++;
     }
 
     counter = 0;
     for (auto const& v : mCandidates)
     {
-        nomState["Z"][counter] = mSlot.getValueString(v);
-        counter++;
-    }
-
-    counter = 0;
-    for (auto const& v : mLatestNominations)
-    {
-        nomState["N"][counter]["id"] =
-            mSlot.getSCPDriver().toShortString(v.first);
-        nomState["N"][counter]["statement"] = mSlot.envToStr(v.second);
-
+        nomState["Z"][counter] = mSlot.getSCP().getValueString(v);
         counter++;
     }