diff --git a/include/xrpl/basics/Logger.h b/include/xrpl/basics/Logger.h index f639bb286b..e9d05d1939 100644 --- a/include/xrpl/basics/Logger.h +++ b/include/xrpl/basics/Logger.h @@ -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 directory; bool isAsync; @@ -379,6 +398,19 @@ protected: static std::unique_ptr 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::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]] diff --git a/include/xrpl/basics/StructuredLogging.h b/include/xrpl/basics/StructuredLogging.h index a1e2378b53..d7375f7e11 100644 --- a/include/xrpl/basics/StructuredLogging.h +++ b/include/xrpl/basics/StructuredLogging.h @@ -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 diff --git a/src/libxrpl/basics/Logger.cpp b/src/libxrpl/basics/Logger.cpp index 048c1b61b5..754a159b7a 100644 --- a/src/libxrpl/basics/Logger.cpp +++ b/src/libxrpl/basics/Logger.cpp @@ -393,10 +393,8 @@ LogServiceState::registerLogger(std::string_view channel, std::optional, std::string> -LogService::getSinks(LoggingConfiguration const& config) +LogService::getSinks(LoggingConfiguration const& config, std::string const& format) { - std::string const format = config.format; - std::vector allSinks = createConsoleSinks(config.enableConsole, format); if (config.directory.has_value()) @@ -422,14 +420,16 @@ LogService::getSinks(LoggingConfiguration const& config) Expected 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(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: "", 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()}); + } } } diff --git a/src/tests/libxrpl/basics/Logger.cpp b/src/tests/libxrpl/basics/Logger.cpp index 2bbacb0edc..c7d6301395 100644 --- a/src/tests/libxrpl/basics/Logger.cpp +++ b/src/tests/libxrpl/basics/Logger.cpp @@ -1,5 +1,6 @@ #include +#include #include #include @@ -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(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); +}