From 208b3e8f8a22bc71642d57996023e7d02853f0bb Mon Sep 17 00:00:00 2001 From: Sergey Kuznetsov Date: Thu, 17 Apr 2025 17:49:44 +0100 Subject: [PATCH] fix: Fix incorrect requests logging (#2005) Fixes #2004. --- src/rpc/RPCHelpers.hpp | 16 +++--- src/web/RPCServerHandler.hpp | 4 +- src/web/ng/RPCServerHandler.hpp | 2 +- tests/common/util/NameGenerator.hpp | 2 - tests/unit/rpc/RPCHelpersTests.cpp | 76 +++++++++++++++++++++++++++++ 5 files changed, 88 insertions(+), 12 deletions(-) diff --git a/src/rpc/RPCHelpers.hpp b/src/rpc/RPCHelpers.hpp index 040a211a..3b72d3f8 100644 --- a/src/rpc/RPCHelpers.hpp +++ b/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 +template 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(dur).count(); auto const seconds = std::chrono::duration_cast(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; } /** diff --git a/src/web/RPCServerHandler.hpp b/src/web/RPCServerHandler.hpp index a0abacb7..2d149b3b 100644 --- a/src/web/RPCServerHandler.hpp +++ b/src/web/RPCServerHandler.hpp @@ -196,8 +196,8 @@ private: auto [result, timeDiff] = util::timed([&]() { return rpcEngine_->buildResponse(*context); }); - auto us = std::chrono::duration(timeDiff); - rpc::logDuration(*context, us); + auto const us = std::chrono::duration(timeDiff); + rpc::logDuration(request, context->tag(), us); boost::json::object response; diff --git a/src/web/ng/RPCServerHandler.hpp b/src/web/ng/RPCServerHandler.hpp index fec8a22f..a1621cd5 100644 --- a/src/web/ng/RPCServerHandler.hpp +++ b/src/web/ng/RPCServerHandler.hpp @@ -241,7 +241,7 @@ private: auto [result, timeDiff] = util::timed([&]() { return rpcEngine_->buildResponse(*context); }); auto us = std::chrono::duration(timeDiff); - rpc::logDuration(*context, us); + rpc::logDuration(request, context->tag(), us); boost::json::object response; diff --git a/tests/common/util/NameGenerator.hpp b/tests/common/util/NameGenerator.hpp index d205ec68..fac53bdd 100644 --- a/tests/common/util/NameGenerator.hpp +++ b/tests/common/util/NameGenerator.hpp @@ -19,8 +19,6 @@ #pragma once -#include - namespace tests::util { static auto const kNAME_GENERATOR = [](auto const& info) { return info.param.testName; }; diff --git a/tests/unit/rpc/RPCHelpersTests.cpp b/tests/unit/rpc/RPCHelpersTests.cpp index 0dd500d3..6d64edd4 100644 --- a/tests/unit/rpc/RPCHelpersTests.cpp +++ b/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 #include #include +#include #include #include #include @@ -48,9 +54,11 @@ #include #include +#include #include #include #include +#include #include #include #include @@ -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 { + 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 +);