Log the caller / reason for server state changes:

* Also log as warning when the state lowers

Author: ximinez

src/ripple/app/consensus/RCLConsensus.cpp

@@ -1062,7 +1062,8 @@ void
 RCLConsensus::Adaptor::updateOperatingMode(std::size_t const positions) const
 {
     if (!positions && app_.getOPs().isFull())
-        app_.getOPs().setMode(OperatingMode::CONNECTED);
+        app_.getOPs().setMode(
+            OperatingMode::CONNECTED, "updateOperatingMode: no positions");
 }
 
 void

src/ripple/app/ledger/impl/InboundLedger.cpp

@@ -538,15 +538,17 @@ InboundLedger::trigger(std::shared_ptr<Peer> const& peer, TriggerReason reason)
 
     if (auto stream = journal_.debug())
     {
-        stream << "Trigger acquiring ledger " << hash_;
+        std::stringstream ss;
+        ss << "Trigger acquiring ledger " << hash_;
         if (peer)
-            stream << " from " << peer;
+            ss << " from " << peer;
 
         if (complete_ || failed_)
-            stream << "complete=" << complete_ << " failed=" << failed_;
+            ss << " complete=" << complete_ << " failed=" << failed_;
         else
-            stream << "header=" << mHaveHeader << " tx=" << mHaveTransactions
-                   << " as=" << mHaveState;
+            ss << " header=" << mHaveHeader << " tx=" << mHaveTransactions
+               << " as=" << mHaveState;
+        stream << ss.str();
     }
 
     if (!mHaveHeader)

src/ripple/app/ledger/impl/TimeoutCounter.cpp

@@ -33,7 +33,8 @@ TimeoutCounter::TimeoutCounter(
     QueueJobParameter&& jobParameter,
     beast::Journal journal)
     : app_(app)
-    , journal_(journal)
+    , sink_(journal, to_short_string(hash) + " ")
+    , journal_(sink_)
     , hash_(hash)
     , timeouts_(0)
     , complete_(false)

src/ripple/app/ledger/impl/TimeoutCounter.h

@@ -23,6 +23,7 @@
 #include <ripple/app/main/Application.h>
 #include <ripple/beast/clock/abstract_clock.h>
 #include <ripple/beast/utility/Journal.h>
+#include <ripple/beast/utility/WrappedSink.h>
 #include <ripple/core/Job.h>
 #include <boost/asio/basic_waitable_timer.hpp>
 #include <mutex>
@@ -121,6 +122,7 @@ class TimeoutCounter
     // Used in this class for access to boost::asio::io_service and
     // ripple::Overlay. Used in subtypes for the kitchen sink.
     Application& app_;
+    beast::WrappedSink sink_;
     beast::Journal journal_;
     mutable std::recursive_mutex mtx_;
 

src/ripple/app/misc/NetworkOPs.cpp

@@ -401,7 +401,7 @@ class NetworkOPsImp final : public NetworkOPs
     isFull() override;
 
     void
-    setMode(OperatingMode om) override;
+    setMode(OperatingMode om, std::string const& reason) override;
 
     bool
     isBlocked() override;
@@ -881,7 +881,7 @@ NetworkOPsImp::strOperatingMode(bool const admin /* = false */) const
 inline void
 NetworkOPsImp::setStandAlone()
 {
-    setMode(OperatingMode::FULL);
+    setMode(OperatingMode::FULL, "setStandAlone");
 }
 
 inline void
@@ -1029,7 +1029,9 @@ NetworkOPsImp::processHeartbeatTimer()
         {
             if (mMode != OperatingMode::DISCONNECTED)
             {
-                setMode(OperatingMode::DISCONNECTED);
+                setMode(
+                    OperatingMode::DISCONNECTED,
+                    "Heartbeat: insufficient peers");
                 JLOG(m_journal.warn())
                     << "Node count (" << numPeers << ") has fallen "
                     << "below required minimum (" << minPeerCount_ << ").";
@@ -1045,17 +1047,17 @@ NetworkOPsImp::processHeartbeatTimer()
 
         if (mMode == OperatingMode::DISCONNECTED)
         {
-            setMode(OperatingMode::CONNECTED);
+            setMode(OperatingMode::CONNECTED, "Heartbeat: sufficient peers");
             JLOG(m_journal.info())
                 << "Node count (" << numPeers << ") is sufficient.";
         }
 
         // Check if the last validated ledger forces a change between these
         // states.
         if (mMode == OperatingMode::SYNCING)
-            setMode(OperatingMode::SYNCING);
+            setMode(OperatingMode::SYNCING, "Heartbeat: check syncing");
         else if (mMode == OperatingMode::CONNECTED)
-            setMode(OperatingMode::CONNECTED);
+            setMode(OperatingMode::CONNECTED, "Heartbeat: check connected");
     }
 
     mConsensus.timerEntry(app_.timeKeeper().closeTime());
@@ -1609,7 +1611,7 @@ void
 NetworkOPsImp::setAmendmentBlocked()
 {
     amendmentBlocked_ = true;
-    setMode(OperatingMode::CONNECTED);
+    setMode(OperatingMode::CONNECTED, "setAmendmentBlocked");
 }
 
 inline bool
@@ -1640,7 +1642,7 @@ void
 NetworkOPsImp::setUNLBlocked()
 {
     unlBlocked_ = true;
-    setMode(OperatingMode::CONNECTED);
+    setMode(OperatingMode::CONNECTED, "setUNLBlocked");
 }
 
 inline void
@@ -1741,7 +1743,7 @@ NetworkOPsImp::checkLastClosedLedger(
 
     if ((mMode == OperatingMode::TRACKING) || (mMode == OperatingMode::FULL))
     {
-        setMode(OperatingMode::CONNECTED);
+        setMode(OperatingMode::CONNECTED, "check LCL: not on consensus ledger");
     }
 
     if (consensus)
@@ -1826,8 +1828,9 @@ NetworkOPsImp::beginConsensus(uint256 const& networkClosed)
         // this shouldn't happen unless we jump ledgers
         if (mMode == OperatingMode::FULL)
         {
-            JLOG(m_journal.warn()) << "Don't have LCL, going to tracking";
-            setMode(OperatingMode::TRACKING);
+            JLOG(m_journal.warn())
+                << "beginConsensus Don't have LCL, going to tracking";
+            setMode(OperatingMode::TRACKING, "beginConsensus: No LCL");
         }
 
         return false;
@@ -1933,7 +1936,7 @@ NetworkOPsImp::endConsensus()
         // validations we have for LCL.  If the ledger is good enough, go to
         // TRACKING - TODO
         if (!needNetworkLedger_)
-            setMode(OperatingMode::TRACKING);
+            setMode(OperatingMode::TRACKING, "endConsensus: check tracking");
     }
 
     if (((mMode == OperatingMode::CONNECTED) ||
@@ -1947,7 +1950,7 @@ NetworkOPsImp::endConsensus()
         if (app_.timeKeeper().now() < (current->info().parentCloseTime +
                                        2 * current->info().closeTimeResolution))
         {
-            setMode(OperatingMode::FULL);
+            setMode(OperatingMode::FULL, "endConsensus: check full");
         }
     }
 
@@ -1959,7 +1962,7 @@ NetworkOPsImp::consensusViewChange()
 {
     if ((mMode == OperatingMode::FULL) || (mMode == OperatingMode::TRACKING))
     {
-        setMode(OperatingMode::CONNECTED);
+        setMode(OperatingMode::CONNECTED, "consensusViewChange");
     }
 }
 
@@ -2277,7 +2280,7 @@ NetworkOPsImp::pubPeerStatus(std::function<Json::Value(void)> const& func)
 }
 
 void
-NetworkOPsImp::setMode(OperatingMode om)
+NetworkOPsImp::setMode(OperatingMode om, std::string const& reason)
 {
     using namespace std::chrono_literals;
     if (om == OperatingMode::CONNECTED)
@@ -2301,7 +2304,7 @@ NetworkOPsImp::setMode(OperatingMode om)
 
     accounting_.mode(om);
 
-    JLOG(m_journal.info()) << "STATE->" << strOperatingMode();
+    JLOG(m_journal.info()) << "STATE->" << strOperatingMode() << " " << reason;
     pubServer();
 }
 

src/ripple/app/misc/NetworkOPs.h

@@ -197,7 +197,7 @@ class NetworkOPs : public InfoSub::Source
     virtual bool
     isFull() = 0;
     virtual void
-    setMode(OperatingMode om) = 0;
+    setMode(OperatingMode om, std::string const& reason) = 0;
     virtual bool
     isBlocked() = 0;
     virtual bool

src/ripple/basics/base_uint.h

@@ -623,6 +623,13 @@ to_string(base_uint<Bits, Tag> const& a)
     return strHex(a.cbegin(), a.cend());
 }
 
+template <std::size_t Bits, class Tag>
+inline std::string
+to_short_string(base_uint<Bits, Tag> const& a)
+{
+    return strHex(a.cbegin(), a.cend()).substr(0, 8) + "...";
+}
+
 template <std::size_t Bits, class Tag>
 inline std::ostream&
 operator<<(std::ostream& out, base_uint<Bits, Tag> const& u)

src/ripple/protocol/LedgerHeader.h

@@ -55,6 +55,8 @@ struct LedgerHeader
 
     // If validated is false, it means "not yet validated."
     // Once validated is true, it will never be set false at a later time.
+    // NOTE: If you are accessing this directly, you are probably doing it
+    //   wrong. Use LedgerMaster::isValidated().
     // VFALCO TODO Make this not mutable
     bool mutable validated = false;
     bool accepted = false;