Skip to content

feat: Pull Logger from Clio and add structured logging#7055

Draft
a1q123456 wants to merge 19 commits intodevelopfrom
a1q123456/spd-log-from-clio
Draft

feat: Pull Logger from Clio and add structured logging#7055
a1q123456 wants to merge 19 commits intodevelopfrom
a1q123456/spd-log-from-clio

Conversation

@a1q123456
Copy link
Copy Markdown
Contributor

@a1q123456 a1q123456 commented Apr 30, 2026

High Level Overview of Change

This PR introduces structured JSON logging to xrpld via a new spdlog-backed Logger class, sitting alongside the existing Logs class. The key changes are:

  • JSON logging mode — a new jsonMode flag on LoggingConfiguration switches between two output formats:

    • Text mode (default) uses kDEFAULT_LOG_FORMAT, producing output identical to the existing Logs class:
      2024-Jan-15 12:34:56.789123 UTC General:NFO hello world
      
    • JSON mode uses defaultJsonLogFormat(), producing structured output:
      {"timestamp":"2024-Jan-15 12:34:56.789123 UTC","channel":"General","severity":"NFO", "message": "hello world" }
    • In JSON mode, Pump accumulates structured parameters passed via log::param() into a values object alongside the message:
      {"timestamp":"...","channel":"Overlay","severity":"NFO", "message": "peer abc connected, latency 42", "values": {"peer_id":"abc","latency":42} }
    • In text mode, log::param() values are inlined into the message body and parameter names are ignored, preserving backward compatibility.
  • Secret scrubbing — the scrubber from the existing Logs class (seed, master_key, passphrase redaction) is carried over to the new implementation, running on the raw message buffer before any JSON wrapping.

  • Logger context inheritance — a child Logger can be constructed from a parent, inheriting its context parameters and adding new ones. This works in both modes:

    • JSON mode: context appears in the values object of every log entry.
    • Text mode: context is prepended as [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 Logs behaviour). In JSON mode, only the message body is truncated; the values object is preserved intact.

  • Performance — the new logger is approximately 3× faster than the existing Logs class in both text and JSON modes. Context parameter passing uses a zero-copy string_view into 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 Logs class 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:

# Find all warnings from the Overlay channel in the last hour
jq 'select(.severity == "WRN" and .channel == "Overlay")' xrpld.log

# Correlate all log entries for a specific transaction
jq 'select(.values.tx_hash == "ABC123")' xrpld.log

# Count errors by channel
jq 'select(.severity == "ERR") | .channel' xrpld.log | sort | uniq -c | sort -rn

Context inheritance enables OpenTelemetry-style trace propagation. A parent logger carrying a trace_id can spawn child loggers for sub-operations, each adding their own span_id. Every log entry in the call chain automatically includes the full trace context without manual plumbing:

Logger overlay("Overlay");
Logger peer(overlay, "Peer", log::param("peer_id", peerId));
Logger tx(peer, "Tx", log::param("tx_hash", txHash));
tx.info() << "processing";
// JSON: {..., "message": "processing", "values": {"peer_id":"10.0.0.1","tx_hash":"ABC123"}}
// Text: 2024-Jan-15 ... Tx:NFO [peer_id=10.0.0.1 tx_hash=ABC123] processing

Next steps (separate PRs):

  1. Add a configuration field to rippled.cfg to enable jsonMode
  2. Replace the existing Logs class with Logger throughout the codebase
  3. Migrate all JLOG() call sites to LOG() with structured parameters

API Impact

  • libxrpl change (any change that may affect libxrpl or dependents of libxrpl)

@a1q123456
Copy link
Copy Markdown
Contributor Author

Performance benchmark results show that the new logging infrastructure is around 3 times after than the existing one:

[==========] Running 2 tests from 1 test suite.
=== Logger performance (100000 iterations) ===
  New (spdlog): 95 ms
  Old (Logs):   323 ms
=== Logger performance JSON mode (100000 iterations) ===
  New (spdlog/JSON): 107 ms
  Old (Logs/text):   318 ms
[==========] 2 tests from 1 test suite ran. (845 ms total)
[  PASSED  ] 2 tests.

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";
}

@a1q123456 a1q123456 added the DraftRunCI Normally CI does not run on draft PRs. This opts in. label Apr 30, 2026
@a1q123456 a1q123456 changed the title feat: Pull Logger from Clio and add structured logging feat: Pull Logger from Clio and add structured logging Apr 30, 2026
@a1q123456 a1q123456 marked this pull request as ready for review April 30, 2026 20:24
@a1q123456 a1q123456 removed the DraftRunCI Normally CI does not run on draft PRs. This opts in. label Apr 30, 2026
@codecov
Copy link
Copy Markdown

codecov Bot commented Apr 30, 2026

Codecov Report

❌ Patch coverage is 99.71182% with 1 line in your changes missing coverage. Please review.
✅ Project coverage is 82.2%. Comparing base (182d844) to head (3f7b2ae).
⚠️ Report is 2 commits behind head on develop.

Files with missing lines Patch % Lines
src/libxrpl/basics/Logger.cpp 99.6% 1 Missing ⚠️
Additional details and impacted files

Impacted file tree graph

@@            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     
Files with missing lines Coverage Δ
include/xrpl/basics/Logger.h 100.0% <100.0%> (ø)
include/xrpl/basics/StructuredLogging.h 100.0% <100.0%> (ø)
src/libxrpl/basics/Logger.cpp 99.6% <99.6%> (ø)

... and 3 files with indirect coverage changes

Impacted file tree graph

🚀 New features to boost your workflow:
  • ❄️ Test Analytics: Detect flaky tests, report on failures, and find test suite problems.

@a1q123456 a1q123456 marked this pull request as draft April 30, 2026 20:58
@a1q123456 a1q123456 added the DraftRunCI Normally CI does not run on draft PRs. This opts in. label Apr 30, 2026
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

DraftRunCI Normally CI does not run on draft PRs. This opts in.

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant