feat: Pull Logger from Clio and add structured logging#7055
Draft
feat: Pull Logger from Clio and add structured logging#7055
Conversation
Contributor
Author
|
Performance benchmark results show that the new logging infrastructure is around 3 times after than the existing one: Test code: // -- Performance comparison ---------------------------------------------------
TEST_F(LoggerFixture, perf_new_vs_old_logger)
{
// Set up new logger with an ostream sink (discards output via ostringstream)
initLogging(false, kDEFAULT_LOG_FORMAT);
Logger logger("PerfChannel");
// Set up old logger
Logs oldLogs(beast::severities::kTrace);
auto oldJournal = oldLogs.journal("PerfChannel");
static constexpr int iterations = 100'000;
// -- Benchmark new logger --
auto const newStart = std::chrono::steady_clock::now();
for (int i = 0; i < iterations; ++i)
{
LOG(logger.info()) << "hello world " << i;
}
auto const newElapsed = std::chrono::steady_clock::now() - newStart;
// -- Benchmark old logger --
auto const oldStart = std::chrono::steady_clock::now();
for (int i = 0; i < iterations; ++i)
{
JLOG(oldJournal.info()) << "hello world " << i;
}
auto const oldElapsed = std::chrono::steady_clock::now() - oldStart;
auto const newMs = std::chrono::duration_cast<std::chrono::milliseconds>(newElapsed).count();
auto const oldMs = std::chrono::duration_cast<std::chrono::milliseconds>(oldElapsed).count();
std::cerr << "\n=== Logger performance (" << iterations << " iterations) ===\n"
<< " New (spdlog): " << newMs << " ms\n"
<< " Old (Logs): " << oldMs << " ms\n"
<< std::endl;
// The new logger should not be dramatically slower than the old one.
// We allow up to 3x as a generous bound (actual should be faster or similar).
EXPECT_LE(newMs, oldMs * 3) << "New logger is unexpectedly slow";
}
TEST_F(LoggerFixture, perf_new_vs_old_logger_json)
{
// Build a JSON pattern with the same fields as kDEFAULT_LOG_FORMAT:
// timestamp, channel, severity
auto const jsonPattern = JsonLoggingPatternBuilder()
.add("timestamp", "%Y-%b-%d %H:%M:%S.%f UTC")
.add("channel", "%n")
.add("severity", "%K")
.build();
initLogging(true, jsonPattern);
Logger logger("PerfChannel");
// Set up old logger (no JSON equivalent — same baseline)
Logs oldLogs(beast::severities::kTrace);
auto oldJournal = oldLogs.journal("PerfChannel");
static constexpr int iterations = 100'000;
// -- Benchmark new logger (JSON) --
auto const newStart = std::chrono::steady_clock::now();
for (int i = 0; i < iterations; ++i)
{
LOG(logger.info()) << "hello world " << i;
}
auto const newElapsed = std::chrono::steady_clock::now() - newStart;
// -- Benchmark old logger (plain text baseline) --
auto const oldStart = std::chrono::steady_clock::now();
for (int i = 0; i < iterations; ++i)
{
JLOG(oldJournal.info()) << "hello world " << i;
}
auto const oldElapsed = std::chrono::steady_clock::now() - oldStart;
auto const newMs = std::chrono::duration_cast<std::chrono::milliseconds>(newElapsed).count();
auto const oldMs = std::chrono::duration_cast<std::chrono::milliseconds>(oldElapsed).count();
std::cerr << "\n=== Logger performance JSON mode (" << iterations << " iterations) ===\n"
<< " New (spdlog/JSON): " << newMs << " ms\n"
<< " Old (Logs/text): " << oldMs << " ms\n"
<< std::endl;
EXPECT_LE(newMs, oldMs * 3) << "New JSON logger is unexpectedly slow";
}
|
Codecov Report❌ Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## develop #7055 +/- ##
=========================================
+ Coverage 82.1% 82.2% +0.1%
=========================================
Files 1010 1013 +3
Lines 76054 76401 +347
Branches 7380 7376 -4
=========================================
+ Hits 62424 62767 +343
- Misses 13630 13634 +4
🚀 New features to boost your workflow:
|
Removed unnecessary include for unistd.h
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Add this suggestion to a batch that can be applied as a single commit.This suggestion is invalid because no changes were made to the code.Suggestions cannot be applied while the pull request is closed.Suggestions cannot be applied while viewing a subset of changes.Only one suggestion per line can be applied in a batch.Add this suggestion to a batch that can be applied as a single commit.Applying suggestions on deleted lines is not supported.You must change the existing code in this line in order to create a valid suggestion.Outdated suggestions cannot be applied.This suggestion has been applied or marked resolved.Suggestions cannot be applied from pending reviews.Suggestions cannot be applied on multi-line comments.Suggestions cannot be applied while the pull request is queued to merge.Suggestion cannot be applied right now. Please check back later.
High Level Overview of Change
This PR introduces structured JSON logging to
xrpldvia a new spdlog-backedLoggerclass, sitting alongside the existingLogsclass. The key changes are:JSON logging mode — a new
jsonModeflag onLoggingConfigurationswitches between two output formats:kDEFAULT_LOG_FORMAT, producing output identical to the existingLogsclass:defaultJsonLogFormat(), producing structured output:{"timestamp":"2024-Jan-15 12:34:56.789123 UTC","channel":"General","severity":"NFO", "message": "hello world" }Pumpaccumulates structured parameters passed vialog::param()into avaluesobject alongside the message:{"timestamp":"...","channel":"Overlay","severity":"NFO", "message": "peer abc connected, latency 42", "values": {"peer_id":"abc","latency":42} }log::param()values are inlined into the message body and parameter names are ignored, preserving backward compatibility.Secret scrubbing — the scrubber from the existing
Logsclass (seed,master_key,passphraseredaction) is carried over to the new implementation, running on the raw message buffer before any JSON wrapping.Logger context inheritance — a child
Loggercan be constructed from a parent, inheriting its context parameters and adding new ones. This works in both modes:valuesobject of every log entry.[trace_id=t1 span_id=s1] message.This gives us a natural integration point for OpenTelemetry trace/span propagation.
Message truncation — oversized messages are truncated to 12,288 characters (matching the existing
Logsbehaviour). In JSON mode, only the message body is truncated; thevaluesobject is preserved intact.Performance — the new logger is approximately 3× faster than the existing
Logsclass in both text and JSON modes. Context parameter passing uses a zero-copystring_viewinto the parent Logger's string, adding ~100 ns per log call.Unit tests — 50 tests covering text/JSON output, severity filtering, structured parameters, domain types (
XRPAmount,Number), context inheritance, secret scrubbing, message truncation, JSON pattern building, and performance benchmarks.Context of Change
The existing
Logsclass produces unstructured text output. In production, operators need to search, filter, and correlate log entries across thousands of lines. Structured JSON logging addresses this by making every field machine-parseable:Context inheritance enables OpenTelemetry-style trace propagation. A parent logger carrying a
trace_idcan spawn child loggers for sub-operations, each adding their ownspan_id. Every log entry in the call chain automatically includes the full trace context without manual plumbing:Next steps (separate PRs):
rippled.cfgto enablejsonModeLogsclass withLoggerthroughout the codebaseJLOG()call sites toLOG()with structured parametersAPI Impact
libxrplchange (any change that may affectlibxrplor dependents oflibxrpl)