From 8bf44c978eb5c84e374b5e62363d433e14d384c5 Mon Sep 17 00:00:00 2001
From: CJ Cobb <46455409+cjcobb23@users.noreply.github.com>
Date: Wed, 11 May 2022 13:46:40 -0400
Subject: [PATCH] Log cleanup (#150)

* log duration of rpc requests and request itself
* clean up book_offers logging
---
 src/backend/BackendInterface.cpp |  9 +++++----
 src/rpc/RPC.cpp                  |  1 +
 src/rpc/RPC.h                    | 18 ++++++++++++++++++
 src/rpc/handlers/BookOffers.cpp  | 14 ++++++++++----
 src/webserver/HttpBase.h         |  1 +
 src/webserver/WsBase.h           |  1 +
 6 files changed, 36 insertions(+), 8 deletions(-)

diff --git a/src/backend/BackendInterface.cpp b/src/backend/BackendInterface.cpp
index 9725e832..6f969617 100644
--- a/src/backend/BackendInterface.cpp
+++ b/src/backend/BackendInterface.cpp
@@ -180,7 +180,7 @@ BackendInterface::fetchBookOffers(
         succMillis += getMillis(mid2 - mid1);
         if (!offerDir || offerDir->key >= bookEnd)
         {
-            BOOST_LOG_TRIVIAL(debug) << __func__ << " - offerDir.has_value() "
+            BOOST_LOG_TRIVIAL(trace) << __func__ << " - offerDir.has_value() "
                                      << offerDir.has_value() << " breaking";
             break;
         }
@@ -197,7 +197,7 @@ BackendInterface::fetchBookOffers(
             auto next = sle.getFieldU64(ripple::sfIndexNext);
             if (!next)
             {
-                BOOST_LOG_TRIVIAL(debug)
+                BOOST_LOG_TRIVIAL(trace)
                     << __func__ << " next is empty. breaking";
                 break;
             }
@@ -215,7 +215,7 @@ BackendInterface::fetchBookOffers(
     auto objs = fetchLedgerObjects(keys, ledgerSequence, yield);
     for (size_t i = 0; i < keys.size() && i < limit; ++i)
     {
-        BOOST_LOG_TRIVIAL(debug)
+        BOOST_LOG_TRIVIAL(trace)
             << __func__ << " key = " << ripple::strHex(keys[i])
             << " blob = " << ripple::strHex(objs[i])
             << " ledgerSequence = " << ledgerSequence;
@@ -236,7 +236,8 @@ BackendInterface::fetchBookOffers(
         << ". Fetching all objects took "
         << std::to_string(getMillis(end - mid))
         << " milliseconds. total time = "
-        << std::to_string(getMillis(end - begin)) << " milliseconds";
+        << std::to_string(getMillis(end - begin)) << " milliseconds"
+        << " book = " << ripple::strHex(book);
 
     return page;
 }
diff --git a/src/rpc/RPC.cpp b/src/rpc/RPC.cpp
index e30aeee7..218f926d 100644
--- a/src/rpc/RPC.cpp
+++ b/src/rpc/RPC.cpp
@@ -238,4 +238,5 @@ buildResponse(Context const& ctx)
         return Status{Error::rpcINTERNAL, err.what()};
     }
 }
+
 }  // namespace RPC
diff --git a/src/rpc/RPC.h b/src/rpc/RPC.h
index 0c52579f..b514dfba 100644
--- a/src/rpc/RPC.h
+++ b/src/rpc/RPC.h
@@ -190,6 +190,24 @@ buildResponse(Context const& ctx);
 bool
 validHandler(std::string const& method);
 
+template <class T>
+void
+logDuration(Context const& ctx, T const& dur)
+{
+    std::stringstream ss;
+    ss << "Request processing duration = "
+       << std::chrono::duration_cast<std::chrono::milliseconds>(dur).count()
+       << " milliseconds. request = " << ctx.params;
+    auto seconds =
+        std::chrono::duration_cast<std::chrono::seconds>(dur).count();
+    if (seconds > 10)
+        BOOST_LOG_TRIVIAL(error) << ss.str();
+    else if (seconds > 1)
+        BOOST_LOG_TRIVIAL(warning) << ss.str();
+    else
+        BOOST_LOG_TRIVIAL(debug) << ss.str();
+}
+
 }  // namespace RPC
 
 #endif  // REPORTING_RPC_H_INCLUDED
diff --git a/src/rpc/handlers/BookOffers.cpp b/src/rpc/handlers/BookOffers.cpp
index 05e1dca5..562becf7 100644
--- a/src/rpc/handlers/BookOffers.cpp
+++ b/src/rpc/handlers/BookOffers.cpp
@@ -87,7 +87,10 @@ doBookOffers(Context const& context)
     auto end = std::chrono::system_clock::now();
 
     BOOST_LOG_TRIVIAL(warning)
-        << "Time loading books: " << ((end - start).count() / 1000000000.0);
+        << "Time loading books: "
+        << std::chrono::duration_cast<std::chrono::milliseconds>(end - start)
+               .count()
+        << " milliseconds - request = " << request;
 
     response["ledger_hash"] = ripple::strHex(lgrInfo.hash);
     response["ledger_index"] = lgrInfo.seq;
@@ -95,10 +98,13 @@ doBookOffers(Context const& context)
     response["offers"] = postProcessOrderBook(
         offers, book, takerID, *context.backend, lgrInfo.seq, context.yield);
 
-    end = std::chrono::system_clock::now();
+    auto end2 = std::chrono::system_clock::now();
 
-    BOOST_LOG_TRIVIAL(warning) << "Time transforming to json: "
-                               << ((end - start).count() / 1000000000.0);
+    BOOST_LOG_TRIVIAL(warning)
+        << "Time transforming to json: "
+        << std::chrono::duration_cast<std::chrono::milliseconds>(end2 - end)
+               .count()
+        << " milliseconds - request = " << request;
 
     if (retCursor)
         response["marker"] = ripple::strHex(*retCursor);
diff --git a/src/webserver/HttpBase.h b/src/webserver/HttpBase.h
index f3db8a52..af6611d8 100644
--- a/src/webserver/HttpBase.h
+++ b/src/webserver/HttpBase.h
@@ -366,6 +366,7 @@ handle_request(
         auto end = std::chrono::system_clock::now();
         auto us =
             std::chrono::duration_cast<std::chrono::microseconds>(end - start);
+        RPC::logDuration(*context, us);
 
         if (auto status = std::get_if<RPC::Status>(&v))
         {
diff --git a/src/webserver/WsBase.h b/src/webserver/WsBase.h
index 6d315a59..94df204b 100644
--- a/src/webserver/WsBase.h
+++ b/src/webserver/WsBase.h
@@ -275,6 +275,7 @@ public:
                 auto end = std::chrono::system_clock::now();
                 auto us = std::chrono::duration_cast<std::chrono::microseconds>(
                     end - start);
+                logDuration(*context, us);
 
                 if (auto status = std::get_if<RPC::Status>(&v))
                 {