From 580d179dd0382ace593ab3ee8912211cfcee3c1b Mon Sep 17 00:00:00 2001
From: Vinnie Falco <vinnie.falco@gmail.com>
Date: Fri, 15 Nov 2013 13:19:10 -0800
Subject: [PATCH] Tidy up Validators logging

---
 src/ripple/validators/api/Source.h           |  6 +-
 src/ripple/validators/impl/Count.h           | 10 +++
 src/ripple/validators/impl/Logic.h           | 48 ++++++++++----
 src/ripple/validators/impl/Manager.cpp       | 66 ++++++--------------
 src/ripple/validators/impl/Source.cpp        |  6 ++
 src/ripple/validators/impl/SourceFile.cpp    |  9 ++-
 src/ripple/validators/impl/SourceStrings.cpp |  7 ++-
 src/ripple/validators/impl/SourceURL.cpp     |  9 ++-
 src/ripple/validators/impl/StoreSqdb.cpp     | 25 +++++---
 src/ripple/validators/impl/Tests.cpp         |  6 +-
 src/ripple/validators/impl/Tuning.h          |  2 +-
 11 files changed, 112 insertions(+), 82 deletions(-)

diff --git a/src/ripple/validators/api/Source.h b/src/ripple/validators/api/Source.h
index bead5a800..8bb2ef225 100644
--- a/src/ripple/validators/api/Source.h
+++ b/src/ripple/validators/api/Source.h
@@ -45,12 +45,12 @@ public:
     virtual ~Source () { }
 
     /** The name of the source, used in diagnostic output. */
-    virtual String name () = 0;
+    virtual std::string to_string () const = 0;
 
     /** An identifier that uniquely describes the source.
         This is used for identification in the database.
     */
-    virtual String uniqueID () = 0;
+    virtual String uniqueID () const = 0;
 
     /** A string that is used to recreate the source from the database entry. */
     virtual String createParam () = 0;
@@ -77,6 +77,8 @@ public:
     /** @} */
 };
 
+std::ostream& operator<< (std::ostream& os, Source const& v);
+
 }
 }
 
diff --git a/src/ripple/validators/impl/Count.h b/src/ripple/validators/impl/Count.h
index 0a9c9f602..fcbed76ca 100644
--- a/src/ripple/validators/impl/Count.h
+++ b/src/ripple/validators/impl/Count.h
@@ -66,6 +66,16 @@ struct Count
         return 0;
     }
 
+    /** Output to PropertyStream. */
+    void onWrite (PropertyStream::Map& map)
+    {
+        map["received"] = received;
+        map["expected"] = expected;
+        map["closed"]   = closed;
+        map["percent"]  = percent ();
+        map["percent_orphan"] = percent_orphaned();
+    }
+
     std::size_t received;   // Count of validations without a closed ledger
     std::size_t expected;   // Count of closed ledgers without a validation
     std::size_t closed;     // Number of validations with closed ledgers
diff --git a/src/ripple/validators/impl/Logic.h b/src/ripple/validators/impl/Logic.h
index dabdff6bb..ae4cf0650 100644
--- a/src/ripple/validators/impl/Logic.h
+++ b/src/ripple/validators/impl/Logic.h
@@ -51,6 +51,10 @@ public:
     Store& m_store;
     Journal m_journal;
 
+    // A small integer assigned to each closed ledger
+    //
+    int m_ledgerID;
+
     // The chosen set of trusted validators (formerly the "UNL")
     //
     bool m_rebuildChosenList;
@@ -87,6 +91,7 @@ public:
     explicit Logic (Store& store, Journal journal = Journal ())
         : m_store (store)
         , m_journal (journal)
+        , m_ledgerID (0)
         , m_rebuildChosenList (false)
         , m_seenValidations (seenValidationsCacheSize)
         , m_seenLedgerHashes (seenLedgersCacheSize)
@@ -133,11 +138,13 @@ public:
     {
         if (findSourceByID (source->uniqueID()))
         {
-            m_journal.error << "Duplicate static " << source->name();
+            m_journal.error <<
+                "Duplicate static " << *source;
             return;
         }
 
-        m_journal.info << "Addding static " << source->name();
+        m_journal.trace <<
+            "Addding static " << *source;
 
         Source::Results results;
         source->fetch (results, m_journal);
@@ -145,8 +152,9 @@ public:
         if (results.success)
         {
             std::size_t const numAdded (merge (results.list, source));
-            m_journal.info << "Added " << numAdded
-                           << " trusted validators from " << source->name();
+            m_journal.trace <<
+                "Added " << numAdded <<
+                " trusted validators from " << *source;
         }
         else
         {
@@ -161,11 +169,13 @@ public:
         if (findSourceByID (source->uniqueID()))
         {
             std::unique_ptr <Source> object (source);
-            m_journal.error << "Duplicate " << source->name();
+            m_journal.error <<
+                "Duplicate " << *source;
             return;
         }
 
-        m_journal.info << "Adding " << source->name();
+        m_journal.info <<
+            "Adding " << *source;
 
         {
             m_sources.resize (m_sources.size() + 1);
@@ -331,20 +341,20 @@ public:
                 m_journal.info <<
                     "Fetched " << numFetched <<
                     "(" << (numAdded - numRemoved) << " new) " <<
-                    " trusted validators from " << source->name();
+                    " trusted validators from " << *source;
             }
             else if (numRemoved > numAdded)
             {
                 m_journal.info <<
                     "Fetched " << numFetched <<
                     "(" << numRemoved - numAdded << " removed) " <<
-                    " trusted validators from " << source->name();
+                    " trusted validators from " << *source;
             }
             else
             {
-                m_journal.info <<
+                m_journal.debug <<
                     "Fetched " << numFetched <<
-                    " trusted validators from " << source->name();
+                    " trusted validators from " << *source;
             }
 
             // See if we need to rebuild
@@ -359,7 +369,8 @@ public:
         }
         else
         {
-            m_journal.error << "Failed to fetch " << source->name();
+            m_journal.error <<
+                "Failed to fetch " << *source;
 
             ++desc.numberOfFailures;
             desc.status = SourceDesc::statusFailed;
@@ -429,6 +440,16 @@ public:
                 return;
 
             iter->second.receiveValidation (rv.ledgerHash);
+
+            m_journal.trace <<
+                "New trusted validation for " << rv.ledgerHash <<
+                " from " << rv.publicKey;
+        }
+        else
+        {
+            m_journal.trace <<
+                "Untrusted validation for " << rv.ledgerHash <<
+                " from " << rv.publicKey;
         }
     }
 
@@ -440,6 +461,11 @@ public:
         if (! m_seenLedgerHashes.insert (ledgerHash))
             return;
 
+        ++m_ledgerID;
+
+        m_journal.trace <<
+            "Closed ledger " << m_ledgerID;
+
         for (ValidatorTable::iterator iter (m_validators.begin());
             iter != m_validators.end(); ++iter)
         {
diff --git a/src/ripple/validators/impl/Manager.cpp b/src/ripple/validators/impl/Manager.cpp
index f1807e293..1f40a6a70 100644
--- a/src/ripple/validators/impl/Manager.cpp
+++ b/src/ripple/validators/impl/Manager.cpp
@@ -158,6 +158,12 @@ public:
         , m_checkTimer (this)
         , m_checkSources (false)
     {
+        m_journal.trace <<
+            "Validators constructed";
+        m_journal.debug <<
+            "Validators constructed (debug)";
+        m_journal.info <<
+            "Validators constructed (info)";
     }
 
     ~ManagerImp ()
@@ -199,12 +205,8 @@ public:
 
     void addStaticSource (Validators::Source* source)
     {
-#if RIPPLE_USE_VALIDATORS
         m_queue.dispatch (m_context.wrap (bind (
             &Logic::addStatic, &m_logic, source)));
-#else
-        delete source;
-#endif
     }
 
     void addURL (URL const& url)
@@ -214,32 +216,24 @@ public:
 
     void addSource (Validators::Source* source)
     {
-#if RIPPLE_USE_VALIDATORS
         m_queue.dispatch (m_context.wrap (bind (
             &Logic::add, &m_logic, source)));
-#else
-        delete source;
-#endif
     }
 
     //--------------------------------------------------------------------------
 
     void receiveValidation (ReceivedValidation const& rv)
     {
-#if RIPPLE_USE_VALIDATORS
         if (! isStopping())
             m_queue.dispatch (m_context.wrap (bind (
                 &Logic::receiveValidation, &m_logic, rv)));
-#endif
     }
 
     void ledgerClosed (RippleLedgerHash const& ledgerHash)
     {
-#if RIPPLE_USE_VALIDATORS
         if (! isStopping())
             m_queue.dispatch (m_context.wrap (bind (
                 &Logic::ledgerClosed, &m_logic, ledgerHash)));
-#endif
     }
 
     //--------------------------------------------------------------------------
@@ -250,42 +244,23 @@ public:
 
     void onPrepare ()
     {
-#if RIPPLE_USE_VALIDATORS
-        m_journal.info << "Validators preparing";
-#endif
     }
 
     void onStart ()
     {
-#if RIPPLE_USE_VALIDATORS
-        m_journal.info << "Validators starting";
-
         // Do this late so the sources have a chance to be added.
         m_queue.dispatch (m_context.wrap (bind (
             &ManagerImp::setCheckSources, this)));
 
         startThread();
-#endif
     }
 
     void onStop ()
     {
-#if RIPPLE_USE_VALIDATORS
-        m_journal.info << "Validators stopping";
-#endif
-
         m_logic.stop ();
 
-        if (this->Thread::isThreadRunning())
-        {
-            m_journal.debug << "Signaling thread exit";
-            m_queue.dispatch (m_context.wrap (bind (
-                &Thread::signalThreadShouldExit, this)));
-        }
-        else
-        {
-            stopped();
-        }
+        m_queue.dispatch (m_context.wrap (bind (
+            &Thread::signalThreadShouldExit, this)));
     }
 
     //--------------------------------------------------------------------------
@@ -306,7 +281,7 @@ public:
             PropertyStream::Set items ("sources", map);
             for (Logic::SourceTable::const_iterator iter (m_logic.m_sources.begin());
                 iter != m_logic.m_sources.end(); ++iter)
-                items.add (iter->source->name().toStdString());
+                items.add (iter->source->to_string());
         }
 
         {
@@ -314,6 +289,11 @@ public:
             for (Logic::ValidatorTable::iterator iter (m_logic.m_validators.begin());
                 iter != m_logic.m_validators.end(); ++iter)
             {
+                RipplePublicKey const& publicKey (iter->first);
+                Validator const& validator (iter->second);
+                PropertyStream::Map item (items);
+                item["public_key"] = publicKey.to_string();
+                validator.count().onWrite (item);
             }
         }
     }
@@ -326,21 +306,11 @@ public:
 
     void init ()
     {
-        m_journal.debug << "Initializing";
-
         File const file (File::getSpecialLocation (
             File::userDocumentsDirectory).getChildFile ("validators.sqlite"));
         
-        m_journal.debug << "Opening database at '" << file.getFullPathName() << "'";
-
         Error error (m_store.open (file));
 
-        if (error)
-        {
-            m_journal.fatal <<
-                "Failed to open '" << file.getFullPathName() << "'";
-        }
-
         if (! error)
         {
             m_logic.load ();
@@ -351,7 +321,7 @@ public:
     {
         if (timer == m_checkTimer)
         {
-            m_journal.debug << "Check timer expired";
+            m_journal.trace << "Check timer expired";
             m_queue.dispatch (m_context.wrap (bind (
                 &ManagerImp::setCheckSources, this)));
         }
@@ -359,7 +329,7 @@ public:
 
     void setCheckSources ()
     {
-        m_journal.debug << "Checking sources";
+        m_journal.trace << "Checking sources";
         m_checkSources = true;
     }
 
@@ -369,14 +339,14 @@ public:
         {
             if (m_logic.fetch_one () == 0)
             {
-                m_journal.debug << "All sources checked";
+                m_journal.trace << "All sources checked";
 
                 // Made it through the list without interruption!
                 // Clear the flag and set the deadline timer again.
                 //
                 m_checkSources = false;
 
-                m_journal.debug << "Next check timer expires in " <<
+                m_journal.trace << "Next check timer expires in " <<
                     RelativeTime::seconds (checkEverySeconds);
 
                 m_checkTimer.setExpiration (checkEverySeconds);
diff --git a/src/ripple/validators/impl/Source.cpp b/src/ripple/validators/impl/Source.cpp
index 7ef24cb0b..7a7358e3d 100644
--- a/src/ripple/validators/impl/Source.cpp
+++ b/src/ripple/validators/impl/Source.cpp
@@ -26,5 +26,11 @@ Source::Results::Results ()
 {
 }
 
+std::ostream& operator<< (std::ostream& os, Source const& v)
+{
+    os << v.to_string();
+    return os;
+}
+
 }
 }
diff --git a/src/ripple/validators/impl/SourceFile.cpp b/src/ripple/validators/impl/SourceFile.cpp
index 7da64eb28..98458a71f 100644
--- a/src/ripple/validators/impl/SourceFile.cpp
+++ b/src/ripple/validators/impl/SourceFile.cpp
@@ -34,12 +34,15 @@ public:
     {
     }
     
-    String name ()
+    std::string to_string () const
     {
-        return "File: '" + m_file.getFullPathName () + "'";
+        std::stringstream ss;
+        ss <<
+            "File: '" << m_file.getFullPathName().toStdString() + "'";
+        return ss.str();
     }
 
-    String uniqueID ()
+    String uniqueID () const
     {
         return "File," + m_file.getFullPathName ();
     }
diff --git a/src/ripple/validators/impl/SourceStrings.cpp b/src/ripple/validators/impl/SourceStrings.cpp
index d128f3998..938d60a45 100644
--- a/src/ripple/validators/impl/SourceStrings.cpp
+++ b/src/ripple/validators/impl/SourceStrings.cpp
@@ -36,13 +36,14 @@ public:
     {
     }
 
-    String name ()
+    std::string to_string () const
     {
-        return m_name;
+        return m_name.toStdString();
     }
 
-    String uniqueID ()
+    String uniqueID () const
     {
+        // VFALCO TODO This can't be right...?
         return String::empty;
     }
 
diff --git a/src/ripple/validators/impl/SourceURL.cpp b/src/ripple/validators/impl/SourceURL.cpp
index 7bca13961..1be5f4e89 100644
--- a/src/ripple/validators/impl/SourceURL.cpp
+++ b/src/ripple/validators/impl/SourceURL.cpp
@@ -37,12 +37,15 @@ public:
     {
     }
 
-    String name ()
+    std::string to_string () const
     {
-        return "URL: '" + m_url.toString() + "'";
+        std::stringstream ss;
+        ss <<
+            "URL: '" << m_url.to_string() << "'";
+        return ss.str();
     }
 
-    String uniqueID ()
+    String uniqueID () const
     {
         return "URL," + m_url.toString();
     }
diff --git a/src/ripple/validators/impl/StoreSqdb.cpp b/src/ripple/validators/impl/StoreSqdb.cpp
index 7e55bbaa4..4f636d02f 100644
--- a/src/ripple/validators/impl/StoreSqdb.cpp
+++ b/src/ripple/validators/impl/StoreSqdb.cpp
@@ -33,12 +33,19 @@ Error StoreSqdb::open (File const& file)
 {
     Error error (m_session.open (file.getFullPathName ()));
 
+    m_journal.info <<
+        "Opening " << file.getFullPathName();
+
     if (!error)
         error = init ();
 
     if (!error)
         error = update ();
 
+    if (error)
+        m_journal.error <<
+            "Failed opening database: " << error.what();
+
     return error;
 }
 
@@ -206,8 +213,8 @@ bool StoreSqdb::select (SourceDesc& desc)
 
     if (st.execute_and_fetch (error))
     {
-        m_journal.debug << "Found record for " <<
-            desc.source->name ();
+        m_journal.debug <<
+            "Found record for " << *desc.source;
         
         found = true;
         desc.lastFetchTime = Utilities::stringToTime (lastFetchTime);
@@ -215,8 +222,8 @@ bool StoreSqdb::select (SourceDesc& desc)
     }
     else if (! error)
     {
-        m_journal.info << "No previous record for " <<
-            desc.source->name ();
+        m_journal.info <<
+            "No previous record for " << *desc.source;
     }
 
     if (error)
@@ -296,16 +303,18 @@ void StoreSqdb::selectList (SourceDesc& desc)
                 }
                 else
                 {
-                    m_journal.error << "Invalid public key '" <<
-                        publicKeyString << "' found in database";
+                    m_journal.error <<
+                        "Invalid public key '" << publicKeyString <<
+                        "' found in database";
                 }
             }
             while (st.fetch (error));
 
             if (! error)
             {
-                m_journal.info << "Loaded " << desc.results.list.size() <<
-                    " trusted validators for " << desc.source->name ();
+                m_journal.info <<
+                    "Loaded " << desc.results.list.size() <<
+                    " trusted validators for " << *desc.source;
             }
         }
     }
diff --git a/src/ripple/validators/impl/Tests.cpp b/src/ripple/validators/impl/Tests.cpp
index 7de4a606b..fa1b4e32f 100644
--- a/src/ripple/validators/impl/Tests.cpp
+++ b/src/ripple/validators/impl/Tests.cpp
@@ -104,12 +104,12 @@ public:
         {
         }
 
-        String name ()
+        std::string to_string () const
         {
-            return uniqueID ();
+            return uniqueID().toStdString();
         }
 
-        String uniqueID ()
+        String uniqueID () const
         {
             return String ("Test,") + m_name + "," +
                 String::fromNumber (m_start) + "," +
diff --git a/src/ripple/validators/impl/Tuning.h b/src/ripple/validators/impl/Tuning.h
index 4f1f6f938..54cf65eb8 100644
--- a/src/ripple/validators/impl/Tuning.h
+++ b/src/ripple/validators/impl/Tuning.h
@@ -29,7 +29,7 @@ namespace Validators {
 //
 enum
 {
-#if 0
+#if 1
     // We will fetch a source at this interval
     hoursBetweenFetches = 24
     ,secondsBetweenFetches = hoursBetweenFetches * 60 * 60