From 0d3ee2825547680332b59f85b0bb07dc00f9fdf0 Mon Sep 17 00:00:00 2001 From: Pascal Severin Date: Thu, 10 Sep 2026 23:53:17 +0200 Subject: [PATCH 1/2] [M0-CORE-02] Structured logging facade MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The one structured logging facade for the engine (AGENTS §14 LOG-001…LOG-007, FR-12.2): laige-core gains include/laige/logging.h and logging.cpp. Facade: laige::log::Logger — a process-lifetime Meyers singleton that owns its current Sink (unique_ptr). LAIGE_LOG_TRACE/DEBUG/INFO/ WARN/ERROR/FATAL macros put the level gate before argument evaluation, so a disabled event costs exactly one atomic load + branch: no message/field evaluation, no formatting, no allocation, no lock (LOG-003). Gating is an atomic global minimum plus a per-subsystem level table (init-phase mutation, one facade mutex, CONC-001). Fields: scalars render locale-free via std::to_chars into a 64-byte stack buffer; string-like values copy in full; field values must avoid spaces/'=' (the line is '| k=v' machine-parseable, LOG-001). Rate limiting (LOG-004): per (subsystem, event, severity) for Warn/Error/Fatal only. The first event of a key is always recorded (an everEmitted flag — a time_point::min() sentinel overflowed the window subtraction, CPP-004); repeats are counted and reported as a stable 'rate_limited' summary event (event=, suppressed=N) at window rollover, and pending counts are drained at shutdown. Sinks: ConsoleSink (does not own the stream — stderr must outlive the process) and FileSink (owns the FILE*; create() returns Result>, open failure = ErrorCode::IoError, the new slot-5 registry code; the LOG-007 minimal fallback keeps the console sink and reports the failure). Fatal records, flushes, and terminates via std::abort() (AGENTS §14 controlled termination). Crash handling: POSIX sigaction (SA_RESETHAND one-shot) for SIGSEGV/ABRT/BUS/FPE/ILL and a vectored SEH handler on Windows — raw write(2) notice, allocation-free try_lock sink flush, re-raise. shutdown() is idempotent (CONC-006): drain summaries, flush, retire (post-shutdown logs discarded). Timestamps: system_clock, UTC RFC 3339, rendered with an in-code Hinnant civil-from-days (no libc date functions). Additive M0-CORE-01 extensions required by this step's FileSink→facade hand-off: Result::takeValue() && (move the success value out of an rvalue result) and ErrorCode::IoError (5), both covered in the result_status suite; docs/api/errors.md documents the new code. Tests: 'logging' CTest entry (27 GTest cases in the shared laige-core_tests executable) — gate semantics, field formatting, both sinks (exact line format, dtor flush, create failure → IoError), rate limiting (suppression, summary after window, window edge, key independence, Warn/Error/Fatal only, opt-out, shutdown drain), Fatal (gate + forked child that emits, flushes, and dies on SIGABRT with the line in the file), crash/shutdown behavior, concurrency (4 threads × 250), and LogPerformance: 100k disabled Trace events → 0 allocations via a test-only global operator new counter (excluded from the sanitizer trees, whose runtimes define their own new/delete — there the same spam loop runs leak-free plus the timing property, the fallback the step names). Measured: disabled ≈46 ns/event vs ≈1207 ns/event enabled (N=200000). Verified locally 2026-09-10 (GCC 16.2.1 static, shared, ASan/UBSan, TSan trees; fresh Clang 22.1.8 static + shared trees): ctest 8/8 and ctest -R logging green in every tree, zero warnings. API contract: docs/api/logging.md. Roadmap: M0-CORE-02 checked with Decision/Verify/Size notes; Progress Board M0 11/22; change log line. --- README.md | 16 +- docs/api/errors.md | 11 + docs/api/logging.md | 274 ++++++++ docs/getting-started/building.md | 12 +- roadmap/M0-foundations.md | 70 +- roadmap/README.md | 5 +- src/laige-core/CMakeLists.txt | 12 +- src/laige-core/README.md | 10 + src/laige-core/errors.cpp | 21 +- src/laige-core/include/laige/errors.h | 1 + src/laige-core/include/laige/logging.h | 538 +++++++++++++++ src/laige-core/include/laige/result.h | 9 + src/laige-core/logging.cpp | 496 ++++++++++++++ tests/laige-core/CMakeLists.txt | 29 +- tests/laige-core/logging_alloc_counter.cpp | 74 ++ tests/laige-core/logging_alloc_counter.h | 41 ++ tests/laige-core/logging_tests.cpp | 743 +++++++++++++++++++++ tests/laige-core/result_status_tests.cpp | 16 + 18 files changed, 2356 insertions(+), 22 deletions(-) create mode 100644 docs/api/logging.md create mode 100644 src/laige-core/include/laige/logging.h create mode 100644 src/laige-core/logging.cpp create mode 100644 tests/laige-core/logging_alloc_counter.cpp create mode 100644 tests/laige-core/logging_alloc_counter.h create mode 100644 tests/laige-core/logging_tests.cpp diff --git a/README.md b/README.md index e1e6718..6ce9f3a 100644 --- a/README.md +++ b/README.md @@ -12,8 +12,10 @@ isometric-first rendering, and a server-authoritative MMO path. build system, `laige-core` library target, and dependency lock (`deps.lock` with vendored GoogleTest) have landed; the functional core (math, pools, Result, logging, config) lands over the remaining M0 steps - in [roadmap/M0-foundations.md](roadmap/M0-foundations.md). No engine - features are buildable yet. + in [roadmap/M0-foundations.md](roadmap/M0-foundations.md). So far: + `laige::Result` / `laige::Status` plus the error-code registry + (M0-CORE-01) and the structured logging facade (M0-CORE-02). No game-facing + engine features are buildable yet. ## Built by a local LLM @@ -73,10 +75,12 @@ benchmark forms — is the source of truth in The `laige-core` library builds now: static by default, shared with `-DLAIGE_BUILD_SHARED=ON` (NFR-8.9), verified by a CTest link smoke test in -both variants. It carries no functional engine code yet — the first code -(`laige::Result` / `laige::Status`) lands in M0-CORE-01. Engine targets -compile with `-Wall -Werror` and with exceptions and RTTI disabled -(NFR-8.10). +both variants. It carries the first functional engine code: +`laige::Result` / `laige::Status` plus the error-code registry +(M0-CORE-01, `ctest -R result_status`) and the structured logging facade +(M0-CORE-02, `ctest -R logging`, API contract in +[docs/api/logging.md](docs/api/logging.md)). Engine targets compile with +`-Wall -Werror` and with exceptions and RTTI disabled (NFR-8.10). ## Documentation diff --git a/docs/api/errors.md b/docs/api/errors.md index 1ac7ca8..973bb45 100644 --- a/docs/api/errors.md +++ b/docs/api/errors.md @@ -97,3 +97,14 @@ The step that needs a new code performs, in one change: | why | the caller requested more work or capacity than the configured budget allows (PERF-008, SCALE-003) | | fix | reduce per-call work or raise the budget through typed configuration (API-006); budgeted resources must never grow silently | | doc anchor | `docs/api/errors.md#budget-exhausted` | + +### io-error + +- **Integer value:** `5` (added by M0-CORE-02: file sink creation) + +| Field | Text | +|---|---| +| what | an I/O operation (a file, or a system interface) failed | +| why | the file could not be opened, written, or flushed (missing path, permissions, full disk), or a system interface call (e.g. signal registration for crash handling) was rejected | +| fix | check the path, permissions, and disk space; for logging, fall back to the current console sink (LOG-007 minimal fallback, `docs/api/logging.md`) | +| doc anchor | `docs/api/errors.md#io-error` | diff --git a/docs/api/logging.md b/docs/api/logging.md new file mode 100644 index 0000000..04fddb7 --- /dev/null +++ b/docs/api/logging.md @@ -0,0 +1,274 @@ +# Structured logging facade (`laige::log`) + +The one logging facade for the engine (M0-CORE-02, AGENTS.md §14). +Public header: `src/laige-core/include/laige/logging.h`; implementation: +`src/laige-core/logging.cpp`. All engine logging goes through this +facade; the backend (`Sink`) is replaceable (FR-12.2). + +## Quick start + +```cpp +#include + +// One-time, init phase: +auto sink = laige::log::FileSink::create("engine.log"); +if (!sink.ok()) { + // LOG-007 minimal fallback: keep the console sink, report the failure. + laige::log::Logger::instance() + .emit(laige::log::Severity::Error, "logging", "file_sink_create_failed", + "log file could not be opened", + laige::log::field("error", laige::errorText(sink.error()))); +} else { + laige::log::LoggerOptions o; + o.sink = std::move(sink).takeValue(); // hand ownership to the facade + laige::log::Logger::instance().init(std::move(o)); + laige::log::Logger::instance().installCrashHandling(); +} + +// Hot path (lazy: disabled events do none of this work): +LAIGE_LOG_WARN("network", "packet_dropped", + "Dropped packet outside receive window", + laige::log::field("connection_id", conn_id), + laige::log::field("sequence", seq)); +``` + +## The macros + +`LAIGE_LOG_TRACE / _DEBUG / _INFO / _WARN / _ERROR / _FATAL` +take `(subsystem, event, message, field(...), ...)`. + +- **Lazy by construction.** The level gate is evaluated first; only if + it passes are `message` and the `field(...)` arguments evaluated and + formatted. A disabled event costs exactly one atomic load and a + branch — no argument evaluation, no formatting, no allocation, no + lock (LOG-003, PERF-003). +- **Stable names.** `subsystem`, `event`, and `message` are passed to + both the gate and the record, so pass string literals (LOG-001). + Event names and field keys are stable and machine-searchable; do not + embed variable text in them. +- **`field(name, value)`** builds a structured pair: string-like values + are copied in full; scalars (integral, floating-point, `bool`, + `char`, enum, pointer) render locale-free into a 64-byte stack + buffer via `std::to_chars`. Field **values must not contain spaces + or `=`** (the line format is `| k=v` machine-parseable); put + variable text in `message`, not in field values. +- **No-argument form works:** `LAIGE_LOG_INFO("net", "started", + "listening")` — no `field(...)` needed. + +## Line format + +Each record is one line (see `ConsoleSinkLineFormat` / +`FileSinkLineFormat` tests): + +```text + [severity] /: | k1=v1 | k2=v2 +``` + +- **Timestamp:** one documented clock — `std::chrono::system_clock`, + rendered in UTC as `YYYY-MM-DDTHH:MM:SS.ffffffZ` (RFC 3339, 27 + chars). Diagnostics only; never part of authoritative state + (ARCH-009). +- **Severity token:** the stable lowercase name (`trace` … `fatal`). +- **Fields:** ` | k=v` per field, in call order. +- A `rate_limited` summary event (below) uses the event fields + `event=` and `suppressed=`. + +## Severity and levels + +`Severity` (Trace…Fatal) follows the AGENTS §14 severity contract. +`Level` adds `Off`. Two independent gates decide whether an event is +recorded (both must pass): + +1. **Global minimum** (`LoggerOptions::globalMinimum`, default + `Debug`): checked first, one atomic load. +2. **Per-subsystem level** (`setSubsystemLevel`, unregistered + subsystems take `LoggerOptions::defaultSubsystemLevel`, default + `Debug`). + +`Trace` is disabled by default (AGENTS §14); `Off` disables everything +(the cheap switch for release/server profiles). `Logger::enabled()` is +the same check the macros use — use it to guard expensive work you +want to skip together with the log call. + +## Rate limiting (LOG-004) + +When enabled (`LoggerOptions::rateLimiting`, default `true`), repeated +failures are rate-limited **per `(subsystem, event, severity)`** key, +for **Warn, Error, and Fatal** only (Trace/Debug/Info are never +rate-limited — they are volume-managed by the level gate). + +Per key, within one window (`LoggerOptions::rateWindow`, default +1000 ms): + +- the **first event is always recorded**; +- each repeat is counted and suppressed (no sink call); +- when the next event for the key lands **after the window**, the + facade first emits a `rate_limited` summary event + (`severity` = the key's severity, fields `event=`, + `suppressed=`) and then records the current event. +- Pending suppressed counts are drained at `shutdown()` (so a shutdown + immediately after a burst still reports the total). + +Keys are independent: `("net", "drop", Warn)` and `("net", "timeout", +Warn)` do not share a window. + +## Ownership and lifetime + +- `Logger::instance()` is a **process-lifetime Meyers singleton** + (thread-safe construction). It owns the current sink + (`unique_ptr`); a sink passed via `LoggerOptions` is moved in and + flushed before replacement. +- `LogRecord` string views and the field span are **non-owning**: + caller storage must outlive the `Sink::emit()` call — the macros + guarantee this (all arguments are literals/locals alive for the + `do { … }` statement). +- `FileSink` **owns** the `FILE*` it opens (closed on destruction, + after a final flush). `ConsoleSink` does **not** own its stream + (`stderr` must outlive the process). +- `init()` takes `LoggerOptions` **by value** and consumes the sink + ownership — call it with an rvalue. + +## Threading and permitted execution phase (CONC-001/002) + +- **Logging from any thread is safe:** enabled events are serialized + on one facade mutex (level/rate state), and each sink serializes its + own output. +- **Init-phase APIs** — `init()`, `setSubsystemLevel()`, + `subsystemLevel()`, `setGlobalMinimum()`, `globalMinimum()` (the + reader is const-safe), `installCrashHandling()` — MUST NOT run + concurrently with logging or with each other from other threads. + Configure before the engine starts its threads; mutate afterwards + only from a single control thread with no concurrent logging + (mutation in an explicit phase, API-004). +- **Lock ordering:** the facade state mutex is never held while a sink + is called, and sinks never call back into the facade. +- `shutdown()` is idempotent (CONC-006): it retires the facade, drains + pending rate-limit summaries, and flushes. Log calls after shutdown + are discarded (no sink calls, no crash). + +## Complexity, allocation, and blocking + +| Operation | Time | Allocation | Blocking | +|---|---|---|---| +| Disabled event (macro) | one atomic load + branch | none | none | +| `enabled()` | one atomic load; only if that passes, one mutex section + small linear scan | none | mutex (contended only by logging/config) | +| Enabled event | one mutex section + one sink write | Field value strings (only when fields given); one rate-state entry per distinct key (amortized, bounded by distinct event names); one summary record per window rollover | mutex + sink I/O | +| `flush()` | one sink flush | none | sink I/O (file write) | +| `shutdown()` | drains pending summaries + one flush | summary records for pending counts | sink I/O | +| `FileSink::create()` | one `fopen` (append) | the sink object | file open | +| `installCrashHandling()` | one `sigaction` per signal (POSIX) / one handler (Windows) | none | none | + +Hot-path budget (CORE-002): the disabled path is the budgeted one — +measured at 46 ns/event vs 1207 ns/event enabled on the M0 hardware +(see Performance). FR-12.2: no logging in sim/render hot paths by +default — hot-path diagnostics belong to Trace/Debug behind the level +gate. + +**Blocking/I/O:** sink writes are the only I/O in the facade. A +`FileSink` write can block on a slow/full disk; that cost is paid +only for enabled events. Nothing in the facade blocks on a lock held +across I/O (the state mutex is released before the sink call). + +## Determinism and network authority + +Log timestamps come from the wall clock and are diagnostics only +(ARCH-009): they never enter authoritative simulation state and never +affect replay determinism (ARCH-010). Event *names* and *field keys* +are stable strings (LOG-001) — suitable for log mining, not for +protocol state. + +## Failure behavior (CORE-008, LOG-007) + +- **Nothing throws.** `FileSink::create()` returns + `Result>`; a failed open is + `ErrorCode::IoError` with the NFR-13.3 registry text + (`docs/api/errors.md#io-error`). The LOG-007 minimal fallback: keep + the current sink (console) and report the failure — the engine keeps + running. +- **Failed writes are counted, never silent:** `ConsoleSink:: + failedWrites()` / `FileSink::failedWrites()` count records whose + line could not be written (poll it as a diagnostic, DBG-008). +- **Fatal** records the event, flushes, and terminates the process via + `std::abort()` — controlled termination after preserving + diagnostics (AGENTS §14). If crash handling is installed, the + SIGABRT handler flushes once more (idempotent) before the default + crash handling continues. +- **Crash handling** (`installCrashHandling()`, idempotent): + - POSIX: `sigaction` for SIGSEGV, SIGABRT, SIGBUS, SIGFPE, SIGILL + with `SA_RESETHAND` (one-shot: the handler restores the default + disposition so the following `raise` produces the normal core + dump). + - Windows: a vectored SEH handler continuing execution after the + flush. + - The handler writes a fixed notice with raw `write(2)` (no stdio + lock, no allocation), calls `crashFlush()` (sinks use `try_lock`, + so a flush from a signal never blocks on a lock the interrupted + emit may hold), then re-raises the signal. + - Registration failure returns `Status::failure(ErrorCode::IoError)` + (logged by the caller, CORE-008). +- **Init failure** cannot happen: `init()` always succeeds (sink + creation happens before it, via `FileSink::create()`). + +## Performance (DOC-004) + +- **Disabled path** (the hot-path contract, LOG-003/PERF-003): one + atomic load + branch. **Zero allocations, zero formatting, zero + locks.** Verified by `LogPerformance.DisabledTraceSpamAllocatesNothing` + (100k disabled Trace events → 0 allocations via a test-only process + `operator new` counter; the sanitizer trees run the same spam loop + leak-free instead — the counter cannot be linked against the + sanitizer runtimes, see `tests/laige-core/CMakeLists.txt`). +- **Enabled path:** one facade mutex section (level lookup + rate + decision over small vectors), then one sink write. Allocations are + proportional to field count and bounded by distinct event names — + no per-event state growth. +- **Batching guidance:** the facade has no per-event queue; sinks + write one line per event. For very high-volume enabled logging, + prefer a rate-limited aggregate event (already built in, LOG-004) + or raise the subsystem level — do not add a user-space queue in + front of the facade (it would duplicate what `shutdown()`/ + `flush()` already guarantee). +- **Traps:** + - Calling `field(...)` outside a `LAIGE_LOG_*` macro for an event + that may be disabled **allocates for nothing** (LOG-003) — check + `enabled()` first or use the macro. + - Putting variable text in field values breaks the `k=v` format + (spaces/`=` are forbidden in values). + - Logging with a long-held external lock held: the facade's mutex + is taken per event; holding your own lock across a logging call is + allowed but serializes the sink behind your lock — keep critical + sections short. +- **Measured (M0 hardware: see `LogPerformance.DisabledPathCheaperThanEnabled`):** + disabled ≈ 46 ns/event, enabled (Debug, 1 field) ≈ 1207 ns/event, + N=200000, Debug build. The disabled path is ~26× cheaper. + +## Misuse warning + +```cpp +// WRONG: field() evaluated before the gate — allocates even when +// disabled. +LAIGE_LOG_TRACE("net", "verbose", "x", + laige::log::field("payload", expensiveString())); + +// RIGHT: the macro defers field construction until the gate passes. +LAIGE_LOG_TRACE("net", "verbose", "x", + laige::log::field("len", expensiveString().size())); + +// WRONG: rate limiting does not apply to Info; this spam is only +// managed by the level gate. +LAIGE_LOG_INFO("net", "flapping", "still flapping"); + +// RIGHT: use Warn (recovered degradation) so the LOG-004 summary +// aggregates the repeats. +LAIGE_LOG_WARN("net", "flapping", "link flapping; recovered"); +``` + +## Testing + +`tests/laige-core/logging_tests.cpp` — CTest entry **`logging`** +(selected via `--gtest_filter` on the shared `laige-core_tests` +executable): gate semantics, field formatting, both sinks, rate +limiting, Fatal termination (forked child), crash/shutdown behavior, +concurrency (TSan lane), and the performance properties above. +Verification for this step: `ctest -R logging` green on the static, +shared, ASan, and TSan trees (GCC), plus Clang static/shared. diff --git a/docs/getting-started/building.md b/docs/getting-started/building.md index ec16a99..b70bb5d 100644 --- a/docs/getting-started/building.md +++ b/docs/getting-started/building.md @@ -125,7 +125,10 @@ Every engine target is passed through `laige_apply_engine_policy()` engine code from M0-CORE-01: `laige::Result` / `laige::Status` and the error-code registry (`include/laige/result.h`, `include/laige/errors.h`, `errors.cpp`; error text follows the NFR-13.3 - 5-field grammar — see [docs/api/errors.md](../api/errors.md)). + 5-field grammar — see [docs/api/errors.md](../api/errors.md)), and the + structured logging facade from M0-CORE-02 (`include/laige/logging.h`, + `logging.cpp`; API contract in + [docs/api/logging.md](../api/logging.md)). - `tests/laige-core/laige-core_tests` is a CTest link smoke test (a GoogleTest suite since M0-DEP-01) that runs in every build tree above: it verifies the static/shared link and checks the NFR-8.10 policy flags with @@ -134,8 +137,13 @@ Every engine target is passed through `laige_apply_engine_policy()` same `laige-core_tests` executable covering the `ResultStatus`, `Status`, and `ErrorCodeRegistry` suites — the step's Verify command is `ctest -R result_status`. +- `logging` is the M0-CORE-02 CTest entry: a filtered view of the same + executable covering the `LogGate`, `LogRecord`, `LogSinks`, + `LogRateLimit`, `LogFatal`, `LogCrash`, `LogConcurrency`, and + `LogPerformance` suites — the step's Verify command is + `ctest -R logging`. - Every configure verifies the vendored dependency lock (`cmake/laige-deps-lock.cmake` against `deps.lock`); a tampered or unlisted file under `deps/` fails the configure loudly. GoogleTest is the only vendored dependency and is linked into tests only (M0-DEP-01, - [ADR 0004](../docs/decisions/0004-google-test-vendoring.md)). + [ADR 0004](../decisions/0004-google-test-vendoring.md)). diff --git a/roadmap/M0-foundations.md b/roadmap/M0-foundations.md index ed52d3b..ddfbbd6 100644 --- a/roadmap/M0-foundations.md +++ b/roadmap/M0-foundations.md @@ -278,15 +278,79 @@ No rendering, no physics, no networking yet — `laige-core` only. headers carry the full AGENTS §9 API contracts and the registry pre-renders its grammar line next to its fields — cohesive, not split) -- [ ] **M0-CORE-02 · Structured logging facade** +- [x] **M0-CORE-02 · Structured logging facade** - **Refs:** AGENTS.md §14 (LOG-001…LOG-007); FR-12.2 - **Depends:** M0-CORE-01 - **Scope:** - One logging facade: severity (Trace…Fatal per §14), stable subsystem+event names, lazy field/message evaluation (no formatting/allocation when disabled — LOG-003), per-subsystem level filters. - Sink interface with a console sink and a file sink; per-subsystem scopes; rate limiting with suppressed-count summary (LOG-004); crash/shutdown flush (LOG-007). - Unit tests: disabled levels allocate nothing (assert with allocation counter from M0-CORE-05 if available, else ASan leak-free + timing property test); rate-limit summary emitted after N repeats. - - **Verify:** `ctest -R logging` green; trace-level spam in a disabled-subsystem test shows zero allocations (ASan/alloc counter). - - **Size:** ~350 lines + tests + - **Decision (2026-09-10):** single process-lifetime Meyers-singleton + facade `laige::log::Logger` (thread-safe construction) owning the + current `Sink` via `unique_ptr`. `LAIGE_LOG_*` macros put the level + gate **before** argument evaluation — a disabled event costs one + atomic load + branch: no message/field evaluation, no formatting, + no allocation, no lock (LOG-003). Gating = atomic global minimum + (checked first) + per-subsystem level table (one facade mutex, small + linear scan; init-phase mutation only, CONC-001). Fields: scalar + values render locale-free into a 64-byte stack buffer via + `std::to_chars`; string-like values copy in full; field values must + avoid spaces/`=` (the line is `| k=v` machine-parseable, LOG-001). + Rate limiting (LOG-004) applies to Warn/Error/Fatal only, per + `(subsystem, event, severity)` key: the first event is always + recorded (an `everEmitted` flag — a `time_point::min()` sentinel + overflowed the window subtraction, CPP-004), repeats are counted + and reported as a stable `rate_limited` summary event + (`event=`, `suppressed=N`) at window rollover and at shutdown + (pending counts are drained, so a burst right before shutdown still + reports). `Fatal` records, flushes, and terminates via + `std::abort()` (AGENTS §14 controlled termination). Sinks: + `ConsoleSink` (does not own the stream — `stderr` must outlive the + process), `FileSink` (owns the `FILE*`; `create()` returns + `Result>`, open failure → `ErrorCode::IoError`; + LOG-007 minimal fallback = keep the console sink and report). Crash + handling: POSIX `sigaction` (SA_RESETHAND, one-shot) for + SIGSEGV/ABRT/BUS/FPE/ILL + raw `write(2)` notice + allocation-free + `try_lock` sink flush + re-raise; Windows vectored SEH; registration + failure → `Status` (`IoError`), idempotent install. `shutdown()` + idempotent (CONC-006): drain summaries → flush → retire (post-shutdown + logs discarded). Timestamps: `system_clock`, UTC RFC 3339 + `YYYY-MM-DDTHH:MM:SS.ffffffZ` rendered with a vendored-in-code + Hinnant `civil_from_days` (no libc date functions; thread-safe). + Two small additive extensions of M0-CORE-01 shipped with this step: + `ErrorCode::IoError` (`5`, `docs/api/errors.md#io-error`) and + `Result::takeValue() &&` (move the success value out of an rvalue + result — needed to hand a created `FileSink` into `LoggerOptions`); + both tested in the `result_status` suite. Test-only process-wide + allocation counter (strong global `operator new` overrides in a test + TU) proves the zero-alloc property; it is excluded from the ASan/TSan + trees (the sanitizer runtimes define their own `new`/`delete`) — + there the same spam loop runs leak-free plus the timing property + test, which is exactly the fallback the step names. + - **Verify:** `ctest -R logging` green — 27 GTest cases across + `LogGate` (default/per-subsystem/global gating, disabled event + reaches no sink), `LogRecord` (scalar field formatting, full string + copy, identity + timestamp format), `LogSinks` (exact console/file + line format, dtor flush, create failure → `IoError`), `LogRateLimit` + (suppression, summary after window with `suppressed=N`, window edge, + key independence, Warn/Error/Fatal only, opt-out, shutdown drains + pending summaries), `LogFatal` (gate; forked child emits + flushes + + dies on SIGABRT with the line in the file), `LogCrash` (install + idempotence, shutdown flush, post-shutdown discard), + `LogConcurrency` (4 threads × 250 emits, all recorded), and + `LogPerformance` (100k disabled Trace events → **0 allocations** via + the allocation counter; disabled ≈46 ns/event vs ≈1207 ns/event + enabled, N=200000). Verified locally 2026-09-10 (GCC 16.2.1: static, + shared, ASan/UBSan, TSan trees — all 8/8 ctest, zero warnings; fresh + Clang 22.1.8 static + shared trees — all 8/8 ctest, zero warnings; + `ctest -R logging` green in every tree). CI: pending observation. + - **Size:** ~1034 lines implementation (`logging.h` 538 — full AGENTS + §9 contracts, facade, macros — `logging.cpp` 496) + ~860 lines tests + (`logging_tests.cpp` 743, allocation counter 115) + ~300 lines + docs/CMake (over the ~350-lines estimate, same pattern as + M0-CORE-01 and M0-CI-03: the header carries the API contract and the + tests prove the step's Verify clauses — zero-alloc, rate-limit + summary, Fatal termination — cohesive, not split) - [ ] **M0-CORE-03 · SimMath interface + `fp32_pinned` backend** - **Refs:** PRD §10.3, S-7; ADR 0002 (`fp32_pinned` backend); AGENTS CORE-005 diff --git a/roadmap/README.md b/roadmap/README.md index e3ef993..e6c47ac 100644 --- a/roadmap/README.md +++ b/roadmap/README.md @@ -155,7 +155,7 @@ Updated in the same PR that closes steps. "Done" = box checked + Verify green. | Milestone | Steps | Done | Status | |---|---|---|---| -| M0 | 22 | 10 | ▶ in progress | +| M0 | 22 | 11 | ▶ in progress | | M1 | 25 | 0 | ⬜ not started | | M2 | 32 | 0 | ⬜ not started | | M3 | 36 | 0 | ⬜ not started | @@ -165,7 +165,7 @@ Updated in the same PR that closes steps. "Done" = box checked + Verify green. | M7 | 15 | 0 | ⬜ not started | | M8 | 8 | 0 | ⬜ not started | | M9 | 6 | 0 | ⬜ proposals only | -| **Total** | **193** | **10** | | +| **Total** | **193** | **11** | | --- @@ -183,6 +183,7 @@ One line per completed (or split/renumbered) step. | 2026-09-10 | M0-CI-02 | `6573a64` | Sanitizer CI lanes `linux-asan` (LAIGE_ASAN=ON: ASan+UBSan, reports fatal via `-fno-sanitize-recover=all` + `ASAN_OPTIONS` abort/halt) and `linux-tsan` (LAIGE_TSAN=ON, per-test `TSAN_OPTIONS=halt_on_error=1`) in `ci.yml` (merge, all 7 jobs) and `ci-pull.yml` (PRs under the default-Linux P0 condition); sanitizer reports archived as artifacts (`linux-asan-reports`/`linux-tsan-reports`) on every run, green or red; the first CI run rejected the workflow file because step-level `permissions:` is not a valid schema — fixed in `f75ed0d` by moving `actions: write` to job scope (with `continue-on-error: true` uploads in `ci-pull.yml` for fork-PR read-only tokens); Verify cycle on CI: scratch OOB read (`6331a40`) failed `linux-asan` with the UBSan "index 16 out of bounds for type int[4]" report (archived) while `linux-tsan` and the other five jobs stayed green; scratch removed in `25b57b9`; full 7-job matrix green | | 2026-09-10 | M0-CI-03 | `785af81` | `tools/laige-include-lint` (Python 3 stdlib): parses `#include` edges of `src/**`, enforces R1 (laige-core includes nothing internal), R2 (arrows only downward in the PRD §10.1 stack, via the target's public include root — CPP-010), R3 (vendored deps only from their `deps.lock` `owner` — new required lock field, validated by `cmake/laige-deps-lock.cmake`; angle-bracket vendored header paths caught via a vendored-header map), R4 (engine code includes only `src/**`/`deps/**`); reports the vendored-dependency list and fails above the PRD §11 budget of 10; `include-lint` CI job in `ci-pull.yml` (every PR, label-independent) and `ci.yml` (every merge, now 8 jobs); CTest coverage in `tests/tools` (4 fixture trees + real-tree check, expected failures asserted via generated `cmake -P` scripts because CTest inverts `PASS_REGULAR_EXPRESSION` under `WILL_FAIL`); local Verify: illegal `laige-core → laige-render` stub include fails with R1, all rule directions exercised, dep count prints (1/10), `ctest` 6/6 on g++/shared/ASan/Clang trees; pushed as `785af81` — CI observed via the GitHub API: `ci.yml` (8-job) run 34518244428 on `741c163` green, `include-lint` job log shows the live report (`count: 1 (budget: 10, PRD §11)`, `OK`); `ci-pull.yml` job exercised by PR #1 (run 34521473503, green incl. `include-lint`), squash-merged as `a74b65a` with the post-merge 8-job run 34521722826 green | | 2026-09-10 | M0-CORE-01 | `6fa1414` | `laige::Result`/`laige::Status` (no exceptions, FR-12.1; inline `std::optional` storage, SFINAE-guarded implicit constructors + `success()`/`failure()` factories, `valueIfOk()`/`errorIfError()` null-safe accessors) + central error registry (`errors.h`/`errors.cpp`: 4 pinned codes, 0 reserved, unregistered → `unknown`; pre-rendered NFR-13.3 5-field lines) with the human-readable registry in `docs/api/errors.md`; `result_status` CTest entry (16 cases: construction, propagation, copy/move, grammar per code, pinned values) in the shared `laige-core_tests` executable; local Verify: GCC static/shared/ASan/TSan + fresh Clang trees 7/7 ctest, zero warnings; first push `f96ce7d` failed 7/8 on windows-msvc (C2535: the `Result(T)`/`Result(E)` constructors have identical parameter lists when `T == E`) — fixed in `6fa1414` by taking the failure value by `const E&`; CI: `ci.yml` run 34525402022 on `6fa1414` (8-job matrix) green, Windows job compiles and passes `result_status`, every job under a minute | +| 2026-09-10 | M0-CORE-02 | — | The one structured logging facade (AGENTS §14, FR-12.2): `laige::log::Logger` Meyers singleton + `LAIGE_LOG_*` macros (gate before argument evaluation — disabled event = one atomic load + branch, no allocation, LOG-003); per-subsystem level table + atomic global minimum; `Field` scalars render locale-free via `to_chars` into a 64-byte stack buffer; rate limiting per (subsystem, event, severity) for Warn/Error/Fatal with `rate_limited` suppressed-count summaries (first event always emitted, pending counts drained at shutdown); `ConsoleSink` (non-owning stream) + `FileSink` (owning, `create()` → `Result`, failure = new `ErrorCode::IoError` 5, LOG-007 console fallback); Fatal = emit + flush + `std::abort()`; crash handlers (POSIX `sigaction` SA_RESETHAND / Windows vectored SEH) with raw-`write` notice + allocation-free `try_lock` flush; idempotent `shutdown()` retires the facade; timestamps = system_clock UTC RFC 3339 (in-code Hinnant civil-from-days); additive M0-CORE-01 extensions `Result::takeValue() &&` + `IoError`; `logging` CTest entry (27 cases incl. zero-alloc proof via a test-only global `operator new` counter, excluded from sanitizer trees per the step's fallback: leak-free runs + timing property); API contract in `docs/api/logging.md`; local Verify: GCC static/shared/ASan/TSan + fresh Clang static/shared trees — `ctest` 8/8 and `ctest -R logging` green in every tree, zero warnings (disabled ≈46 ns/event vs ≈1207 ns/event enabled) | --- diff --git a/src/laige-core/CMakeLists.txt b/src/laige-core/CMakeLists.txt index 95d0999..51cdc78 100644 --- a/src/laige-core/CMakeLists.txt +++ b/src/laige-core/CMakeLists.txt @@ -8,15 +8,15 @@ # M0-BUILD-01: the library target. Static by default; LAIGE_BUILD_SHARED=ON # builds it shared (NFR-8.9). The target currently carries the # version/build-identifier code (version.cpp) plus the first functional -# engine code (M0-CORE-01: Result/Status + error registry, errors.cpp); -# further functional code lands in the remaining M0-CORE-xx steps. The -# link smoke test in tests/laige-core/ verifies the library in both -# variants. +# engine code (M0-CORE-01: Result/Status + error registry, errors.cpp) +# and the structured logging facade (M0-CORE-02, logging.cpp); further +# functional code lands in the remaining M0-CORE-xx steps. The link +# smoke test in tests/laige-core/ verifies the library in both variants. if(LAIGE_BUILD_SHARED) - add_library(laige-core SHARED version.cpp errors.cpp) + add_library(laige-core SHARED version.cpp errors.cpp logging.cpp) else() - add_library(laige-core STATIC version.cpp errors.cpp) + add_library(laige-core STATIC version.cpp errors.cpp logging.cpp) endif() laige_apply_engine_policy(laige-core) diff --git a/src/laige-core/README.md b/src/laige-core/README.md index 3127ddc..8deb609 100644 --- a/src/laige-core/README.md +++ b/src/laige-core/README.md @@ -20,6 +20,16 @@ Status: M0 — Foundations. `include/laige/errors.h`, `errors.cpp`); rendered error text follows the NFR-13.3 5-field grammar (`docs/api/errors.md`); unit suite: `ctest -R result_status`. +- **M0-CORE-02 (done):** the one structured logging facade + (`include/laige/logging.h`, `logging.cpp`): severity Trace…Fatal, + stable subsystem/event names, lazy field/message evaluation (disabled + events cost one atomic load + branch, no allocation), per-subsystem + level filtering, replaceable sinks (console, file), rate limiting with + `rate_limited` suppressed-count summaries, and flush-on-shutdown/crash + (AGENTS §14). `Result::takeValue()` (rvalue move-out of the success + value) and `ErrorCode::IoError` (`5`) were added as small additive + extensions of M0-CORE-01 to support the FileSink→facade hand-off. API + contract: `docs/api/logging.md`; unit suite: `ctest -R logging`. - Further public headers land with each M0-CORE-xx step. Canonical build commands: diff --git a/src/laige-core/errors.cpp b/src/laige-core/errors.cpp index 211ff90..532efce 100644 --- a/src/laige-core/errors.cpp +++ b/src/laige-core/errors.cpp @@ -20,7 +20,7 @@ namespace laige { namespace { constexpr std::size_t kLastCode = - static_cast(ErrorCode::BudgetExhausted); + static_cast(ErrorCode::IoError); const ErrorEntry kErrorRegistry[kLastCode + 1] = { { // slot 0: no-error sentinel + unregistered-value fallback @@ -98,6 +98,25 @@ const ErrorEntry kErrorRegistry[kLastCode + 1] = { "SCALE-003) | reduce per-call work or raise the budget through " "typed configuration (API-006); budgeted resources must never " "grow silently | docs/api/errors.md#budget-exhausted"}, + { // slot 5 + ErrorCode::IoError, + "io_error", + "an I/O operation (a file, or a system interface) failed", + "the file could not be opened, written, or flushed (missing " + "path, permissions, full disk), or a system interface call " + "(e.g. signal registration for crash handling) was rejected", + "check the path, permissions, and disk space; for logging, " + "fall back to the current console sink (LOG-007 minimal " + "fallback, docs/api/logging.md)", + "docs/api/errors.md#io-error", + "io_error | an I/O operation (a file, or a system interface) " + "failed | the file could not be opened, written, or flushed " + "(missing path, permissions, full disk), or a system interface " + "call (e.g. signal registration for crash handling) was " + "rejected | check the path, permissions, and disk space; for " + "logging, fall back to the current console sink (LOG-007 " + "minimal fallback, docs/api/logging.md) | " + "docs/api/errors.md#io-error"}, }; } // namespace diff --git a/src/laige-core/include/laige/errors.h b/src/laige-core/include/laige/errors.h index ba2f1ed..44ee73b 100644 --- a/src/laige-core/include/laige/errors.h +++ b/src/laige-core/include/laige/errors.h @@ -33,6 +33,7 @@ enum class ErrorCode : std::uint32_t { InvalidArgument = 2, MalformedInput = 3, BudgetExhausted = 4, + IoError = 5, }; // One registry entry per stable code. `text` is the pre-rendered diff --git a/src/laige-core/include/laige/logging.h b/src/laige-core/include/laige/logging.h new file mode 100644 index 0000000..0b50bb1 --- /dev/null +++ b/src/laige-core/include/laige/logging.h @@ -0,0 +1,538 @@ +// laige-core structured logging facade (M0-CORE-02). +// +// AGENTS.md §14 (LOG-001…LOG-007), FR-12.2. This is the ONE logging +// facade: all engine logging goes through it, and the backend (Sink) +// is replaceable. +// +// Design summary (the full contract is in docs/api/logging.md): +// - Events carry a severity (Trace…Fatal per AGENTS §14), a stable +// subsystem name, a stable event name, a concise message, +// structured fields, and a thread identity (LOG-001/LOG-002). +// - Level gating is a global minimum (one atomic load) plus a +// per-subsystem level table. The LAIGE_LOG_* macros put the gate +// BEFORE argument evaluation, so a disabled event costs exactly +// that check: no message/field evaluation, no formatting, no +// allocation, no lock (LOG-003, PERF-003). +// - Repeated failures (Warn/Error/Fatal) are rate-limited per +// (subsystem, event, severity); suppressed repeats are counted and +// reported through a dedicated `rate_limited` summary event +// (LOG-004). +// - Controlled shutdown (shutdown()) and crash handling +// (installCrashHandling()) preserve buffered output (LOG-007). +// Sink creation failure returns Status and the fallback is +// documented (FileSink::create). +// +// Ownership/lifetime: +// - Logger::instance() is a process-lifetime Meyers singleton +// (thread-safe construction, C++11 [stmt.dcl]). It owns the +// current sink (unique_ptr); a sink passed via LoggerOptions is +// moved into it. +// - LogRecord's string_views (subsystem/event/message) and its field +// span are non-owning: they must outlive the Sink::emit() call. +// The LAIGE_LOG_* macros guarantee this; a direct emit() call must +// guarantee it as well. +// +// Threading (CONC-001/002): +// - Recording enabled events is safe from any thread: level/rate +// state is serialized on one facade mutex, each sink serializes +// its own output. +// - init(), setSubsystemLevel(), setGlobalMinimum(), and +// installCrashHandling() are init-phase operations: they MUST NOT +// run concurrently with logging or with each other from other +// threads (mutation in an explicit phase). +// - Lock ordering: the facade state mutex is never held while a sink +// is called, and sinks never call back into the facade. +// +// Performance (DOC-004; measured by the LogPerformance suite): +// - Disabled event: one atomic load + one branch. No allocation, no +// formatting, no lock. +// - Enabled event: state-mutex section (level lookup, rate decision), +// then one sink write. Allocations: Field value strings (only when +// fields are given), one rate-state entry per distinct +// (subsystem, event, severity) key, one summary record per rate +// window rollover. +// - FR-12.2: no logging in sim/render hot paths by default — Trace is +// off by default and hot-path diagnostics belong to Trace/Debug +// behind the level gate. + +#pragma once + +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include "laige/result.h" + +namespace laige::log { + +// --------------------------------------------------------------------------- +// Severity and level (AGENTS §14 severity contract) +// --------------------------------------------------------------------------- + +// Event severity. Contract per level (AGENTS.md §14): +// Trace very high-volume diagnostic detail; disabled by default +// Debug developer-facing state +// Info low-volume lifecycle / significant state transitions +// Warn degraded behavior the engine recovered from +// Error an operation or subsystem failed +// Fatal continued execution is unsafe: the facade records the event, +// flushes, and terminates the process (std::abort) — controlled +// termination after preserving diagnostics +enum class Severity : std::uint8_t { + Trace = 0, + Debug = 1, + Info = 2, + Warn = 3, + Error = 4, + Fatal = 5, +}; + +// Minimum-severity filter, used either logger-wide (global minimum) or +// for one subsystem (per-subsystem scope, FR-12.2). An event is +// recorded only when severity >= the applicable level. Off disables +// everything (the cheap switch for release/server profiles). +enum class Level : std::uint8_t { + Trace = 0, + Debug = 1, + Info = 2, + Warn = 3, + Error = 4, + Fatal = 5, + Off = 6, +}; + +// The stable lowercase token for a severity, as rendered in log lines. +// O(1), no allocation, thread-safe. +[[nodiscard]] inline const char* severityName(Severity severity) noexcept { + switch (severity) { + case Severity::Trace: return "trace"; + case Severity::Debug: return "debug"; + case Severity::Info: return "info"; + case Severity::Warn: return "warn"; + case Severity::Error: return "error"; + case Severity::Fatal: return "fatal"; + } + return "unknown"; // unreachable: the enum domain is exhaustive +} + +// The stable event name of the rate-limit summary (LOG-001: machine +// searchable). A summary reports suppressed repeats of another event. +inline constexpr const char* kRateLimitedEvent = "rate_limited"; + +// --------------------------------------------------------------------------- +// Structured fields (LOG-001) +// --------------------------------------------------------------------------- + +// One structured key/value pair of a log event. +// +// `name` is a non-owning view into caller storage (a literal in +// practice; keys must be stable and machine-searchable, LOG-001). +// `value` is owned and is constructed only when the event is actually +// recorded — the LAIGE_LOG_* macros guarantee that disabled events +// never construct their fields (LOG-003). +struct Field { + std::string_view name; + std::string value; +}; + +namespace detail { + +// The stack buffer field() renders scalar values into (CORE-005): +// 64 B holds int64 (-20 digits), float/double shortest round-trip +// forms (<= 25), hex pointers (<= 18), and bools with margin. +inline constexpr std::size_t kFieldBufferBytes = 64; + +// The overloads below render one scalar value into [first, first + n) +// and return the byte count n, or -1 when the value does not fit. +// They run only on the enabled path (called from field()). +int formatScalar(char* first, std::size_t size, bool value); +int formatScalar(char* first, std::size_t size, char value); +int formatScalar(char* first, std::size_t size, const char* value); +int formatScalar(char* first, std::size_t size, const void* value); + +template + requires(std::is_integral_v && !std::is_same_v && + !std::is_same_v) +int formatScalar(char* first, std::size_t size, T value) { + const auto [ptr, ec] = std::to_chars(first, first + size, value); + return (ec == std::errc{}) ? static_cast(ptr - first) : -1; +} + +template + requires(std::is_floating_point_v) +int formatScalar(char* first, std::size_t size, T value) { + // Shortest round-trip decimal (std::chars_format::general default): + // locale-independent and bit-stable, matching the engine's + // deterministic numeric policy (ADR 0002 scope). + const auto [ptr, ec] = std::to_chars(first, first + size, value); + return (ec == std::errc{}) ? static_cast(ptr - first) : -1; +} + +template + requires(std::is_enum_v) +int formatScalar(char* first, std::size_t size, T value) { + return formatScalar(first, size, + static_cast>(value)); +} + +} // namespace detail + +// Build a log field from a scalar value (see Field). +// +// MISUSE WARNING: constructing a Field allocates (the value string). +// Call it only inside a LAIGE_LOG_* macro (or where you know the event +// will be recorded) — a disabled event must not construct fields +// (LOG-003). +// +// String-like values (std::string, std::string_view, const char*, char +// arrays) are copied in full (no truncation). Other scalars (integral, +// floating-point, bool, char, enum, pointer) are rendered +// locale-free into a 64-byte stack buffer (no allocation beyond the +// Field's value string). +template +Field field(std::string_view name, const T& value) { + using D = std::remove_cvref_t; + if constexpr (std::is_same_v || + std::is_same_v || + std::is_same_v || + (std::is_array_v && + std::is_same_v, char>)) { + return Field{name, std::string(value)}; + } else { + char buf[detail::kFieldBufferBytes]; + const int n = detail::formatScalar(buf, sizeof(buf), value); + return Field{name, + std::string(buf, static_cast(n < 0 ? 0 : n))}; + } +} + +// --------------------------------------------------------------------------- +// Records and sinks +// --------------------------------------------------------------------------- + +// One recorded log event — what a Sink receives. +// +// The string_views and the field span are non-owning: they point at +// caller storage that must outlive the Sink::emit() call. +// (LOG-002: `message` is concise human-readable text; `fields` carry +// the structured detail, so failures state what failed and why.) +struct LogRecord { + // One documented clock (AGENTS §14): std::chrono::system_clock, + // rendered by the sinks in UTC as "YYYY-MM-DDTHH:MM:SS.ffffffZ" + // (RFC 3339). Diagnostics only — never part of authoritative state + // (ARCH-009). + std::chrono::system_clock::time_point timestamp; + Severity severity; + std::string_view subsystem; // stable, machine-searchable (LOG-001) + std::string_view event; // stable, machine-searchable (LOG-001) + std::string_view message; // concise human text (LOG-002) + std::span fields; + // Emitting-thread identity (std::hash of std::thread::id; the + // "thread or job identity" field of AGENTS §14). + std::uint32_t threadId; +}; + +// A replaceable logging backend (FR-12.2: sink-swappable). +// +// Contract for implementations: +// - emit() is called only for events the facade has enabled, never +// concurrently with itself. Implementations still serialize their +// own output (CONC-001) and MUST NOT call back into the facade +// (lock ordering: facade state → sink, never the reverse). +// - flush() MUST be callable from a crash handler (LOG-007): no +// blocking on an already-held lock (try_lock), no allocation. +// - A sink MUST flush in its own destructor, so a destroyed sink +// never drops buffered output (LOG-007 safe fallback). The base +// destructor is therefore default. +class Sink { + public: + virtual ~Sink() = default; + virtual void emit(const LogRecord& record) = 0; + virtual void flush() = 0; +}; + +// Sink writing one line per event to a std::FILE stream (default: +// stderr). The sink does NOT own the stream — it never fopens or +// fcloses it (a ConsoleSink(stderr) must outlive the process and the +// process must keep stderr usable for crash diagnostics). +// +// Complexity per event: O(1) writes + O(fields). A failed write is +// counted (failedWrites()), never thrown and never silent (CORE-008). +class ConsoleSink : public Sink { + public: + explicit ConsoleSink(std::FILE* stream) : stream_(stream) {} + ~ConsoleSink() override { flush(); } + + void emit(const LogRecord& record) override; + void flush() override; + + // Records whose line could not be written (0 = healthy). + [[nodiscard]] std::uint64_t failedWrites() const noexcept { + return failedWrites_; + } + + private: + std::mutex mutex_; + std::FILE* stream_; + std::uint64_t failedWrites_ = 0; +}; + +// Sink appending one line per event to a file. +// +// Create via FileSink::create() — open failure returns +// Status::failure(ErrorCode::IoError); the LOG-007 minimal fallback is +// to keep the current sink (console) and report the failure with its +// NFR-13.3 registry text. The sink owns the FILE* it opens. +class FileSink : public Sink { + public: + // Opens `path` in append mode. Never throws (NFR-8.10): a failed open + // is a Status carrying ErrorCode::IoError. + [[nodiscard]] static laige::Result> + create(std::string path); + + ~FileSink() override { flush(); } + + void emit(const LogRecord& record) override; + void flush() override; + + // Records whose line could not be written (0 = healthy). + [[nodiscard]] std::uint64_t failedWrites() const noexcept { + return failedWrites_; + } + [[nodiscard]] std::string_view path() const noexcept { return path_; } + + private: + // Use create(); the constructor exists only for the factory. + FileSink(std::string path, std::FILE* stream) + : path_(std::move(path)), + stream_(stream, closeFile) {} + + // unique_ptr deleter (fclose returns int, so it cannot be named + // directly as a void(*)(FILE*) deleter). + static void closeFile(std::FILE* f) { + if (f != nullptr) std::fclose(f); + } + + std::string path_; + std::unique_ptr stream_; + std::mutex mutex_; + std::uint64_t failedWrites_ = 0; +}; + +// --------------------------------------------------------------------------- +// The facade +// --------------------------------------------------------------------------- + +// Init-phase configuration for Logger::init(). +struct LoggerOptions { + // The sink to use; null → a ConsoleSink on stderr. The logger takes + // ownership (unique_ptr). + std::unique_ptr sink = nullptr; + // Global minimum severity, checked before the per-subsystem level — + // one atomic load, the cheap first gate. + Level globalMinimum = Level::Debug; + // Level applied to subsystems not registered via + // setSubsystemLevel(). Trace is disabled by default (AGENTS §14). + Level defaultSubsystemLevel = Level::Debug; + // LOG-004: repeated failures are rate-limited per + // (subsystem, event, severity) for Warn/Error/Fatal. + bool rateLimiting = true; + // Rate window: at most one event per key per window reaches the + // sink; the rest are counted and reported in a `rate_limited` + // summary event when the next event for the key lands after the + // window (and at shutdown for pending counts). + std::chrono::milliseconds rateWindow = std::chrono::milliseconds(1000); + // Clock for timestamps and rate decisions; null → + // std::chrono::system_clock::now(). Called only for enabled events + // (never on the disabled path); injectable for tests. + using ClockFn = std::chrono::system_clock::time_point (*)(); + ClockFn clock = nullptr; +}; + +// The one logging facade (AGENTS §14): a process-lifetime Meyers +// singleton. See the header top for ownership, threading, and +// performance contracts; the full API contract is in +// docs/api/logging.md. +class Logger { + public: + [[nodiscard]] static Logger& instance(); + + // Init-phase configuration (MUST NOT run concurrently with logging + // from other threads). Replaces the current sink (flushed first) and + // resets subsystem levels, rate state, and the retired flag; a + // previously installed crash handler is re-registered by a later + // installCrashHandling() call. Always succeeds: a sink that can fail + // is created via FileSink::create() before init (hand its sink over + // with Result::takeValue()). Takes options by value and consumes the + // sink ownership — call with an rvalue. + [[nodiscard]] laige::Status init(LoggerOptions options); + + // Per-subsystem level filter (FR-12.2 per-subsystem scopes). + // Init-phase API. The subsystem name is copied into the facade. + void setSubsystemLevel(std::string_view subsystem, Level level); + + // The effective level for `subsystem` (its registered level, or + // defaultSubsystemLevel_ when unregistered). Init-phase API. + [[nodiscard]] Level subsystemLevel(std::string_view subsystem) const; + + void setGlobalMinimum(Level level); + [[nodiscard]] Level globalMinimum() const noexcept; + + // Cheap gate behind LAIGE_LOG_*: true only when an event of + // `severity` from `subsystem` will be recorded. Cost: one atomic + // load, plus (only if that passes) one mutex section over a small + // linear scan — no allocation, no formatting (LOG-003). + [[nodiscard]] bool enabled(Severity severity, + std::string_view subsystem) const; + + // Record an enabled event. Fields are moved into the record; the + // subsystem/event/message string_views must outlive the call. + // Direct calls evaluate their arguments eagerly — prefer the + // LAIGE_LOG_* macros (lazy). Fatal events flush and then terminate + // the process (AGENTS §14 controlled termination). + template + void emit(Severity severity, std::string_view subsystem, + std::string_view event, std::string_view message, + Fields&&... fields) { + std::array storage{std::move(fields)...}; + record(severity, subsystem, event, message, std::as_const(storage)); + } + + // Flush the sink (LOG-007). + void flush(); + + // Controlled shutdown (CONC-006, idempotent): drain pending + // rate-limit summaries, flush the sink, and retire the facade — + // log calls after shutdown are discarded (no sink calls). + void shutdown(); + + // Install crash handlers (LOG-007): SIGSEGV/SIGABRT/SIGBUS/SIGFPE/ + // SIGILL on POSIX (sigaction, one-shot SA_RESETHAND), a vectored SEH + // filter on Windows. The handler writes a raw notice to stderr + // (write(2): no stdio lock, no allocation), flushes the sink + // (try_lock, allocation-free), and lets the default crash handling + // continue (core dump / debugger / abort). Init-phase API; + // idempotent. + [[nodiscard]] laige::Status installCrashHandling(); + + // The current sink (diagnostics, DBG-008); never null. + [[nodiscard]] const Sink* sink() const noexcept { return sink_.get(); } + + // Flush from a crash handler: no facade lock (the signal may have + // interrupted a dispatch holding it), no allocation (LOG-007). + void crashFlush() const { + if (sink_) sink_->flush(); + } + + private: + struct SubsystemEntry { + std::string name; + Level level; + }; + + // Rate-limit state for one (subsystem, event, severity) key + // (LOG-004). everEmitted marks the first event of a key, which is + // always recorded (it also keeps the window arithmetic free of the + // sentinel-value overflow a min() lastEmit would cause, CPP-004). + struct RateEntry { + std::string subsystem; + std::string event; + Severity severity; + bool everEmitted = false; + std::chrono::system_clock::time_point lastEmit{}; + std::uint64_t suppressed = 0; + }; + + Logger(); + Logger(const Logger&) = delete; + Logger& operator=(const Logger&) = delete; + + void record(Severity severity, std::string_view subsystem, + std::string_view event, std::string_view message, + std::span fields); + void dispatch(const LogRecord& record); + [[nodiscard]] bool rateLimited(Severity severity) const noexcept; + RateEntry* findRate(std::string_view subsystem, std::string_view event, + Severity severity); + // `entry.suppressed` carries the count reported by the summary. + void emitRateSummary(const RateEntry& entry); + + // Gate 1: global minimum (one atomic load). + std::atomic globalMinimum_; + // Retired after shutdown(); log calls are discarded. + std::atomic retired_{false}; + mutable std::mutex stateMutex_; + // Guarded by stateMutex_: small by design (a few dozen entries). + std::vector subsystems_; + std::vector rates_; + std::unique_ptr sink_; + Level defaultSubsystemLevel_{Level::Debug}; + bool rateLimiting_{true}; + std::chrono::milliseconds rateWindow_{std::chrono::milliseconds(1000)}; + LoggerOptions::ClockFn clock_{nullptr}; + bool crashHandlingInstalled_{false}; +}; + +} // namespace laige::log + +// --------------------------------------------------------------------------- +// The public logging macros (AGENTS §14 example shape) +// +// LAIGE_LOG_WARN("network", "packet_dropped", +// "Dropped packet outside receive window", +// laige::log::field("connection_id", id), +// laige::log::field("sequence", seq)); +// +// Lazy by construction: the level gate is evaluated first, and only if +// it passes are the message/field arguments evaluated and formatted — +// a disabled event costs one atomic load + branch (LOG-003). +// `subsystem`, `event`, and `message` are stable names and are passed +// twice (gate + record), so pass string literals. +// +// `##__VA_ARGS__` elides the separating comma when no fields are given: +// the portable comma-elision idiom for GCC/Clang/AppleClang and MSVC +// (its default preprocessor). If a future step enables +// /Zc:preprocessor on the engine targets, these macros need to be +// revisited (noted now per CORE-004 rather than handled now). +// --------------------------------------------------------------------------- + +#define LAIGE_LOG(severity, subsystem, event, message, ...) \ + do { \ + if (::laige::log::Logger::instance().enabled( \ + static_cast<::laige::log::Severity>(severity), subsystem)) { \ + ::laige::log::Logger::instance().emit( \ + static_cast<::laige::log::Severity>(severity), subsystem, event, \ + message, ##__VA_ARGS__); \ + } \ + } while (0) + +#define LAIGE_LOG_TRACE(subsystem, event, message, ...) \ + LAIGE_LOG(::laige::log::Severity::Trace, subsystem, event, message, \ + ##__VA_ARGS__) +#define LAIGE_LOG_DEBUG(subsystem, event, message, ...) \ + LAIGE_LOG(::laige::log::Severity::Debug, subsystem, event, message, \ + ##__VA_ARGS__) +#define LAIGE_LOG_INFO(subsystem, event, message, ...) \ + LAIGE_LOG(::laige::log::Severity::Info, subsystem, event, message, \ + ##__VA_ARGS__) +#define LAIGE_LOG_WARN(subsystem, event, message, ...) \ + LAIGE_LOG(::laige::log::Severity::Warn, subsystem, event, message, \ + ##__VA_ARGS__) +#define LAIGE_LOG_ERROR(subsystem, event, message, ...) \ + LAIGE_LOG(::laige::log::Severity::Error, subsystem, event, message, \ + ##__VA_ARGS__) +#define LAIGE_LOG_FATAL(subsystem, event, message, ...) \ + LAIGE_LOG(::laige::log::Severity::Fatal, subsystem, event, message, \ + ##__VA_ARGS__) diff --git a/src/laige-core/include/laige/result.h b/src/laige-core/include/laige/result.h index fc9de19..d12f39e 100644 --- a/src/laige-core/include/laige/result.h +++ b/src/laige-core/include/laige/result.h @@ -102,6 +102,15 @@ class Result { return error_; } + // Move the success value out of an rvalue result (ownership transfer, + // e.g. handing a freshly created resource to a container). + // Precondition: ok() and an rvalue result. Debug builds assert; in + // release builds an unchecked call is undefined behavior. + [[nodiscard]] T takeValue() && { + assert(ok() && "Result::takeValue() called on an error result"); + return std::move(*value_); + } + // Null-safe accessors (no precondition): nullptr when the result does // not carry the requested state. [[nodiscard]] const T* valueIfOk() const noexcept { diff --git a/src/laige-core/logging.cpp b/src/laige-core/logging.cpp new file mode 100644 index 0000000..8bf1bc5 --- /dev/null +++ b/src/laige-core/logging.cpp @@ -0,0 +1,496 @@ +// laige-core logging facade implementation (M0-CORE-02). +// +// File-scope design notes: +// - Timestamps use one documented clock and format (AGENTS §14): +// std::chrono::system_clock rendered in UTC as RFC 3339 +// "YYYY-MM-DDTHH:MM:SS.ffffffZ". The days→civil-date conversion is +// Howard Hinnant's calendar-date algorithm (C++ calendar-date +// proposal P0437R1, public domain; also published on cppreference) +// — no libc date functions, hence thread-safe, allocation-free, +// and identical on every P0 platform (no platform-specific date +// behavior can leak into log lines). +// - Line format (both sinks): +// [] /: +// [ | =]* +// Field values are emitted verbatim; callers should keep them free +// of spaces and '=' (machine-parseable keys, LOG-001). +// - Write failures are counted (failedWrites) and never silent +// (CORE-008); a sink that fails to open returns Status(IoError) +// before it exists (LOG-007 minimal fallback: keep the console +// sink). +// - Crash handling (LOG-007): POSIX sigaction for SEGV/ABRT/BUS/FPE/ +// ILL with SA_RESETHAND (one-shot, then the default disposition), +// a raw write(2) notice (async-signal-safe: no stdio lock, no +// allocation), a sink flush (try_lock per the Sink contract), and +// a re-raise so normal crash diagnostics (core dump, debugger, +// crash reporter) proceed unchanged. Windows uses a vectored SEH +// filter with the same flush and EXCEPTION_CONTINUE_EXECUTION. + +#include "laige/logging.h" + +#include +#include +#include +#include +#include +#include +#include + +#if defined(_WIN32) +#include +#else +#include +#include +#endif + +namespace laige::log { + +namespace { + +// Howard Hinnant's calendar-date algorithm (P0437R1 civil_from_days, +// public domain; see also cppreference, "How to determine the calendar +// date from the number of days since the epoch"): days since 1970-01-01 +// → proleptic Gregorian date. No libc date functions: thread-safe, no +// allocation, identical results on every P0 platform. +struct Civil { + int year; + std::uint16_t month; // 1-12 + std::uint16_t day; // 1-31 +}; + +Civil civilFromDays(std::int64_t z) { + z += 719468; + const std::int64_t era = (z >= 0 ? z : z - 146096) / 146097; + const std::uint64_t doe = + static_cast(z - era * 146097); // [0, 146096] + const std::uint64_t yoe = + (doe - doe / 1460 + doe / 36524 - doe / 146096) / 365; // [0, 399] + const int year = static_cast(yoe) + static_cast(era) * 400; + const std::uint64_t doy = + doe - (365 * yoe + yoe / 4 - yoe / 100); // [0, 365] + const std::uint64_t mp = (5 * doy + 2) / 153; // [0, 11] + const std::uint64_t day = doy - (153 * mp + 2) / 5 + 1; // [1, 31] + const std::uint64_t month = mp < 10 ? mp + 3 : mp - 9; // [1, 12] + return Civil{year + (month <= 2 ? 1 : 0), + static_cast(month), + static_cast(day)}; +} + +// Render the record's timestamp in the documented format into `out` +// (27 chars + NUL; `out` must be at least 64 bytes, see the comment at +// the snprintf). +void formatTimestamp(std::chrono::system_clock::time_point tp, char* out) { + const std::int64_t wholeSeconds = + std::chrono::time_point_cast(tp) + .time_since_epoch() + .count(); + std::int64_t days = wholeSeconds / 86400; + std::int64_t secondOfDay = wholeSeconds % 86400; + if (secondOfDay < 0) { + // division truncates toward zero; normalize to days + [0, 86400) + secondOfDay += 86400; + --days; + } + const std::int64_t micros = + std::chrono::duration_cast( + tp.time_since_epoch()) + .count() % + 1000000; + const unsigned frac = + static_cast(micros < 0 ? micros + 1000000 : micros); + const Civil c = civilFromDays(days); + const unsigned h = static_cast(secondOfDay / 3600); + const unsigned m = static_cast((secondOfDay % 3600) / 60); + const unsigned s = static_cast(secondOfDay % 60); + // 64 B: the documented form is 27 chars, and the buffer also satisfies + // the compiler's worst-case width analysis for the %d year (CORE-010: + // no -Wformat-truncation under -Werror). + std::snprintf(out, 64, "%04d-%02u-%02uT%02u:%02u:%02u.%06uZ", c.year, + static_cast(c.month), static_cast(c.day), + h, m, s, frac); +} + +// Render one full line into `stream` (see the file header for the +// format). Returns 0 on success, -1 if any write failed. +int writeLine(std::FILE* stream, const LogRecord& r) { + char ts[64]; + formatTimestamp(r.timestamp, ts); + int written = std::fprintf( + stream, "%s [%s] %.*s/%.*s: %.*s", ts, severityName(r.severity), + static_cast(r.subsystem.size()), r.subsystem.data(), + static_cast(r.event.size()), r.event.data(), + static_cast(r.message.size()), r.message.data()); + if (written < 0) return -1; + for (const Field& f : r.fields) { + const int n = std::fprintf(stream, " | %.*s=%s", + static_cast(f.name.size()), + f.name.data(), f.value.c_str()); + if (n < 0) return -1; + } + return (std::fputc('\n', stream) == EOF) ? -1 : 0; +} + +} // namespace + +// --------------------------------------------------------------------------- +// detail::formatScalar — the non-template overloads (see logging.h) +// --------------------------------------------------------------------------- + +namespace detail { + +int formatScalar(char* first, std::size_t size, bool value) { + const char* s = value ? "true" : "false"; + const std::size_t n = std::strlen(s); + if (n > size) return -1; + std::memcpy(first, s, n); + return static_cast(n); +} + +int formatScalar(char* first, std::size_t size, char value) { + if (size == 0) return -1; + first[0] = value; + return 1; +} + +int formatScalar(char* first, std::size_t size, const char* value) { + const std::size_t n = (value != nullptr) ? std::strlen(value) : 0; + if (n > size) return -1; + if (n > 0) std::memcpy(first, value, n); + return static_cast(n); +} + +int formatScalar(char* first, std::size_t size, const void* value) { + const int n = std::snprintf(first, size, "%p", value); + return (n < 0 || n >= static_cast(size)) ? -1 : n; +} + +} // namespace detail + +// --------------------------------------------------------------------------- +// ConsoleSink +// --------------------------------------------------------------------------- + +void ConsoleSink::emit(const LogRecord& record) { + std::lock_guard lk(mutex_); + if (writeLine(stream_, record) == -1) ++failedWrites_; +} + +void ConsoleSink::flush() { + // try_lock: a flush from a crash handler must not block on a lock the + // interrupted emit() may still hold (LOG-007). + if (mutex_.try_lock()) { + if (std::fflush(stream_) != 0) ++failedWrites_; + mutex_.unlock(); + } +} + +// --------------------------------------------------------------------------- +// FileSink +// --------------------------------------------------------------------------- + +laige::Result> FileSink::create(std::string path) { + std::FILE* stream = std::fopen(path.c_str(), "a"); + if (stream == nullptr) { + // LOG-007 minimal fallback: the caller keeps its current sink + // (console) and reports the failure; the Status carries the + // NFR-13.3 registry text (docs/api/errors.md#io-error). + return laige::Result>::failure( + laige::ErrorCode::IoError); + } + // The factory is the sole creation path and encapsulates the one + // owning new (std::make_unique cannot call the private constructor). + return std::unique_ptr(new FileSink(std::move(path), stream)); +} + +void FileSink::emit(const LogRecord& record) { + std::lock_guard lk(mutex_); + if (writeLine(stream_.get(), record) == -1) ++failedWrites_; +} + +void FileSink::flush() { + // try_lock: same crash-handler constraint as ConsoleSink::flush(). + if (mutex_.try_lock()) { + if (std::fflush(stream_.get()) != 0) ++failedWrites_; + mutex_.unlock(); + } +} + +// --------------------------------------------------------------------------- +// Logger +// --------------------------------------------------------------------------- + +Logger& Logger::instance() { + static Logger logger; + return logger; +} + +Logger::Logger() + : globalMinimum_(static_cast(Level::Debug)), + sink_(std::make_unique(stderr)) {} + +laige::Status Logger::init(LoggerOptions options) { + std::unique_ptr sink = + (options.sink != nullptr) ? std::move(options.sink) + : std::make_unique(stderr); + { + std::lock_guard lk(stateMutex_); + if (sink_ != nullptr) sink_->flush(); // replaced sink flushes first + sink_ = std::move(sink); + globalMinimum_.store(static_cast(options.globalMinimum), + std::memory_order_relaxed); + defaultSubsystemLevel_ = options.defaultSubsystemLevel; + rateLimiting_ = options.rateLimiting; + rateWindow_ = options.rateWindow; + clock_ = options.clock; + subsystems_.clear(); + rates_.clear(); + crashHandlingInstalled_ = false; + } + retired_.store(false, std::memory_order_relaxed); + return {}; +} + +void Logger::setSubsystemLevel(std::string_view subsystem, Level level) { + std::lock_guard lk(stateMutex_); + for (SubsystemEntry& e : subsystems_) { + if (e.name == subsystem) { + e.level = level; + return; + } + } + subsystems_.push_back(SubsystemEntry{std::string(subsystem), level}); +} + +Level Logger::subsystemLevel(std::string_view subsystem) const { + std::lock_guard lk(stateMutex_); + for (const SubsystemEntry& e : subsystems_) { + if (e.name == subsystem) return e.level; + } + return defaultSubsystemLevel_; +} + +void Logger::setGlobalMinimum(Level level) { + globalMinimum_.store(static_cast(level), + std::memory_order_relaxed); +} + +Level Logger::globalMinimum() const noexcept { + return static_cast(globalMinimum_.load(std::memory_order_relaxed)); +} + +bool Logger::enabled(Severity severity, std::string_view subsystem) const { + if (retired_.load(std::memory_order_relaxed)) return false; + // Gate 1: the global minimum (one atomic load — the cheap reject for + // Trace under the default configuration). + if (static_cast(severity) < + globalMinimum_.load(std::memory_order_relaxed)) { + return false; + } + // Gate 2: the per-subsystem level (small linear scan; N is the number + // of registered subsystems, expected to be well under a few dozen). + std::lock_guard lk(stateMutex_); + for (const SubsystemEntry& e : subsystems_) { + if (e.name == subsystem) { + return static_cast(severity) >= + static_cast(e.level); + } + } + return static_cast(severity) >= + static_cast(defaultSubsystemLevel_); +} + +void Logger::record(Severity severity, std::string_view subsystem, + std::string_view event, std::string_view message, + std::span fields) { + if (retired_.load(std::memory_order_relaxed)) return; + const auto now = (clock_ != nullptr) + ? clock_() + : std::chrono::system_clock::now(); + const std::uint32_t threadId = static_cast( + std::hash{}(std::this_thread::get_id())); + const LogRecord record{now, severity, subsystem, event, message, fields, + threadId}; + dispatch(record); +} + +void Logger::dispatch(const LogRecord& record) { + // The rate decision runs under the state mutex; the sink is called + // only after the lock is released (lock ordering: state → sink). + // `summary` is a copy: the lock release can let another thread + // reallocate rates_, so no pointer into it survives the section. + RateEntry summary; + bool hasSummary = false; + { + std::lock_guard lk(stateMutex_); + if (rateLimiting_ && rateLimited(record.severity)) { + RateEntry* e = findRate(record.subsystem, record.event, + record.severity); + if (e == nullptr) { + e = &rates_.emplace_back( + RateEntry{std::string(record.subsystem), std::string(record.event), + record.severity, false, {}, 0}); + } + // everEmitted short-circuits before the window subtraction (no + // sentinel-value overflow; CPP-004). + if (!e->everEmitted || record.timestamp - e->lastEmit >= rateWindow_) { + // Window elapsed (or first event of the key): record this event, + // and report the suppressed repeats of the just-ended window. + if (e->suppressed > 0) { + summary = *e; // copies the strings; summary.suppressed = count + e->suppressed = 0; + hasSummary = true; + } + e->everEmitted = true; + e->lastEmit = record.timestamp; + } else { + ++e->suppressed; // LOG-004: counted; reported at window end + return; + } + } + } + if (hasSummary) { + emitRateSummary(summary); + } + sink_->emit(record); + if (record.severity == Severity::Fatal) { + // AGENTS §14: Fatal initiates controlled termination after + // preserving useful diagnostics (emit above, flush here). std::abort + // raises SIGABRT, which the crash handler (if installed) flushes + // once more (idempotent) before the default handling takes over. + sink_->flush(); + std::abort(); + } +} + +bool Logger::rateLimited(Severity severity) const noexcept { + // LOG-004 scopes rate limiting to repeated failures. + return severity == Severity::Warn || severity == Severity::Error || + severity == Severity::Fatal; +} + +Logger::RateEntry* Logger::findRate(std::string_view subsystem, + std::string_view event, Severity severity) { + for (RateEntry& e : rates_) { + if (e.severity == severity && e.subsystem == subsystem && e.event == event) { + return &e; + } + } + return nullptr; +} + +void Logger::emitRateSummary(const Logger::RateEntry& entry) { + // A dedicated, stable summary event (kRateLimitedEvent, LOG-001) with + // the original event name and the suppressed count (entry.suppressed) + // as fields, so rate-limited failures stay machine-searchable. Runs + // after the state lock is released; called from dispatch() (window + // rollover) and shutdown() (pending drain). + const std::uint64_t suppressed = entry.suppressed; + char countBuf[32]; + const auto [ptr, ec] = + std::to_chars(countBuf, countBuf + sizeof(countBuf), suppressed); + const std::size_t n = (ec == std::errc{}) ? static_cast(ptr - countBuf) + : 0; + const std::string count(countBuf, n); + const std::string message = "suppressed " + count + " repeats of '" + + entry.subsystem + "/" + entry.event + "'"; + std::array fields{ + Field{"event", entry.event}, + Field{"suppressed", count}, + }; + const auto now = (clock_ != nullptr) + ? clock_() + : std::chrono::system_clock::now(); + const LogRecord summary{now, entry.severity, entry.subsystem, + kRateLimitedEvent, message, std::as_const(fields), + static_cast( + std::hash{}( + std::this_thread::get_id()))}; + sink_->emit(summary); +} + +void Logger::flush() { + if (sink_ != nullptr) sink_->flush(); +} + +void Logger::shutdown() { + std::vector pending; + { + std::lock_guard lk(stateMutex_); + retired_.store(true, std::memory_order_relaxed); + for (const RateEntry& e : rates_) { + if (e.suppressed > 0) pending.push_back(e); // copy: state is cleared + } + rates_.clear(); + } + for (const RateEntry& e : pending) { + emitRateSummary(e); + } + if (sink_ != nullptr) sink_->flush(); +} + +// --------------------------------------------------------------------------- +// Crash handling (LOG-007) +// --------------------------------------------------------------------------- + +#if defined(_WIN32) + +namespace { + +// Vectored SEH filter: flush the sink, then continue to the default SEH +// handling (the OS error dialog / debugger / abort path). +LONG WINAPI crashFilter(EXCEPTION_POINTERS*) { + Logger::instance().crashFlush(); + return EXCEPTION_CONTINUE_EXECUTION; +} + +} // namespace + +laige::Status Logger::installCrashHandling() { + std::lock_guard lk(stateMutex_); + if (crashHandlingInstalled_) return {}; // idempotent + if (AddVectoredExceptionHandler(1 /*FIRST*/, crashFilter) == 0) { + // Registration failed: report it (CORE-008), leave state unchanged. + return laige::Status::failure(laige::ErrorCode::IoError); + } + crashHandlingInstalled_ = true; + return {}; +} + +#else // POSIX + +namespace { + +// LOG-007: preserve output on crash. The notice goes out with a raw +// write(2) — no stdio lock, no allocation, no locale — so it is +// async-signal-safe. After flushing, re-raise the signal so the default +// disposition (core dump / debugger / abort) continues unchanged. +void crashHandler(int signum, siginfo_t*, void*) { + static const char msg[] = "laige: fatal signal received; flushing logs\n"; + (void)write(STDERR_FILENO, msg, sizeof(msg) - 1); + Logger::instance().crashFlush(); + raise(signum); +} + +} // namespace + +laige::Status Logger::installCrashHandling() { + std::lock_guard lk(stateMutex_); + if (crashHandlingInstalled_) return {}; // idempotent + static const int kCrashSignals[] = {SIGSEGV, SIGABRT, SIGBUS, SIGFPE, + SIGILL}; + struct sigaction sa{}; + sa.sa_sigaction = &crashHandler; + sa.sa_flags = SA_RESETHAND; // one-shot: default disposition resumes + sigemptyset(&sa.sa_mask); + for (const int signum : kCrashSignals) { + if (sigaction(signum, &sa, nullptr) != 0) { + return laige::Status::failure(laige::ErrorCode::IoError); + } + } + crashHandlingInstalled_ = true; + return {}; +} + +#endif // _WIN32 + +} // namespace laige::log diff --git a/tests/laige-core/CMakeLists.txt b/tests/laige-core/CMakeLists.txt index fd502d4..98d0724 100644 --- a/tests/laige-core/CMakeLists.txt +++ b/tests/laige-core/CMakeLists.txt @@ -10,7 +10,23 @@ # in this shared executable as separate source files and are exposed as # their own CTest entries (M0-CORE-01 adds `result_status`; later # M0-CORE-xx steps follow the same pattern). -add_executable(laige-core_tests laige-core_tests.cpp result_status_tests.cpp) +set(LAIGE_CORE_TEST_SOURCES laige-core_tests.cpp result_status_tests.cpp + logging_tests.cpp) +# M0-CORE-02: the test-only allocation counter overrides the global +# operator new/new[]; the sanitizer runtimes define their own new/delete +# (strong symbols in the Clang/GCC TSan runtime archives, interposed by +# ASan), so the counter is excluded from the sanitizer trees. There, the +# step's zero-allocation property is covered by the leak-free sanitizer +# run of the same spam loop plus the LogPerformance timing property — +# the fallback the roadmap names for this step. +if(NOT LAIGE_ASAN AND NOT LAIGE_TSAN) + list(APPEND LAIGE_CORE_TEST_SOURCES logging_alloc_counter.cpp) +endif() + +add_executable(laige-core_tests ${LAIGE_CORE_TEST_SOURCES}) +if(NOT LAIGE_ASAN AND NOT LAIGE_TSAN) + target_compile_definitions(laige-core_tests PRIVATE LAIGE_ALLOC_COUNTER=1) +endif() laige_apply_engine_policy(laige-core_tests) # Links the library under test (the link itself is the static/shared check) @@ -39,9 +55,18 @@ add_test(NAME result_status COMMAND laige-core_tests --gtest_filter="ResultStatus.*:Status.*:ErrorCodeRegistry.*") +# M0-CORE-02: structured logging facade. The step's Verify command is +# `ctest -R logging`; this entry selects exactly the logging suites +# from the shared laige-core_tests executable. +add_test(NAME logging + COMMAND laige-core_tests + --gtest_filter="LogGate.*:LogRecord.*:LogSinks.*:LogRateLimit.*:" + "LogFatal.*:LogCrash.*:LogConcurrency.*:" + "LogPerformance.*") + if(LAIGE_TSAN) # Make the first data race report fatal to the test process (NFR-8.2), # so ctest fails loudly on any TSan report. - set_tests_properties(laige-core_tests result_status + set_tests_properties(laige-core_tests result_status logging PROPERTIES ENVIRONMENT "TSAN_OPTIONS=halt_on_error=1") endif() diff --git a/tests/laige-core/logging_alloc_counter.cpp b/tests/laige-core/logging_alloc_counter.cpp new file mode 100644 index 0000000..0fa0510 --- /dev/null +++ b/tests/laige-core/logging_alloc_counter.cpp @@ -0,0 +1,74 @@ +// Test-only global operator new/new[] overrides (see the header). +// +// A strong definition of the global operator new/new[] in this +// translation unit is linked ahead of the CRT's weak defaults +// (GCC/Clang/AppleClang: the library definitions are weak; MSVC: the +// linker only pulls in a CRT allocator module to resolve undefined +// symbols, which this object already defines). Every heap allocation +// made by any translation unit in the test executable therefore +// passes through the counters below. + +#include "logging_alloc_counter.h" + +#include +#include +#include +#include + +namespace laige::test { + +void resetAllocCounter() { + detail::allocCount.store(0, std::memory_order_relaxed); +} + +std::uint64_t allocCounter() { + return detail::allocCount.load(std::memory_order_relaxed); +} + +} // namespace laige::test + +namespace { + +void count() noexcept { + laige::test::detail::allocCount.fetch_add(1, std::memory_order_relaxed); +} + +} // namespace + +void* operator new(std::size_t size) { + count(); + void* p = std::malloc(size); + if (p == nullptr) std::terminate(); // no exceptions (NFR-8.10) + return p; +} + +void* operator new[](std::size_t size) { + count(); + void* p = std::malloc(size); + if (p == nullptr) std::terminate(); + return p; +} + +void* operator new(std::size_t size, const std::nothrow_t&) noexcept { + void* p = std::malloc(size); + if (p != nullptr) count(); + return p; +} + +void* operator new[](std::size_t size, const std::nothrow_t&) noexcept { + void* p = std::malloc(size); + if (p != nullptr) count(); + return p; +} + +void operator delete(void* p) noexcept { std::free(p); } +void operator delete[](void* p) noexcept { std::free(p); } + +// The sized deallocations too: libstdc++ deallocates through +// operator delete(p, size), and without these overrides the CRT +// defaults would present the free to the sanitizer as a delete of a +// malloc-style allocation (ASan alloc-dealloc-mismatch). Routing them +// through std::free keeps every allocation/deallocation pair +// malloc/free-consistent under the sanitizers. +void operator delete(void* p, std::size_t) noexcept { std::free(p); } +void operator delete[](void* p, std::size_t) noexcept { std::free(p); } diff --git a/tests/laige-core/logging_alloc_counter.h b/tests/laige-core/logging_alloc_counter.h new file mode 100644 index 0000000..4fefaae --- /dev/null +++ b/tests/laige-core/logging_alloc_counter.h @@ -0,0 +1,41 @@ +// Test-only process-wide allocation counter (M0-CORE-02). +// +// logging_alloc_counter.cpp defines the program's global operator +// new/new[] (the strong definition overrides the CRT's weak default +// for the whole test executable), so every heap allocation made +// anywhere in the process — test framework, engine under test, test +// code — is counted. It is the M0 stand-in for M0-CORE-05's pool +// accounting for this roadmap step's "disabled levels allocate +// nothing" assertion (M0-CORE-05 does not exist yet). +// +// TEST-ONLY: never link this translation unit into an engine library +// or a tool — it would replace the real allocator for that binary. It +// is also excluded from the sanitizer build trees (LAIGE_ASAN/ +// LAIGE_TSAN): the sanitizer runtimes define their own new/delete, so +// the overrides cannot be linked there (see tests/laige-core/ +// CMakeLists.txt; the zero-allocation property is verified in those +// trees by the leak-free runs of the same spam loop plus the timing +// property test). + +#pragma once + +#include +#include + +namespace laige::test { + +namespace detail { + +// The process-wide heap-allocation count (see the file header). +inline std::atomic allocCount{0}; + +} // namespace detail + +// Reset the counter to zero. Call it after the test framework has +// finished its startup allocations and before the region under test. +void resetAllocCounter(); + +// The number of heap allocations since the last reset. +std::uint64_t allocCounter(); + +} // namespace laige::test diff --git a/tests/laige-core/logging_tests.cpp b/tests/laige-core/logging_tests.cpp new file mode 100644 index 0000000..d8d4a47 --- /dev/null +++ b/tests/laige-core/logging_tests.cpp @@ -0,0 +1,743 @@ +// laige-core logging facade suite (M0-CORE-02). +// +// Step Verify scope (roadmap/M0-foundations.md): +// - `ctest -R logging` green +// - disabled levels allocate nothing: asserted with the test-only +// process-wide allocation counter (logging_alloc_counter.cpp — +// the M0 stand-in for M0-CORE-05's pool accounting, which does not +// exist yet), backed by the ASan/TSan build trees and a timing +// property test +// - rate-limit summary emitted after N repeats (LOG-004) +// +// NFR-8.10 self-checks: this translation unit compiles with +// -fno-exceptions -fno-rtti (laige_apply_engine_policy); the +// static_asserts below make a policy violation fail the build. + +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include "gtest/gtest.h" +#include "laige/errors.h" +#include "laige/logging.h" +#include "laige/result.h" + +#include "logging_alloc_counter.h" + +#if defined(__unix__) +#include +#include +#include +#endif + +// --------------------------------------------------------------------------- +// NFR-8.10 policy self-checks (compile-time; a violation fails the build) +// --------------------------------------------------------------------------- + +#if defined(__cpp_exceptions) +static_assert(false, + "logging_tests must be built with exceptions disabled " + "(NFR-8.10); see laige_apply_engine_policy()."); +#elif defined(__EXCEPTIONS) && __EXCEPTIONS +static_assert(false, + "logging_tests must be built with exceptions disabled " + "(NFR-8.10); see laige_apply_engine_policy()."); +#endif + +#if defined(__cpp_rtti) && __cpp_rtti +static_assert(false, + "logging_tests must be built with RTTI disabled " + "(NFR-8.10); see laige_apply_engine_policy()."); +#endif + +#if defined(_MSC_VER) +# define LOGGING_TESTS_ACTIVE_CPLUSPLUS _MSVC_LANG +#else +# define LOGGING_TESTS_ACTIVE_CPLUSPLUS __cplusplus +#endif + +#if LOGGING_TESTS_ACTIVE_CPLUSPLUS < 202002L +static_assert(false, + "logging_tests must be built as C++20 (NFR-8.10); see " + "laige_apply_engine_policy()."); +#endif + +namespace { + +using laige::log::Level; +using laige::log::Logger; +using laige::log::LogRecord; +using laige::log::Severity; + +// A sink that records every emitted record in memory (test oracle). +struct CapturedRecord { + Severity severity{}; + std::string subsystem; + std::string event; + std::string message; + std::vector> fields; + std::chrono::system_clock::time_point timestamp{}; + std::uint32_t threadId{}; +}; + +class CaptureSink : public laige::log::Sink { + public: + void emit(const LogRecord& r) override { + std::lock_guard lk(mutex_); + CapturedRecord c; + c.severity = r.severity; + c.subsystem.assign(r.subsystem); + c.event.assign(r.event); + c.message.assign(r.message); + for (const laige::log::Field& f : r.fields) { + c.fields.emplace_back(std::string(f.name), f.value); + } + c.timestamp = r.timestamp; + c.threadId = r.threadId; + records_.push_back(std::move(c)); + } + void flush() override { + std::lock_guard lk(mutex_); + ++flushCount_; + } + void reset() { + std::lock_guard lk(mutex_); + records_.clear(); + flushCount_ = 0; + } + std::vector takeRecords() { + std::lock_guard lk(mutex_); + std::vector out = std::move(records_); + records_.clear(); + return out; + } + std::size_t recordCount() const { + std::lock_guard lk(mutex_); + return records_.size(); + } + std::size_t flushCount() const { + std::lock_guard lk(mutex_); + return flushCount_; + } + + private: + mutable std::mutex mutex_; + std::vector records_; + std::size_t flushCount_ = 0; +}; + +CaptureSink& capture() { + static CaptureSink cap; + return cap; +} + +// Forwards into the global capture sink so the logger can own its sink +// (LoggerOptions moves the unique_ptr in) while the test keeps an +// observable handle. Test shim: it intentionally does not flush in its +// destructor (the logger never relies on a forwarding shim for +// LOG-007; the real sinks honor the Sink contract). +class ForwardingSink : public laige::log::Sink { + public: + explicit ForwardingSink(CaptureSink& target) : target_(target) {} + void emit(const LogRecord& r) override { target_.emit(r); } + void flush() override { target_.flush(); } + + private: + CaptureSink& target_; +}; + +// (Re)configure the process logger for one test: fresh forwarding sink, +// real clock unless the options carry one. Takes the options by value +// (LoggerOptions owns a unique_ptr and is move-only) — callers pass an +// rvalue. +void resetLogger(laige::log::LoggerOptions tweaks = + laige::log::LoggerOptions()) { + if (tweaks.sink == nullptr) { + tweaks.sink = std::make_unique(capture()); + } + EXPECT_TRUE(Logger::instance().init(std::move(tweaks)).ok()); + capture().reset(); +} + +// Fake clock (rate-limit tests): advances manually, same thread. +std::chrono::system_clock::time_point gFakeNow{}; +std::chrono::system_clock::time_point fakeClock() { return gFakeNow; } + +void resetRateLogger(std::chrono::milliseconds window) { + laige::log::LoggerOptions o; + o.clock = &fakeClock; + o.rateWindow = window; + resetLogger(std::move(o)); +} + +// The field value for `name` in a captured record (""); tests only rely +// on non-empty expected values, so "" doubles as "absent". +std::string fieldAt(const CapturedRecord& r, std::string_view name) { + for (const auto& [k, v] : r.fields) { + if (k == name) return v; + } + return {}; +} + +// True for a well-formed log line start: +// "YYYY-MM-DDTHH:MM:SS.ffffffZ " (27 chars + a space). Hand-rolled so +// this suite stays free of the exception machinery it tests the engine +// against (std::regex would work but is not needed). +bool hasTimestampPrefix(std::string_view line) { + if (line.size() < 28) return false; + static const char kSpecial[28] = {0, 0, 0, 0, '-', 0, 0, '-', + 0, 0, 'T', 0, 0, ':', 0, 0, + ':', 0, 0, '.', 0, 0, 0, 0, 0, + 0, 'Z', ' '}; + for (int i = 0; i < 28; ++i) { + const char c = line[i]; + if (kSpecial[i] != 0) { + if (c != kSpecial[i]) return false; + } else if (c < '0' || c > '9') { + return false; + } + } + return true; +} + +std::string tempFilePath(const char* name) { + return std::string("laige_logging_test_") + name + ".log"; +} + +std::string readWholeFile(const std::string& path) { + std::FILE* f = std::fopen(path.c_str(), "rb"); + if (f == nullptr) return {}; + std::string out; + char buf[4096]; + std::size_t n; + while ((n = std::fread(buf, 1, sizeof(buf), f)) > 0) { + out.append(buf, n); + } + std::fclose(f); + return out; +} + +LogRecord makeRecord(Severity severity, std::string_view subsystem, + std::string_view event, std::string_view message, + std::span fields) { + return LogRecord{std::chrono::system_clock::now(), severity, subsystem, + event, message, fields, 0}; +} + +} // namespace + +// --------------------------------------------------------------------------- +// Level gating: global minimum + per-subsystem scopes +// --------------------------------------------------------------------------- + +TEST(LogGate, DefaultLevelsGateTrace) { + resetLogger(); + const Logger& lg = Logger::instance(); + // Trace is disabled by default (AGENTS §14); the rest pass. + EXPECT_FALSE(lg.enabled(Severity::Trace, "sys")); + EXPECT_TRUE(lg.enabled(Severity::Debug, "sys")); + EXPECT_TRUE(lg.enabled(Severity::Info, "sys")); + EXPECT_TRUE(lg.enabled(Severity::Warn, "sys")); + EXPECT_TRUE(lg.enabled(Severity::Error, "sys")); + EXPECT_TRUE(lg.enabled(Severity::Fatal, "sys")); + EXPECT_EQ(lg.globalMinimum(), Level::Debug); + // Unregistered subsystems take the default subsystem level. + EXPECT_EQ(lg.subsystemLevel("unregistered"), Level::Debug); +} + +TEST(LogGate, PerSubsystemLevels) { + resetLogger(); + Logger& lg = Logger::instance(); + lg.setSubsystemLevel("quiet", Level::Off); + EXPECT_FALSE(lg.enabled(Severity::Error, "quiet")); + EXPECT_FALSE(lg.enabled(Severity::Fatal, "quiet")); + EXPECT_EQ(lg.subsystemLevel("quiet"), Level::Off); + + lg.setSubsystemLevel("critical", Level::Fatal); + EXPECT_FALSE(lg.enabled(Severity::Error, "critical")); + EXPECT_TRUE(lg.enabled(Severity::Fatal, "critical")); + EXPECT_EQ(lg.subsystemLevel("critical"), Level::Fatal); + + // Re-setting the same subsystem updates in place. + lg.setSubsystemLevel("quiet", Level::Warn); + EXPECT_TRUE(lg.enabled(Severity::Warn, "quiet")); + EXPECT_FALSE(lg.enabled(Severity::Info, "quiet")); +} + +TEST(LogGate, GlobalMinimumDominates) { + resetLogger(); + Logger& lg = Logger::instance(); + lg.setSubsystemLevel("loose", Level::Debug); + lg.setGlobalMinimum(Level::Error); + EXPECT_FALSE(lg.enabled(Severity::Warn, "loose")); + EXPECT_TRUE(lg.enabled(Severity::Error, "loose")); + EXPECT_EQ(lg.globalMinimum(), Level::Error); + + lg.setGlobalMinimum(Level::Off); + EXPECT_FALSE(lg.enabled(Severity::Fatal, "loose")); + EXPECT_FALSE(lg.enabled(Severity::Fatal, "anything")); +} + +TEST(LogGate, DisabledEventReachesNoSink) { + resetLogger(); + Logger::instance().setSubsystemLevel("spam", Level::Info); + for (int i = 0; i < 100; ++i) { + LAIGE_LOG_TRACE("spam", "spam_event", "spam message", + laige::log::field("i", i)); + } + EXPECT_EQ(capture().recordCount(), 0u); +} + +// --------------------------------------------------------------------------- +// Records: fields, identity, timestamp +// --------------------------------------------------------------------------- + +TEST(LogRecord, FieldFormattingScalars) { + resetLogger(); + const int x = 42; + LAIGE_LOG_INFO("demo", "fields", "scalar fields", + laige::log::field("i32", 7), + laige::log::field("neg", -3), + laige::log::field("i64", INT64_MAX), + laige::log::field("u64", UINT64_MAX), + laige::log::field("d", 0.1), + laige::log::field("f", 1.5f), + laige::log::field("b", true), + laige::log::field("c", 'x'), + laige::log::field("e", Severity::Warn), + laige::log::field("p", &x), + laige::log::field("pnull", static_cast(nullptr))); + const std::vector recs = capture().takeRecords(); + ASSERT_EQ(recs.size(), 1u); + const CapturedRecord& r = recs[0]; + EXPECT_EQ(r.severity, Severity::Info); + EXPECT_EQ(fieldAt(r, "i32"), "7"); + EXPECT_EQ(fieldAt(r, "neg"), "-3"); + EXPECT_EQ(fieldAt(r, "i64"), std::to_string(INT64_MAX)); + EXPECT_EQ(fieldAt(r, "u64"), std::to_string(UINT64_MAX)); + EXPECT_EQ(fieldAt(r, "d"), "0.1"); + EXPECT_EQ(fieldAt(r, "f"), "1.5"); + EXPECT_EQ(fieldAt(r, "b"), "true"); + EXPECT_EQ(fieldAt(r, "c"), "x"); + EXPECT_EQ(fieldAt(r, "e"), "3"); // enum renders its underlying value + // Pointer fields are platform-rendered (%p); assert presence only. + EXPECT_FALSE(fieldAt(r, "p").empty()); + EXPECT_FALSE(fieldAt(r, "pnull").empty()); +} + +TEST(LogRecord, StringFieldsCopiedInFull) { + resetLogger(); + const std::string longValue(256, 'a'); + LAIGE_LOG_INFO("demo", "string_fields", "string-like fields", + laige::log::field("s", longValue), + laige::log::field("sv", std::string_view("literal")), + laige::log::field("arr", "char array")); + const std::vector recs = capture().takeRecords(); + ASSERT_EQ(recs.size(), 1u); + EXPECT_EQ(fieldAt(recs[0], "s"), longValue); + EXPECT_EQ(fieldAt(recs[0], "sv"), "literal"); + EXPECT_EQ(fieldAt(recs[0], "arr"), "char array"); +} + +TEST(LogRecord, IdentityAndTimestamp) { + resetLogger(); + const auto before = std::chrono::system_clock::now(); + LAIGE_LOG_INFO("sub", "evt", "message"); + const auto after = std::chrono::system_clock::now(); + const std::vector recs = capture().takeRecords(); + ASSERT_EQ(recs.size(), 1u); + const CapturedRecord& r = recs[0]; + EXPECT_EQ(r.subsystem, "sub"); + EXPECT_EQ(r.event, "evt"); + EXPECT_EQ(r.message, "message"); + EXPECT_TRUE(r.fields.empty()); + EXPECT_EQ(r.threadId, static_cast( + std::hash{}( + std::this_thread::get_id()))); + // One documented clock (system_clock): the timestamp brackets the + // emission instant. + EXPECT_GE(r.timestamp, before); + EXPECT_LE(r.timestamp, after); +} + +// --------------------------------------------------------------------------- +// Sinks: line format, file sink, create failure +// --------------------------------------------------------------------------- + +TEST(LogSinks, ConsoleSinkLineFormat) { + const std::string path = tempFilePath("console"); + std::FILE* f = std::fopen(path.c_str(), "w+"); + ASSERT_NE(f, nullptr); + { + laige::log::ConsoleSink sink(f); + const laige::log::Field fields[] = {laige::log::field("connection_id", 42)}; + sink.emit(makeRecord(Severity::Warn, "network", "packet_dropped", + "Dropped packet outside receive window", + std::as_const(fields))); + sink.emit(makeRecord(Severity::Info, "engine", "boot", "engine started", + std::span{})); + sink.flush(); + } + std::fclose(f); + const std::string content = readWholeFile(path); + std::remove(path.c_str()); + + const std::string expected1 = + "[warn] network/packet_dropped: Dropped packet outside receive " + "window | connection_id=42\n"; + const std::string expected2 = + "[info] engine/boot: engine started\n"; + const std::size_t pos2 = content.find(expected2); + ASSERT_NE(pos2, std::string::npos) << content; + ASSERT_EQ(content.size(), pos2 + expected2.size()) << content; + ASSERT_TRUE(hasTimestampPrefix(content.substr(0, pos2 - 28))); + EXPECT_EQ(content.substr(28, pos2 - 28 - 28), expected1); +} + +TEST(LogSinks, ConsoleSinkDoesNotOwnStream) { + // A ConsoleSink must leave its stream usable after destruction + // (LOG-007: stderr must stay usable for crash diagnostics). + const std::string path = tempFilePath("console2"); + std::FILE* f = std::fopen(path.c_str(), "w+"); + ASSERT_NE(f, nullptr); + { + laige::log::ConsoleSink sink(f); + sink.emit(makeRecord(Severity::Info, "s", "e", "m", + std::span{})); + } // sink destroyed; stream must still be open + const int n = std::fputc('\n', f); + EXPECT_NE(n, EOF); + std::fclose(f); + std::remove(path.c_str()); +} + +TEST(LogSinks, FileSinkLineFormat) { + const std::string path = tempFilePath("file"); + std::remove(path.c_str()); + const laige::Result> created = + laige::log::FileSink::create(path); + ASSERT_TRUE(created.ok()); + created.value()->emit( + makeRecord(Severity::Error, "assets", "decode_failed", "bad texture", + std::span{})); + created.value()->emit(makeRecord(Severity::Debug, "assets", "cache_hit", + "hit", std::span{})); + created.value()->flush(); + EXPECT_EQ(created.value()->failedWrites(), 0u); + const std::string content = readWholeFile(path); + std::remove(path.c_str()); + + const std::string expected1 = + "[error] assets/decode_failed: bad texture\n"; + const std::string expected2 = "[debug] assets/cache_hit: hit\n"; + const std::size_t pos2 = content.find(expected2); + ASSERT_NE(pos2, std::string::npos) << content; + ASSERT_EQ(content.size(), pos2 + expected2.size()) << content; + ASSERT_TRUE(hasTimestampPrefix(content.substr(0, pos2 - 28))); + EXPECT_EQ(content.substr(28, pos2 - 28 - 28), expected1); +} + +TEST(LogSinks, FileSinkFlushesOnDestruction) { + // LOG-007 safe fallback: a destroyed sink must not drop buffered + // output even without an explicit flush(). + const std::string path = tempFilePath("destructor"); + std::remove(path.c_str()); + { + const auto created = laige::log::FileSink::create(path); + ASSERT_TRUE(created.ok()); + created.value()->emit(makeRecord(Severity::Info, "s", "e", "m", + std::span{})); + // no explicit flush + } // destructor flushes + const std::string content = readWholeFile(path); + std::remove(path.c_str()); + ASSERT_TRUE(hasTimestampPrefix(content)); + EXPECT_NE(content.find("[info] s/e: m\n"), std::string::npos) << content; +} + +TEST(LogSinks, FileSinkCreateFailureReturnsIoError) { + // LOG-007: open failure is a Status (never an exception, never + // silent); the caller falls back to the current console sink. + const auto r = laige::log::FileSink::create( + std::string("/nonexistent_dir_laige_xyz/") + tempFilePath("missing")); + ASSERT_TRUE(r.isError()); + EXPECT_EQ(r.error(), laige::ErrorCode::IoError); + // The failure code maps to the registry entry (NFR-13.3 text). + const laige::ErrorEntry& info = laige::errorInfo(r.error()); + EXPECT_STREQ(info.codeId, "io_error"); + EXPECT_STREQ(laige::errorText(r.error()), info.text); +} + +// --------------------------------------------------------------------------- +// Rate limiting (LOG-004) +// --------------------------------------------------------------------------- + +TEST(LogRateLimit, SuppressesRepeatsWithinWindow) { + resetRateLogger(std::chrono::seconds(1)); + gFakeNow = std::chrono::system_clock::time_point(std::chrono::seconds(1000)); + for (int i = 0; i < 5; ++i) { + gFakeNow += std::chrono::milliseconds(100); + LAIGE_LOG_WARN("net", "drop", "dropped", laige::log::field("i", i)); + } + const std::vector recs = capture().takeRecords(); + ASSERT_EQ(recs.size(), 1u); // first only; the rest suppressed + EXPECT_EQ(recs[0].event, "drop"); +} + +TEST(LogRateLimit, SummaryEmittedAfterWindow) { + resetRateLogger(std::chrono::seconds(1)); + gFakeNow = std::chrono::system_clock::time_point(std::chrono::seconds(1000)); + // One emitted, two suppressed within the window. + for (int i = 0; i < 3; ++i) { + gFakeNow += std::chrono::milliseconds(200); + LAIGE_LOG_WARN("net", "drop", "dropped", laige::log::field("i", i)); + } + // After the window: the summary reports the suppressed repeats, then + // the current event is recorded. (Records: first event, summary, + // current event.) + gFakeNow = std::chrono::system_clock::time_point(std::chrono::seconds(1000)) + + std::chrono::milliseconds(1500); + LAIGE_LOG_WARN("net", "drop", "dropped", laige::log::field("i", 3)); + + const std::vector recs = capture().takeRecords(); + ASSERT_EQ(recs.size(), 3u); + EXPECT_EQ(recs[0].event, "drop"); + const CapturedRecord& summary = recs[1]; + EXPECT_EQ(summary.severity, Severity::Warn); + EXPECT_EQ(summary.subsystem, "net"); + EXPECT_EQ(summary.event, laige::log::kRateLimitedEvent); + EXPECT_EQ(fieldAt(summary, "suppressed"), "2"); + EXPECT_EQ(fieldAt(summary, "event"), "drop"); + EXPECT_NE( + summary.message.find("suppressed 2 repeats of 'net/drop'"), + std::string::npos) + << summary.message; + const CapturedRecord& evt = recs[2]; + EXPECT_EQ(evt.event, "drop"); +} + +TEST(LogRateLimit, WindowEdgeEmitsWithoutSummary) { + resetRateLogger(std::chrono::seconds(1)); + gFakeNow = std::chrono::system_clock::time_point(std::chrono::seconds(1000)); + LAIGE_LOG_WARN("net", "drop", "dropped", laige::log::field("i", 0)); + gFakeNow += std::chrono::seconds(1); // exactly one window later + LAIGE_LOG_WARN("net", "drop", "dropped", laige::log::field("i", 1)); + const std::vector recs = capture().takeRecords(); + ASSERT_EQ(recs.size(), 2u); + EXPECT_EQ(recs[0].event, "drop"); + EXPECT_EQ(recs[1].event, "drop"); // no rate_limited summary in between +} + +TEST(LogRateLimit, KeysAreIndependent) { + resetRateLogger(std::chrono::seconds(1)); + gFakeNow = std::chrono::system_clock::time_point(std::chrono::seconds(1000)); + LAIGE_LOG_WARN("a", "x", "m", laige::log::field("i", 0)); // emitted + LAIGE_LOG_WARN("a", "x", "m", laige::log::field("i", 1)); // suppressed + LAIGE_LOG_WARN("b", "x", "m", laige::log::field("i", 0)); // other sub + LAIGE_LOG_WARN("a", "y", "m", laige::log::field("i", 0)); // other event + EXPECT_EQ(capture().recordCount(), 3u); +} + +TEST(LogRateLimit, OnlyFailuresAreRateLimited) { + resetRateLogger(std::chrono::seconds(1)); + gFakeNow = std::chrono::system_clock::time_point(std::chrono::seconds(1000)); + for (int i = 0; i < 5; ++i) { + gFakeNow += std::chrono::milliseconds(100); + LAIGE_LOG_INFO("n", "i", "m", laige::log::field("i", i)); + } + for (int i = 0; i < 5; ++i) { + gFakeNow += std::chrono::milliseconds(100); + LAIGE_LOG_DEBUG("n", "d", "m", laige::log::field("i", i)); + } + EXPECT_EQ(capture().recordCount(), 10u); // none suppressed +} + +TEST(LogRateLimit, CanBeDisabled) { + laige::log::LoggerOptions o; + o.clock = &fakeClock; + o.rateWindow = std::chrono::seconds(1); + o.rateLimiting = false; + resetLogger(std::move(o)); + gFakeNow = std::chrono::system_clock::time_point(std::chrono::seconds(1000)); + for (int i = 0; i < 5; ++i) { + gFakeNow += std::chrono::milliseconds(100); + LAIGE_LOG_WARN("n", "w", "m", laige::log::field("i", i)); + } + EXPECT_EQ(capture().recordCount(), 5u); +} + +TEST(LogRateLimit, ShutdownDrainsPendingSummaries) { + resetRateLogger(std::chrono::seconds(1)); + gFakeNow = std::chrono::system_clock::time_point(std::chrono::seconds(1000)); + for (int i = 0; i < 3; ++i) { + gFakeNow += std::chrono::milliseconds(100); + LAIGE_LOG_ERROR("db", "query_failed", "query failed", + laige::log::field("i", i)); + } + Logger::instance().shutdown(); + const std::vector recs = capture().takeRecords(); + ASSERT_GE(recs.size(), 2u); + const CapturedRecord& summary = recs.back(); + EXPECT_EQ(summary.event, laige::log::kRateLimitedEvent); + EXPECT_EQ(fieldAt(summary, "suppressed"), "2"); + EXPECT_EQ(fieldAt(summary, "event"), "query_failed"); + + // Shutdown is idempotent (CONC-006): a second call adds nothing. + const std::size_t n = capture().recordCount(); + Logger::instance().shutdown(); + EXPECT_EQ(capture().recordCount(), n); +} + +// --------------------------------------------------------------------------- +// Fatal severity and crash/shutdown flushing (LOG-007) +// --------------------------------------------------------------------------- + +TEST(LogFatal, Gate) { + resetLogger(); + EXPECT_TRUE(Logger::instance().enabled(Severity::Fatal, "s")); + Logger::instance().setGlobalMinimum(Level::Off); + EXPECT_FALSE(Logger::instance().enabled(Severity::Fatal, "s")); +} + +TEST(LogFatal, ChildEmitsFlushesAndTerminates) { +// AGENTS §14: Fatal records the event, flushes, and terminates the +// process. Exercised in a forked child so the test process survives: +// the child must die on SIGABRT with the fatal line flushed to the +// file sink. POSIX only (fork); the Windows jobs skip with a reason. +#if defined(__unix__) + const std::string path = tempFilePath("fatal"); + std::remove(path.c_str()); + const pid_t pid = fork(); + ASSERT_GE(pid, 0); + if (pid == 0) { + // Child: fresh file sink, one Fatal event. Never returns — Fatal + // terminates the process via std::abort(). + auto created = laige::log::FileSink::create(path); + if (!created.ok()) _exit(117); + laige::log::LoggerOptions o; + o.sink = std::move(created).takeValue(); + if (!Logger::instance().init(std::move(o)).ok()) _exit(119); + LAIGE_LOG_FATAL("crash_test", "fatal_child", + "deliberate fatal event from the test child"); + _exit(118); // unreachable + } + int status = 0; + ASSERT_EQ(waitpid(pid, &status, 0), pid); + EXPECT_TRUE(WIFSIGNALED(status) && WTERMSIG(status) == SIGABRT) + << "child should die on SIGABRT (controlled termination after " + "emit + flush)"; + const std::string content = readWholeFile(path); + std::remove(path.c_str()); + EXPECT_NE(content.find("[fatal] crash_test/fatal_child"), std::string::npos) + << content; +#else + GTEST_SKIP() << "fork() is not available on Windows; the Fatal " + "termination contract is exercised on the POSIX jobs."; +#endif +} + +TEST(LogCrash, InstallCrashHandlingIsIdempotent) { + resetLogger(); + EXPECT_TRUE(Logger::instance().installCrashHandling().ok()); + EXPECT_TRUE(Logger::instance().installCrashHandling().ok()); +} + +TEST(LogCrash, ShutdownFlushesSink) { + resetLogger(); + LAIGE_LOG_INFO("s", "e", "m"); + const std::size_t flushesBefore = capture().flushCount(); + Logger::instance().shutdown(); + EXPECT_GT(capture().flushCount(), flushesBefore); +} + +TEST(LogCrash, PostShutdownLogsAreDiscarded) { + resetLogger(); + Logger::instance().shutdown(); + LAIGE_LOG_INFO("s", "e", "m", laige::log::field("x", 1)); + EXPECT_EQ(capture().recordCount(), 0u); + EXPECT_FALSE(Logger::instance().enabled(Severity::Info, "s")); +} + +// --------------------------------------------------------------------------- +// Concurrency (TSan coverage comes from the CI tsan lane) +// --------------------------------------------------------------------------- + +TEST(LogConcurrency, ConcurrentEmitsAreAllRecorded) { + resetLogger(); + constexpr int kThreads = 4; + constexpr int kPerThread = 250; + std::vector threads; + threads.reserve(kThreads); + for (int t = 0; t < kThreads; ++t) { + threads.emplace_back([t]() { + const std::string sub = "t" + std::to_string(t); + for (int i = 0; i < kPerThread; ++i) { + LAIGE_LOG_DEBUG(sub.c_str(), "ev", "m", laige::log::field("i", i)); + } + }); + } + for (auto& th : threads) th.join(); + EXPECT_EQ(capture().recordCount(), + static_cast(kThreads * kPerThread)); +} + +// --------------------------------------------------------------------------- +// Performance: LOG-003 (no work when disabled) + timing property +// --------------------------------------------------------------------------- + +TEST(LogPerformance, DisabledTraceSpamAllocatesNothing) { + resetLogger(); // also constructs the capture() static before the reset + Logger::instance().setSubsystemLevel("spam", Level::Info); +#if defined(LAIGE_ALLOC_COUNTER) + laige::test::resetAllocCounter(); +#endif + for (int i = 0; i < 100000; ++i) { + LAIGE_LOG_TRACE("spam", "trace_spam", "spam message", + laige::log::field("i", i)); + } + EXPECT_EQ(capture().recordCount(), 0u); +#if defined(LAIGE_ALLOC_COUNTER) + // The roadmap's Verify property: trace-level spam in a disabled + // subsystem shows zero allocations. (M0-CORE-05's pool accounting is + // the future refinement; the sanitizer trees run this same spam loop + // leak-free instead of counting — see tests/laige-core/CMakeLists.txt.) + EXPECT_EQ(laige::test::allocCounter(), 0u); +#endif +} + +TEST(LogPerformance, DisabledPathCheaperThanEnabled) { + resetLogger(); + Logger::instance().setGlobalMinimum(Level::Trace); + Logger::instance().setSubsystemLevel("off", Level::Info); // gate 2 rejects + Logger::instance().setSubsystemLevel("on", Level::Trace); // gate 2 passes + constexpr int N = 200000; + const auto t0 = std::chrono::steady_clock::now(); + for (int i = 0; i < N; ++i) { + LAIGE_LOG_TRACE("off", "ev", "m", laige::log::field("i", i)); + } + const auto t1 = std::chrono::steady_clock::now(); + for (int i = 0; i < N; ++i) { + LAIGE_LOG_TRACE("on", "ev", "m", laige::log::field("i", i)); + } + const auto t2 = std::chrono::steady_clock::now(); + const long long disabledNs = + std::chrono::duration_cast(t1 - t0).count(); + const long long enabledNs = + std::chrono::duration_cast(t2 - t1).count(); + std::printf("LogPerformance: disabled=%lld ns/event, enabled=%lld " + "ns/event (N=%d)\n", + disabledNs / N, enabledNs / N, N); + // Property: the disabled path (gate + branch, no sink, no allocation) + // is strictly cheaper than the enabled path (sink write + field + // construction). + EXPECT_LT(disabledNs, enabledNs); +} diff --git a/tests/laige-core/result_status_tests.cpp b/tests/laige-core/result_status_tests.cpp index 7de90b5..841c9ba 100644 --- a/tests/laige-core/result_status_tests.cpp +++ b/tests/laige-core/result_status_tests.cpp @@ -68,6 +68,7 @@ const laige::ErrorCode kRegistered[] = { laige::ErrorCode::InvalidArgument, laige::ErrorCode::MalformedInput, laige::ErrorCode::BudgetExhausted, + laige::ErrorCode::IoError, }; // NFR-13.3 grammar check on a rendered error line: exactly 5 fields @@ -175,6 +176,20 @@ TEST(ResultStatus, MoveOnlyPayload) { // only for destruction here. } +TEST(ResultStatus, TakeValueMovesOutSuccessValue) { + // Ownership transfer path (rvalue results only): used e.g. to hand a + // freshly created resource (FileSink, M0-CORE-02) to a container. + auto makePtr = [](int x) { return std::make_unique(x); }; + auto r = laige::Result>::success(makePtr(9)); + std::unique_ptr moved = std::move(r).takeValue(); + ASSERT_NE(moved, nullptr); + EXPECT_EQ(*moved, 9); + + // An error result has no value to take. + auto e = laige::Result::failure(laige::ErrorCode::InvalidArgument); + EXPECT_TRUE(e.isError()); +} + TEST(ResultStatus, CopySemantics) { const laige::Result a = laige::Result::success(5); const laige::Result b = a; @@ -293,6 +308,7 @@ TEST(ErrorCodeRegistry, IntegerValuesArePinned) { 3u); EXPECT_EQ(static_cast(laige::ErrorCode::BudgetExhausted), 4u); + EXPECT_EQ(static_cast(laige::ErrorCode::IoError), 5u); } TEST(ErrorCodeRegistry, UnregisteredValuesRenderUnknown) { From 39e71a3f29db48a3c230624bb6862ff96684e65e Mon Sep 17 00:00:00 2001 From: Pascal Severin Date: Thu, 10 Sep 2026 23:59:47 +0200 Subject: [PATCH 2/2] [M0-CORE-02] Record CI observation: run 34534697621 green (5/5 active jobs) ci-pull.yml run 34534697621 on 0d3ee28 (PR #2): linux-gcc (g++), linux-clang, linux-asan+UBSan (clang++), linux-tsan (clang++), and include-lint all passed in 50 s; macOS/Windows jobs skipped (label-gated, default lane is Linux). Change-log hash filled in; roadmap Verify note updated. --- roadmap/M0-foundations.md | 7 ++++++- roadmap/README.md | 2 +- 2 files changed, 7 insertions(+), 2 deletions(-) diff --git a/roadmap/M0-foundations.md b/roadmap/M0-foundations.md index ddfbbd6..e78ba08 100644 --- a/roadmap/M0-foundations.md +++ b/roadmap/M0-foundations.md @@ -343,7 +343,12 @@ No rendering, no physics, no networking yet — `laige-core` only. enabled, N=200000). Verified locally 2026-09-10 (GCC 16.2.1: static, shared, ASan/UBSan, TSan trees — all 8/8 ctest, zero warnings; fresh Clang 22.1.8 static + shared trees — all 8/8 ctest, zero warnings; - `ctest -R logging` green in every tree). CI: pending observation. + `ctest -R logging` green in every tree). CI (observed 2026-09-10 + via the GitHub API): `ci-pull.yml` run 34534697621 on `0d3ee28` + green — all 5 jobs of the default-Linux lane passed (linux-gcc + g++, linux-clang clang++, linux-asan+UBSan clang++, linux-tsan + clang++, include-lint), finished in 50 s; macOS/Windows jobs + skipped (label-gated). - **Size:** ~1034 lines implementation (`logging.h` 538 — full AGENTS §9 contracts, facade, macros — `logging.cpp` 496) + ~860 lines tests (`logging_tests.cpp` 743, allocation counter 115) + ~300 lines diff --git a/roadmap/README.md b/roadmap/README.md index e6c47ac..e443ba5 100644 --- a/roadmap/README.md +++ b/roadmap/README.md @@ -183,7 +183,7 @@ One line per completed (or split/renumbered) step. | 2026-09-10 | M0-CI-02 | `6573a64` | Sanitizer CI lanes `linux-asan` (LAIGE_ASAN=ON: ASan+UBSan, reports fatal via `-fno-sanitize-recover=all` + `ASAN_OPTIONS` abort/halt) and `linux-tsan` (LAIGE_TSAN=ON, per-test `TSAN_OPTIONS=halt_on_error=1`) in `ci.yml` (merge, all 7 jobs) and `ci-pull.yml` (PRs under the default-Linux P0 condition); sanitizer reports archived as artifacts (`linux-asan-reports`/`linux-tsan-reports`) on every run, green or red; the first CI run rejected the workflow file because step-level `permissions:` is not a valid schema — fixed in `f75ed0d` by moving `actions: write` to job scope (with `continue-on-error: true` uploads in `ci-pull.yml` for fork-PR read-only tokens); Verify cycle on CI: scratch OOB read (`6331a40`) failed `linux-asan` with the UBSan "index 16 out of bounds for type int[4]" report (archived) while `linux-tsan` and the other five jobs stayed green; scratch removed in `25b57b9`; full 7-job matrix green | | 2026-09-10 | M0-CI-03 | `785af81` | `tools/laige-include-lint` (Python 3 stdlib): parses `#include` edges of `src/**`, enforces R1 (laige-core includes nothing internal), R2 (arrows only downward in the PRD §10.1 stack, via the target's public include root — CPP-010), R3 (vendored deps only from their `deps.lock` `owner` — new required lock field, validated by `cmake/laige-deps-lock.cmake`; angle-bracket vendored header paths caught via a vendored-header map), R4 (engine code includes only `src/**`/`deps/**`); reports the vendored-dependency list and fails above the PRD §11 budget of 10; `include-lint` CI job in `ci-pull.yml` (every PR, label-independent) and `ci.yml` (every merge, now 8 jobs); CTest coverage in `tests/tools` (4 fixture trees + real-tree check, expected failures asserted via generated `cmake -P` scripts because CTest inverts `PASS_REGULAR_EXPRESSION` under `WILL_FAIL`); local Verify: illegal `laige-core → laige-render` stub include fails with R1, all rule directions exercised, dep count prints (1/10), `ctest` 6/6 on g++/shared/ASan/Clang trees; pushed as `785af81` — CI observed via the GitHub API: `ci.yml` (8-job) run 34518244428 on `741c163` green, `include-lint` job log shows the live report (`count: 1 (budget: 10, PRD §11)`, `OK`); `ci-pull.yml` job exercised by PR #1 (run 34521473503, green incl. `include-lint`), squash-merged as `a74b65a` with the post-merge 8-job run 34521722826 green | | 2026-09-10 | M0-CORE-01 | `6fa1414` | `laige::Result`/`laige::Status` (no exceptions, FR-12.1; inline `std::optional` storage, SFINAE-guarded implicit constructors + `success()`/`failure()` factories, `valueIfOk()`/`errorIfError()` null-safe accessors) + central error registry (`errors.h`/`errors.cpp`: 4 pinned codes, 0 reserved, unregistered → `unknown`; pre-rendered NFR-13.3 5-field lines) with the human-readable registry in `docs/api/errors.md`; `result_status` CTest entry (16 cases: construction, propagation, copy/move, grammar per code, pinned values) in the shared `laige-core_tests` executable; local Verify: GCC static/shared/ASan/TSan + fresh Clang trees 7/7 ctest, zero warnings; first push `f96ce7d` failed 7/8 on windows-msvc (C2535: the `Result(T)`/`Result(E)` constructors have identical parameter lists when `T == E`) — fixed in `6fa1414` by taking the failure value by `const E&`; CI: `ci.yml` run 34525402022 on `6fa1414` (8-job matrix) green, Windows job compiles and passes `result_status`, every job under a minute | -| 2026-09-10 | M0-CORE-02 | — | The one structured logging facade (AGENTS §14, FR-12.2): `laige::log::Logger` Meyers singleton + `LAIGE_LOG_*` macros (gate before argument evaluation — disabled event = one atomic load + branch, no allocation, LOG-003); per-subsystem level table + atomic global minimum; `Field` scalars render locale-free via `to_chars` into a 64-byte stack buffer; rate limiting per (subsystem, event, severity) for Warn/Error/Fatal with `rate_limited` suppressed-count summaries (first event always emitted, pending counts drained at shutdown); `ConsoleSink` (non-owning stream) + `FileSink` (owning, `create()` → `Result`, failure = new `ErrorCode::IoError` 5, LOG-007 console fallback); Fatal = emit + flush + `std::abort()`; crash handlers (POSIX `sigaction` SA_RESETHAND / Windows vectored SEH) with raw-`write` notice + allocation-free `try_lock` flush; idempotent `shutdown()` retires the facade; timestamps = system_clock UTC RFC 3339 (in-code Hinnant civil-from-days); additive M0-CORE-01 extensions `Result::takeValue() &&` + `IoError`; `logging` CTest entry (27 cases incl. zero-alloc proof via a test-only global `operator new` counter, excluded from sanitizer trees per the step's fallback: leak-free runs + timing property); API contract in `docs/api/logging.md`; local Verify: GCC static/shared/ASan/TSan + fresh Clang static/shared trees — `ctest` 8/8 and `ctest -R logging` green in every tree, zero warnings (disabled ≈46 ns/event vs ≈1207 ns/event enabled) | +| 2026-09-10 | M0-CORE-02 | `0d3ee28` | The one structured logging facade (AGENTS §14, FR-12.2): `laige::log::Logger` Meyers singleton + `LAIGE_LOG_*` macros (gate before argument evaluation — disabled event = one atomic load + branch, no allocation, LOG-003); per-subsystem level table + atomic global minimum; `Field` scalars render locale-free via `to_chars` into a 64-byte stack buffer; rate limiting per (subsystem, event, severity) for Warn/Error/Fatal with `rate_limited` suppressed-count summaries (first event always emitted, pending counts drained at shutdown); `ConsoleSink` (non-owning stream) + `FileSink` (owning, `create()` → `Result`, failure = new `ErrorCode::IoError` 5, LOG-007 console fallback); Fatal = emit + flush + `std::abort()`; crash handlers (POSIX `sigaction` SA_RESETHAND / Windows vectored SEH) with raw-`write` notice + allocation-free `try_lock` flush; idempotent `shutdown()` retires the facade; timestamps = system_clock UTC RFC 3339 (in-code Hinnant civil-from-days); additive M0-CORE-01 extensions `Result::takeValue() &&` + `IoError`; `logging` CTest entry (27 cases incl. zero-alloc proof via a test-only global `operator new` counter, excluded from sanitizer trees per the step's fallback: leak-free runs + timing property); API contract in `docs/api/logging.md`; local Verify: GCC static/shared/ASan/TSan + fresh Clang static/shared trees — `ctest` 8/8 and `ctest -R logging` green in every tree, zero warnings (disabled ≈46 ns/event vs ≈1207 ns/event enabled); CI (observed 2026-09-10 via the GitHub API): `ci-pull.yml` run 34534697621 on `0d3ee28` green — all 5 jobs of the default-Linux lane (linux-gcc g++, linux-clang clang++, linux-asan+UBSan clang++, linux-tsan clang++, include-lint) passed in 50 s, macOS/Windows skipped (label-gated) | ---