Structured logging

When a test fails at simulation time 41,250 ns and three processes were running, a bare printf will not tell you which one spoke. cpptb’s loggers stamp every message with the simulation time, the source location, and the process that emitted it, so a diagnostic stream stays readable as concurrency grows.

Logging is part of the framework, not the command-line runner, so it works in any embedding. Messages go to a sink as they are emitted rather than into TestResult; retaining them for later inspection is opt-in via LogHistory.

Create a logger from the current test context and give it a stable component or activity scope:

Task<void> response_monitor(Dut dut, TestContext test) {
    auto log = test.logger("response_monitor");

    while (true) {
        co_await RisingEdge{dut.response_valid};
        co_await ReadOnly{};
        log.info("response observed");
    }
}

Task<void> protocol_test(Dut dut, TestContext& test) {
    auto log = test.logger("protocol_test");
    log.info("starting traffic");
    test.spawn_detached(response_monitor(dut, test));
    co_await drive_traffic(dut);
}

Every emitted LogRecord contains:

• severity, message, and user-selected scope;

• origin (Cpp or SystemVerilog) and, for HDL records, instance hierarchy;

• test name, simulation time in femtoseconds, and a per-test sequence number;

• logging call source file and line; and

• owning process ID, description, spawn source file, and spawn line.

Root and spawned processes use the same stable identities as failures, warnings, and uncaught exceptions. Logs issued outside a lifecycle-owned process still retain their scope, source location, and simulation time; their process ID is zero.

The sequence starts at one for each test. Simulation time orders records across time steps; sequence order is the stable tie-breaker when several processes log at the same simulation time. The default console sink prints both values.

cpptb: packet_test.cpp:31: 0 fs #1: info [driver] [process 1: root process]: starting traffic
cpptb: packet_test.cpp:18: 20000000 fs #2: info [monitor] [process 2: spawned process]: response observed
cpptb: packet_test.cpp:44: 20000000 fs #3: info [scoreboard] [process 3: spawned process]: response matched

Levels and filtering

The available levels are Trace, Debug, Info, Warning, and Error. Off disables every level. A message is enabled when its level is at least the configured minimum:

auto log = test.logger("apb.driver");

log.trace("entered transfer");
log.debug("PSEL asserted");
log.info("write completed");
log.warning("slave inserted ten wait states");
log.error("slave returned an error response");

Log levels are observational. warning() and error() do not increment the test’s warning or failure counts and do not stop the test. Use the lifecycle APIs when a condition affects the result:

Intent	API
Diagnostic message only	log.warning(...) or log.error(...)
Structured nonfatal test warning	test.warn(...)
Nonfatal correctness check	test.expect(...) or test.expect_eq(...)
Fatal prerequisite	test.require(...) or test.require_eq(...)

The default minimum is Info. The reference executable reads CPPTB_LOG_LEVEL through its normal environment request:

CPPTB_LOG_LEVEL=debug build/cpptb/my_design/obj/Vdpi_my_design
CPPTB_LOG_LEVEL=off build/cpptb/my_design/obj/Vdpi_my_design

Accepted values are trace, debug, info, warning (or warn), error, and off. Embedding applications configure the same policy directly:

RunRequest request{
    .test_name = "packet_test",
    .logging = {.minimum_level = LogLevel::Debug},
};
run_registered_test(scheduler, dut, result, request);

SystemVerilog messages

RTL and SystemVerilog verification code can publish into the same structured stream as C++. cpptb build automatically compiles the logging package and DPI bridge; the project file needs no logging sources, include paths, or extra link settings.

Include the shipped macro header where messages are authored:

`ifdef CPPTB_ENABLE_SV_LOGGING
`include "cpptb/sv/cpptb_log.svh"
`endif

module packet_buffer (...);
  always_ff @(posedge clk) begin
    if (input_valid && input_ready) begin
`ifdef CPPTB_ENABLE_SV_LOGGING
      `cpptb_debug($sformatf("accepted tag=%0d", input_tag), "input")
`endif
    end
  end
endmodule

The available macros are cpptb_trace, cpptb_debug, cpptb_info, cpptb_warning (or cpptb_warn), and cpptb_error. The optional second argument is the user scope. The macro captures `__FILE__, `__LINE__, %m, and $realtime at the call site. The message expression is evaluated only when its level is enabled, so a disabled $sformatf stays on the filtered path.

SystemVerilog and C++ records receive sequence numbers from the same test-owned counter. They therefore remain deterministic at equal simulation times and appear in one LogHistory in emission order. An HDL record has origin == LogOrigin::SystemVerilog, its %m path in hierarchy, and process_id == 0; SystemVerilog processes do not have CPPTB lifecycle process IDs. C++ records retain std::source_location and lifecycle process attribution as before.

cpptb: testbench.cpp:14: 20000000 fs #1: info [cpp.driver] [process 1: root process]: drove request
cpptb: packet_buffer.sv:27: 25000000 fs #2: info [input] [sv TOP.dut.i_buffer]: accepted request
cpptb: testbench.cpp:19: 26000000 fs #3: info [cpp.monitor] [process 1: root process]: observed response

The logging levels remain observational on both sides: an SV cpptb_error does not fail the test. Use an assertion, a C++ check, or another explicit result-changing mechanism for correctness. Plain $display, $warning, and simulator diagnostics are not intercepted and continue to use the simulator’s own output stream. Guarding the include and calls with CPPTB_ENABLE_SV_LOGGING keeps the RTL usable in non-CPPTB and synthesis flows.

The runnable mixed-language logging example shows C++ stimulus and RTL messages interleaved in one trace.

Portable timestamp conversion

SystemVerilog timestamps are converted with $realtime / 1s * 1.0e15. The seconds literal remains exactly representable when the calling scope has a timeprecision coarser than 1 fs, while dividing by 1fs directly could round that divisor to zero on an IEEE-compliant simulator. The mixed-language integration test asserts the exact femtosecond values received through DPI.

This fixes a portability bug found during the Verilator-reference review. Running the same assertion on a second standards-compliant simulator remains part of the portability milestone.

Lazy messages

Pass a zero-argument callable when constructing the message requires work:

log.debug([&] {
    return "write address=" + std::to_string(address) +
           " data=" + std::to_string(data);
});

cpptb checks the level before invoking the callable. A disabled message does not format values, allocate a message string, or call the sink. enabled() is also available when preparing several values is itself expensive:

if (log.enabled(LogLevel::Trace)) {
    const auto snapshot = collect_protocol_snapshot(dut);
    log.trace([&] { return format_snapshot(snapshot); });
}

Immediate string messages use the same filtering path. C++ logging after the test has reached a terminal state is ignored. SystemVerilog records emitted after test completion, or after test selection fails, are unowned diagnostics: they have sequence zero and no test name and use the runtime fallback sink. The default runtime fallback sink is stderr, not the test’s configured sink or history, whose lifetime is allowed to end with the test.

The value returned by a lazy message factory must remain valid until the factory call returns and CPPTB emits the record. Returning std::string by value is safe and recommended. A returned std::string_view is safe only when it refers to storage that outlives the logging call; never return a view into a factory-local string.

Ordered history

Use LogHistory when a harness, report, or test artifact needs to retain the trace. History is opt-in so ordinary logging does not allocate storage or grow memory throughout a long simulation:

LogHistory history;
history.reserve(1024);  // Optional when the expected volume is known.

RunRequest request{
    .test_name = "packet_test",
    .logging = {
        .minimum_level = LogLevel::Debug,
        .history = &history,
    },
};
run_registered_test(scheduler, dut, result, request);

for (const auto& entry : history) {
    consume_trace_entry(entry.simulation_time_fs, entry.sequence,
                        entry.scope, entry.process_id, entry.message);
}

The normal console or custom sink still receives each record. LogHistory stores owned StoredLogRecord values in exact emission order, including owned copies of every text field. Therefore temporary lazy-message strings remain valid in the history after emit() returns. For any adjacent records, the simulation time is nondecreasing during a normal simulator run; records at the same time have increasing sequence numbers that preserve scheduler execution order.

Use history.records(), history[index], or range iteration to inspect the trace. size(), empty(), reserve(), and clear() support harness-managed storage. Call clear() between tests when reusing one history; test_name still identifies entries if a harness intentionally accumulates several tests. The configured history must outlive the running test invocation.

Custom sinks

Without an explicit sink, enabled records are written to stderr. An embedding harness or verification package can provide a LogSink for JSON, console coloring, transaction databases, or another logging library:

class JsonLogSink final : public LogSink {
  public:
    void emit(const LogRecord& record) override {
        write_json(record.level, record.scope, record.message,
                   record.simulation_time_fs, record.process_id);
    }
};

JsonLogSink sink;
RunRequest request{
    .logging = {
        .minimum_level = LogLevel::Debug,
        .sink = &sink,
    },
};
run_registered_test(scheduler, dut, result, request);

LogRecord uses non-owning string views so an enabled message does not require framework-owned copies. Those views are valid only during emit(). A sink that queues or retains records must copy the fields it needs. Sink callbacks are synchronous and run on the simulator thread; expensive file or network work should be buffered by the sink rather than performed for each message. The configured sink must outlive the running test invocation. Sinks must not throw; a thrown sink exception is handled as a test error. This exception containment also applies when an SV-origin record invokes the sink through DPI; the resulting failure retains the originating .sv file and line instead of allowing a C++ exception to cross the DPI boundary. When both a history and output sink are configured, history stores the record first so the message remains available when the output sink throws.

Verification components can accept a Logger by value. The logger retains the test lifecycle state and owns its scope string, while the harness remains responsible for sink policy. A retained logger must not outlive the scheduler and TestResult used by the running test.

Performance

Logging has three matched C++/pure-SV benchmark pairs — sparse hot-loop logging (structured_logging), retained history (structured_log_history), and the mixed C++/RTL path (mixed_logging) — all certified under the standard 1.10x hard guard at 0.5285x, 0.5044x, and 0.7843x respectively. Below-threshold logging costs so little that the timing runs needed 200,000,000 iterations to rise above the measurement noise floor. Performance has each workload’s description, the tabbed side-by-side implementations, and the make feature-* commands to reproduce them.

Related APIs

• TestContext reference — the test.logger() signature and the CPPTB_LOG_LEVEL environment variable.

• Framework test lifecycle defines result-changing warnings, checks, requirements, and process ownership.

• Scheduling explains the simulation time attached to each record.

• Performance documents the matched benchmark methodology and host-load admission rules.