diff --git a/include/xrpl/basics/Logger.h b/include/xrpl/basics/Logger.h index e9d05d1939..5a8dfe7cb9 100644 --- a/include/xrpl/basics/Logger.h +++ b/include/xrpl/basics/Logger.h @@ -86,11 +86,12 @@ inline constexpr char const* kDEFAULT_LOG_FORMAT = "%Y-%b-%d %H:%M:%S.%f UTC %n: inline std::string defaultJsonLogFormat() { - return JsonLoggingPatternBuilder() - .add("timestamp", "%Y-%b-%d %H:%M:%S.%f UTC") - .add("channel", "%n") - .add("severity", "%K") - .build(); + using sv = std::string_view; + return buildJsonPattern( + "", + log::param("timestamp", sv("%Y-%b-%d %H:%M:%S.%f UTC")), + log::param("channel", sv("%n")), + log::param("severity", sv("%K"))); } struct LoggingConfiguration @@ -113,6 +114,8 @@ struct LoggingConfiguration class Logger { std::shared_ptr logger_; + std::string contextParams_; // inherited parameter fragments (JSON or text) + bool jsonMode_ = false; // captured at construction from LogServiceState friend class LogService; // to expose the Pump interface @@ -127,12 +130,18 @@ class Logger fmt::memory_buffer stream_; bool const enabled_; bool const jsonMode_; - std::string parameters_; // accumulated JSON parameter fragments + std::string_view contextParams_; // points into Logger's string (no copy) + std::string messageParams_; // per-message params (JSON mode only) public: ~Pump(); - Pump(spdlog::logger* logger, Severity sev, std::source_location const& loc, bool jsonMode); + Pump( + spdlog::logger* logger, + Severity sev, + std::source_location const& loc, + bool jsonMode, + std::string_view contextParams = {}); Pump(Pump&&) = delete; Pump(Pump const&) = delete; @@ -217,11 +226,7 @@ class Logger if (jsonMode_) { - // Also build up the parameters for the "values" object - if (!parameters_.empty()) - parameters_ += ','; - fmt::format_to(std::back_inserter(parameters_), "\"{}\":", p.name()); - detail::appendJsonValue(parameters_, p.value()); + detail::appendJsonField(messageParams_, p.name(), p.value()); } return *this; @@ -248,6 +253,27 @@ public: */ Logger(std::string_view const channel); + /** + * @brief Construct a child Logger that inherits context from a parent. + * + * The child uses a new channel and carries all of the parent's context + * parameters plus any additional parameters supplied here. Every log + * line produced by the child will automatically include these + * parameters in the JSON @c values object. + * + * @tparam Ts Value types of the extra parameters. + * @param parent The parent Logger whose context is inherited. + * @param channel The channel name for this child logger. + * @param params Extra context parameters to attach. + */ + template + Logger(Logger const& parent, std::string_view channel, log::Parameter const&... params) + : Logger(channel) + { + contextParams_ = parent.contextParams_; + (appendContextParam(params), ...); + } + Logger(Logger const&) = default; ~Logger(); @@ -314,6 +340,21 @@ public: private: Logger(std::shared_ptr logger); + + /** @brief Serialise a single parameter into contextParams_. */ + template + void + appendContextParam(log::Parameter const& p) + { + if (jsonMode_) + { + detail::appendJsonField(contextParams_, p.name(), p.value()); + } + else + { + detail::appendTextField(contextParams_, p.name(), p.value()); + } + } }; /** diff --git a/include/xrpl/basics/StructuredLogging.h b/include/xrpl/basics/StructuredLogging.h index d7375f7e11..9f520a3a32 100644 --- a/include/xrpl/basics/StructuredLogging.h +++ b/include/xrpl/basics/StructuredLogging.h @@ -65,148 +65,80 @@ appendJsonValue(std::string& dest, T const& value) } } -} // namespace detail +/** + * @brief Append a @c "key":value JSON field to @p dest. + * + * Inserts a comma separator when @p dest already contains fields. + * The value is formatted by @ref appendJsonValue. + */ +template +void +appendJsonField(std::string& dest, std::string_view key, T const& value) +{ + if (!dest.empty()) + dest += ','; + fmt::format_to(std::back_inserter(dest), "\"{}\":", key); + appendJsonValue(dest, value); +} /** - * @brief Builds a JSON-structured spdlog format pattern string. + * @brief Append a @c key=value plain-text field to @p dest. * - * This class produces a pattern string suitable for passing to - * @c spdlog::pattern_formatter. Each field maps a JSON key to an spdlog - * pattern flag (e.g. @c %t for thread ID, @c %n for channel name). + * Inserts a space separator when @p dest already contains fields. + */ +template +void +appendTextField(std::string& dest, std::string_view key, T const& value) +{ + if (!dest.empty()) + dest += ' '; + if constexpr (HasToString) + { + fmt::format_to(std::back_inserter(dest), "{}={}", key, to_string(value)); + } + else + { + fmt::format_to(std::back_inserter(dest), "{}={}", key, value); + } +} + +/** @brief Internal builder used by @ref buildJsonPattern. * - * The pattern ends with @c %%v so that the log message (a partial JSON - * fragment) is spliced in at the end. - * - * Composability is lightweight: construct from an existing pattern string - * (e.g. obtained from another logger's pattern) and append more fields. - * No map copying — just string concatenation. - * - * Common spdlog pattern flags: - * - @c %%v — the log message text - * - @c %%t — thread ID - * - @c %%n — logger/channel name - * - @c %%l — log level (e.g. "info", "warning") - * - @c %%Y-%%m-%%d %%H:%%M:%%S.%%e — date/time with milliseconds - * - @c %%s — source file name - * - @c %%# — source line number - * - @c %%P — process ID - * - * Example usage: - * @code - * // Build a fresh pattern - * JsonLoggingPatternBuilder builder; - * builder.add("timestamp", "%Y-%m-%d %H:%M:%S.%e"); - * builder.add("channel", "%n"); - * builder.add("level", "%l"); - * std::string pattern = builder.build(); - * // Produces: {"timestamp":"%Y-%m-%d %H:%M:%S.%e","channel":"%n","level":"%l" %v } - * - * // Extend an existing pattern from another logger - * JsonLoggingPatternBuilder extended(pattern); - * extended.add("source", "%s:%#"); - * std::string newPattern = extended.build(); - * // Produces: {"timestamp":"%Y-%m-%d %H:%M:%S.%e","channel":"%n","level":"%l","source":"%s:%#" - * %v } - * @endcode + * Not part of the public API — use @ref buildJsonPattern instead. */ class JsonLoggingPatternBuilder { - // Accumulated "key":"value" fragments, comma-separated. - // e.g. "\"timestamp\":\"%Y-%m-%d\",\"channel\":\"%n\"" std::string fields_; static constexpr std::string_view kSUFFIX = ", \"message\": %v }"; - /** - * @brief Extract the fields portion from an existing pattern string. - * - * Strips the leading '{' and trailing ' %%v }' suffix, leaving just - * the comma-separated field fragments. - */ static std::string extractFields(std::string_view pattern) { - // Strip leading '{' if (!pattern.empty() && pattern.front() == '{') pattern.remove_prefix(1); - - // Strip trailing ' %v }' if (auto pos = pattern.rfind(kSUFFIX); pos != std::string_view::npos) pattern = pattern.substr(0, pos); - return std::string(pattern); } public: - /** @brief Construct an empty builder. */ JsonLoggingPatternBuilder() = default; - /** - * @brief Construct from an existing pattern string. - * - * Extracts the fields from the pattern so that new fields can be - * appended. This is a lightweight string copy — no map involved. - * - * @param existingPattern A pattern previously produced by build(). - */ explicit JsonLoggingPatternBuilder(std::string_view existingPattern) : fields_(extractFields(existingPattern)) { } - /** - * @brief Add a field to the JSON pattern. - * - * The value is an spdlog pattern flag or any literal text that spdlog - * will expand at log time. - * - * @param key The JSON field name (e.g. "timestamp", "thread"). - * @param value The spdlog pattern string (e.g. "%%Y-%%m-%%d", "%%t"). - * @return Reference to this builder for chaining. - */ - JsonLoggingPatternBuilder& - add(std::string_view key, std::string_view value) - { - if (!fields_.empty()) - fields_ += ','; - fmt::format_to(std::back_inserter(fields_), "\"{}\":\"{}\"", key, value); - return *this; - } - - /** - * @brief Add a typed field to the JSON pattern. - * - * Uses @ref detail::appendJsonValue to format the value as a JSON - * fragment (unquoted for numbers/bools, quoted for everything else). - * - * @tparam T The value type (bool, integral, floating-point, or streamable). - * @param key The JSON field name. - * @param value The value to embed. - * @return Reference to this builder for chaining. - */ + /** @brief Add a field. Delegates to @ref appendJsonField. */ template - requires(!std::is_convertible_v) JsonLoggingPatternBuilder& add(std::string_view key, T const& value) { - if (!fields_.empty()) - fields_ += ','; - fmt::format_to(std::back_inserter(fields_), "\"{}\":", key); - detail::appendJsonValue(fields_, value); + appendJsonField(fields_, key, value); return *this; } - /** - * @brief Build the final spdlog-compatible pattern string. - * - * Produces a compact JSON object where each value contains the raw - * spdlog pattern flags, terminated with %%v for the message body: - * @code - * {"level":"%l","channel":"%n" %v } - * @endcode - * - * @return The pattern string to pass to spdlog::pattern_formatter. - */ [[nodiscard]] std::string build() const { @@ -214,6 +146,8 @@ public: } }; +} // namespace detail + namespace log { /** @@ -267,4 +201,38 @@ param(std::string_view name, T&& value) } // namespace log +/** + * @brief Build or extend a JSON log pattern from @ref log::Parameter objects. + * + * Each parameter's name becomes a JSON key and its value becomes the + * corresponding JSON value in the spdlog pattern string. String-like + * values are treated as spdlog pattern flags (e.g. @c "%%n", @c "%%l"); + * numeric and boolean values are embedded as literals. + * + * @code + * // Build from scratch (empty existing pattern) + * auto pattern = buildJsonPattern("", + * log::param("channel", std::string_view("%n")), + * log::param("level", std::string_view("%l"))); + * + * // Extend an existing pattern with extra fields + * auto extended = buildJsonPattern(pattern, + * log::param("trace_id", traceId)); + * @endcode + * + * @tparam Ts Value types of the parameters. + * @param existingPattern A pattern previously produced by build() or an + * empty string to start fresh. + * @param params The parameters to add as JSON fields. + * @return The spdlog-compatible JSON pattern string. + */ +template +[[nodiscard]] std::string +buildJsonPattern(std::string_view existingPattern, log::Parameter const&... params) +{ + detail::JsonLoggingPatternBuilder builder(existingPattern); + (builder.add(params.name(), params.value()), ...); + return builder.build(); +} + } // namespace xrpl diff --git a/src/libxrpl/basics/Logger.cpp b/src/libxrpl/basics/Logger.cpp index 754a159b7a..99666a6f94 100644 --- a/src/libxrpl/basics/Logger.cpp +++ b/src/libxrpl/basics/Logger.cpp @@ -530,7 +530,8 @@ LogServiceState::makeFormatter(std::string const& pattern) return createPatternFormatter(pattern); } -Logger::Logger(std::string_view const channel) : logger_(LogServiceState::registerLogger(channel)) +Logger::Logger(std::string_view const channel) + : logger_(LogServiceState::registerLogger(channel)), jsonMode_(LogServiceState::jsonMode_) { } @@ -554,12 +555,14 @@ Logger::Pump::Pump( spdlog::logger* logger, Severity sev, std::source_location const& loc, - bool jsonMode) + bool jsonMode, + std::string_view contextParams) : logger_(logger) , severity_(sev) , sourceLocation_(loc) , enabled_(logger_ != nullptr && logger_->should_log(toSpdlogLevel(sev))) , jsonMode_(jsonMode) + , contextParams_(contextParams) { } @@ -583,11 +586,18 @@ Logger::Pump::~Pump() wrapped.append(stream_.data(), stream_.data() + stream_.size()); wrapped.push_back('"'); - if (!parameters_.empty()) + bool const hasContext = !contextParams_.empty(); + bool const hasMessage = !messageParams_.empty(); + if (hasContext || hasMessage) { static constexpr char valuesOpen[] = ", \"values\": {"; wrapped.append(valuesOpen, valuesOpen + sizeof(valuesOpen) - 1); - wrapped.append(parameters_.data(), parameters_.data() + parameters_.size()); + wrapped.append( + contextParams_.data(), contextParams_.data() + contextParams_.size()); + if (hasContext && hasMessage) + wrapped.push_back(','); + wrapped.append( + messageParams_.data(), messageParams_.data() + messageParams_.size()); wrapped.push_back('}'); } @@ -598,10 +608,27 @@ Logger::Pump::~Pump() } else { - logger_->log( - sourceLocation, - toSpdlogLevel(severity_), - std::string_view{stream_.data(), stream_.size()}); + if (!contextParams_.empty()) + { + // Prepend [key=val ...] context to the message + fmt::memory_buffer buf; + buf.push_back('['); + buf.append(contextParams_.data(), contextParams_.data() + contextParams_.size()); + static constexpr char close[] = "] "; + buf.append(close, close + 2); + buf.append(stream_.data(), stream_.data() + stream_.size()); + logger_->log( + sourceLocation, + toSpdlogLevel(severity_), + std::string_view{buf.data(), buf.size()}); + } + else + { + logger_->log( + sourceLocation, + toSpdlogLevel(severity_), + std::string_view{stream_.data(), stream_.size()}); + } } } } @@ -609,35 +636,36 @@ Logger::Pump::~Pump() Logger::Pump Logger::trace(std::source_location const& loc) const { - return {logger_.get(), Severity::TRC, loc, LogServiceState::jsonMode_}; + return {logger_.get(), Severity::TRC, loc, LogServiceState::jsonMode_, contextParams_}; } Logger::Pump Logger::debug(std::source_location const& loc) const { - return {logger_.get(), Severity::DBG, loc, LogServiceState::jsonMode_}; + return {logger_.get(), Severity::DBG, loc, LogServiceState::jsonMode_, contextParams_}; } Logger::Pump Logger::info(std::source_location const& loc) const { - return {logger_.get(), Severity::NFO, loc, LogServiceState::jsonMode_}; + return {logger_.get(), Severity::NFO, loc, LogServiceState::jsonMode_, contextParams_}; } Logger::Pump Logger::warn(std::source_location const& loc) const { - return {logger_.get(), Severity::WRN, loc, LogServiceState::jsonMode_}; + return {logger_.get(), Severity::WRN, loc, LogServiceState::jsonMode_, contextParams_}; } Logger::Pump Logger::error(std::source_location const& loc) const { - return {logger_.get(), Severity::ERR, loc, LogServiceState::jsonMode_}; + return {logger_.get(), Severity::ERR, loc, LogServiceState::jsonMode_, contextParams_}; } Logger::Pump Logger::fatal(std::source_location const& loc) const { - return {logger_.get(), Severity::FTL, loc, LogServiceState::jsonMode_}; + return {logger_.get(), Severity::FTL, loc, LogServiceState::jsonMode_, contextParams_}; } -Logger::Logger(std::shared_ptr logger) : logger_(std::move(logger)) +Logger::Logger(std::shared_ptr logger) + : logger_(std::move(logger)), jsonMode_(LogServiceState::jsonMode_) { } diff --git a/src/tests/libxrpl/basics/Logger.cpp b/src/tests/libxrpl/basics/Logger.cpp index c7d6301395..aff6c3f976 100644 --- a/src/tests/libxrpl/basics/Logger.cpp +++ b/src/tests/libxrpl/basics/Logger.cpp @@ -19,8 +19,11 @@ class LoggerFixture : public ::testing::Test protected: std::ostringstream output_; + // Regex fragment matching the UTC timestamp produced by spdlog + static constexpr char kTS_RE[] = R"(\d{4}-[A-Z][a-z]{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{6} UTC)"; + void - initLogging(bool jsonMode, std::string const& pattern = "%v", Severity severity = Severity::TRC) + initLogging(bool jsonMode, Severity severity = Severity::TRC) { LoggingConfiguration config{ .enableConsole = false, @@ -32,15 +35,55 @@ protected: auto const result = LogService::init(config); ASSERT_TRUE(result); - // Replace the (empty) sinks with our ostream sink so we can - // capture output in tests. The `pattern` parameter controls - // the test sink's formatter independently of LogService's format. + // Replace the (empty) sinks with our ostream sink using the + // effective format chosen by LogService (text or JSON). auto sink = std::make_shared(output_); sink->set_level(spdlog::level::trace); - sink->set_formatter(LogServiceState::makeFormatter(pattern)); + sink->set_formatter(LogServiceState::makeFormatter(LogServiceState::format())); LogServiceState::replaceSinks({sink}); } + /// Escape special regex characters in a literal string. + static std::string + escapeRegex(std::string_view s) + { + std::string result; + for (char c : s) + { + if (std::string_view(R"(\^$.|?*+()[]{}-)").find(c) != std::string_view::npos) + result += '\\'; + result += c; + } + return result; + } + + /// Assert that the captured output matches the expected text-mode line. + /// Format: channel:sev message\n + void + expectText(std::string_view channel, std::string_view sev, std::string_view message) + { + auto const& line = output_.str(); + auto const re = fmt::format("{} {}:{} {}\n", kTS_RE, channel, sev, escapeRegex(message)); + EXPECT_TRUE(std::regex_match(line, std::regex(re))) << "got: " << line; + } + + /// Assert that the captured output matches the expected JSON-mode line. + /// Format: {"timestamp":"...","channel":"...","severity":"...", + /// "message": }\n + void + expectJson(std::string_view channel, std::string_view sev, std::string_view msgPart) + { + auto const& line = output_.str(); + auto const re = fmt::format( + R"(\{{"timestamp":"{}","channel":"{}","severity":"{}")" + R"(, "message": {} \}}\n)", + kTS_RE, + channel, + sev, + escapeRegex(msgPart)); + EXPECT_TRUE(std::regex_match(line, std::regex(re))) << "got: " << line; + } + void TearDown() override { @@ -57,7 +100,7 @@ TEST_F(LoggerFixture, plain_text_simple_message) initLogging(false); Logger logger("TestChannel"); logger.info() << "hello world"; - EXPECT_EQ(output_.str(), "hello world\n"); + expectText("TestChannel", "NFO", "hello world"); } TEST_F(LoggerFixture, plain_text_multiple_values) @@ -65,7 +108,7 @@ TEST_F(LoggerFixture, plain_text_multiple_values) initLogging(false); Logger logger("TestChannel2"); logger.info() << "count=" << 42 << " active=" << true; - EXPECT_EQ(output_.str(), "count=42 active=true\n"); + expectText("TestChannel2", "NFO", "count=42 active=true"); } TEST_F(LoggerFixture, plain_text_with_parameter) @@ -74,7 +117,7 @@ TEST_F(LoggerFixture, plain_text_with_parameter) Logger logger("TestChannel3"); logger.info() << "tx " << log::param("hash", "ABC"); // In plain text mode, parameter value is just streamed - EXPECT_EQ(output_.str(), "tx ABC\n"); + expectText("TestChannel3", "NFO", "tx ABC"); } // -- JSON mode --------------------------------------------------------------- @@ -84,8 +127,7 @@ TEST_F(LoggerFixture, json_mode_simple_message) initLogging(true); Logger logger("JsonChannel"); logger.info() << "hello world"; - // In JSON mode, message is quoted - EXPECT_EQ(output_.str(), "\"hello world\"\n"); + expectJson("JsonChannel", "NFO", "\"hello world\""); } TEST_F(LoggerFixture, json_mode_with_parameters) @@ -94,11 +136,11 @@ TEST_F(LoggerFixture, json_mode_with_parameters) Logger logger("JsonChannel2"); logger.info() << "processing " << log::param("tx_hash", std::string("ABC123")) << " amount=" << log::param("amount", 42); - // Message body is quoted, then values object appended - EXPECT_EQ( - output_.str(), + expectJson( + "JsonChannel2", + "NFO", "\"processing ABC123 amount=42\", " - "\"values\": {\"tx_hash\":\"ABC123\",\"amount\":42}\n"); + "\"values\": {\"tx_hash\":\"ABC123\",\"amount\":42}"); } TEST_F(LoggerFixture, json_mode_no_parameters) @@ -106,21 +148,7 @@ TEST_F(LoggerFixture, json_mode_no_parameters) initLogging(true); Logger logger("JsonChannel3"); logger.info() << "simple message"; - // No values object when no parameters - EXPECT_EQ(output_.str(), "\"simple message\"\n"); -} - -TEST_F(LoggerFixture, json_mode_with_pattern) -{ - std::string pattern = - JsonLoggingPatternBuilder().add("level", "%l").add("channel", "%n").build(); - initLogging(true, pattern); - Logger logger("Overlay"); - logger.info() << "peer connected"; - EXPECT_EQ( - output_.str(), - "{\"level\":\"info\",\"channel\":\"Overlay\"," - " \"message\": \"peer connected\" }\n"); + expectJson("JsonChannel3", "NFO", "\"simple message\""); } TEST_F(LoggerFixture, json_mode_bool_parameter) @@ -128,21 +156,21 @@ TEST_F(LoggerFixture, json_mode_bool_parameter) initLogging(true); Logger logger("JsonChannel4"); logger.info() << "status " << log::param("active", true); - EXPECT_EQ(output_.str(), "\"status true\", \"values\": {\"active\":true}\n"); + expectJson("JsonChannel4", "NFO", "\"status true\", \"values\": {\"active\":true}"); } // -- Severity filtering ------------------------------------------------------ TEST_F(LoggerFixture, severity_filtering) { - initLogging(false, "%v", Severity::WRN); + initLogging(false, Severity::WRN); Logger logger("FilterChannel"); logger.info() << "should not appear"; EXPECT_TRUE(output_.str().empty()); logger.warn() << "should appear"; - EXPECT_EQ(output_.str(), "should appear\n"); + expectText("FilterChannel", "WRN", "should appear"); } // -- xrpl::to_string integration -------------------------------------------- @@ -152,7 +180,7 @@ TEST_F(LoggerFixture, text_mode_xrp_amount) initLogging(false); Logger logger("AmountChannel"); logger.info() << "balance: " << XRPAmount{1000}; - EXPECT_EQ(output_.str(), "balance: 1000\n"); + expectText("AmountChannel", "NFO", "balance: 1000"); } TEST_F(LoggerFixture, json_mode_xrp_amount) @@ -160,7 +188,7 @@ TEST_F(LoggerFixture, json_mode_xrp_amount) initLogging(true); Logger logger("AmountChannel"); logger.info() << "balance " << XRPAmount{500}; - EXPECT_EQ(output_.str(), "\"balance 500\"\n"); + expectJson("AmountChannel", "NFO", "\"balance 500\""); } TEST_F(LoggerFixture, json_mode_xrp_amount_parameter) @@ -168,7 +196,7 @@ TEST_F(LoggerFixture, json_mode_xrp_amount_parameter) initLogging(true); Logger logger("AmountChannel"); logger.info() << "tx" << log::param("fee", XRPAmount{10}); - EXPECT_EQ(output_.str(), "\"tx10\", \"values\": {\"fee\":\"10\"}\n"); + expectJson("AmountChannel", "NFO", "\"tx10\", \"values\": {\"fee\":\"10\"}"); } TEST_F(LoggerFixture, text_mode_number) @@ -176,7 +204,7 @@ TEST_F(LoggerFixture, text_mode_number) initLogging(false); Logger logger("NumberChannel"); logger.info() << "result: " << Number{42}; - EXPECT_EQ(output_.str(), "result: 42\n"); + expectText("NumberChannel", "NFO", "result: 42"); } TEST_F(LoggerFixture, json_mode_number) @@ -184,7 +212,7 @@ TEST_F(LoggerFixture, json_mode_number) initLogging(true); Logger logger("NumberChannel"); logger.info() << "value " << Number{25, -3}; - EXPECT_EQ(output_.str(), "\"value 0.025\"\n"); + expectJson("NumberChannel", "NFO", "\"value 0.025\""); } TEST_F(LoggerFixture, json_mode_number_parameter) @@ -192,29 +220,14 @@ TEST_F(LoggerFixture, json_mode_number_parameter) initLogging(true); Logger logger("NumberChannel"); logger.info() << "calc" << log::param("rate", Number{100}); - EXPECT_EQ(output_.str(), "\"calc100\", \"values\": {\"rate\":\"100\"}\n"); + expectJson("NumberChannel", "NFO", "\"calc100\", \"values\": {\"rate\":\"100\"}"); } -// -- Legacy format matching --------------------------------------------------- - -TEST_F(LoggerFixture, default_format_matches_legacy) -{ - // Use the default format (kDEFAULT_LOG_FORMAT) which includes %K for severity - initLogging(false, kDEFAULT_LOG_FORMAT); - Logger logger("General"); - logger.info() << "hello world"; - auto const line = output_.str(); - - // The full output must be: - // YYYY-Mon-DD HH:MM:SS.ffffff UTC General:NFO hello world\n - std::regex const expected( - R"(\d{4}-[A-Z][a-z]{2}-\d{2} \d{2}:\d{2}:\d{2}\.\d{6} UTC General:NFO hello world\n)"); - EXPECT_TRUE(std::regex_match(line, expected)) << "got: " << line; -} +// -- Severity codes ----------------------------------------------------------- TEST_F(LoggerFixture, severity_codes_in_default_format) { - initLogging(false, "%n:%K %v"); + initLogging(false); Logger logger("Test"); logger.trace() << "t"; @@ -224,30 +237,87 @@ TEST_F(LoggerFixture, severity_codes_in_default_format) logger.error() << "e"; logger.fatal() << "f"; - EXPECT_EQ( - output_.str(), - "Test:TRC t\n" - "Test:DBG d\n" - "Test:NFO i\n" - "Test:WRN w\n" - "Test:ERR e\n" - "Test:FTL f\n"); + // Each line has the full default format; build a regex for all six. + auto const line = [&](std::string_view sev, std::string_view msg) { + return fmt::format("{} Test:{} {}\n", kTS_RE, sev, msg); + }; + std::string re; + re += line("TRC", "t"); + re += line("DBG", "d"); + re += line("NFO", "i"); + re += line("WRN", "w"); + re += line("ERR", "e"); + re += line("FTL", "f"); + EXPECT_TRUE(std::regex_match(output_.str(), std::regex(re))) << "got: " << output_.str(); } -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(); +// -- Pattern builder function ------------------------------------------------- - 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; +TEST_F(LoggerFixture, build_json_pattern_from_scratch) +{ + auto pattern = buildJsonPattern( + "", + log::param("channel", std::string_view("%n")), + log::param("level", std::string_view("%l"))); + EXPECT_EQ(pattern, R"({"channel":"%n","level":"%l", "message": %v })"); +} + +TEST_F(LoggerFixture, build_json_pattern_extends_existing) +{ + auto const base = buildJsonPattern("", log::param("channel", std::string_view("%n"))); + auto const extended = buildJsonPattern(base, log::param("trace_id", std::string("abc123"))); + EXPECT_EQ(extended, R"({"channel":"%n","trace_id":"abc123", "message": %v })"); +} + +// -- Logger context inheritance ----------------------------------------------- + +TEST_F(LoggerFixture, child_logger_inherits_context_params) +{ + initLogging(true); + Logger parent("Parent"); + Logger child(parent, "Child", log::param("peer_id", std::string("abc"))); + child.info() << "hello"; + expectJson("Child", "NFO", "\"hello\", \"values\": {\"peer_id\":\"abc\"}"); +} + +TEST_F(LoggerFixture, child_logger_merges_context_and_message_params) +{ + initLogging(true); + Logger parent("Parent"); + Logger child(parent, "Child", log::param("peer_id", std::string("abc"))); + child.info() << "event" << log::param("count", 42); + expectJson("Child", "NFO", "\"event42\", \"values\": {\"peer_id\":\"abc\",\"count\":42}"); +} + +TEST_F(LoggerFixture, grandchild_logger_accumulates_context) +{ + initLogging(true); + Logger root("Root"); + Logger child(root, "Child", log::param("trace_id", std::string("t1"))); + Logger grandchild(child, "Grandchild", log::param("span_id", std::string("s1"))); + grandchild.info() << "deep"; + expectJson( + "Grandchild", "NFO", "\"deep\", \"values\": {\"trace_id\":\"t1\",\"span_id\":\"s1\"}"); +} + +TEST_F(LoggerFixture, context_params_in_text_mode) +{ + initLogging(false); + Logger parent("Parent"); + Logger child(parent, "Child", log::param("peer_id", std::string("abc"))); + child.info() << "hello"; + // In text mode, context params are shown as [key=val] prefix + expectText("Child", "NFO", "[peer_id=abc] hello"); +} + +TEST_F(LoggerFixture, context_params_text_mode_multiple) +{ + initLogging(false); + Logger root("Root"); + Logger child(root, "Child", log::param("trace_id", std::string("t1"))); + Logger grandchild(child, "GC", log::param("span_id", std::string("s1"))); + grandchild.info() << "deep"; + expectText("GC", "NFO", "[trace_id=t1 span_id=s1] deep"); } // -- Secret scrubbing --------------------------------------------------------- @@ -258,7 +328,7 @@ TEST_F(LoggerFixture, scrubs_seed) Logger logger("Scrub"); logger.info() << R"({"seed":"sEdTM1uX8pu2do5XvTnutH6HsouMaM2"})"; // 31 chars in the seed value → 31 asterisks - EXPECT_EQ(output_.str(), "{\"seed\":\"*******************************\"}\n"); + expectText("Scrub", "NFO", R"({"seed":"*******************************"})"); } TEST_F(LoggerFixture, scrubs_master_key) @@ -266,7 +336,7 @@ TEST_F(LoggerFixture, scrubs_master_key) initLogging(false); Logger logger("Scrub2"); logger.info() << R"({"master_key":"SOME_SECRET_VALUE"})"; - EXPECT_EQ(output_.str(), "{\"master_key\":\"*****************\"}\n"); + expectText("Scrub2", "NFO", R"({"master_key":"*****************"})"); } TEST_F(LoggerFixture, scrubs_passphrase) @@ -274,7 +344,7 @@ TEST_F(LoggerFixture, scrubs_passphrase) initLogging(false); Logger logger("Scrub3"); logger.info() << R"({"passphrase":"my_secret_pass"})"; - EXPECT_EQ(output_.str(), "{\"passphrase\":\"**************\"}\n"); + expectText("Scrub3", "NFO", R"({"passphrase":"**************"})"); } TEST_F(LoggerFixture, scrubs_seed_json_mode) @@ -283,7 +353,7 @@ TEST_F(LoggerFixture, scrubs_seed_json_mode) 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"); + expectJson("ScrubJson", "NFO", "\"{\"seed\":\"*******************************\"}\""); } TEST_F(LoggerFixture, scrubs_master_key_json_mode) @@ -291,7 +361,7 @@ 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"); + expectJson("ScrubJson2", "NFO", "\"{\"master_key\":\"*****************\"}\""); } // -- Message truncation ------------------------------------------------------- @@ -305,10 +375,10 @@ TEST_F(LoggerFixture, truncates_oversized_message) std::string const bigMessage(13000, 'x'); logger.info() << bigMessage; - // Expected: (kMAX - 3) 'x' chars + "..." + newline - std::string expected(kMAX - 3, 'x'); - expected += "...\n"; - EXPECT_EQ(output_.str(), expected); + // The message body is truncated; full line includes timestamp prefix. + std::string truncatedMsg(kMAX - 3, 'x'); + truncatedMsg += "..."; + expectText("Trunc", "NFO", truncatedMsg); } TEST_F(LoggerFixture, truncates_oversized_message_json) @@ -319,9 +389,9 @@ TEST_F(LoggerFixture, truncates_oversized_message_json) 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); + // Message body is truncated; values object is preserved in full. + std::string msgPart = "\""; + msgPart += std::string(kMAX - 3, 'x'); + msgPart += "...\", \"values\": {\"key\":\"value\"}"; + expectJson("Trunc", "NFO", msgPart); } diff --git a/src/tests/libxrpl/basics/StructuredLogging.cpp b/src/tests/libxrpl/basics/StructuredLogging.cpp index 096ab4dc59..77b3fc2d4b 100644 --- a/src/tests/libxrpl/basics/StructuredLogging.cpp +++ b/src/tests/libxrpl/basics/StructuredLogging.cpp @@ -61,55 +61,55 @@ TEST(AppendJsonValue, appends_to_existing) EXPECT_EQ(dest, "prefix:99"); } -// -- JsonLoggingPatternBuilder ----------------------------------------------- +// -- buildJsonPattern -------------------------------------------------------- -TEST(JsonLoggingPatternBuilder, empty_build) +TEST(BuildJsonPattern, no_params) { - JsonLoggingPatternBuilder builder; - EXPECT_EQ(builder.build(), "{, \"message\": %v }"); + auto const pattern = buildJsonPattern(""); + EXPECT_EQ(pattern, "{, \"message\": %v }"); } -TEST(JsonLoggingPatternBuilder, single_string_field) +TEST(BuildJsonPattern, single_string_field) { - JsonLoggingPatternBuilder builder; - builder.add("level", "%l"); - EXPECT_EQ(builder.build(), "{\"level\":\"%l\", \"message\": %v }"); + auto const pattern = buildJsonPattern("", log::param("level", std::string_view("%l"))); + EXPECT_EQ(pattern, "{\"level\":\"%l\", \"message\": %v }"); } -TEST(JsonLoggingPatternBuilder, multiple_string_fields) +TEST(BuildJsonPattern, multiple_string_fields) { - JsonLoggingPatternBuilder builder; - builder.add("level", "%l"); - builder.add("channel", "%n"); - EXPECT_EQ(builder.build(), "{\"level\":\"%l\",\"channel\":\"%n\", \"message\": %v }"); + auto const pattern = buildJsonPattern( + "", + log::param("level", std::string_view("%l")), + log::param("channel", std::string_view("%n"))); + EXPECT_EQ(pattern, "{\"level\":\"%l\",\"channel\":\"%n\", \"message\": %v }"); } -TEST(JsonLoggingPatternBuilder, typed_fields) +TEST(BuildJsonPattern, typed_fields) { - JsonLoggingPatternBuilder builder; - builder.add("enabled", true); - builder.add("count", 5); - EXPECT_EQ(builder.build(), "{\"enabled\":true,\"count\":5, \"message\": %v }"); + auto const pattern = buildJsonPattern("", log::param("enabled", true), log::param("count", 5)); + EXPECT_EQ(pattern, "{\"enabled\":true,\"count\":5, \"message\": %v }"); } -TEST(JsonLoggingPatternBuilder, chaining) +TEST(BuildJsonPattern, many_fields) { - JsonLoggingPatternBuilder builder; - builder.add("a", "1").add("b", "2").add("c", "3"); - EXPECT_EQ(builder.build(), "{\"a\":\"1\",\"b\":\"2\",\"c\":\"3\", \"message\": %v }"); + auto const pattern = buildJsonPattern( + "", + log::param("a", std::string_view("1")), + log::param("b", std::string_view("2")), + log::param("c", std::string_view("3"))); + EXPECT_EQ(pattern, "{\"a\":\"1\",\"b\":\"2\",\"c\":\"3\", \"message\": %v }"); } -TEST(JsonLoggingPatternBuilder, from_existing_pattern) +TEST(BuildJsonPattern, extends_existing_pattern) { - JsonLoggingPatternBuilder original; - original.add("level", "%l").add("channel", "%n"); - auto const pattern = original.build(); + auto const base = buildJsonPattern( + "", + log::param("level", std::string_view("%l")), + log::param("channel", std::string_view("%n"))); - JsonLoggingPatternBuilder extended(pattern); - extended.add("source", "%s:%#"); + auto const extended = buildJsonPattern(base, log::param("source", std::string_view("%s:%#"))); EXPECT_EQ( - extended.build(), - "{\"level\":\"%l\",\"channel\":\"%n\",\"source\":\"%s:%#\", \"message\": %v }"); + extended, "{\"level\":\"%l\",\"channel\":\"%n\",\"source\":\"%s:%#\", \"message\": %v }"); } // -- log::Parameter / log::param ---------------------------------------------