fix: Fix incorrect requests logging (#2005)

Fixes #2004.

src/rpc/RPCHelpers.hpp

@@ -30,6 +30,7 @@
 #include "rpc/Errors.hpp"
 #include "rpc/common/Types.hpp"
 #include "util/JsonUtils.hpp"
+#include "util/Taggable.hpp"
 #include "util/log/Logger.hpp"
 #include "web/Context.hpp"
 
@@ -744,12 +745,13 @@ decodeCTID(T const ctid) noexcept
  * @brief Log the duration of the request processing
  *
  * @tparam T The type of the duration
- * @param ctx The context of the request
+ * @param request The request to log
+ * @param tag The tag of the context of the request
  * @param dur The duration to log
  */
-template <typename T>
+template <typename DurationType>
 void
-logDuration(web::Context const& ctx, T const& dur)
+logDuration(boost::json::object const& request, util::BaseTagDecorator const& tag, DurationType const& dur)
 {
     using boost::json::serialize;
 
@@ -759,15 +761,15 @@ logDuration(web::Context const& ctx, T const& dur)
     auto const millis = std::chrono::duration_cast<std::chrono::milliseconds>(dur).count();
     auto const seconds = std::chrono::duration_cast<std::chrono::seconds>(dur).count();
     auto const msg = fmt::format(
-        "Request processing duration = {} milliseconds. request = {}", millis, serialize(util::removeSecret(ctx.params))
+        "Request processing duration = {} milliseconds. request = {}", millis, serialize(util::removeSecret(request))
     );
 
     if (seconds > kDURATION_ERROR_THRESHOLD_SECONDS) {
-        LOG(log.error()) << ctx.tag() << msg;
+        LOG(log.error()) << tag << msg;
     } else if (seconds > 1) {
-        LOG(log.warn()) << ctx.tag() << msg;
+        LOG(log.warn()) << tag << msg;
     } else
-        LOG(log.info()) << ctx.tag() << msg;
+        LOG(log.info()) << tag << msg;
 }
 
 /**

src/web/RPCServerHandler.hpp

@@ -196,8 +196,8 @@ private:
 
             auto [result, timeDiff] = util::timed([&]() { return rpcEngine_->buildResponse(*context); });
 
-            auto us = std::chrono::duration<int, std::milli>(timeDiff);
-            rpc::logDuration(*context, us);
+            auto const us = std::chrono::duration<int, std::milli>(timeDiff);
+            rpc::logDuration(request, context->tag(), us);
 
             boost::json::object response;
 

src/web/ng/RPCServerHandler.hpp

@@ -241,7 +241,7 @@ private:
             auto [result, timeDiff] = util::timed([&]() { return rpcEngine_->buildResponse(*context); });
 
             auto us = std::chrono::duration<int, std::milli>(timeDiff);
-            rpc::logDuration(*context, us);
+            rpc::logDuration(request, context->tag(), us);
 
             boost::json::object response;
 

tests/common/util/NameGenerator.hpp

@@ -19,8 +19,6 @@
 
 #pragma once
 
-#include <string>
-
 namespace tests::util {
 
 static auto const kNAME_GENERATOR = [](auto const& info) { return info.param.testName; };

tests/unit/rpc/RPCHelpersTests.cpp

@@ -24,15 +24,21 @@
 #include "rpc/RPCHelpers.hpp"
 #include "rpc/common/Types.hpp"
 #include "util/AsioContextTestFixture.hpp"
+#include "util/LoggerFixtures.hpp"
 #include "util/MockAmendmentCenter.hpp"
 #include "util/MockBackendTestFixture.hpp"
 #include "util/MockPrometheus.hpp"
 #include "util/NameGenerator.hpp"
+#include "util/Taggable.hpp"
 #include "util/TestObject.hpp"
+#include "util/newconfig/ConfigDefinition.hpp"
+#include "util/newconfig/ConfigValue.hpp"
+#include "util/newconfig/Types.hpp"
 
 #include <boost/asio/impl/spawn.hpp>
 #include <boost/asio/spawn.hpp>
 #include <boost/json/array.hpp>
+#include <boost/json/object.hpp>
 #include <boost/json/parse.hpp>
 #include <fmt/core.h>
 #include <gmock/gmock.h>
@@ -48,9 +54,11 @@
 #include <xrpl/protocol/jss.h>
 
 #include <array>
+#include <chrono>
 #include <cstddef>
 #include <cstdint>
 #include <optional>
+#include <sstream>
 #include <stdexcept>
 #include <string>
 #include <string_view>
@@ -1166,3 +1174,71 @@ TEST_P(IsAdminCmdParameterTest, Test)
     auto const testBundle = GetParam();
     EXPECT_EQ(isAdminCmd(testBundle.method, boost::json::parse(testBundle.testJson).as_object()), testBundle.expected);
 }
+
+struct RPCHelpersLogDurationTestBundle {
+    std::string testName;
+    std::chrono::milliseconds duration;
+    std::string expectedLogLevel;
+    bool expectDuration;
+};
+
+struct RPCHelpersLogDurationTest : LoggerFixture, testing::WithParamInterface<RPCHelpersLogDurationTestBundle> {
+    boost::json::object const request = {
+        {"method", "account_info"},
+        {"params",
+         boost::json::array{
+             boost::json::object{{"account", "rHb9CJAWyB4rj91VRWn96DkukG4bwdtyTh"}, {"secret", "should be deleted"}}
+         }}
+    };
+    util::TagDecoratorFactory tagFactory{util::config::ClioConfigDefinition{
+        {"log_tag_style", util::config::ConfigValue{util::config::ConfigType::String}.defaultValue("none")}
+    }};
+    struct DummyTaggable : util::Taggable {
+        DummyTaggable(util::TagDecoratorFactory& f) : util::Taggable(f)
+        {
+        }
+    };
+    DummyTaggable taggable{tagFactory};
+};
+
+TEST_P(RPCHelpersLogDurationTest, LogDuration)
+{
+    auto const& tag = taggable.tag();
+    // TOOD: Update in https://github.com/XRPLF/clio/issues/2008
+    auto const tagStr = [&tag]() {
+        std::stringstream ss;
+        ss << tag;
+        return ss.str();
+    }();
+
+    logDuration(request, tag, GetParam().duration);
+
+    std::string const output = getLoggerString();
+
+    EXPECT_NE(output.find(GetParam().expectedLogLevel), std::string::npos) << output;
+    EXPECT_NE(output.find(tagStr), std::string::npos);
+
+    if (GetParam().expectDuration) {
+        std::string durationStr = std::to_string(GetParam().duration.count()) + " milliseconds";
+        EXPECT_NE(output.find(durationStr), std::string::npos);
+    }
+
+    EXPECT_NE(output.find("account_info"), std::string::npos);
+    EXPECT_EQ(output.find("should be deleted"), std::string::npos);
+}
+
+INSTANTIATE_TEST_SUITE_P(
+    RPCHelpersLogDurationTests,
+    RPCHelpersLogDurationTest,
+    testing::Values(
+        RPCHelpersLogDurationTestBundle{"ShortDurationLogsAsInfo", std::chrono::milliseconds(500), "RPC:NFO", true},
+        RPCHelpersLogDurationTestBundle{
+            "MediumDurationLogsAsWarning",
+            std::chrono::milliseconds(5000),
+            "RPC:WRN",
+            true
+        },
+        RPCHelpersLogDurationTestBundle{"LongDurationLogsAsError", std::chrono::milliseconds(15000), "RPC:ERR", true}
+    ),
+    tests::util::kNAME_GENERATOR
+);