Optimisation

This commit is contained in:
JCW
2026-04-30 12:23:00 +01:00
parent 06193bde5d
commit d1f6d4f339
4 changed files with 123 additions and 39 deletions

View File

@@ -73,9 +73,28 @@ enum class Severity {
*/
inline constexpr char const* kDEFAULT_LOG_FORMAT = "%Y-%b-%d %H:%M:%S.%f UTC %n:%K %v";
/**
* @brief Build the default JSON log format pattern.
*
* Contains the same fields as @ref kDEFAULT_LOG_FORMAT (timestamp, channel,
* severity) plus the trailing message placeholder:
* @code
* {"timestamp":"2024-Jan-15 12:34:56.789123 UTC","channel":"General","severity":"NFO",
* "message": "hello world" }
* @endcode
*/
inline std::string
defaultJsonLogFormat()
{
return JsonLoggingPatternBuilder()
.add("timestamp", "%Y-%b-%d %H:%M:%S.%f UTC")
.add("channel", "%n")
.add("severity", "%K")
.build();
}
struct LoggingConfiguration
{
std::string format{kDEFAULT_LOG_FORMAT};
bool enableConsole;
std::optional<std::string> directory;
bool isAsync;
@@ -379,6 +398,19 @@ protected:
static std::unique_ptr<spdlog::formatter>
makeFormatter(std::string const& pattern);
/**
* @brief Returns the active log format pattern.
*
* Automatically determined by the logging mode:
* text mode uses @ref kDEFAULT_LOG_FORMAT, JSON mode uses
* @ref defaultJsonLogFormat().
*/
static std::string const&
format()
{
return format_;
}
protected:
static bool isAsync_; // NOLINT(readability-identifier-naming)
static Severity defaultSeverity_; // NOLINT(readability-identifier-naming)
@@ -489,14 +521,13 @@ private:
* @return A vector of sinks on success, error message on failure
*/
[[nodiscard]] static Expected<std::vector<std::shared_ptr<spdlog::sinks::sink>>, std::string>
getSinks(LoggingConfiguration const& config);
getSinks(LoggingConfiguration const& config, std::string const& format);
struct FileLoggingParams
{
std::string logDir;
};
friend struct ::BenchmarkLoggingInitializer;
friend class ::LoggerFixture;
[[nodiscard]]

View File

@@ -205,8 +205,7 @@ public:
* {"level":"%l","channel":"%n" %v }
* @endcode
*
* @return The pattern string to pass to spdlog::pattern_formatter or
* LoggingConfiguration::format.
* @return The pattern string to pass to spdlog::pattern_formatter.
*/
[[nodiscard]] std::string
build() const

View File

@@ -393,10 +393,8 @@ LogServiceState::registerLogger(std::string_view channel, std::optional<Severity
}
Expected<std::vector<spdlog::sink_ptr>, std::string>
LogService::getSinks(LoggingConfiguration const& config)
LogService::getSinks(LoggingConfiguration const& config, std::string const& format)
{
std::string const format = config.format;
std::vector<spdlog::sink_ptr> allSinks = createConsoleSinks(config.enableConsole, format);
if (config.directory.has_value())
@@ -422,14 +420,16 @@ LogService::getSinks(LoggingConfiguration const& config)
Expected<void, std::string>
LogService::init(LoggingConfiguration const& config)
{
auto const sinksMaybe = getSinks(config);
// Format is fully determined by the logging mode.
format_ = config.jsonMode ? defaultJsonLogFormat() : std::string(kDEFAULT_LOG_FORMAT);
auto const sinksMaybe = getSinks(config, format_);
if (!sinksMaybe.has_value())
{
return Unexpected{sinksMaybe.error()};
}
logDir_ = config.directory;
format_ = config.format;
LogServiceState::init(
config.isAsync, config.defaultSeverity, std::move(sinksMaybe).value(), config.jsonMode);
@@ -537,14 +537,14 @@ Logger::Logger(std::string_view const channel) : logger_(LogServiceState::regist
Logger::~Logger()
{
// One reference is held by logger_ and the other by spdlog registry
static constexpr size_t kLAST_LOGGER_REF_COUNT = 2;
static constexpr size_t LAST_LOGGER_REF_COUNT = 2;
if (logger_ == nullptr)
{
return;
}
if (logger_.use_count() == kLAST_LOGGER_REF_COUNT)
if (logger_.use_count() == LAST_LOGGER_REF_COUNT)
{
spdlog::drop(logger_->name());
}
@@ -561,11 +561,6 @@ Logger::Pump::Pump(
, enabled_(logger_ != nullptr && logger_->should_log(toSpdlogLevel(sev)))
, jsonMode_(jsonMode)
{
if (enabled_ && jsonMode_)
{
// Open the quoted message value
stream_.push_back('"');
}
}
Logger::Pump::~Pump()
@@ -575,29 +570,39 @@ Logger::Pump::~Pump()
spdlog::source_loc const sourceLocation{
sourceLocation_.file_name(), static_cast<int>(sourceLocation_.line()), nullptr};
if (jsonMode_)
{
// Close the quoted message value
stream_.push_back('"');
// Append the parameters object if any were captured
if (!parameters_.empty())
{
static constexpr char kVALUES_OPEN[] = ", \"values\": {";
stream_.append(kVALUES_OPEN, kVALUES_OPEN + sizeof(kVALUES_OPEN) - 1);
stream_.append(parameters_.data(), parameters_.data() + parameters_.size());
stream_.push_back('}');
}
}
// Apply legacy safeguards: truncate oversized messages and scrub secrets
// Apply legacy safeguards on the raw message BEFORE JSON wrapping.
// This lets scrubSecrets short-circuit (no '"' in typical messages).
truncateMessage(stream_);
scrubSecrets(stream_);
logger_->log(
sourceLocation,
toSpdlogLevel(severity_),
std::string_view{stream_.data(), stream_.size()});
if (jsonMode_)
{
// Wrap the scrubbed message: "<message>", plus optional values object
fmt::memory_buffer wrapped;
wrapped.push_back('"');
wrapped.append(stream_.data(), stream_.data() + stream_.size());
wrapped.push_back('"');
if (!parameters_.empty())
{
static constexpr char valuesOpen[] = ", \"values\": {";
wrapped.append(valuesOpen, valuesOpen + sizeof(valuesOpen) - 1);
wrapped.append(parameters_.data(), parameters_.data() + parameters_.size());
wrapped.push_back('}');
}
logger_->log(
sourceLocation,
toSpdlogLevel(severity_),
std::string_view{wrapped.data(), wrapped.size()});
}
else
{
logger_->log(
sourceLocation,
toSpdlogLevel(severity_),
std::string_view{stream_.data(), stream_.size()});
}
}
}

View File

@@ -1,5 +1,6 @@
#include <xrpl/basics/Logger.h>
#include <xrpl/basics/Log.h>
#include <xrpl/basics/Number.h>
#include <xrpl/protocol/XRPAmount.h>
@@ -22,7 +23,6 @@ protected:
initLogging(bool jsonMode, std::string const& pattern = "%v", Severity severity = Severity::TRC)
{
LoggingConfiguration config{
.format = pattern,
.enableConsole = false,
.directory = std::nullopt,
.isAsync = false,
@@ -33,7 +33,8 @@ protected:
ASSERT_TRUE(result);
// Replace the (empty) sinks with our ostream sink so we can
// capture output in tests.
// capture output in tests. The `pattern` parameter controls
// the test sink's formatter independently of LogService's format.
auto sink = std::make_shared<spdlog::sinks::ostream_sink_mt>(output_);
sink->set_level(spdlog::level::trace);
sink->set_formatter(LogServiceState::makeFormatter(pattern));
@@ -233,6 +234,22 @@ TEST_F(LoggerFixture, severity_codes_in_default_format)
"Test:FTL f\n");
}
TEST_F(LoggerFixture, default_json_format)
{
// JSON mode should produce a JSON object with timestamp, channel,
// severity and message fields.
initLogging(true, defaultJsonLogFormat());
Logger logger("General");
logger.info() << "hello world";
auto const line = output_.str();
std::regex const expected(
R"(\{"timestamp":"\d{4}-[A-Z][a-z]{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{6} UTC")"
R"(,"channel":"General","severity":"NFO")"
R"(, "message": "hello world" \}\n)");
EXPECT_TRUE(std::regex_match(line, expected)) << "got: " << line;
}
// -- Secret scrubbing ---------------------------------------------------------
TEST_F(LoggerFixture, scrubs_seed)
@@ -260,6 +277,23 @@ TEST_F(LoggerFixture, scrubs_passphrase)
EXPECT_EQ(output_.str(), "{\"passphrase\":\"**************\"}\n");
}
TEST_F(LoggerFixture, scrubs_seed_json_mode)
{
initLogging(true);
Logger logger("ScrubJson");
logger.info() << R"({"seed":"sEdTM1uX8pu2do5XvTnutH6HsouMaM2"})";
// In JSON mode the message is wrapped in quotes, but scrubbing still works
EXPECT_EQ(output_.str(), "\"{\"seed\":\"*******************************\"}\"\n");
}
TEST_F(LoggerFixture, scrubs_master_key_json_mode)
{
initLogging(true);
Logger logger("ScrubJson2");
logger.info() << R"({"master_key":"SOME_SECRET_VALUE"})";
EXPECT_EQ(output_.str(), "\"{\"master_key\":\"*****************\"}\"\n");
}
// -- Message truncation -------------------------------------------------------
TEST_F(LoggerFixture, truncates_oversized_message)
@@ -276,3 +310,18 @@ TEST_F(LoggerFixture, truncates_oversized_message)
expected += "...\n";
EXPECT_EQ(output_.str(), expected);
}
TEST_F(LoggerFixture, truncates_oversized_message_json)
{
initLogging(true);
Logger logger("Trunc");
static constexpr std::size_t kMAX = 12 * 1024;
std::string const bigMessage(13000, 'x');
logger.info() << bigMessage << log::param("key", std::string("value"));
// and the values object is preserved in full.
std::string expected = "\"";
expected += std::string(kMAX - 3, 'x');
expected += "...\", \"values\": {\"key\":\"value\"}\n";
EXPECT_EQ(output_.str(), expected);
}