Detailed consensus data correlated together.

include/xrpl/basics/Log.h

@@ -67,6 +67,10 @@ class Logs
         void
         write(beast::severities::Severity level, std::string const& text)
             override;
+
+        void
+        writeAlways(beast::severities::Severity level, std::string const& text)
+            override;
     };
 
     /** Manages a system file containing logged output.
@@ -256,6 +260,14 @@ class Logs
         x
 #endif
 
+#ifndef CLOG
+#define CLOG(ss) \
+    if (!ss)     \
+        ;        \
+    else         \
+        *ss
+#endif
+
 //------------------------------------------------------------------------------
 // Debug logging:
 

include/xrpl/beast/utility/Journal.h

@@ -112,6 +112,16 @@ class Journal
         virtual void
         write(Severity level, std::string const& text) = 0;
 
+        /** Bypass filter and write text to the sink at the specified severity.
+         * Always write the message, but maintain the same formatting as if
+         * it passed through a level filter.
+         *
+         * @param level Level to display in message.
+         * @param text Text to write to sink.
+         */
+        virtual void
+        writeAlways(Severity level, std::string const& text) = 0;
+
     private:
         Severity thresh_;
         bool m_console;

include/xrpl/beast/utility/WrappedSink.h

@@ -93,6 +93,13 @@
         using beast::Journal;
         sink_.write(level, prefix_ + text);
     }
+
+    void
+    writeAlways(severities::Severity level, std::string const& text) override
+    {
+        using beast::Journal;
+        sink_.writeAlways(level, prefix_ + text);
+    }
 };
 
 }  // namespace beast

src/libxrpl/basics/Log.cpp

@@ -47,6 +47,14 @@
     logs_.write(level, partition_, text, console());
 }
 
+void
+Logs::Sink::writeAlways(
+    beast::severities::Severity level,
+    std::string const& text)
+{
+    logs_.write(level, partition_, text, console());
+}
+
 //------------------------------------------------------------------------------
 
 Logs::File::File() : m_stream(nullptr)

src/libxrpl/beast/utility/src/beast_Journal.cpp

@@ -66,6 +66,11 @@
     write(severities::Severity, std::string const&) override
     {
     }
+
+    void
+    writeAlways(severities::Severity, std::string const&) override
+    {
+    }
 };
 
 //------------------------------------------------------------------------------

src/test/beast/beast_Journal_test.cpp

@@ -53,6 +53,12 @@ class Journal_test : public unit_test::suite
             if (level >= threshold())
                 ++m_count;
         }
+
+        void
+        writeAlways(severities::Severity level, std::string const&) override
+        {
+            ++m_count;
+        }
     };
 
     void

src/test/csf/Peer.h

@@ -116,6 +116,10 @@ struct Peer
         }
     };
 
+    class TestConsensusLogger
+    {
+    };
+
     /** Generic Validations adaptor that simply ignores recently stale
      * validations
      */
@@ -532,7 +536,8 @@ struct Peer
             closeResolution,
             rawCloseTimes,
             mode,
-            std::move(consensusJson));
+            std::move(consensusJson),
+            validating());
     }
 
     void
@@ -542,7 +547,8 @@ struct Peer
         NetClock::duration const& closeResolution,
         ConsensusCloseTimes const& rawCloseTimes,
         ConsensusMode const& mode,
-        Json::Value&& consensusJson)
+        Json::Value&& consensusJson,
+        const bool validating)
     {
         schedule(delays.ledgerAccept, [=, this]() {
             const bool proposing = mode == ConsensusMode::proposing;
@@ -877,6 +883,13 @@ struct Peer
     {
     }
 
+    bool
+    validating() const
+    {
+        // does not matter
+        return false;
+    }
+
     //--------------------------------------------------------------------------
     //  A locally submitted transaction
     void
@@ -917,7 +930,7 @@ struct Peer
         // Not yet modeling dynamic UNL.
         hash_set<PeerID> nowUntrusted;
         consensus.startRound(
-            now(), bestLCL, lastClosedLedger, nowUntrusted, runAsValidator);
+            now(), bestLCL, lastClosedLedger, nowUntrusted, runAsValidator, {});
     }
 
     // Start the consensus process assuming it is not yet running

src/test/csf/Sim.h

@@ -57,6 +57,14 @@ class BasicSink : public beast::Journal::Sink
         std::cout << clock_.now().time_since_epoch().count() << " " << text
                   << std::endl;
     }
+
+    void
+    writeAlways(beast::severities::Severity level, std::string const& text)
+        override
+    {
+        std::cout << clock_.now().time_since_epoch().count() << " " << text
+                  << std::endl;
+    }
 };
 
 class Sim

src/test/jtx/CaptureLogs.h

@@ -60,6 +60,14 @@ class CaptureLogs : public Logs
             std::lock_guard lock(strmMutex_);
             strm_ << text;
         }
+
+        void
+        writeAlways(beast::severities::Severity level, std::string const& text)
+            override
+        {
+            std::lock_guard lock(strmMutex_);
+            strm_ << text;
+        }
     };
 
 public:

src/test/jtx/CheckMessageLogs.h

@@ -48,6 +48,13 @@ class CheckMessageLogs : public Logs
             if (text.find(owner_.msg_) != std::string::npos)
                 *owner_.pFound_ = true;
         }
+
+        void
+        writeAlways(beast::severities::Severity level, std::string const& text)
+            override
+        {
+            write(level, text);
+        }
     };
 
 public:

src/test/server/ServerStatus_test.cpp

@@ -860,7 +860,7 @@ class ServerStatus_test : public beast::unit_test::suite,
 
         // mark the Network as having an Amendment Warning, but won't fail
         env.app().getOPs().setAmendmentWarned();
-        env.app().getOPs().beginConsensus(env.closed()->info().hash);
+        env.app().getOPs().beginConsensus(env.closed()->info().hash, {});
 
         // consensus doesn't change
         BEAST_EXPECT(
@@ -991,7 +991,7 @@ class ServerStatus_test : public beast::unit_test::suite,
         // mark the Network as Amendment Blocked, but still won't fail until
         // ELB is enabled (next step)
         env.app().getOPs().setAmendmentBlocked();
-        env.app().getOPs().beginConsensus(env.closed()->info().hash);
+        env.app().getOPs().beginConsensus(env.closed()->info().hash, {});
 
         // consensus now sees validation disabled
         BEAST_EXPECT(

src/test/server/Server_test.cpp

@@ -96,6 +96,13 @@ class Server_test : public beast::unit_test::suite
 
             suite_.log << text << std::endl;
         }
+
+        void
+        writeAlways(beast::severities::Severity level, std::string const& text)
+            override
+        {
+            suite_.log << text << std::endl;
+        }
     };
 
     //--------------------------------------------------------------------------

src/test/unit_test/SuiteJournal.h

@@ -50,12 +50,26 @@ class SuiteJournalSink : public beast::Journal::Sink
 
     void
     write(beast::severities::Severity level, std::string const& text) override;
+
+    void
+    writeAlways(beast::severities::Severity level, std::string const& text)
+        override;
 };
 
 inline void
 SuiteJournalSink::write(
     beast::severities::Severity level,
     std::string const& text)
+{
+    // Only write the string if the level at least equals the threshold.
+    if (level >= threshold())
+        writeAlways(level, text);
+}
+
+inline void
+SuiteJournalSink::writeAlways(
+    beast::severities::Severity level,
+    std::string const& text)
 {
     using namespace beast::severities;
 
@@ -80,9 +94,7 @@ SuiteJournalSink::write(
         return "FTL:";
     }();
 
-    // Only write the string if the level at least equals the threshold.
-    if (level >= threshold())
-        suite_.log << s << partition_ << text << std::endl;
+    suite_.log << s << partition_ << text << std::endl;
 }
 
 class SuiteJournal
@@ -127,9 +139,16 @@ class StreamSink : public beast::Journal::Sink
     {
         if (level < threshold())
             return;
+        writeAlways(level, text);
+    }
 
+    inline void
+    writeAlways(beast::severities::Severity level, std::string const& text)
+        override
+    {
         strm_ << text << std::endl;
     }
+
     std::stringstream const&
     messages() const
     {

src/xrpld/app/consensus/RCLConsensus.cpp

@@ -45,6 +45,7 @@
 #include <xrpl/protocol/digest.h>
 
 #include <algorithm>
+#include <iomanip>
 #include <mutex>
 
 namespace ripple {
@@ -434,7 +435,8 @@
     NetClock::duration const& closeResolution,
     ConsensusCloseTimes const& rawCloseTimes,
     ConsensusMode const& mode,
-    Json::Value&& consensusJson)
+    Json::Value&& consensusJson,
+    const bool validating)
 {
     app_.getJobQueue().addJob(
         jtACCEPT,
@@ -445,14 +447,15 @@
             // is accepted, the consensus results and capture by reference state
             // will not change until startRound is called (which happens via
             // endConsensus).
+            RclConsensusLogger clog("onAccept", validating, j_);
             this->doAccept(
                 result,
                 prevLedger,
                 closeResolution,
                 rawCloseTimes,
                 mode,
                 std::move(cj));
-            this->app_.getOPs().endConsensus();
+            this->app_.getOPs().endConsensus(clog.ss());
         });
 }
 
@@ -935,17 +938,22 @@
 }
 
 void
-RCLConsensus::timerEntry(NetClock::time_point const& now)
+RCLConsensus::timerEntry(
+    NetClock::time_point const& now,
+    std::unique_ptr<std::stringstream> const& clog)
 {
     try
     {
         std::lock_guard _{mutex_};
-        consensus_.timerEntry(now);
+        consensus_.timerEntry(now, clog);
     }
     catch (SHAMapMissingNode const& mn)
     {
         // This should never happen
-        JLOG(j_.error()) << "During consensus timerEntry: " << mn.what();
+        std::stringstream ss;
+        ss << "During consensus timerEntry: " << mn.what();
+        JLOG(j_.error()) << ss.str();
+        CLOG(clog) << ss.str();
         Rethrow();
     }
 }
@@ -1082,14 +1090,45 @@
     RCLCxLedger::ID const& prevLgrId,
     RCLCxLedger const& prevLgr,
     hash_set<NodeID> const& nowUntrusted,
-    hash_set<NodeID> const& nowTrusted)
+    hash_set<NodeID> const& nowTrusted,
+    std::unique_ptr<std::stringstream> const& clog)
 {
     std::lock_guard _{mutex_};
     consensus_.startRound(
         now,
         prevLgrId,
         prevLgr,
         nowUntrusted,
-        adaptor_.preStartRound(prevLgr, nowTrusted));
+        adaptor_.preStartRound(prevLgr, nowTrusted),
+        clog);
 }
+
+RclConsensusLogger::RclConsensusLogger(
+    const char* label,
+    const bool validating,
+    beast::Journal j)
+    : j_(j)
+{
+    if (!validating && !j.info())
+        return;
+    start_ = std::chrono::steady_clock::now();
+    ss_ = std::make_unique<std::stringstream>();
+    header_ = "ConsensusLogger ";
+    header_ += label;
+    header_ += ": ";
+}
+
+RclConsensusLogger::~RclConsensusLogger()
+{
+    if (!ss_)
+        return;
+    auto const duration = std::chrono::duration_cast<std::chrono::milliseconds>(
+        std::chrono::steady_clock::now() - start_);
+    std::stringstream outSs;
+    outSs << header_ << "duration " << (duration.count() / 1000) << '.'
+          << std::setw(3) << std::setfill('0') << (duration.count() % 1000)
+          << "s. " << ss_->str();
+    j_.sink().writeAlways(beast::severities::kInfo, outSs.str());
+}
+
 }  // namespace ripple