From 81747cca3b811eb747a8c3e63f590d5909fb272f Mon Sep 17 00:00:00 2001 From: bitc0der <59016822+bitc0der@users.noreply.github.com> Date: Fri, 22 May 2026 23:02:40 +0700 Subject: [PATCH 1/8] Add init log spec --- .../add-tracker-config-logging/.openspec.yaml | 2 + .../add-tracker-config-logging/design.md | 80 +++++++++++++++++++ .../add-tracker-config-logging/proposal.md | 31 +++++++ .../specs/structured-logging/spec.md | 64 +++++++++++++++ .../add-tracker-config-logging/tasks.md | 50 ++++++++++++ 5 files changed, 227 insertions(+) create mode 100644 openspec/changes/add-tracker-config-logging/.openspec.yaml create mode 100644 openspec/changes/add-tracker-config-logging/design.md create mode 100644 openspec/changes/add-tracker-config-logging/proposal.md create mode 100644 openspec/changes/add-tracker-config-logging/specs/structured-logging/spec.md create mode 100644 openspec/changes/add-tracker-config-logging/tasks.md diff --git a/openspec/changes/add-tracker-config-logging/.openspec.yaml b/openspec/changes/add-tracker-config-logging/.openspec.yaml new file mode 100644 index 0000000..4a1c677 --- /dev/null +++ b/openspec/changes/add-tracker-config-logging/.openspec.yaml @@ -0,0 +1,2 @@ +schema: spec-driven +created: 2026-05-22 diff --git a/openspec/changes/add-tracker-config-logging/design.md b/openspec/changes/add-tracker-config-logging/design.md new file mode 100644 index 0000000..e299ca6 --- /dev/null +++ b/openspec/changes/add-tracker-config-logging/design.md @@ -0,0 +1,80 @@ +## Context + +The existing `structured-logging` capability covers runtime events emitted by `OutboxPublisherService`, `ChangeSubscriber`, and `ChangeTrackingHostedService`. It does **not** cover the configuration/build phase. Today, when a caller wires up `ChangeTrackingBuilder` (directly or via `AddChangeTracking`), nothing is logged about which plugins were registered, which entity types were configured, or which defaults were applied. Operators bringing up a new service can only confirm correct wiring by waiting for the first runtime event (a publish, a consumer ACK, an error). Misconfigurations such as a forgotten `UseOutbox`, a wrong consumer factory, or a serializer/compressor mismatch surface as cryptic runtime failures. + +The builder layer already receives an `ILoggerFactory` (`NullLoggerFactory` by default; the host's factory under DI) and forwards it to the publisher and subscriber builders. That same factory can produce a `ILogger` and a `ILogger` at zero extra wiring cost. + +## Goals / Non-Goals + +**Goals:** +- Emit a structured `Information` log for every `Use*` builder call so the log stream documents how the tracker was wired up. +- Emit one `Information` summary log at `Build()` containing the configured entity types and the list of registered plugins. +- Emit `Information` start / complete logs from `EntityChangeTracker.InitializeAsync`, with `Debug` sub-step logs for publisher and consumer initialization. +- Preserve the existing opt-in semantics: `NullLoggerFactory` produces zero output and zero allocations on the hot path. +- Make the new output additive — no public-API changes; no test or sample needs to be modified to keep working. + +**Non-Goals:** +- Changing the existing runtime-event log requirements in the `structured-logging` spec. +- Adding metrics or traces for configuration events (already covered by `opentelemetry-metrics`). +- Logging at `Trace` level — `Information` for top-level events and `Debug` for sub-steps is sufficient. +- Reformatting or rewriting existing log messages. + +## Decisions + +### Decision 1: Logger acquired once in the builder, never per-call +The builder resolves `ILogger` once in the constructor and caches it in a field. Every `Use*` and `ForEntity` method calls `_log.LogInformation(...)` on that cached instance. Matches the existing pattern in `OutboxPublisherService` and `ChangeSubscriber`. + +### Decision 2: Build summary as a single structured event, not a multi-line dump +The build summary log entry uses `LogInformation("ChangeTracker built. EntityTypes={EntityTypes} Plugins={Plugins} HasCustomMeter={HasCustomMeter} HasCustomDeduplicationStore={HasCustomDeduplicationStore} HasCustomLoggerFactory={HasCustomLoggerFactory}", ...)` so that structured log sinks (Seq, Elastic, OTel logs) can index each property individually. + +**Rationale:** Multi-line `LogInformation` payloads cannot be filtered or aggregated. A single structured event with rich properties is the idiomatic .NET logging pattern. + +**Alternative considered:** Several `LogInformation` calls (one per plugin slot). Rejected — produces excessive noise at `Information` and forces operators to reconstruct the picture from several lines. + +### Decision 3: Per-entity overrides log at `Debug`, not `Information` +The per-entity configuration delegate may apply many overrides; logging each at `Information` would drown out the more important global registrations. Instead, `ForEntity` logs the entity type at `Information` and each override (UseOutbox/UseSerializer/OnInsert/...) at `Debug`. + +**Rationale:** Matches the existing convention in `OutboxPublisherService` (start/stop at `Information`; per-record events at `Debug`). + +**Alternative considered:** Single summary log per entity type. Rejected — loses the ability to spot a forgotten override during diagnosis. + +### Decision 4: Initialization logs live on `EntityChangeTracker`, not `ChangeTrackingBuilder` +`InitializeAsync` is a method on `EntityChangeTracker`. The tracker already has access to the `ILoggerFactory` (passed through `ChangePublisher` and `ChangeSubscriber`) and can resolve `ILogger` once in its constructor. + +**Rationale:** Keeps the builder concerned only with *configuration* events; runtime/lifecycle events stay with the tracker. The split mirrors the proposal/specs split (build summary → builder; init lifecycle → tracker). + +**Alternative considered:** Have the builder log around the `InitializeAsync` call inside `Build()` / `BuildAsync()`. Rejected — would only cover sync `Build()`, not `tracker.InitializeAsync()` called via DI through the hosted service. + +### Decision 5: Guard every logging call with `IsEnabled` +Every new log call (builder `Use*` Information logs, per-entity Debug logs, build-summary log, init lifecycle logs) is wrapped in `if (_log.IsEnabled())` to avoid `params object?[]` allocation and value-type boxing under `NullLoggerFactory`. `NullLogger.IsEnabled` returns `false` for all levels, so the body is fully skipped. + +**Rationale:** The build-summary log in particular constructs a `{Plugins}` anonymous structure and an `{EntityTypes}` array; skipping that under `NullLoggerFactory` makes the "zero allocations" claim in the test (task 5.5) literally true. + +### Decision 6: `EntityBuilder` constructor gains a logger parameter +`EntityBuilder` is `internal sealed` with a constructor taking `(ChangePublisherBuilder, ChangeSubscriberBuilder)`. Extending it to also accept `ILogger` is an internal-only signature change with no public API impact. `ChangeTrackingBuilder.ForEntity` passes its cached logger when constructing the inner builder; the same logger is forwarded to `SharedHandlerBuilder` and `IsolatedHandlerBuilder` so per-entity overrides log at `Debug` from a consistent category. + +### Decision 7: DI-context log lives on `ChangeTrackingHostedService.StartAsync`, not the DI factory delegate +`AddChangeTracking` captures `configuration != null` into a small DI-registered record (or sets a field on the hosted service via DI). `ChangeTrackingHostedService.StartAsync` (which runs exactly once per host instance) emits the `Information` "ChangeTracking starting" log with `{ConfigurationBound}`. + +**Rationale:** Logging from inside the singleton factory delegate appears one-shot but is not guaranteed if the lifetime is ever changed or if the tracker is resolved early during a concurrent startup. The hosted-service `StartAsync` is the only place the framework guarantees a single invocation per host. This also keeps the existing hosted-service lifecycle log (consumer start / graceful stop) and the new DI-context log co-located. + +## Risks / Trade-offs + +- **Risk: log volume during startup spikes** → Mitigation: top-level Use* calls log at `Information` (small, bounded — one per call); per-entity overrides log at `Debug` (filterable). A typical service with 5 entity types and global plugins emits roughly 10–20 `Information` lines at startup, which is acceptable for one-shot bring-up events. +- **Risk: existing assertions on log output break** → Mitigation: the existing `structured-logging` requirements are not modified, only extended. Existing test fixtures that capture logs by exact message will still pass; tests that count `Information` entries over a build cycle will need to update — these tests are internal to `RayTree.Core.Tests` and can be updated in the same change. +- **Risk: structured-property name churn** → Mitigation: property names (`{EntityType}`, `{Plugin}`, `{EntityTypes}`, `{Plugins}`, `{HasCustomMeter}`, etc.) are documented in the spec scenarios so downstream parsers have a stable contract. +- **Trade-off: a small amount of allocation on the build path** → Acceptable: build is a one-time event per process. Hot-path runtime logging is unaffected. + +## Migration Plan + +1. Implement builder-side logging in `ChangeTrackingBuilder`. +2. Implement initialization logging in `EntityChangeTracker.InitializeAsync`. +3. Implement DI registration log in `ServiceCollectionExtensions.AddChangeTracking`. +4. Add unit tests in `tests/RayTree.Core.Tests` using an in-memory `ILoggerProvider` to capture and assert on entries. +5. Update `CLAUDE.md` to describe the new configuration-time logs alongside the existing logging-placement rule. +6. No data migration. No public-API change. No rollback needed — the feature is additive and silent under `NullLoggerFactory`. + +## Open Questions + +- Should the build summary include the global `OutboxPublisherOptions` and `SubscriberOptions` values? **Decision: No** — these can be large and noisy; if operators need them they can log the options themselves via the host. The summary lists only plugin type names and capability flags. +- Should per-entity override `Debug` logs include the override target type (e.g. the IOutbox concrete type) or just the override slot name? **Decision: include both** — `{EntityType}`, `{Override}` (slot), `{Plugin}` (type name). diff --git a/openspec/changes/add-tracker-config-logging/proposal.md b/openspec/changes/add-tracker-config-logging/proposal.md new file mode 100644 index 0000000..c55295f --- /dev/null +++ b/openspec/changes/add-tracker-config-logging/proposal.md @@ -0,0 +1,31 @@ +## Why + +Today the tracker emits log output for runtime events (outbox poll errors, publish retries, subscriber retries, hosted service lifecycle) but the **configuration and build phase is virtually silent**. When operators stand up a new service or change the wiring, they have no visible evidence of what plugins were registered, which entity types were configured, or what defaults were applied. Misconfigurations (forgotten outbox, wrong consumer factory, mismatched serializer) only surface much later as runtime errors that are hard to trace back to the build step. Adding structured configuration-time logs makes the tracker's setup observable and dramatically shortens diagnosis time during bring-up. + +## What Changes + +- `ChangeTrackingBuilder` emits structured `Information` logs for each top-level configuration call (`UseOutbox`, `UsePublisher`, `UseSerializer`, `UseCompressor`, `UseRepository`, `UseDeduplicationStore`, `UseMeter`, `UsePublisherOptions`, `UseSubscriberOptions`) recording which plugin type was registered. +- `ChangeTrackingBuilder.ForEntity` emits an `Information` log naming the configured entity type and (at `Debug`) the per-entity plugin overrides applied inside the configure delegate. +- `BuildInternal` / `Build` / `BuildAsync` log a single `Information` "tracker built" summary line including: configured entity types, whether a custom meter / dedup store / logger factory was supplied, and the registered outbox/publisher/serializer/compressor plugin type names. +- `EntityChangeTracker.InitializeAsync` logs `Information` at start and completion of initialization (publisher initialization + consumer connection initialization), plus `Debug` per-step events (`outbox initialized`, `publisher initialized`, `consumer initialized`). +- Validation / defaulting decisions inside the builder (e.g. "no meter supplied, creating default `RayTreeMeter`"; "no logger factory supplied, falling back to `NullLoggerFactory`") emit `Debug` logs so operators can confirm which defaults are in effect. +- The existing `ChangeTrackingBuilder` constructor's `ILoggerFactory` is now also used to create an internal `ILogger`; under DI (`AddChangeTracking`) it is automatically the host's factory, so no caller changes are required to get the new output. +- Tests cover: each builder method emits exactly one configuration log; the build summary contains the expected structured properties; `NullLoggerFactory` produces zero allocations / output. + +## Capabilities + +### New Capabilities +_None_ + +### Modified Capabilities +- `structured-logging`: extends the spec with new requirements covering builder configuration logs, build summary log, and initialization lifecycle logs. + +## Impact + +- **Affected code**: + - `src/RayTree.Core/Tracking/ChangeTrackingBuilder.cs` — acquire `ILogger` from the injected factory and emit logs from each `Use*` / `ForEntity` / `BuildInternal` method. + - `src/RayTree.Core/Tracking/EntityChangeTracker.cs` — acquire `ILogger` (already has one for runtime via publisher/subscriber; add a tracker-level logger or reuse) and emit init start/complete logs from `InitializeAsync`. + - `src/RayTree.Core/Distribution/ChangePublisherBuilder.cs` and `src/RayTree.Core/Handling/ChangeSubscriberBuilder.cs` — optional `Debug` logs when per-entity overrides are stored. +- **APIs**: no public surface change. New logs are additive and respect the existing `ILoggerFactory` opt-in (silent under `NullLoggerFactory`). +- **Dependencies**: none — uses `Microsoft.Extensions.Logging.Abstractions` already referenced. +- **Tests**: new test fixtures in `tests/RayTree.Core.Tests` using an in-memory `ILoggerProvider` to capture log entries and assert structured properties / counts. diff --git a/openspec/changes/add-tracker-config-logging/specs/structured-logging/spec.md b/openspec/changes/add-tracker-config-logging/specs/structured-logging/spec.md new file mode 100644 index 0000000..34a7624 --- /dev/null +++ b/openspec/changes/add-tracker-config-logging/specs/structured-logging/spec.md @@ -0,0 +1,64 @@ +## ADDED Requirements + +### Requirement: Builder configuration calls emit structured logs +`ChangeTrackingBuilder` SHALL emit a structured `Information` log for each top-level configuration call made by the caller: `UseOutbox`, `UsePublisher`, `UseSerializer`, `UseCompressor`, `UseRepository`, `UseDeduplicationStore`, `UseMeter`, `UsePublisherOptions`, and `UseSubscriberOptions`. Each log entry SHALL include the registered plugin's CLR type name (or the options class name for option-configurers) as a structured property so that the log stream documents how the tracker was wired up. + +#### Scenario: Outbox registration is logged +- **WHEN** a caller invokes `builder.UseOutbox(factory)` +- **THEN** an `Information` log is emitted with `{Plugin}` equal to `"MyOutbox"` and a message identifying it as an outbox registration + +#### Scenario: Each Use* method emits exactly one log entry +- **WHEN** a caller chains `UseOutbox`, `UsePublisher`, `UseSerializer`, `UseCompressor`, `UseRepository`, `UseDeduplicationStore`, and `UseMeter` +- **THEN** seven distinct `Information` log entries are captured, one per call, each with the corresponding plugin type name + +#### Scenario: Null logger factory produces no configuration output +- **WHEN** a caller builds without supplying an `ILoggerFactory` (defaulting to `NullLoggerFactory.Instance`) +- **THEN** no configuration log entries are emitted and the builder still completes successfully + +### Requirement: Per-entity configuration is logged +`ChangeTrackingBuilder.ForEntity` SHALL emit an `Information` log naming the configured entity type before invoking the configure delegate, and SHALL emit `Debug` logs for each per-entity plugin override (`UseOutbox`, `UsePublisher`, `UseSerializer`, `UseCompressor`, `UseRepository`, `UseConsumer`, `UseConsumerFactory`, `UseSubscriberOptions`, `OnInsert`/`OnUpdate`/`OnDelete`/`OnChange`) applied inside the delegate. + +#### Scenario: ForEntity logs the entity type at Information +- **WHEN** a caller invokes `builder.ForEntity(b => { /* ... */ })` +- **THEN** an `Information` log is emitted with `{EntityType}` equal to `"Order"` + +#### Scenario: Per-entity plugin overrides log at Debug +- **WHEN** the configure delegate calls `b.UseOutbox(...)` and `b.OnInsert("name", handler)` +- **THEN** a `Debug` log is emitted for each override with `{EntityType}` and the override kind (e.g. `{Override}` = `"Outbox"`, `"OnInsert:name"`) as structured properties + +### Requirement: Tracker build emits a summary log +When `ChangeTrackingBuilder.Build()` or `BuildAsync()` completes the `BuildInternal` step, the builder SHALL emit a single `Information` log entry summarising the configured tracker. The log entry SHALL include the following structured properties: `{EntityTypes}` (the list of configured entity-type names), `{HasCustomMeter}` (bool), `{HasCustomDeduplicationStore}` (bool), `{HasCustomLoggerFactory}` (bool), and `{Plugins}` containing the registered global outbox, publisher, serializer, and compressor type names (or `""` when not registered). + +#### Scenario: Build summary is emitted once +- **WHEN** `builder.Build()` is called +- **THEN** exactly one `Information` "tracker built" log entry is captured containing the listed structured properties + +#### Scenario: Build summary reflects unconfigured plugins +- **WHEN** the builder is built without a global serializer registration +- **THEN** the build summary's `{Plugins}` property contains `Serializer = ""` + +### Requirement: Builder default-meter decision is logged +When `ChangeTrackingBuilder.BuildInternal` falls back to a default `RayTreeMeter` (because `UseMeter` was not called) it SHALL emit a `Debug` log indicating that a default meter was created and is owned by the tracker. (The `NullLoggerFactory` fallback path is already covered by the existing "Logger factory opt-in on the unified builder" requirement and is not restated here.) + +#### Scenario: Default meter creation is logged +- **WHEN** `Build()` is called without a prior `UseMeter` call +- **THEN** a `Debug` log is emitted stating that a default `RayTreeMeter` was created and is owned by the tracker + +### Requirement: Tracker initialization lifecycle is logged +`EntityChangeTracker.InitializeAsync` SHALL log at `Information` level when initialization begins and when it completes successfully, and SHALL log at `Debug` level after each major sub-step: publisher initialization complete, and consumer connections initialized. On failure, an `Error` log SHALL be emitted with the exception before re-throwing. + +#### Scenario: Successful initialization emits start and complete logs +- **WHEN** `InitializeAsync` is called and completes without error +- **THEN** an `Information` "tracker initialization started" log is captured followed by an `Information` "tracker initialization completed" log +- **THEN** exactly one `Debug` "publisher initialized" log is captured with `{EntityTypeCount}` structured property, and exactly one `Debug` "consumers initialized" log is captured with `{ConsumerCount}` structured property + +#### Scenario: Initialization failure is logged before re-throw +- **WHEN** `InitializeAsync` throws because a plugin's `InitializeAsync` fails +- **THEN** an `Error` log is emitted with the exception details and the failing sub-step before the exception propagates + +### Requirement: ChangeTrackingHostedService logs DI startup details +When `ChangeTrackingHostedService.StartAsync` runs (guaranteed one-shot per host instance), it SHALL emit a single `Information` "ChangeTracking starting" log with `{ConfigurationBound}` (bool — captured at `AddChangeTracking` registration time and stored on the hosted service) indicating whether configuration was bound from `IConfiguration`. This is additive to the existing hosted-service lifecycle logs and consolidates DI-registration visibility with the host start event. + +#### Scenario: Hosted service startup emits a registration-context log +- **WHEN** the host starts and `ChangeTrackingHostedService.StartAsync` is invoked +- **THEN** exactly one `Information` "ChangeTracking starting" log is emitted with `{ConfigurationBound}` matching whether `AddChangeTracking` received a non-null `IConfiguration` diff --git a/openspec/changes/add-tracker-config-logging/tasks.md b/openspec/changes/add-tracker-config-logging/tasks.md new file mode 100644 index 0000000..684218f --- /dev/null +++ b/openspec/changes/add-tracker-config-logging/tasks.md @@ -0,0 +1,50 @@ +## 1. Builder configuration logging + +- [ ] 1.1 Add a cached `ILogger` field on `ChangeTrackingBuilder`, initialised from `_loggerFactory` in the constructor. +- [ ] 1.2 Emit an `Information` log from each of `UseOutbox`, `UsePublisher`, `UseSerializer`, `UseCompressor`, `UseRepository`, `UseDeduplicationStore`, `UseMeter`, `UsePublisherOptions`, and `UseSubscriberOptions` recording the registered plugin's CLR type name (or options class name) as a structured `{Plugin}` property. +- [ ] 1.3 In `ForEntity`, emit an `Information` log with `{EntityType}` before invoking the configure delegate. +- [ ] 1.4 Extend `EntityBuilder`'s constructor (currently `(ChangePublisherBuilder, ChangeSubscriberBuilder)`) to also accept `ILogger`; update `ChangeTrackingBuilder.ForEntity` to pass its cached logger. Forward the same logger to `SharedHandlerBuilder` and `IsolatedHandlerBuilder`. +- [ ] 1.5 In the post-fork builders, emit `Debug` logs for each per-entity override (`UseOutbox`, `UsePublisher`, `UseSerializer`, `UseCompressor`, `UseRepository`, `UseConsumer`, `UseConsumerFactory`, `UseSubscriberOptions`, `OnInsert`/`OnUpdate`/`OnDelete`/`OnChange`) with structured `{EntityType}`, `{Override}`, and `{Plugin}` properties. +- [ ] 1.6 Guard every new log call (Information and Debug) with `if (_log.IsEnabled())` to ensure zero allocation under `NullLoggerFactory` (see design Decision 5). + +## 2. Build summary log + +- [ ] 2.1 In `ChangeTrackingBuilder.BuildInternal`, after wiring the publisher and subscriber, emit a single `Information` log (guarded by `IsEnabled(LogLevel.Information)`) with structured properties `{EntityTypes}` (string[] of configured entity-type names), `{Plugins}` (an anonymous structure naming the global outbox, publisher, serializer, compressor CLR types or `""`), `{HasCustomMeter}`, `{HasCustomDeduplicationStore}`, and `{HasCustomLoggerFactory}` (bool). Read the entity-type and plugin information directly from the builder's existing private dictionaries — do NOT introduce new accessor methods on `ChangePublisherBuilder` / `ChangeSubscriberBuilder`. +- [ ] 2.2 Track whether the caller supplied an `ILoggerFactory` via a new internal flag on `ChangeTrackingBuilder` so `{HasCustomLoggerFactory}` is correctly reported. +- [ ] 2.3 Emit a `Debug` log when `BuildInternal` creates a default `RayTreeMeter` because `UseMeter` was not called, stating the meter is owned by the tracker. + +## 3. Tracker initialization logging + +- [ ] 3.1 Add an `ILoggerFactory` parameter to `EntityChangeTracker`'s internal constructor (passed through from `ChangeTrackingBuilder.BuildInternal`). Resolve `ILogger` from it in the constructor and store in a field. +- [ ] 3.2 In `EntityChangeTracker.InitializeAsync`, log an `Information` "tracker initialization started" entry before any sub-step. +- [ ] 3.3 After publisher initialization completes (call to `ChangePublisher.InitializeAsync`), log a `Debug` "publisher initialized" entry with `{EntityTypeCount}` structured property. +- [ ] 3.4 After consumer connections initialize, log a `Debug` "consumers initialized" entry with `{ConsumerCount}` structured property. +- [ ] 3.5 On success, log an `Information` "tracker initialization completed" entry. +- [ ] 3.6 Do NOT add a catch-log-rethrow wrapper around the whole `InitializeAsync` body — the publisher/subscriber/plugin layers already log their own `Error` entries on initialization failures, and a tracker-level catch would double-log. Instead, log a single `Warning` "tracker initialization aborted" (no exception payload) immediately before any exception propagates, so operators can see the abort point without losing the inner error context. + +## 4. DI startup logging + +- [ ] 4.1 In `ServiceCollectionExtensions.AddChangeTracking`, capture `configuration != null` into a small internal record/options class registered as a singleton (e.g. `ChangeTrackingDiContext { bool ConfigurationBound }`). +- [ ] 4.2 Inject `ChangeTrackingDiContext` into `ChangeTrackingHostedService`. In its `StartAsync`, emit a single `Information` "ChangeTracking starting" log with `{ConfigurationBound}`. This guarantees one-shot firing per host instance (hosted services start exactly once) and avoids the singleton-factory pitfall where a future lifetime change or concurrent resolution could double-log. + +## 5. Tests + +- [ ] 5.1 Add `tests/RayTree.Core.Tests/Logging/ConfigurationLoggingTests.cs` with an in-memory `ILoggerProvider` capturing log entries. +- [ ] 5.2 Test: each `Use*` call emits exactly one `Information` entry with `{Plugin}` equal to the expected CLR type name. +- [ ] 5.3 Test: `ForEntity` emits one `Information` entry with `{EntityType}="Order"` and `Debug` entries per applied override. +- [ ] 5.4 Test: `Build()` emits the build summary log with all required structured properties; verify `{Plugins}` reports `""` for unregistered slots. +- [ ] 5.5 Test: building with `NullLoggerFactory` produces zero log entries. +- [ ] 5.6 Test: `EntityChangeTracker.InitializeAsync` logs start, sub-steps (`Debug`), and completion in order; on a forced sub-step failure, a `Warning` "tracker initialization aborted" is logged before the exception propagates (no `Error` payload — that's the inner service's responsibility). +- [ ] 5.7 Test: `ChangeTrackingHostedService.StartAsync` emits exactly one `Information` "ChangeTracking starting" log per host instance, with `{ConfigurationBound}` matching how `AddChangeTracking` was called. +- [ ] 5.8 Update any existing log-counting tests in `tests/RayTree.Core.Tests` to account for new `Information` entries (or filter their assertions by message/category). + +## 6. Documentation + +- [ ] 6.1 Update `CLAUDE.md` "Logging placement rule" section to mention that `ChangeTrackingBuilder` and `EntityChangeTracker.InitializeAsync` now emit configuration and lifecycle logs. +- [ ] 6.2 Add a short "Configuration logs" subsection to `CLAUDE.md` (or a docs/logging.md if one exists) listing the structured property names introduced here (`{Plugin}`, `{EntityType}`, `{EntityTypes}`, `{Plugins}`, `{HasCustomMeter}`, `{HasCustomDeduplicationStore}`, `{HasCustomLoggerFactory}`, `{Override}`, `{ConfigurationBound}`) so operators have a single reference for log-parsing. + +## 7. Verification + +- [ ] 7.1 Run `dotnet build RayTree.slnx -c Release` and confirm no warnings (TreatWarningsAsErrors is on). +- [ ] 7.2 Run `dotnet test tests/RayTree.Core.Tests` and confirm all tests pass. +- [ ] 7.3 Run `openspec status --change add-tracker-config-logging` and confirm the change is marked complete. From 2638892b4b212bc908f232931ca639ec04c96122 Mon Sep 17 00:00:00 2001 From: bitc0der <59016822+bitc0der@users.noreply.github.com> Date: Fri, 22 May 2026 23:12:19 +0700 Subject: [PATCH 2/8] Add init logging --- CLAUDE.md | 1 + .../add-tracker-config-logging/tasks.md | 60 ++-- src/RayTree.Core/Handling/ChangeSubscriber.cs | 2 + .../Handling/IsolatedHandlerBuilder.cs | 9 +- .../Handling/SharedHandlerBuilder.cs | 18 +- .../Tracking/ChangeTrackingBuilder.cs | 64 +++- src/RayTree.Core/Tracking/EntityBuilder.cs | 46 ++- .../Tracking/EntityChangeTracker.cs | 39 ++- .../ChangeTrackingDiContext.cs | 8 + .../ChangeTrackingHostedService.cs | 18 +- .../ServiceCollectionExtensions.cs | 2 + .../Logging/ConfigurationLoggingTests.cs | 284 ++++++++++++++++++ 12 files changed, 501 insertions(+), 50 deletions(-) create mode 100644 src/RayTree.Hosting/ChangeTrackingDiContext.cs create mode 100644 tests/RayTree.Core.Tests/Logging/ConfigurationLoggingTests.cs diff --git a/CLAUDE.md b/CLAUDE.md index 5d33ac8..66f282b 100644 --- a/CLAUDE.md +++ b/CLAUDE.md @@ -131,6 +131,7 @@ All durations are emitted in seconds (`s`) per OTel semantic conventions; bytes - **Metrics placement rule — required meter, no null fallback**: `RayTreeMeter` is a required non-null constructor parameter on every runtime service that emits metrics (`ChangePublisher`, `OutboxPublisherService`, `ChangeSubscriber`). There is no internal `new RayTreeMeter()` fallback in those classes — the builder layer (`ChangeTrackingBuilder.BuildInternal`) constructs a default meter when the caller didn't supply one via `UseMeter`, then injects it everywhere. This matches the logging rule: callers make a conscious choice at builder/DI level, runtime services have no hidden defaults. `EntityChangeTracker` tracks ownership via an `ownsMeter` flag and disposes the meter only when it created it; caller-supplied meters are left alone. Instrument calls are silent no-ops when no listener is attached, so opting out costs nothing at runtime. - **OTel SDK isolation via peer assembly**: `RayTree.Core` and `RayTree.Hosting` use only `System.Diagnostics.Metrics` (BCL) — no `OpenTelemetry.*` package references. `RayTree.OpenTelemetry` is a separate assembly with two members (`RayTreeInstrumentation.MeterName` + `AddRayTreeMetrics`) that an application opts into. Applications that don't need OTel receive zero transitive OTel dependencies; applications that do reference exactly one well-versioned dependency. This mirrors the `RayTree.Hosting` / `RayTree.EntityFrameworkCore` split. - **Logging placement rule**: `NullLoggerFactory.Instance` / `NullLogger.Instance` defaults belong **only** in builders and builder-context extension methods (`ChangeTrackingBuilder`, `ChangePublisherBuilder`, `ChangeSubscriberBuilder`, `KafkaSubscriberExtensions.UseKafka`, `RabbitMqBuilderExtensions.UseRabbitMq`, `RabbitMqSubscriberExtensions.UseRabbitMq`, `BuilderExtensions.UsePostgreSqlOutbox`, `RepositoryExtensions.UsePostgreSqlRepository`). All runtime service classes (`ChangePublisher`, `OutboxPublisherService`, `ChangeSubscriber`, `ChangeTrackingHostedService`, `KafkaConsumer`, `NotificationBasedPublisher`, `PostgreSqlOutbox`, `PostgreSqlRepository`) require a non-nullable logger — no internal fallback. `RabbitMqPublisher` accepts an optional `ILoggerFactory?` (null → `NullLoggerFactory.Instance`) to support topology-wait logging without forcing every caller through DI. **Exception**: `RabbitMqConsumer` intentionally has no logger — message-receive errors silently NACK and requeue, which is the correct broker-level recovery; no useful context is available inside the RabbitMQ delivery callback to produce a meaningful log entry. Consumer-side topology-wait probes therefore pass `logger: null` to `TopologyProbe`, preserving the exception. This ensures that callers always make a conscious choice about whether to produce log output. +- **Configuration & lifecycle logs**: `ChangeTrackingBuilder` emits `Information` for each `Use*` registration (with `{Plugin}` = type name), an `Information` "ChangeTracker built" summary at `BuildInternal` time (with `{EntityTypes}`, `{Plugins}`, `{HasCustomMeter}`, `{HasCustomDeduplicationStore}`, `{HasCustomLoggerFactory}`), and a `Debug` "no meter supplied" note when it creates the default `RayTreeMeter`. `ForEntity` logs `Information` for the entity type; per-entity overrides (`UseOutbox`, `UsePublisher`, `UseSerializer`, `UseCompressor`, `UseRepository`, `UseSubscriberOptions`, `UseConsumer`, `UseConsumerFactory`, `OnInsert`/`OnUpdate`/`OnDelete`/`OnChange`) log at `Debug` with `{EntityType}`, `{Override}` (slot name like `"Outbox"` or `"OnInsert:handlerName"`), and `{Plugin}` (concrete type name). `EntityChangeTracker.InitializeAsync` logs `Information` "tracker initialization started" / "completed" bracketing two `Debug` sub-step entries: "publisher initialized" with `{EntityTypeCount}` and "consumers initialized" with `{ConsumerCount}`; on failure it emits one `Warning` "tracker initialization aborted" (no exception payload — the inner service's own `Error` carries the cause) before rethrowing. `ChangeTrackingHostedService.StartAsync` emits one `Information` "ChangeTracking starting" with `{ConfigurationBound}` (sourced from the `ChangeTrackingDiContext` singleton registered by `AddChangeTracking`). Every call is guarded by `IsEnabled(...)` so `NullLoggerFactory` produces zero allocations. ## Code Style & Conventions diff --git a/openspec/changes/add-tracker-config-logging/tasks.md b/openspec/changes/add-tracker-config-logging/tasks.md index 684218f..34fb5c1 100644 --- a/openspec/changes/add-tracker-config-logging/tasks.md +++ b/openspec/changes/add-tracker-config-logging/tasks.md @@ -1,50 +1,50 @@ ## 1. Builder configuration logging -- [ ] 1.1 Add a cached `ILogger` field on `ChangeTrackingBuilder`, initialised from `_loggerFactory` in the constructor. -- [ ] 1.2 Emit an `Information` log from each of `UseOutbox`, `UsePublisher`, `UseSerializer`, `UseCompressor`, `UseRepository`, `UseDeduplicationStore`, `UseMeter`, `UsePublisherOptions`, and `UseSubscriberOptions` recording the registered plugin's CLR type name (or options class name) as a structured `{Plugin}` property. -- [ ] 1.3 In `ForEntity`, emit an `Information` log with `{EntityType}` before invoking the configure delegate. -- [ ] 1.4 Extend `EntityBuilder`'s constructor (currently `(ChangePublisherBuilder, ChangeSubscriberBuilder)`) to also accept `ILogger`; update `ChangeTrackingBuilder.ForEntity` to pass its cached logger. Forward the same logger to `SharedHandlerBuilder` and `IsolatedHandlerBuilder`. -- [ ] 1.5 In the post-fork builders, emit `Debug` logs for each per-entity override (`UseOutbox`, `UsePublisher`, `UseSerializer`, `UseCompressor`, `UseRepository`, `UseConsumer`, `UseConsumerFactory`, `UseSubscriberOptions`, `OnInsert`/`OnUpdate`/`OnDelete`/`OnChange`) with structured `{EntityType}`, `{Override}`, and `{Plugin}` properties. -- [ ] 1.6 Guard every new log call (Information and Debug) with `if (_log.IsEnabled())` to ensure zero allocation under `NullLoggerFactory` (see design Decision 5). +- [x] 1.1 Add a cached `ILogger` field on `ChangeTrackingBuilder`, initialised from `_loggerFactory` in the constructor. +- [x] 1.2 Emit an `Information` log from each of `UseOutbox`, `UsePublisher`, `UseSerializer`, `UseCompressor`, `UseRepository`, `UseDeduplicationStore`, `UseMeter`, `UsePublisherOptions`, and `UseSubscriberOptions` recording the registered plugin's CLR type name (or options class name) as a structured `{Plugin}` property. +- [x] 1.3 In `ForEntity`, emit an `Information` log with `{EntityType}` before invoking the configure delegate. +- [x] 1.4 Extend `EntityBuilder`'s constructor (currently `(ChangePublisherBuilder, ChangeSubscriberBuilder)`) to also accept `ILogger`; update `ChangeTrackingBuilder.ForEntity` to pass its cached logger. Forward the same logger to `SharedHandlerBuilder` and `IsolatedHandlerBuilder`. +- [x] 1.5 In the post-fork builders, emit `Debug` logs for each per-entity override (`UseOutbox`, `UsePublisher`, `UseSerializer`, `UseCompressor`, `UseRepository`, `UseConsumer`, `UseConsumerFactory`, `UseSubscriberOptions`, `OnInsert`/`OnUpdate`/`OnDelete`/`OnChange`) with structured `{EntityType}`, `{Override}`, and `{Plugin}` properties. +- [x] 1.6 Guard every new log call (Information and Debug) with `if (_log.IsEnabled())` to ensure zero allocation under `NullLoggerFactory` (see design Decision 5). ## 2. Build summary log -- [ ] 2.1 In `ChangeTrackingBuilder.BuildInternal`, after wiring the publisher and subscriber, emit a single `Information` log (guarded by `IsEnabled(LogLevel.Information)`) with structured properties `{EntityTypes}` (string[] of configured entity-type names), `{Plugins}` (an anonymous structure naming the global outbox, publisher, serializer, compressor CLR types or `""`), `{HasCustomMeter}`, `{HasCustomDeduplicationStore}`, and `{HasCustomLoggerFactory}` (bool). Read the entity-type and plugin information directly from the builder's existing private dictionaries — do NOT introduce new accessor methods on `ChangePublisherBuilder` / `ChangeSubscriberBuilder`. -- [ ] 2.2 Track whether the caller supplied an `ILoggerFactory` via a new internal flag on `ChangeTrackingBuilder` so `{HasCustomLoggerFactory}` is correctly reported. -- [ ] 2.3 Emit a `Debug` log when `BuildInternal` creates a default `RayTreeMeter` because `UseMeter` was not called, stating the meter is owned by the tracker. +- [x] 2.1 In `ChangeTrackingBuilder.BuildInternal`, after wiring the publisher and subscriber, emit a single `Information` log (guarded by `IsEnabled(LogLevel.Information)`) with structured properties `{EntityTypes}` (string[] of configured entity-type names), `{Plugins}` (an anonymous structure naming the global outbox, publisher, serializer, compressor CLR types or `""`), `{HasCustomMeter}`, `{HasCustomDeduplicationStore}`, and `{HasCustomLoggerFactory}` (bool). Read the entity-type and plugin information directly from the builder's existing private dictionaries — do NOT introduce new accessor methods on `ChangePublisherBuilder` / `ChangeSubscriberBuilder`. +- [x] 2.2 Track whether the caller supplied an `ILoggerFactory` via a new internal flag on `ChangeTrackingBuilder` so `{HasCustomLoggerFactory}` is correctly reported. +- [x] 2.3 Emit a `Debug` log when `BuildInternal` creates a default `RayTreeMeter` because `UseMeter` was not called, stating the meter is owned by the tracker. ## 3. Tracker initialization logging -- [ ] 3.1 Add an `ILoggerFactory` parameter to `EntityChangeTracker`'s internal constructor (passed through from `ChangeTrackingBuilder.BuildInternal`). Resolve `ILogger` from it in the constructor and store in a field. -- [ ] 3.2 In `EntityChangeTracker.InitializeAsync`, log an `Information` "tracker initialization started" entry before any sub-step. -- [ ] 3.3 After publisher initialization completes (call to `ChangePublisher.InitializeAsync`), log a `Debug` "publisher initialized" entry with `{EntityTypeCount}` structured property. -- [ ] 3.4 After consumer connections initialize, log a `Debug` "consumers initialized" entry with `{ConsumerCount}` structured property. -- [ ] 3.5 On success, log an `Information` "tracker initialization completed" entry. -- [ ] 3.6 Do NOT add a catch-log-rethrow wrapper around the whole `InitializeAsync` body — the publisher/subscriber/plugin layers already log their own `Error` entries on initialization failures, and a tracker-level catch would double-log. Instead, log a single `Warning` "tracker initialization aborted" (no exception payload) immediately before any exception propagates, so operators can see the abort point without losing the inner error context. +- [x] 3.1 Add an `ILoggerFactory` parameter to `EntityChangeTracker`'s internal constructor (passed through from `ChangeTrackingBuilder.BuildInternal`). Resolve `ILogger` from it in the constructor and store in a field. +- [x] 3.2 In `EntityChangeTracker.InitializeAsync`, log an `Information` "tracker initialization started" entry before any sub-step. +- [x] 3.3 After publisher initialization completes (call to `ChangePublisher.InitializeAsync`), log a `Debug` "publisher initialized" entry with `{EntityTypeCount}` structured property. +- [x] 3.4 After consumer connections initialize, log a `Debug` "consumers initialized" entry with `{ConsumerCount}` structured property. +- [x] 3.5 On success, log an `Information` "tracker initialization completed" entry. +- [x] 3.6 Do NOT add a catch-log-rethrow wrapper around the whole `InitializeAsync` body — the publisher/subscriber/plugin layers already log their own `Error` entries on initialization failures, and a tracker-level catch would double-log. Instead, log a single `Warning` "tracker initialization aborted" (no exception payload) immediately before any exception propagates, so operators can see the abort point without losing the inner error context. ## 4. DI startup logging -- [ ] 4.1 In `ServiceCollectionExtensions.AddChangeTracking`, capture `configuration != null` into a small internal record/options class registered as a singleton (e.g. `ChangeTrackingDiContext { bool ConfigurationBound }`). -- [ ] 4.2 Inject `ChangeTrackingDiContext` into `ChangeTrackingHostedService`. In its `StartAsync`, emit a single `Information` "ChangeTracking starting" log with `{ConfigurationBound}`. This guarantees one-shot firing per host instance (hosted services start exactly once) and avoids the singleton-factory pitfall where a future lifetime change or concurrent resolution could double-log. +- [x] 4.1 In `ServiceCollectionExtensions.AddChangeTracking`, capture `configuration != null` into a small internal record/options class registered as a singleton (e.g. `ChangeTrackingDiContext { bool ConfigurationBound }`). +- [x] 4.2 Inject `ChangeTrackingDiContext` into `ChangeTrackingHostedService`. In its `StartAsync`, emit a single `Information` "ChangeTracking starting" log with `{ConfigurationBound}`. This guarantees one-shot firing per host instance (hosted services start exactly once) and avoids the singleton-factory pitfall where a future lifetime change or concurrent resolution could double-log. ## 5. Tests -- [ ] 5.1 Add `tests/RayTree.Core.Tests/Logging/ConfigurationLoggingTests.cs` with an in-memory `ILoggerProvider` capturing log entries. -- [ ] 5.2 Test: each `Use*` call emits exactly one `Information` entry with `{Plugin}` equal to the expected CLR type name. -- [ ] 5.3 Test: `ForEntity` emits one `Information` entry with `{EntityType}="Order"` and `Debug` entries per applied override. -- [ ] 5.4 Test: `Build()` emits the build summary log with all required structured properties; verify `{Plugins}` reports `""` for unregistered slots. -- [ ] 5.5 Test: building with `NullLoggerFactory` produces zero log entries. -- [ ] 5.6 Test: `EntityChangeTracker.InitializeAsync` logs start, sub-steps (`Debug`), and completion in order; on a forced sub-step failure, a `Warning` "tracker initialization aborted" is logged before the exception propagates (no `Error` payload — that's the inner service's responsibility). -- [ ] 5.7 Test: `ChangeTrackingHostedService.StartAsync` emits exactly one `Information` "ChangeTracking starting" log per host instance, with `{ConfigurationBound}` matching how `AddChangeTracking` was called. -- [ ] 5.8 Update any existing log-counting tests in `tests/RayTree.Core.Tests` to account for new `Information` entries (or filter their assertions by message/category). +- [x] 5.1 Add `tests/RayTree.Core.Tests/Logging/ConfigurationLoggingTests.cs` with an in-memory `ILoggerProvider` capturing log entries. +- [x] 5.2 Test: each `Use*` call emits exactly one `Information` entry with `{Plugin}` equal to the expected CLR type name. +- [x] 5.3 Test: `ForEntity` emits one `Information` entry with `{EntityType}="Order"` and `Debug` entries per applied override. +- [x] 5.4 Test: `Build()` emits the build summary log with all required structured properties; verify `{Plugins}` reports `""` for unregistered slots. +- [x] 5.5 Test: building with `NullLoggerFactory` produces zero log entries. +- [x] 5.6 Test: `EntityChangeTracker.InitializeAsync` logs start, sub-steps (`Debug`), and completion in order; on a forced sub-step failure, a `Warning` "tracker initialization aborted" is logged before the exception propagates (no `Error` payload — that's the inner service's responsibility). +- [x] 5.7 Test: `ChangeTrackingHostedService.StartAsync` emits exactly one `Information` "ChangeTracking starting" log per host instance, with `{ConfigurationBound}` matching how `AddChangeTracking` was called. +- [x] 5.8 Update any existing log-counting tests in `tests/RayTree.Core.Tests` to account for new `Information` entries (or filter their assertions by message/category). ## 6. Documentation -- [ ] 6.1 Update `CLAUDE.md` "Logging placement rule" section to mention that `ChangeTrackingBuilder` and `EntityChangeTracker.InitializeAsync` now emit configuration and lifecycle logs. -- [ ] 6.2 Add a short "Configuration logs" subsection to `CLAUDE.md` (or a docs/logging.md if one exists) listing the structured property names introduced here (`{Plugin}`, `{EntityType}`, `{EntityTypes}`, `{Plugins}`, `{HasCustomMeter}`, `{HasCustomDeduplicationStore}`, `{HasCustomLoggerFactory}`, `{Override}`, `{ConfigurationBound}`) so operators have a single reference for log-parsing. +- [x] 6.1 Update `CLAUDE.md` "Logging placement rule" section to mention that `ChangeTrackingBuilder` and `EntityChangeTracker.InitializeAsync` now emit configuration and lifecycle logs. +- [x] 6.2 Add a short "Configuration logs" subsection to `CLAUDE.md` (or a docs/logging.md if one exists) listing the structured property names introduced here (`{Plugin}`, `{EntityType}`, `{EntityTypes}`, `{Plugins}`, `{HasCustomMeter}`, `{HasCustomDeduplicationStore}`, `{HasCustomLoggerFactory}`, `{Override}`, `{ConfigurationBound}`) so operators have a single reference for log-parsing. ## 7. Verification -- [ ] 7.1 Run `dotnet build RayTree.slnx -c Release` and confirm no warnings (TreatWarningsAsErrors is on). -- [ ] 7.2 Run `dotnet test tests/RayTree.Core.Tests` and confirm all tests pass. -- [ ] 7.3 Run `openspec status --change add-tracker-config-logging` and confirm the change is marked complete. +- [x] 7.1 Run `dotnet build RayTree.slnx -c Release` and confirm no warnings (TreatWarningsAsErrors is on). +- [x] 7.2 Run `dotnet test tests/RayTree.Core.Tests` and confirm all tests pass. +- [x] 7.3 Run `openspec status --change add-tracker-config-logging` and confirm the change is marked complete. diff --git a/src/RayTree.Core/Handling/ChangeSubscriber.cs b/src/RayTree.Core/Handling/ChangeSubscriber.cs index 789d16c..cf5411e 100644 --- a/src/RayTree.Core/Handling/ChangeSubscriber.cs +++ b/src/RayTree.Core/Handling/ChangeSubscriber.cs @@ -65,6 +65,8 @@ public ChangeSubscriber( internal IReadOnlyCollection IsolatedQueueKeys => _isolatedQueues.Keys; + internal int ConsumerCount => _queues.Count + _isolatedQueues.Count; + private List? _consumeTasks; internal async Task InitializeAsync(CancellationToken cancellationToken = default) diff --git a/src/RayTree.Core/Handling/IsolatedHandlerBuilder.cs b/src/RayTree.Core/Handling/IsolatedHandlerBuilder.cs index 94a5633..d5e1f65 100644 --- a/src/RayTree.Core/Handling/IsolatedHandlerBuilder.cs +++ b/src/RayTree.Core/Handling/IsolatedHandlerBuilder.cs @@ -1,3 +1,4 @@ +using Microsoft.Extensions.Logging; using RayTree.Core.Plugins.Consumer; using RayTree.Core.Tracking; @@ -11,11 +12,13 @@ namespace RayTree.Core.Handling; /// internal sealed class IsolatedHandlerBuilder( EntitySubscriberBuilder subBuilder, - Func factory) + Func factory, + ILogger log) : IIsolatedHandlerBuilder where TEntity : class { private readonly List<(string HandlerName, ChangeType ChangeType, ChangeHandlerAsync Handler, SubscriberOptions? Options)> _entries = new(); + private static readonly string EntityTypeName = typeof(TEntity).Name; /// public IIsolatedHandlerBuilder OnInsert(string handlerName, ChangeHandlerAsync handler, @@ -43,6 +46,10 @@ public IIsolatedHandlerBuilder OnChange(string handlerName, ChangeType ArgumentNullException.ThrowIfNull(handler); _entries.Add((handlerName, changeType, handler, options)); + if (log.IsEnabled(LogLevel.Debug)) + log.LogDebug( + "ChangeTracking: entity override applied EntityType={EntityType} Override={Override} Plugin={Plugin}", + EntityTypeName, $"On{changeType}:{handlerName}", handler.Method.DeclaringType?.Name ?? ""); return this; } diff --git a/src/RayTree.Core/Handling/SharedHandlerBuilder.cs b/src/RayTree.Core/Handling/SharedHandlerBuilder.cs index 7e0ab12..d66cdd4 100644 --- a/src/RayTree.Core/Handling/SharedHandlerBuilder.cs +++ b/src/RayTree.Core/Handling/SharedHandlerBuilder.cs @@ -1,3 +1,4 @@ +using Microsoft.Extensions.Logging; using RayTree.Core.Tracking; namespace RayTree.Core.Handling; @@ -13,10 +14,21 @@ internal sealed class SharedHandlerBuilder : ISharedHandlerBuilder _subBuilder; + private readonly ILogger _log; + private static readonly string EntityTypeName = typeof(TEntity).Name; - internal SharedHandlerBuilder(EntitySubscriberBuilder subBuilder) + internal SharedHandlerBuilder(EntitySubscriberBuilder subBuilder, ILogger log) { _subBuilder = subBuilder ?? throw new ArgumentNullException(nameof(subBuilder)); + _log = log; + } + + private void LogHandler(string slot, ChangeHandlerAsync handler) + { + if (_log.IsEnabled(LogLevel.Debug)) + _log.LogDebug( + "ChangeTracking: entity override applied EntityType={EntityType} Override={Override} Plugin={Plugin}", + EntityTypeName, slot, handler.Method.DeclaringType?.Name ?? ""); } /// @@ -24,6 +36,7 @@ public ISharedHandlerBuilder OnInsert(ChangeHandlerAsync handl { ArgumentNullException.ThrowIfNull(handler); _subBuilder.OnInsert(handler); + LogHandler("OnInsert", handler); return this; } @@ -32,6 +45,7 @@ public ISharedHandlerBuilder OnUpdate(ChangeHandlerAsync handl { ArgumentNullException.ThrowIfNull(handler); _subBuilder.OnUpdate(handler); + LogHandler("OnUpdate", handler); return this; } @@ -40,6 +54,7 @@ public ISharedHandlerBuilder OnDelete(ChangeHandlerAsync handl { ArgumentNullException.ThrowIfNull(handler); _subBuilder.OnDelete(handler); + LogHandler("OnDelete", handler); return this; } @@ -48,6 +63,7 @@ public ISharedHandlerBuilder OnChange(ChangeType changeType, ChangeHand { ArgumentNullException.ThrowIfNull(handler); _subBuilder.OnChange(changeType, handler); + LogHandler($"OnChange:{changeType}", handler); return this; } } diff --git a/src/RayTree.Core/Tracking/ChangeTrackingBuilder.cs b/src/RayTree.Core/Tracking/ChangeTrackingBuilder.cs index 1ae99fa..a660372 100644 --- a/src/RayTree.Core/Tracking/ChangeTrackingBuilder.cs +++ b/src/RayTree.Core/Tracking/ChangeTrackingBuilder.cs @@ -17,22 +17,42 @@ public sealed class ChangeTrackingBuilder : IChangeTrackingBuilder private readonly ChangePublisherBuilder _publisherBuilder = new(); private readonly ChangeSubscriberBuilder _subscriberBuilder = new(); private readonly ILoggerFactory _loggerFactory; + private readonly bool _hasCustomLoggerFactory; + private readonly ILogger _log; private RayTreeMeter? _meter; + // Captured plugin-type metadata for the build-summary log. Populated lazily as the + // caller chains Use* registrations; read once in BuildInternal. + private string? _globalOutboxType; + private string? _globalPublisherType; + private string? _globalSerializerType; + private string? _globalCompressorType; + private string? _globalRepositoryType; + private bool _hasCustomDedupStore; + private readonly List _entityTypes = new(); + internal ChangeTrackingBuilder(ILoggerFactory? loggerFactory = null) { + _hasCustomLoggerFactory = loggerFactory is not null; _loggerFactory = loggerFactory ?? NullLoggerFactory.Instance; + _log = _loggerFactory.CreateLogger(); } public IChangeTrackingBuilder UseOutbox(Func factory) where T : IOutbox { _publisherBuilder.UseOutbox(factory); + _globalOutboxType = typeof(T).Name; + if (_log.IsEnabled(LogLevel.Information)) + _log.LogInformation("ChangeTracking: registered global outbox {Plugin}", typeof(T).Name); return this; } public IChangeTrackingBuilder UsePublisher(Func factory) where T : IQueuePublisher { _publisherBuilder.UsePublisher(factory); + _globalPublisherType = typeof(T).Name; + if (_log.IsEnabled(LogLevel.Information)) + _log.LogInformation("ChangeTracking: registered global publisher {Plugin}", typeof(T).Name); return this; } @@ -41,6 +61,9 @@ public IChangeTrackingBuilder UseSerializer(Func fac ArgumentNullException.ThrowIfNull(factory); _publisherBuilder.UseSerializer(factory); _subscriberBuilder.UseSerializer(factory(typeof(object))); + _globalSerializerType = typeof(T).Name; + if (_log.IsEnabled(LogLevel.Information)) + _log.LogInformation("ChangeTracking: registered global serializer {Plugin}", typeof(T).Name); return this; } @@ -49,30 +72,43 @@ public IChangeTrackingBuilder UseCompressor(Func fac ArgumentNullException.ThrowIfNull(factory); _publisherBuilder.UseCompressor(factory); _subscriberBuilder.UseCompressor(factory(typeof(object))); + _globalCompressorType = typeof(T).Name; + if (_log.IsEnabled(LogLevel.Information)) + _log.LogInformation("ChangeTracking: registered global compressor {Plugin}", typeof(T).Name); return this; } public IChangeTrackingBuilder UseRepository(Func factory) where T : IRepository { _publisherBuilder.UseRepository(factory); + _globalRepositoryType = typeof(T).Name; + if (_log.IsEnabled(LogLevel.Information)) + _log.LogInformation("ChangeTracking: registered global repository {Plugin}", typeof(T).Name); return this; } public IChangeTrackingBuilder UsePublisherOptions(Action configure) { _publisherBuilder.UseOptions(configure); + if (_log.IsEnabled(LogLevel.Information)) + _log.LogInformation("ChangeTracking: configured {Plugin}", nameof(OutboxPublisherOptions)); return this; } public IChangeTrackingBuilder UseSubscriberOptions(Action configure) { _subscriberBuilder.UseOptions(configure); + if (_log.IsEnabled(LogLevel.Information)) + _log.LogInformation("ChangeTracking: configured {Plugin}", nameof(SubscriberOptions)); return this; } public IChangeTrackingBuilder UseDeduplicationStore(IDeduplicationStore store) { _subscriberBuilder.UseDeduplicationStore(store); + _hasCustomDedupStore = true; + if (_log.IsEnabled(LogLevel.Information)) + _log.LogInformation("ChangeTracking: registered deduplication store {Plugin}", store.GetType().Name); return this; } @@ -80,6 +116,8 @@ public IChangeTrackingBuilder UseMeter(RayTreeMeter meter) { ArgumentNullException.ThrowIfNull(meter); _meter = meter; + if (_log.IsEnabled(LogLevel.Information)) + _log.LogInformation("ChangeTracking: registered meter {Plugin}", nameof(RayTreeMeter)); return this; } @@ -87,7 +125,11 @@ public IChangeTrackingBuilder ForEntity(Action> where TEntity : class { ArgumentNullException.ThrowIfNull(configure); - var entityBuilder = new EntityBuilder(_publisherBuilder, _subscriberBuilder); + _entityTypes.Add(typeof(TEntity)); + if (_log.IsEnabled(LogLevel.Information)) + _log.LogInformation("ChangeTracking: configuring entity {EntityType}", typeof(TEntity).Name); + + var entityBuilder = new EntityBuilder(_publisherBuilder, _subscriberBuilder, _log); configure(entityBuilder); entityBuilder.RegisterSubscriberApplicator(); return this; @@ -112,6 +154,9 @@ private EntityChangeTracker BuildInternal() var meter = _meter ?? new RayTreeMeter(); var ownsMeter = _meter == null; // builder-created meter is disposed by the tracker + if (ownsMeter && _log.IsEnabled(LogLevel.Debug)) + _log.LogDebug("ChangeTracking: no meter supplied; created default RayTreeMeter (owned by tracker)"); + _publisherBuilder.UseLoggerFactory(_loggerFactory); // always non-null — resolved once here _subscriberBuilder.UseLoggerFactory(_loggerFactory); _publisherBuilder.UseMeter(meter); @@ -125,6 +170,21 @@ private EntityChangeTracker BuildInternal() meter.RegisterPendingGauge(() => publisher.GetOutboxes().Select(kvp => (kvp.Key, kvp.Value))); - return new EntityChangeTracker(publisher, subscriber, meter, ownsMeter: ownsMeter); + if (_log.IsEnabled(LogLevel.Information)) + { + var entityTypeNames = _entityTypes.Select(t => t.Name).ToArray(); + var plugins = $"Outbox={_globalOutboxType ?? ""} Publisher={_globalPublisherType ?? ""} " + + $"Serializer={_globalSerializerType ?? ""} Compressor={_globalCompressorType ?? ""} " + + $"Repository={_globalRepositoryType ?? ""}"; + _log.LogInformation( + "ChangeTracker built. EntityTypes={EntityTypes} Plugins={Plugins} HasCustomMeter={HasCustomMeter} HasCustomDeduplicationStore={HasCustomDeduplicationStore} HasCustomLoggerFactory={HasCustomLoggerFactory}", + entityTypeNames, + plugins, + _meter is not null, + _hasCustomDedupStore, + _hasCustomLoggerFactory); + } + + return new EntityChangeTracker(publisher, subscriber, meter, ownsMeter: ownsMeter, loggerFactory: _loggerFactory); } } diff --git a/src/RayTree.Core/Tracking/EntityBuilder.cs b/src/RayTree.Core/Tracking/EntityBuilder.cs index 221e38d..a66e8c8 100644 --- a/src/RayTree.Core/Tracking/EntityBuilder.cs +++ b/src/RayTree.Core/Tracking/EntityBuilder.cs @@ -1,3 +1,4 @@ +using Microsoft.Extensions.Logging; using RayTree.Core.Distribution; using RayTree.Core.Handling; using RayTree.Core.Plugins; @@ -17,17 +18,38 @@ namespace RayTree.Core.Tracking; /// post-fork builder is created and returned; /// later wires the chosen path into the parent . /// -internal sealed class EntityBuilder(ChangePublisherBuilder publisherBuilder, ChangeSubscriberBuilder subscriberBuilder) - : IEntityBuilder +internal sealed class EntityBuilder : IEntityBuilder where TEntity : class { - private readonly EntityPublisherBuilder _pubBuilder = new(publisherBuilder); - private readonly EntitySubscriberBuilder _subBuilder = new(subscriberBuilder); + private readonly ChangeSubscriberBuilder _subscriberBuilder; + private readonly EntityPublisherBuilder _pubBuilder; + private readonly EntitySubscriberBuilder _subBuilder; + private readonly ILogger _log; + private static readonly string EntityTypeName = typeof(TEntity).Name; // Exactly one of these is non-null once a consumer-binding method has been called. private SharedHandlerBuilder? _sharedBuilder; private IsolatedHandlerBuilder? _isolatedBuilder; + internal EntityBuilder( + ChangePublisherBuilder publisherBuilder, + ChangeSubscriberBuilder subscriberBuilder, + ILogger log) + { + _subscriberBuilder = subscriberBuilder; + _pubBuilder = new EntityPublisherBuilder(publisherBuilder); + _subBuilder = new EntitySubscriberBuilder(subscriberBuilder); + _log = log; + } + + private void LogOverride(string slot, string pluginName) + { + if (_log.IsEnabled(LogLevel.Debug)) + _log.LogDebug( + "ChangeTracking: entity override applied EntityType={EntityType} Override={Override} Plugin={Plugin}", + EntityTypeName, slot, pluginName); + } + // ------------------------------------------------------------------------- // Publisher side // ------------------------------------------------------------------------- @@ -36,6 +58,7 @@ public IEntityBuilder UseRepository(IRepository repository) { ArgumentNullException.ThrowIfNull(repository); _pubBuilder.UseRepository(repository); + LogOverride("Repository", repository.GetType().Name); return this; } @@ -43,6 +66,7 @@ public IEntityBuilder UseOutbox(IOutbox outbox) { ArgumentNullException.ThrowIfNull(outbox); _pubBuilder.UseOutbox(outbox); + LogOverride("Outbox", outbox.GetType().Name); return this; } @@ -50,6 +74,7 @@ public IEntityBuilder UsePublisher(IQueuePublisher queue) { ArgumentNullException.ThrowIfNull(queue); _pubBuilder.UsePublisher(queue); + LogOverride("Publisher", queue.GetType().Name); return this; } @@ -58,6 +83,7 @@ public IEntityBuilder UseSerializer(IChangeSerializer serializer) ArgumentNullException.ThrowIfNull(serializer); _pubBuilder.UseSerializer(serializer); _subBuilder.UseSerializer(serializer); + LogOverride("Serializer", serializer.GetType().Name); return this; } @@ -66,6 +92,7 @@ public IEntityBuilder UseCompressor(IChangeCompressor compressor) ArgumentNullException.ThrowIfNull(compressor); _pubBuilder.UseCompressor(compressor); _subBuilder.UseCompressor(compressor); + LogOverride("Compressor", compressor.GetType().Name); return this; } @@ -77,6 +104,7 @@ public IEntityBuilder UseSubscriberOptions(Action co { ArgumentNullException.ThrowIfNull(configure); _subBuilder.UseOptions(configure); + LogOverride("SubscriberOptions", nameof(SubscriberOptions)); return this; } @@ -88,14 +116,16 @@ public ISharedHandlerBuilder UseConsumer(IQueueConsumer consumer) { ArgumentNullException.ThrowIfNull(consumer); _subBuilder.UseConsumer(consumer); - _sharedBuilder = new SharedHandlerBuilder(_subBuilder); + LogOverride("Consumer", consumer.GetType().Name); + _sharedBuilder = new SharedHandlerBuilder(_subBuilder, _log); return _sharedBuilder; } public IIsolatedHandlerBuilder UseConsumerFactory(Func factory) { ArgumentNullException.ThrowIfNull(factory); - _isolatedBuilder = new IsolatedHandlerBuilder(_subBuilder, factory); + LogOverride("ConsumerFactory", factory.GetType().Name); + _isolatedBuilder = new IsolatedHandlerBuilder(_subBuilder, factory, _log); return _isolatedBuilder; } @@ -106,8 +136,8 @@ public IIsolatedHandlerBuilder UseConsumerFactory(Func _log; private bool _disposed; internal ChangePublisher Publisher => _publisher; @@ -38,20 +40,49 @@ internal EntityChangeTracker( ChangePublisher publisher, ChangeSubscriber? subscriber = null, RayTreeMeter? meter = null, - bool ownsMeter = false) + bool ownsMeter = false, + ILoggerFactory? loggerFactory = null) { _publisher = publisher ?? throw new ArgumentNullException(nameof(publisher)); _subscriber = subscriber; _meter = meter ?? publisher.Meter; _ownsMeter = ownsMeter; + _log = (loggerFactory ?? NullLoggerFactory.Instance).CreateLogger(); } internal async Task InitializeAsync(CancellationToken cancellationToken = default) { - await _publisher.InitializeAsync(cancellationToken); + if (_log.IsEnabled(LogLevel.Information)) + _log.LogInformation("ChangeTracking: tracker initialization started"); - if (_subscriber != null) - await _subscriber.InitializeAsync(cancellationToken); + try + { + await _publisher.InitializeAsync(cancellationToken); + + if (_log.IsEnabled(LogLevel.Debug)) + _log.LogDebug( + "ChangeTracking: publisher initialized EntityTypeCount={EntityTypeCount}", + _publisher.GetOutboxes().Count); + + if (_subscriber != null) + { + await _subscriber.InitializeAsync(cancellationToken); + + if (_log.IsEnabled(LogLevel.Debug)) + _log.LogDebug( + "ChangeTracking: consumers initialized ConsumerCount={ConsumerCount}", + _subscriber.ConsumerCount); + } + + if (_log.IsEnabled(LogLevel.Information)) + _log.LogInformation("ChangeTracking: tracker initialization completed"); + } + catch + { + if (_log.IsEnabled(LogLevel.Warning)) + _log.LogWarning("ChangeTracking: tracker initialization aborted"); + throw; + } } internal IOutbox GetOutbox(Type entityType) => _publisher.GetOutbox(entityType); diff --git a/src/RayTree.Hosting/ChangeTrackingDiContext.cs b/src/RayTree.Hosting/ChangeTrackingDiContext.cs new file mode 100644 index 0000000..3c0add9 --- /dev/null +++ b/src/RayTree.Hosting/ChangeTrackingDiContext.cs @@ -0,0 +1,8 @@ +namespace RayTree.Hosting; + +/// +/// DI-scoped context captured at +/// registration time. Consumed by to emit the +/// one-shot "ChangeTracking starting" log with details from the registration call. +/// +public sealed record ChangeTrackingDiContext(bool ConfigurationBound); diff --git a/src/RayTree.Hosting/ChangeTrackingHostedService.cs b/src/RayTree.Hosting/ChangeTrackingHostedService.cs index 5cddc7f..e874f6f 100644 --- a/src/RayTree.Hosting/ChangeTrackingHostedService.cs +++ b/src/RayTree.Hosting/ChangeTrackingHostedService.cs @@ -8,18 +8,28 @@ public class ChangeTrackingHostedService : IHostedService { private readonly EntityChangeTracker _tracker; private readonly ILogger _logger; + private readonly ChangeTrackingDiContext? _diContext; private readonly CancellationTokenSource _cts = new(); public ChangeTrackingHostedService( EntityChangeTracker tracker, - ILogger logger) + ILogger logger, + ChangeTrackingDiContext? diContext = null) { - _tracker = tracker ?? throw new ArgumentNullException(nameof(tracker)); - _logger = logger ?? throw new ArgumentNullException(nameof(logger)); + _tracker = tracker ?? throw new ArgumentNullException(nameof(tracker)); + _logger = logger ?? throw new ArgumentNullException(nameof(logger)); + _diContext = diContext; } public Task StartAsync(CancellationToken cancellationToken) - => _tracker.StartAsync(_cts.Token); + { + if (_diContext is not null && _logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation( + "ChangeTracking starting. ConfigurationBound={ConfigurationBound}", + _diContext.ConfigurationBound); + + return _tracker.StartAsync(_cts.Token); + } public async Task StopAsync(CancellationToken cancellationToken) { diff --git a/src/RayTree.Hosting/ServiceCollectionExtensions.cs b/src/RayTree.Hosting/ServiceCollectionExtensions.cs index ce6f991..8e5924a 100644 --- a/src/RayTree.Hosting/ServiceCollectionExtensions.cs +++ b/src/RayTree.Hosting/ServiceCollectionExtensions.cs @@ -15,6 +15,8 @@ public static IServiceCollection AddChangeTracking( IConfiguration? configuration = null, Action? configure = null) { + services.AddSingleton(new ChangeTrackingDiContext(ConfigurationBound: configuration is not null)); + services.AddSingleton(); // RayTreeMeter is a DI singleton so callers can also inject it directly for diff --git a/tests/RayTree.Core.Tests/Logging/ConfigurationLoggingTests.cs b/tests/RayTree.Core.Tests/Logging/ConfigurationLoggingTests.cs new file mode 100644 index 0000000..9b89820 --- /dev/null +++ b/tests/RayTree.Core.Tests/Logging/ConfigurationLoggingTests.cs @@ -0,0 +1,284 @@ +using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.Abstractions; +using RayTree.Core.Plugins.Compression; +using RayTree.Core.Tracking; +using RayTree.Hosting; +using RayTree.Plugins.InMemory; +using RayTree.Plugins.Serializers.Json; + +namespace RayTree.Core.Tests.Logging; + +/// +/// Covers the configuration- and lifecycle-time logging added by the +/// add-tracker-config-logging change. Distinct from which +/// covers runtime-event logging (poll retries, dedup hits, SkipOnFailure drops). +/// +public class ConfigurationLoggingTests +{ + private sealed record LogEntry(string Category, LogLevel Level, string Message, IReadOnlyDictionary Props); + + private sealed class CapturingLoggerFactory : ILoggerFactory + { + public List Entries { get; } = new(); + + public ILogger CreateLogger(string categoryName) => new CapturingLogger(categoryName, Entries); + public void AddProvider(ILoggerProvider provider) { } + public void Dispose() { } + } + + private sealed class CapturingLogger : ILogger + { + private readonly string _category; + private readonly List _entries; + + public CapturingLogger(string category, List entries) + { + _category = category; + _entries = entries; + } + + public IDisposable? BeginScope(TState state) where TState : notnull => null; + public bool IsEnabled(LogLevel logLevel) => true; + + public void Log( + LogLevel logLevel, + EventId eventId, + TState state, + Exception? exception, + Func formatter) + { + var props = new Dictionary(StringComparer.Ordinal); + if (state is IEnumerable> kvps) + foreach (var kvp in kvps) + props[kvp.Key] = kvp.Value; + + _entries.Add(new LogEntry(_category, logLevel, formatter(state, exception), props)); + } + } + + private class SampleEntity + { + public int Id { get; set; } + } + + private static EntityChangeTracker BuildMinimal(ILoggerFactory loggerFactory) + => new ChangeTrackingBuilder(loggerFactory) + .ForEntity(e => + { + e.UseOutbox(new InMemoryOutbox()); + e.UsePublisher(new InMemoryQueue()); + e.UseSerializer(new JsonSerializerPlugin()); + e.UseCompressor(new NoOpCompressorPlugin()); + }) + .Build(); + + // ------------------------------------------------------------------------- + // 5.2 — each Use* call emits exactly one Information entry + // ------------------------------------------------------------------------- + + [Test] + public void GlobalUseCalls_EmitOneInformationLogEach() + { + var lf = new CapturingLoggerFactory(); + + new ChangeTrackingBuilder(lf) + .UseSerializer(_ => new JsonSerializerPlugin()) + .UseCompressor(_ => new NoOpCompressorPlugin()) + .UsePublisherOptions(_ => { }) + .UseSubscriberOptions(_ => { }); + + // Filter to builder category, Information level + var infos = lf.Entries + .Where(e => e.Category.Contains("ChangeTrackingBuilder") && e.Level == LogLevel.Information) + .ToList(); + + Assert.That(infos, Has.Count.EqualTo(4)); + Assert.That(infos.Select(e => e.Props.GetValueOrDefault("Plugin")?.ToString()), + Is.EquivalentTo(new[] { + nameof(JsonSerializerPlugin), + nameof(NoOpCompressorPlugin), + "OutboxPublisherOptions", + "SubscriberOptions" + })); + } + + // ------------------------------------------------------------------------- + // 5.3 — ForEntity logs Information; overrides log Debug + // ------------------------------------------------------------------------- + + [Test] + public void ForEntity_LogsEntityTypeAtInformation_AndOverridesAtDebug() + { + var lf = new CapturingLoggerFactory(); + + new ChangeTrackingBuilder(lf) + .ForEntity(e => + { + e.UseOutbox(new InMemoryOutbox()); + e.UsePublisher(new InMemoryQueue()); + e.UseSerializer(new JsonSerializerPlugin()); + e.UseCompressor(new NoOpCompressorPlugin()); + }); + + var info = lf.Entries.Single(e => + e.Level == LogLevel.Information && + e.Props.GetValueOrDefault("EntityType")?.ToString() == nameof(SampleEntity)); + + Assert.That(info, Is.Not.Null); + + var debugs = lf.Entries + .Where(e => e.Level == LogLevel.Debug && + e.Props.GetValueOrDefault("EntityType")?.ToString() == nameof(SampleEntity)) + .Select(e => e.Props.GetValueOrDefault("Override")?.ToString()) + .ToList(); + + Assert.That(debugs, Is.EquivalentTo(new[] { "Outbox", "Publisher", "Serializer", "Compressor" })); + } + + // ------------------------------------------------------------------------- + // 5.4 — Build emits the summary log with all properties + // ------------------------------------------------------------------------- + + [Test] + public void Build_EmitsSummaryLog_WithAllStructuredProperties() + { + var lf = new CapturingLoggerFactory(); + using var tracker = BuildMinimal(lf); + + var summary = lf.Entries.Single(e => + e.Level == LogLevel.Information && + e.Message.StartsWith("ChangeTracker built")); + + Assert.That(summary.Props.ContainsKey("EntityTypes"), Is.True); + Assert.That(summary.Props.ContainsKey("Plugins"), Is.True); + Assert.That(summary.Props["HasCustomMeter"], Is.EqualTo(false)); + Assert.That(summary.Props["HasCustomDeduplicationStore"], Is.EqualTo(false)); + Assert.That(summary.Props["HasCustomLoggerFactory"], Is.EqualTo(true)); + } + + [Test] + public void Build_SummaryLog_ReportsNone_ForUnregisteredGlobalPlugins() + { + var lf = new CapturingLoggerFactory(); + using var tracker = BuildMinimal(lf); + + var summary = lf.Entries.Single(e => + e.Level == LogLevel.Information && + e.Message.StartsWith("ChangeTracker built")); + + // No global registrations were made (everything per-entity). The {@Plugins} structure + // should report "" for every slot. We assert via the rendered message because + // anonymous-type destructuring is opaque on the props dictionary. + Assert.That(summary.Message, Contains.Substring("")); + } + + // ------------------------------------------------------------------------- + // 5.5 — NullLoggerFactory produces zero log entries + // ------------------------------------------------------------------------- + + [Test] + public void Build_WithNullLoggerFactory_EmitsNoLogs() + { + // NullLogger.IsEnabled returns false, so all our guarded calls are skipped. + using var tracker = new ChangeTrackingBuilder(NullLoggerFactory.Instance) + .ForEntity(e => + { + e.UseOutbox(new InMemoryOutbox()); + e.UsePublisher(new InMemoryQueue()); + e.UseSerializer(new JsonSerializerPlugin()); + e.UseCompressor(new NoOpCompressorPlugin()); + }) + .Build(); + + // No assertion target since NullLogger discards everything — assertion is "does not throw". + Assert.That(tracker, Is.Not.Null); + } + + // ------------------------------------------------------------------------- + // 5.6 — InitializeAsync logs start, sub-steps, completion + // ------------------------------------------------------------------------- + + [Test] + public void InitializeAsync_LogsStartSubStepsAndCompletion_InOrder() + { + var lf = new CapturingLoggerFactory(); + using var tracker = BuildMinimal(lf); + + var trackerLogs = lf.Entries + .Where(e => e.Category.Contains("EntityChangeTracker")) + .ToList(); + + var start = trackerLogs.FindIndex(e => e.Level == LogLevel.Information && e.Message.Contains("started")); + var pubDbg = trackerLogs.FindIndex(e => e.Level == LogLevel.Debug && e.Message.Contains("publisher initialized")); + var consDbg = trackerLogs.FindIndex(e => e.Level == LogLevel.Debug && e.Message.Contains("consumers initialized")); + var complete = trackerLogs.FindIndex(e => e.Level == LogLevel.Information && e.Message.Contains("completed")); + + Assert.That(start, Is.GreaterThanOrEqualTo(0)); + Assert.That(pubDbg, Is.GreaterThan(start)); + Assert.That(consDbg, Is.GreaterThan(pubDbg)); + Assert.That(complete, Is.GreaterThan(consDbg)); + + // Property values + Assert.That(trackerLogs[pubDbg].Props["EntityTypeCount"], Is.EqualTo(1)); + Assert.That(trackerLogs[consDbg].Props["ConsumerCount"], Is.EqualTo(0)); + } + + [Test] + public void InitializeAsync_OnFailure_LogsWarningBeforeRethrow() + { + var lf = new CapturingLoggerFactory(); + + var ex = Assert.Throws(() => + { + using var tracker = new ChangeTrackingBuilder(lf) + .ForEntity(e => + { + e.UseOutbox(new InMemoryOutbox()); + e.UsePublisher(new FailingPublisher()); + e.UseSerializer(new JsonSerializerPlugin()); + e.UseCompressor(new NoOpCompressorPlugin()); + }) + .Build(); + }); + + var aborted = lf.Entries.SingleOrDefault(e => + e.Category.Contains("EntityChangeTracker") && + e.Level == LogLevel.Warning && + e.Message.Contains("aborted")); + + Assert.That(aborted, Is.Not.Null); + } + + private sealed class FailingPublisher : RayTree.Core.Plugins.Publisher.IQueuePublisher + { + public Task InitializeAsync(CancellationToken cancellationToken = default) + => throw new InvalidOperationException("Simulated init failure"); + public Task PublishAsync(RayTree.Core.Models.MessageEnvelope envelope, CancellationToken cancellationToken = default) + => Task.CompletedTask; + } + + // ------------------------------------------------------------------------- + // 5.7 — ChangeTrackingHostedService startup log + // ------------------------------------------------------------------------- + + [Test] + public async Task ChangeTrackingHostedService_StartAsync_EmitsStartingLog_WithConfigurationBound() + { + var lf = new CapturingLoggerFactory(); + using var tracker = BuildMinimal(lf); + + var hostedLogger = lf.CreateLogger(); + var svc = new ChangeTrackingHostedService(tracker, hostedLogger, new ChangeTrackingDiContext(ConfigurationBound: true)); + + await svc.StartAsync(CancellationToken.None); + + var starting = lf.Entries.SingleOrDefault(e => + e.Level == LogLevel.Information && + e.Message.StartsWith("ChangeTracking starting")); + + Assert.That(starting, Is.Not.Null); + Assert.That(starting!.Props["ConfigurationBound"], Is.EqualTo(true)); + + await svc.StopAsync(CancellationToken.None); + } +} From dfa2d80401584b83e8b2be68457cb05d124209df Mon Sep 17 00:00:00 2001 From: bitc0der <59016822+bitc0der@users.noreply.github.com> Date: Fri, 22 May 2026 23:15:52 +0700 Subject: [PATCH 3/8] Fix on review --- src/RayTree.Core/Handling/HandlerDescriptor.cs | 17 +++++++++++++++++ .../Handling/IsolatedHandlerBuilder.cs | 2 +- .../Handling/SharedHandlerBuilder.cs | 2 +- .../Tracking/ChangeTrackingBuilder.cs | 2 -- .../ServiceCollectionExtensions.cs | 3 ++- .../Logging/ConfigurationLoggingTests.cs | 4 ++-- 6 files changed, 23 insertions(+), 7 deletions(-) create mode 100644 src/RayTree.Core/Handling/HandlerDescriptor.cs diff --git a/src/RayTree.Core/Handling/HandlerDescriptor.cs b/src/RayTree.Core/Handling/HandlerDescriptor.cs new file mode 100644 index 0000000..7023944 --- /dev/null +++ b/src/RayTree.Core/Handling/HandlerDescriptor.cs @@ -0,0 +1,17 @@ +namespace RayTree.Core.Handling; + +/// +/// Resolves a human-readable name for a delegate's declaring scope, stripping the +/// compiler-generated closure/display-class names (e.g. <>c__DisplayClass3_0) +/// that lambdas normally surface so log output shows the user's outer type instead. +/// +internal static class HandlerDescriptor +{ + internal static string Describe(Delegate handler) + { + var t = handler.Method.DeclaringType; + while (t is not null && (t.Name.StartsWith("<>", StringComparison.Ordinal) || t.Name.Contains("DisplayClass"))) + t = t.DeclaringType; + return t?.Name ?? ""; + } +} diff --git a/src/RayTree.Core/Handling/IsolatedHandlerBuilder.cs b/src/RayTree.Core/Handling/IsolatedHandlerBuilder.cs index d5e1f65..2fa7ef7 100644 --- a/src/RayTree.Core/Handling/IsolatedHandlerBuilder.cs +++ b/src/RayTree.Core/Handling/IsolatedHandlerBuilder.cs @@ -49,7 +49,7 @@ public IIsolatedHandlerBuilder OnChange(string handlerName, ChangeType if (log.IsEnabled(LogLevel.Debug)) log.LogDebug( "ChangeTracking: entity override applied EntityType={EntityType} Override={Override} Plugin={Plugin}", - EntityTypeName, $"On{changeType}:{handlerName}", handler.Method.DeclaringType?.Name ?? ""); + EntityTypeName, $"On{changeType}:{handlerName}", HandlerDescriptor.Describe(handler)); return this; } diff --git a/src/RayTree.Core/Handling/SharedHandlerBuilder.cs b/src/RayTree.Core/Handling/SharedHandlerBuilder.cs index d66cdd4..40906c0 100644 --- a/src/RayTree.Core/Handling/SharedHandlerBuilder.cs +++ b/src/RayTree.Core/Handling/SharedHandlerBuilder.cs @@ -28,7 +28,7 @@ private void LogHandler(string slot, ChangeHandlerAsync handler) if (_log.IsEnabled(LogLevel.Debug)) _log.LogDebug( "ChangeTracking: entity override applied EntityType={EntityType} Override={Override} Plugin={Plugin}", - EntityTypeName, slot, handler.Method.DeclaringType?.Name ?? ""); + EntityTypeName, slot, HandlerDescriptor.Describe(handler)); } /// diff --git a/src/RayTree.Core/Tracking/ChangeTrackingBuilder.cs b/src/RayTree.Core/Tracking/ChangeTrackingBuilder.cs index a660372..e8e52b1 100644 --- a/src/RayTree.Core/Tracking/ChangeTrackingBuilder.cs +++ b/src/RayTree.Core/Tracking/ChangeTrackingBuilder.cs @@ -21,8 +21,6 @@ public sealed class ChangeTrackingBuilder : IChangeTrackingBuilder private readonly ILogger _log; private RayTreeMeter? _meter; - // Captured plugin-type metadata for the build-summary log. Populated lazily as the - // caller chains Use* registrations; read once in BuildInternal. private string? _globalOutboxType; private string? _globalPublisherType; private string? _globalSerializerType; diff --git a/src/RayTree.Hosting/ServiceCollectionExtensions.cs b/src/RayTree.Hosting/ServiceCollectionExtensions.cs index 8e5924a..89b91da 100644 --- a/src/RayTree.Hosting/ServiceCollectionExtensions.cs +++ b/src/RayTree.Hosting/ServiceCollectionExtensions.cs @@ -1,5 +1,6 @@ using Microsoft.Extensions.Configuration; using Microsoft.Extensions.DependencyInjection; +using Microsoft.Extensions.DependencyInjection.Extensions; using Microsoft.Extensions.Logging; using RayTree.Core.Distribution; using RayTree.Core.Handling; @@ -15,7 +16,7 @@ public static IServiceCollection AddChangeTracking( IConfiguration? configuration = null, Action? configure = null) { - services.AddSingleton(new ChangeTrackingDiContext(ConfigurationBound: configuration is not null)); + services.TryAddSingleton(new ChangeTrackingDiContext(ConfigurationBound: configuration is not null)); services.AddSingleton(); diff --git a/tests/RayTree.Core.Tests/Logging/ConfigurationLoggingTests.cs b/tests/RayTree.Core.Tests/Logging/ConfigurationLoggingTests.cs index 9b89820..2769a15 100644 --- a/tests/RayTree.Core.Tests/Logging/ConfigurationLoggingTests.cs +++ b/tests/RayTree.Core.Tests/Logging/ConfigurationLoggingTests.cs @@ -234,7 +234,7 @@ public void InitializeAsync_OnFailure_LogsWarningBeforeRethrow() .ForEntity(e => { e.UseOutbox(new InMemoryOutbox()); - e.UsePublisher(new FailingPublisher()); + e.UsePublisher(new InitFailingPublisher()); e.UseSerializer(new JsonSerializerPlugin()); e.UseCompressor(new NoOpCompressorPlugin()); }) @@ -249,7 +249,7 @@ public void InitializeAsync_OnFailure_LogsWarningBeforeRethrow() Assert.That(aborted, Is.Not.Null); } - private sealed class FailingPublisher : RayTree.Core.Plugins.Publisher.IQueuePublisher + private sealed class InitFailingPublisher : RayTree.Core.Plugins.Publisher.IQueuePublisher { public Task InitializeAsync(CancellationToken cancellationToken = default) => throw new InvalidOperationException("Simulated init failure"); From e1d8c12bd27ad05d5562df55e22a15600dc86d65 Mon Sep 17 00:00:00 2001 From: bitc0der <59016822+bitc0der@users.noreply.github.com> Date: Sat, 23 May 2026 14:54:04 +0700 Subject: [PATCH 4/8] Pass logger factory --- .../Handling/IsolatedHandlerBuilder.cs | 27 ++++++++++++------- .../Handling/SharedHandlerBuilder.cs | 6 ++--- .../Tracking/ChangeTrackingBuilder.cs | 2 +- src/RayTree.Core/Tracking/EntityBuilder.cs | 12 +++++---- 4 files changed, 29 insertions(+), 18 deletions(-) diff --git a/src/RayTree.Core/Handling/IsolatedHandlerBuilder.cs b/src/RayTree.Core/Handling/IsolatedHandlerBuilder.cs index 2fa7ef7..f122897 100644 --- a/src/RayTree.Core/Handling/IsolatedHandlerBuilder.cs +++ b/src/RayTree.Core/Handling/IsolatedHandlerBuilder.cs @@ -10,16 +10,25 @@ namespace RayTree.Core.Handling; /// (handlerName, changeType, handler, options) tuples and validates the registration /// set at time. /// -internal sealed class IsolatedHandlerBuilder( - EntitySubscriberBuilder subBuilder, - Func factory, - ILogger log) - : IIsolatedHandlerBuilder +internal sealed class IsolatedHandlerBuilder : IIsolatedHandlerBuilder where TEntity : class { + private readonly EntitySubscriberBuilder _subBuilder; + private readonly Func _factory; + private readonly ILogger> _log; private readonly List<(string HandlerName, ChangeType ChangeType, ChangeHandlerAsync Handler, SubscriberOptions? Options)> _entries = new(); private static readonly string EntityTypeName = typeof(TEntity).Name; + internal IsolatedHandlerBuilder( + EntitySubscriberBuilder subBuilder, + Func factory, + ILoggerFactory loggerFactory) + { + _subBuilder = subBuilder; + _factory = factory; + _log = loggerFactory.CreateLogger>(); + } + /// public IIsolatedHandlerBuilder OnInsert(string handlerName, ChangeHandlerAsync handler, SubscriberOptions? options = null) @@ -46,8 +55,8 @@ public IIsolatedHandlerBuilder OnChange(string handlerName, ChangeType ArgumentNullException.ThrowIfNull(handler); _entries.Add((handlerName, changeType, handler, options)); - if (log.IsEnabled(LogLevel.Debug)) - log.LogDebug( + if (_log.IsEnabled(LogLevel.Debug)) + _log.LogDebug( "ChangeTracking: entity override applied EntityType={EntityType} Override={Override} Plugin={Plugin}", EntityTypeName, $"On{changeType}:{handlerName}", HandlerDescriptor.Describe(handler)); return this; @@ -77,7 +86,7 @@ internal void Apply(ChangeSubscriber subscriber) foreach (var name in distinctNames) { - var consumer = factory(name); + var consumer = _factory(name); if (consumer is null) throw new InvalidOperationException( $"Consumer factory returned null for handler name '{name}' " + @@ -99,7 +108,7 @@ internal void Apply(ChangeSubscriber subscriber) } // --- Register entity metadata (serializer / compressor / options, no queue) --- - subBuilder.ApplyMetadataOnly(subscriber); + _subBuilder.ApplyMetadataOnly(subscriber); // --- Register per-name consumers --- foreach (var (name, consumer) in consumers) diff --git a/src/RayTree.Core/Handling/SharedHandlerBuilder.cs b/src/RayTree.Core/Handling/SharedHandlerBuilder.cs index 40906c0..880dbf9 100644 --- a/src/RayTree.Core/Handling/SharedHandlerBuilder.cs +++ b/src/RayTree.Core/Handling/SharedHandlerBuilder.cs @@ -14,13 +14,13 @@ internal sealed class SharedHandlerBuilder : ISharedHandlerBuilder _subBuilder; - private readonly ILogger _log; + private readonly ILogger> _log; private static readonly string EntityTypeName = typeof(TEntity).Name; - internal SharedHandlerBuilder(EntitySubscriberBuilder subBuilder, ILogger log) + internal SharedHandlerBuilder(EntitySubscriberBuilder subBuilder, ILoggerFactory loggerFactory) { _subBuilder = subBuilder ?? throw new ArgumentNullException(nameof(subBuilder)); - _log = log; + _log = loggerFactory.CreateLogger>(); } private void LogHandler(string slot, ChangeHandlerAsync handler) diff --git a/src/RayTree.Core/Tracking/ChangeTrackingBuilder.cs b/src/RayTree.Core/Tracking/ChangeTrackingBuilder.cs index e8e52b1..fd2a321 100644 --- a/src/RayTree.Core/Tracking/ChangeTrackingBuilder.cs +++ b/src/RayTree.Core/Tracking/ChangeTrackingBuilder.cs @@ -127,7 +127,7 @@ public IChangeTrackingBuilder ForEntity(Action> if (_log.IsEnabled(LogLevel.Information)) _log.LogInformation("ChangeTracking: configuring entity {EntityType}", typeof(TEntity).Name); - var entityBuilder = new EntityBuilder(_publisherBuilder, _subscriberBuilder, _log); + var entityBuilder = new EntityBuilder(_publisherBuilder, _subscriberBuilder, _loggerFactory); configure(entityBuilder); entityBuilder.RegisterSubscriberApplicator(); return this; diff --git a/src/RayTree.Core/Tracking/EntityBuilder.cs b/src/RayTree.Core/Tracking/EntityBuilder.cs index a66e8c8..7d817b9 100644 --- a/src/RayTree.Core/Tracking/EntityBuilder.cs +++ b/src/RayTree.Core/Tracking/EntityBuilder.cs @@ -24,7 +24,8 @@ internal sealed class EntityBuilder : IEntityBuilder private readonly ChangeSubscriberBuilder _subscriberBuilder; private readonly EntityPublisherBuilder _pubBuilder; private readonly EntitySubscriberBuilder _subBuilder; - private readonly ILogger _log; + private readonly ILoggerFactory _loggerFactory; + private readonly ILogger> _log; private static readonly string EntityTypeName = typeof(TEntity).Name; // Exactly one of these is non-null once a consumer-binding method has been called. @@ -34,12 +35,13 @@ internal sealed class EntityBuilder : IEntityBuilder internal EntityBuilder( ChangePublisherBuilder publisherBuilder, ChangeSubscriberBuilder subscriberBuilder, - ILogger log) + ILoggerFactory loggerFactory) { _subscriberBuilder = subscriberBuilder; _pubBuilder = new EntityPublisherBuilder(publisherBuilder); _subBuilder = new EntitySubscriberBuilder(subscriberBuilder); - _log = log; + _loggerFactory = loggerFactory; + _log = loggerFactory.CreateLogger>(); } private void LogOverride(string slot, string pluginName) @@ -117,7 +119,7 @@ public ISharedHandlerBuilder UseConsumer(IQueueConsumer consumer) ArgumentNullException.ThrowIfNull(consumer); _subBuilder.UseConsumer(consumer); LogOverride("Consumer", consumer.GetType().Name); - _sharedBuilder = new SharedHandlerBuilder(_subBuilder, _log); + _sharedBuilder = new SharedHandlerBuilder(_subBuilder, _loggerFactory); return _sharedBuilder; } @@ -125,7 +127,7 @@ public IIsolatedHandlerBuilder UseConsumerFactory(Func(_subBuilder, factory, _log); + _isolatedBuilder = new IsolatedHandlerBuilder(_subBuilder, factory, _loggerFactory); return _isolatedBuilder; } From ebc2427ac2e1cbf9846064d62ddc3840ca5be702 Mon Sep 17 00:00:00 2001 From: bitc0der <59016822+bitc0der@users.noreply.github.com> Date: Sat, 23 May 2026 14:58:53 +0700 Subject: [PATCH 5/8] Fix on review --- .../Handling/IsolatedHandlerBuilder.cs | 8 +-- .../Handling/SharedHandlerBuilder.cs | 8 +-- .../Tracking/ChangeTrackingBuilder.cs | 64 +++++++++---------- src/RayTree.Core/Tracking/EntityBuilder.cs | 16 ++--- .../Tracking/EntityChangeTracker.cs | 24 +++---- .../Logging/ConfigurationLoggingTests.cs | 37 ++++++++--- 6 files changed, 88 insertions(+), 69 deletions(-) diff --git a/src/RayTree.Core/Handling/IsolatedHandlerBuilder.cs b/src/RayTree.Core/Handling/IsolatedHandlerBuilder.cs index f122897..b258cca 100644 --- a/src/RayTree.Core/Handling/IsolatedHandlerBuilder.cs +++ b/src/RayTree.Core/Handling/IsolatedHandlerBuilder.cs @@ -15,7 +15,7 @@ internal sealed class IsolatedHandlerBuilder : IIsolatedHandlerBuilder< { private readonly EntitySubscriberBuilder _subBuilder; private readonly Func _factory; - private readonly ILogger> _log; + private readonly ILogger> _logger; private readonly List<(string HandlerName, ChangeType ChangeType, ChangeHandlerAsync Handler, SubscriberOptions? Options)> _entries = new(); private static readonly string EntityTypeName = typeof(TEntity).Name; @@ -26,7 +26,7 @@ internal IsolatedHandlerBuilder( { _subBuilder = subBuilder; _factory = factory; - _log = loggerFactory.CreateLogger>(); + _logger = loggerFactory.CreateLogger>(); } /// @@ -55,8 +55,8 @@ public IIsolatedHandlerBuilder OnChange(string handlerName, ChangeType ArgumentNullException.ThrowIfNull(handler); _entries.Add((handlerName, changeType, handler, options)); - if (_log.IsEnabled(LogLevel.Debug)) - _log.LogDebug( + if (_logger.IsEnabled(LogLevel.Debug)) + _logger.LogDebug( "ChangeTracking: entity override applied EntityType={EntityType} Override={Override} Plugin={Plugin}", EntityTypeName, $"On{changeType}:{handlerName}", HandlerDescriptor.Describe(handler)); return this; diff --git a/src/RayTree.Core/Handling/SharedHandlerBuilder.cs b/src/RayTree.Core/Handling/SharedHandlerBuilder.cs index 880dbf9..019f062 100644 --- a/src/RayTree.Core/Handling/SharedHandlerBuilder.cs +++ b/src/RayTree.Core/Handling/SharedHandlerBuilder.cs @@ -14,19 +14,19 @@ internal sealed class SharedHandlerBuilder : ISharedHandlerBuilder _subBuilder; - private readonly ILogger> _log; + private readonly ILogger> _logger; private static readonly string EntityTypeName = typeof(TEntity).Name; internal SharedHandlerBuilder(EntitySubscriberBuilder subBuilder, ILoggerFactory loggerFactory) { _subBuilder = subBuilder ?? throw new ArgumentNullException(nameof(subBuilder)); - _log = loggerFactory.CreateLogger>(); + _logger = loggerFactory.CreateLogger>(); } private void LogHandler(string slot, ChangeHandlerAsync handler) { - if (_log.IsEnabled(LogLevel.Debug)) - _log.LogDebug( + if (_logger.IsEnabled(LogLevel.Debug)) + _logger.LogDebug( "ChangeTracking: entity override applied EntityType={EntityType} Override={Override} Plugin={Plugin}", EntityTypeName, slot, HandlerDescriptor.Describe(handler)); } diff --git a/src/RayTree.Core/Tracking/ChangeTrackingBuilder.cs b/src/RayTree.Core/Tracking/ChangeTrackingBuilder.cs index fd2a321..196f7bf 100644 --- a/src/RayTree.Core/Tracking/ChangeTrackingBuilder.cs +++ b/src/RayTree.Core/Tracking/ChangeTrackingBuilder.cs @@ -16,9 +16,9 @@ public sealed class ChangeTrackingBuilder : IChangeTrackingBuilder { private readonly ChangePublisherBuilder _publisherBuilder = new(); private readonly ChangeSubscriberBuilder _subscriberBuilder = new(); - private readonly ILoggerFactory _loggerFactory; + private readonly ILoggerFactory _loggergerFactory; private readonly bool _hasCustomLoggerFactory; - private readonly ILogger _log; + private readonly ILogger _logger; private RayTreeMeter? _meter; private string? _globalOutboxType; @@ -32,16 +32,16 @@ public sealed class ChangeTrackingBuilder : IChangeTrackingBuilder internal ChangeTrackingBuilder(ILoggerFactory? loggerFactory = null) { _hasCustomLoggerFactory = loggerFactory is not null; - _loggerFactory = loggerFactory ?? NullLoggerFactory.Instance; - _log = _loggerFactory.CreateLogger(); + _loggergerFactory = loggerFactory ?? NullLoggerFactory.Instance; + _logger = _loggergerFactory.CreateLogger(); } public IChangeTrackingBuilder UseOutbox(Func factory) where T : IOutbox { _publisherBuilder.UseOutbox(factory); _globalOutboxType = typeof(T).Name; - if (_log.IsEnabled(LogLevel.Information)) - _log.LogInformation("ChangeTracking: registered global outbox {Plugin}", typeof(T).Name); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("ChangeTracking: registered global outbox {Plugin}", typeof(T).Name); return this; } @@ -49,8 +49,8 @@ public IChangeTrackingBuilder UsePublisher(Func factor { _publisherBuilder.UsePublisher(factory); _globalPublisherType = typeof(T).Name; - if (_log.IsEnabled(LogLevel.Information)) - _log.LogInformation("ChangeTracking: registered global publisher {Plugin}", typeof(T).Name); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("ChangeTracking: registered global publisher {Plugin}", typeof(T).Name); return this; } @@ -60,8 +60,8 @@ public IChangeTrackingBuilder UseSerializer(Func fac _publisherBuilder.UseSerializer(factory); _subscriberBuilder.UseSerializer(factory(typeof(object))); _globalSerializerType = typeof(T).Name; - if (_log.IsEnabled(LogLevel.Information)) - _log.LogInformation("ChangeTracking: registered global serializer {Plugin}", typeof(T).Name); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("ChangeTracking: registered global serializer {Plugin}", typeof(T).Name); return this; } @@ -71,8 +71,8 @@ public IChangeTrackingBuilder UseCompressor(Func fac _publisherBuilder.UseCompressor(factory); _subscriberBuilder.UseCompressor(factory(typeof(object))); _globalCompressorType = typeof(T).Name; - if (_log.IsEnabled(LogLevel.Information)) - _log.LogInformation("ChangeTracking: registered global compressor {Plugin}", typeof(T).Name); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("ChangeTracking: registered global compressor {Plugin}", typeof(T).Name); return this; } @@ -80,24 +80,24 @@ public IChangeTrackingBuilder UseRepository(Func factory) { _publisherBuilder.UseRepository(factory); _globalRepositoryType = typeof(T).Name; - if (_log.IsEnabled(LogLevel.Information)) - _log.LogInformation("ChangeTracking: registered global repository {Plugin}", typeof(T).Name); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("ChangeTracking: registered global repository {Plugin}", typeof(T).Name); return this; } public IChangeTrackingBuilder UsePublisherOptions(Action configure) { _publisherBuilder.UseOptions(configure); - if (_log.IsEnabled(LogLevel.Information)) - _log.LogInformation("ChangeTracking: configured {Plugin}", nameof(OutboxPublisherOptions)); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("ChangeTracking: configured {Plugin}", nameof(OutboxPublisherOptions)); return this; } public IChangeTrackingBuilder UseSubscriberOptions(Action configure) { _subscriberBuilder.UseOptions(configure); - if (_log.IsEnabled(LogLevel.Information)) - _log.LogInformation("ChangeTracking: configured {Plugin}", nameof(SubscriberOptions)); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("ChangeTracking: configured {Plugin}", nameof(SubscriberOptions)); return this; } @@ -105,8 +105,8 @@ public IChangeTrackingBuilder UseDeduplicationStore(IDeduplicationStore store) { _subscriberBuilder.UseDeduplicationStore(store); _hasCustomDedupStore = true; - if (_log.IsEnabled(LogLevel.Information)) - _log.LogInformation("ChangeTracking: registered deduplication store {Plugin}", store.GetType().Name); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("ChangeTracking: registered deduplication store {Plugin}", store.GetType().Name); return this; } @@ -114,8 +114,8 @@ public IChangeTrackingBuilder UseMeter(RayTreeMeter meter) { ArgumentNullException.ThrowIfNull(meter); _meter = meter; - if (_log.IsEnabled(LogLevel.Information)) - _log.LogInformation("ChangeTracking: registered meter {Plugin}", nameof(RayTreeMeter)); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("ChangeTracking: registered meter {Plugin}", nameof(RayTreeMeter)); return this; } @@ -124,10 +124,10 @@ public IChangeTrackingBuilder ForEntity(Action> { ArgumentNullException.ThrowIfNull(configure); _entityTypes.Add(typeof(TEntity)); - if (_log.IsEnabled(LogLevel.Information)) - _log.LogInformation("ChangeTracking: configuring entity {EntityType}", typeof(TEntity).Name); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("ChangeTracking: configuring entity {EntityType}", typeof(TEntity).Name); - var entityBuilder = new EntityBuilder(_publisherBuilder, _subscriberBuilder, _loggerFactory); + var entityBuilder = new EntityBuilder(_publisherBuilder, _subscriberBuilder, _loggergerFactory); configure(entityBuilder); entityBuilder.RegisterSubscriberApplicator(); return this; @@ -152,11 +152,11 @@ private EntityChangeTracker BuildInternal() var meter = _meter ?? new RayTreeMeter(); var ownsMeter = _meter == null; // builder-created meter is disposed by the tracker - if (ownsMeter && _log.IsEnabled(LogLevel.Debug)) - _log.LogDebug("ChangeTracking: no meter supplied; created default RayTreeMeter (owned by tracker)"); + if (ownsMeter && _logger.IsEnabled(LogLevel.Debug)) + _logger.LogDebug("ChangeTracking: no meter supplied; created default RayTreeMeter (owned by tracker)"); - _publisherBuilder.UseLoggerFactory(_loggerFactory); // always non-null — resolved once here - _subscriberBuilder.UseLoggerFactory(_loggerFactory); + _publisherBuilder.UseLoggerFactory(_loggergerFactory); // always non-null — resolved once here + _subscriberBuilder.UseLoggerFactory(_loggergerFactory); _publisherBuilder.UseMeter(meter); _subscriberBuilder.UseMeter(meter); @@ -168,13 +168,13 @@ private EntityChangeTracker BuildInternal() meter.RegisterPendingGauge(() => publisher.GetOutboxes().Select(kvp => (kvp.Key, kvp.Value))); - if (_log.IsEnabled(LogLevel.Information)) + if (_logger.IsEnabled(LogLevel.Information)) { var entityTypeNames = _entityTypes.Select(t => t.Name).ToArray(); var plugins = $"Outbox={_globalOutboxType ?? ""} Publisher={_globalPublisherType ?? ""} " + $"Serializer={_globalSerializerType ?? ""} Compressor={_globalCompressorType ?? ""} " + $"Repository={_globalRepositoryType ?? ""}"; - _log.LogInformation( + _logger.LogInformation( "ChangeTracker built. EntityTypes={EntityTypes} Plugins={Plugins} HasCustomMeter={HasCustomMeter} HasCustomDeduplicationStore={HasCustomDeduplicationStore} HasCustomLoggerFactory={HasCustomLoggerFactory}", entityTypeNames, plugins, @@ -183,6 +183,6 @@ private EntityChangeTracker BuildInternal() _hasCustomLoggerFactory); } - return new EntityChangeTracker(publisher, subscriber, meter, ownsMeter: ownsMeter, loggerFactory: _loggerFactory); + return new EntityChangeTracker(publisher, subscriber, meter, ownsMeter: ownsMeter, loggerFactory: _loggergerFactory); } } diff --git a/src/RayTree.Core/Tracking/EntityBuilder.cs b/src/RayTree.Core/Tracking/EntityBuilder.cs index 7d817b9..e7997b2 100644 --- a/src/RayTree.Core/Tracking/EntityBuilder.cs +++ b/src/RayTree.Core/Tracking/EntityBuilder.cs @@ -24,8 +24,8 @@ internal sealed class EntityBuilder : IEntityBuilder private readonly ChangeSubscriberBuilder _subscriberBuilder; private readonly EntityPublisherBuilder _pubBuilder; private readonly EntitySubscriberBuilder _subBuilder; - private readonly ILoggerFactory _loggerFactory; - private readonly ILogger> _log; + private readonly ILoggerFactory _loggergerFactory; + private readonly ILogger> _logger; private static readonly string EntityTypeName = typeof(TEntity).Name; // Exactly one of these is non-null once a consumer-binding method has been called. @@ -40,14 +40,14 @@ internal EntityBuilder( _subscriberBuilder = subscriberBuilder; _pubBuilder = new EntityPublisherBuilder(publisherBuilder); _subBuilder = new EntitySubscriberBuilder(subscriberBuilder); - _loggerFactory = loggerFactory; - _log = loggerFactory.CreateLogger>(); + _loggergerFactory = loggerFactory; + _logger = loggerFactory.CreateLogger>(); } private void LogOverride(string slot, string pluginName) { - if (_log.IsEnabled(LogLevel.Debug)) - _log.LogDebug( + if (_logger.IsEnabled(LogLevel.Debug)) + _logger.LogDebug( "ChangeTracking: entity override applied EntityType={EntityType} Override={Override} Plugin={Plugin}", EntityTypeName, slot, pluginName); } @@ -119,7 +119,7 @@ public ISharedHandlerBuilder UseConsumer(IQueueConsumer consumer) ArgumentNullException.ThrowIfNull(consumer); _subBuilder.UseConsumer(consumer); LogOverride("Consumer", consumer.GetType().Name); - _sharedBuilder = new SharedHandlerBuilder(_subBuilder, _loggerFactory); + _sharedBuilder = new SharedHandlerBuilder(_subBuilder, _loggergerFactory); return _sharedBuilder; } @@ -127,7 +127,7 @@ public IIsolatedHandlerBuilder UseConsumerFactory(Func(_subBuilder, factory, _loggerFactory); + _isolatedBuilder = new IsolatedHandlerBuilder(_subBuilder, factory, _loggergerFactory); return _isolatedBuilder; } diff --git a/src/RayTree.Core/Tracking/EntityChangeTracker.cs b/src/RayTree.Core/Tracking/EntityChangeTracker.cs index 1503232..335bbe0 100644 --- a/src/RayTree.Core/Tracking/EntityChangeTracker.cs +++ b/src/RayTree.Core/Tracking/EntityChangeTracker.cs @@ -18,7 +18,7 @@ public sealed class EntityChangeTracker : IEntityChangeTracker private readonly ChangeSubscriber? _subscriber; private readonly RayTreeMeter _meter; private readonly bool _ownsMeter; - private readonly ILogger _log; + private readonly ILogger _logger; private bool _disposed; internal ChangePublisher Publisher => _publisher; @@ -47,20 +47,20 @@ internal EntityChangeTracker( _subscriber = subscriber; _meter = meter ?? publisher.Meter; _ownsMeter = ownsMeter; - _log = (loggerFactory ?? NullLoggerFactory.Instance).CreateLogger(); + _logger = (loggerFactory ?? NullLoggerFactory.Instance).CreateLogger(); } internal async Task InitializeAsync(CancellationToken cancellationToken = default) { - if (_log.IsEnabled(LogLevel.Information)) - _log.LogInformation("ChangeTracking: tracker initialization started"); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("ChangeTracking: tracker initialization started"); try { await _publisher.InitializeAsync(cancellationToken); - if (_log.IsEnabled(LogLevel.Debug)) - _log.LogDebug( + if (_logger.IsEnabled(LogLevel.Debug)) + _logger.LogDebug( "ChangeTracking: publisher initialized EntityTypeCount={EntityTypeCount}", _publisher.GetOutboxes().Count); @@ -68,19 +68,19 @@ internal async Task InitializeAsync(CancellationToken cancellationToken = defaul { await _subscriber.InitializeAsync(cancellationToken); - if (_log.IsEnabled(LogLevel.Debug)) - _log.LogDebug( + if (_logger.IsEnabled(LogLevel.Debug)) + _logger.LogDebug( "ChangeTracking: consumers initialized ConsumerCount={ConsumerCount}", _subscriber.ConsumerCount); } - if (_log.IsEnabled(LogLevel.Information)) - _log.LogInformation("ChangeTracking: tracker initialization completed"); + if (_logger.IsEnabled(LogLevel.Information)) + _logger.LogInformation("ChangeTracking: tracker initialization completed"); } catch { - if (_log.IsEnabled(LogLevel.Warning)) - _log.LogWarning("ChangeTracking: tracker initialization aborted"); + if (_logger.IsEnabled(LogLevel.Warning)) + _logger.LogWarning("ChangeTracking: tracker initialization aborted"); throw; } } diff --git a/tests/RayTree.Core.Tests/Logging/ConfigurationLoggingTests.cs b/tests/RayTree.Core.Tests/Logging/ConfigurationLoggingTests.cs index 2769a15..14020ed 100644 --- a/tests/RayTree.Core.Tests/Logging/ConfigurationLoggingTests.cs +++ b/tests/RayTree.Core.Tests/Logging/ConfigurationLoggingTests.cs @@ -79,15 +79,17 @@ private static EntityChangeTracker BuildMinimal(ILoggerFactory loggerFactory) [Test] public void GlobalUseCalls_EmitOneInformationLogEach() { + // Arrange var lf = new CapturingLoggerFactory(); + // Act new ChangeTrackingBuilder(lf) .UseSerializer(_ => new JsonSerializerPlugin()) .UseCompressor(_ => new NoOpCompressorPlugin()) .UsePublisherOptions(_ => { }) .UseSubscriberOptions(_ => { }); - // Filter to builder category, Information level + // Assert var infos = lf.Entries .Where(e => e.Category.Contains("ChangeTrackingBuilder") && e.Level == LogLevel.Information) .ToList(); @@ -109,8 +111,10 @@ public void GlobalUseCalls_EmitOneInformationLogEach() [Test] public void ForEntity_LogsEntityTypeAtInformation_AndOverridesAtDebug() { + // Arrange var lf = new CapturingLoggerFactory(); + // Act new ChangeTrackingBuilder(lf) .ForEntity(e => { @@ -120,6 +124,7 @@ public void ForEntity_LogsEntityTypeAtInformation_AndOverridesAtDebug() e.UseCompressor(new NoOpCompressorPlugin()); }); + // Assert var info = lf.Entries.Single(e => e.Level == LogLevel.Information && e.Props.GetValueOrDefault("EntityType")?.ToString() == nameof(SampleEntity)); @@ -142,9 +147,13 @@ public void ForEntity_LogsEntityTypeAtInformation_AndOverridesAtDebug() [Test] public void Build_EmitsSummaryLog_WithAllStructuredProperties() { + // Arrange var lf = new CapturingLoggerFactory(); + + // Act using var tracker = BuildMinimal(lf); + // Assert var summary = lf.Entries.Single(e => e.Level == LogLevel.Information && e.Message.StartsWith("ChangeTracker built")); @@ -159,16 +168,18 @@ public void Build_EmitsSummaryLog_WithAllStructuredProperties() [Test] public void Build_SummaryLog_ReportsNone_ForUnregisteredGlobalPlugins() { + // Arrange var lf = new CapturingLoggerFactory(); + + // Act using var tracker = BuildMinimal(lf); + // Assert — no global registrations were made (everything per-entity), so every plugin + // slot in the summary log must read "". var summary = lf.Entries.Single(e => e.Level == LogLevel.Information && e.Message.StartsWith("ChangeTracker built")); - // No global registrations were made (everything per-entity). The {@Plugins} structure - // should report "" for every slot. We assert via the rendered message because - // anonymous-type destructuring is opaque on the props dictionary. Assert.That(summary.Message, Contains.Substring("")); } @@ -179,7 +190,7 @@ public void Build_SummaryLog_ReportsNone_ForUnregisteredGlobalPlugins() [Test] public void Build_WithNullLoggerFactory_EmitsNoLogs() { - // NullLogger.IsEnabled returns false, so all our guarded calls are skipped. + // Arrange & Act — NullLogger.IsEnabled returns false, so all guarded calls are skipped. using var tracker = new ChangeTrackingBuilder(NullLoggerFactory.Instance) .ForEntity(e => { @@ -190,7 +201,7 @@ public void Build_WithNullLoggerFactory_EmitsNoLogs() }) .Build(); - // No assertion target since NullLogger discards everything — assertion is "does not throw". + // Assert — NullLogger discards everything; success is "does not throw". Assert.That(tracker, Is.Not.Null); } @@ -201,9 +212,13 @@ public void Build_WithNullLoggerFactory_EmitsNoLogs() [Test] public void InitializeAsync_LogsStartSubStepsAndCompletion_InOrder() { + // Arrange var lf = new CapturingLoggerFactory(); + + // Act using var tracker = BuildMinimal(lf); + // Assert var trackerLogs = lf.Entries .Where(e => e.Category.Contains("EntityChangeTracker")) .ToList(); @@ -218,7 +233,6 @@ public void InitializeAsync_LogsStartSubStepsAndCompletion_InOrder() Assert.That(consDbg, Is.GreaterThan(pubDbg)); Assert.That(complete, Is.GreaterThan(consDbg)); - // Property values Assert.That(trackerLogs[pubDbg].Props["EntityTypeCount"], Is.EqualTo(1)); Assert.That(trackerLogs[consDbg].Props["ConsumerCount"], Is.EqualTo(0)); } @@ -226,9 +240,11 @@ public void InitializeAsync_LogsStartSubStepsAndCompletion_InOrder() [Test] public void InitializeAsync_OnFailure_LogsWarningBeforeRethrow() { + // Arrange var lf = new CapturingLoggerFactory(); - var ex = Assert.Throws(() => + // Act + Assert.Throws(() => { using var tracker = new ChangeTrackingBuilder(lf) .ForEntity(e => @@ -241,6 +257,7 @@ public void InitializeAsync_OnFailure_LogsWarningBeforeRethrow() .Build(); }); + // Assert var aborted = lf.Entries.SingleOrDefault(e => e.Category.Contains("EntityChangeTracker") && e.Level == LogLevel.Warning && @@ -264,14 +281,16 @@ public Task PublishAsync(RayTree.Core.Models.MessageEnvelope envelope, Cancellat [Test] public async Task ChangeTrackingHostedService_StartAsync_EmitsStartingLog_WithConfigurationBound() { + // Arrange var lf = new CapturingLoggerFactory(); using var tracker = BuildMinimal(lf); - var hostedLogger = lf.CreateLogger(); var svc = new ChangeTrackingHostedService(tracker, hostedLogger, new ChangeTrackingDiContext(ConfigurationBound: true)); + // Act await svc.StartAsync(CancellationToken.None); + // Assert var starting = lf.Entries.SingleOrDefault(e => e.Level == LogLevel.Information && e.Message.StartsWith("ChangeTracking starting")); From 3733abb6631e9b528c8b30baa88782cadbdd8c50 Mon Sep 17 00:00:00 2001 From: bitc0der <59016822+bitc0der@users.noreply.github.com> Date: Sat, 23 May 2026 15:06:51 +0700 Subject: [PATCH 6/8] Fix on review --- .../Handling/HandlerDescriptor.cs | 4 +- .../Tracking/ChangeTrackingBuilder.cs | 37 ++++++++++++++----- src/RayTree.Core/Tracking/EntityBuilder.cs | 8 ++-- .../Tracking/EntityChangeTracker.cs | 3 ++ .../ChangeTrackingHostedService.cs | 2 +- .../Logging/ConfigurationLoggingTests.cs | 7 +++- 6 files changed, 44 insertions(+), 17 deletions(-) diff --git a/src/RayTree.Core/Handling/HandlerDescriptor.cs b/src/RayTree.Core/Handling/HandlerDescriptor.cs index 7023944..3ca0b9a 100644 --- a/src/RayTree.Core/Handling/HandlerDescriptor.cs +++ b/src/RayTree.Core/Handling/HandlerDescriptor.cs @@ -10,8 +10,10 @@ internal static class HandlerDescriptor internal static string Describe(Delegate handler) { var t = handler.Method.DeclaringType; - while (t is not null && (t.Name.StartsWith("<>", StringComparison.Ordinal) || t.Name.Contains("DisplayClass"))) + while (t is not null && (t.Name.StartsWith("<>", StringComparison.Ordinal) || t.Name.Contains("DisplayClass", StringComparison.Ordinal))) + { t = t.DeclaringType; + } return t?.Name ?? ""; } } diff --git a/src/RayTree.Core/Tracking/ChangeTrackingBuilder.cs b/src/RayTree.Core/Tracking/ChangeTrackingBuilder.cs index 196f7bf..0210569 100644 --- a/src/RayTree.Core/Tracking/ChangeTrackingBuilder.cs +++ b/src/RayTree.Core/Tracking/ChangeTrackingBuilder.cs @@ -16,7 +16,7 @@ public sealed class ChangeTrackingBuilder : IChangeTrackingBuilder { private readonly ChangePublisherBuilder _publisherBuilder = new(); private readonly ChangeSubscriberBuilder _subscriberBuilder = new(); - private readonly ILoggerFactory _loggergerFactory; + private readonly ILoggerFactory _loggerFactory; private readonly bool _hasCustomLoggerFactory; private readonly ILogger _logger; private RayTreeMeter? _meter; @@ -32,8 +32,8 @@ public sealed class ChangeTrackingBuilder : IChangeTrackingBuilder internal ChangeTrackingBuilder(ILoggerFactory? loggerFactory = null) { _hasCustomLoggerFactory = loggerFactory is not null; - _loggergerFactory = loggerFactory ?? NullLoggerFactory.Instance; - _logger = _loggergerFactory.CreateLogger(); + _loggerFactory = loggerFactory ?? NullLoggerFactory.Instance; + _logger = _loggerFactory.CreateLogger(); } public IChangeTrackingBuilder UseOutbox(Func factory) where T : IOutbox @@ -127,7 +127,7 @@ public IChangeTrackingBuilder ForEntity(Action> if (_logger.IsEnabled(LogLevel.Information)) _logger.LogInformation("ChangeTracking: configuring entity {EntityType}", typeof(TEntity).Name); - var entityBuilder = new EntityBuilder(_publisherBuilder, _subscriberBuilder, _loggergerFactory); + var entityBuilder = new EntityBuilder(_publisherBuilder, _subscriberBuilder, _loggerFactory); configure(entityBuilder); entityBuilder.RegisterSubscriberApplicator(); return this; @@ -136,14 +136,33 @@ public IChangeTrackingBuilder ForEntity(Action> public EntityChangeTracker Build() { var tracker = BuildInternal(); - tracker.InitializeAsync().GetAwaiter().GetResult(); + try + { + tracker.InitializeAsync().GetAwaiter().GetResult(); + } + catch + { + // Dispose the partially-initialized tracker (owned meter, background services + // started by the publisher, dedup store, etc.) — the caller never receives a + // reference, so without this it would leak. + tracker.Dispose(); + throw; + } return tracker; } public async Task BuildAsync(CancellationToken cancellationToken = default) { var tracker = BuildInternal(); - await tracker.InitializeAsync(cancellationToken); + try + { + await tracker.InitializeAsync(cancellationToken); + } + catch + { + tracker.Dispose(); + throw; + } return tracker; } @@ -155,8 +174,8 @@ private EntityChangeTracker BuildInternal() if (ownsMeter && _logger.IsEnabled(LogLevel.Debug)) _logger.LogDebug("ChangeTracking: no meter supplied; created default RayTreeMeter (owned by tracker)"); - _publisherBuilder.UseLoggerFactory(_loggergerFactory); // always non-null — resolved once here - _subscriberBuilder.UseLoggerFactory(_loggergerFactory); + _publisherBuilder.UseLoggerFactory(_loggerFactory); // always non-null — resolved once here + _subscriberBuilder.UseLoggerFactory(_loggerFactory); _publisherBuilder.UseMeter(meter); _subscriberBuilder.UseMeter(meter); @@ -183,6 +202,6 @@ private EntityChangeTracker BuildInternal() _hasCustomLoggerFactory); } - return new EntityChangeTracker(publisher, subscriber, meter, ownsMeter: ownsMeter, loggerFactory: _loggergerFactory); + return new EntityChangeTracker(publisher, subscriber, meter, ownsMeter: ownsMeter, loggerFactory: _loggerFactory); } } diff --git a/src/RayTree.Core/Tracking/EntityBuilder.cs b/src/RayTree.Core/Tracking/EntityBuilder.cs index e7997b2..8a0ee20 100644 --- a/src/RayTree.Core/Tracking/EntityBuilder.cs +++ b/src/RayTree.Core/Tracking/EntityBuilder.cs @@ -24,7 +24,7 @@ internal sealed class EntityBuilder : IEntityBuilder private readonly ChangeSubscriberBuilder _subscriberBuilder; private readonly EntityPublisherBuilder _pubBuilder; private readonly EntitySubscriberBuilder _subBuilder; - private readonly ILoggerFactory _loggergerFactory; + private readonly ILoggerFactory _loggerFactory; private readonly ILogger> _logger; private static readonly string EntityTypeName = typeof(TEntity).Name; @@ -40,7 +40,7 @@ internal EntityBuilder( _subscriberBuilder = subscriberBuilder; _pubBuilder = new EntityPublisherBuilder(publisherBuilder); _subBuilder = new EntitySubscriberBuilder(subscriberBuilder); - _loggergerFactory = loggerFactory; + _loggerFactory = loggerFactory; _logger = loggerFactory.CreateLogger>(); } @@ -119,7 +119,7 @@ public ISharedHandlerBuilder UseConsumer(IQueueConsumer consumer) ArgumentNullException.ThrowIfNull(consumer); _subBuilder.UseConsumer(consumer); LogOverride("Consumer", consumer.GetType().Name); - _sharedBuilder = new SharedHandlerBuilder(_subBuilder, _loggergerFactory); + _sharedBuilder = new SharedHandlerBuilder(_subBuilder, _loggerFactory); return _sharedBuilder; } @@ -127,7 +127,7 @@ public IIsolatedHandlerBuilder UseConsumerFactory(Func(_subBuilder, factory, _loggergerFactory); + _isolatedBuilder = new IsolatedHandlerBuilder(_subBuilder, factory, _loggerFactory); return _isolatedBuilder; } diff --git a/src/RayTree.Core/Tracking/EntityChangeTracker.cs b/src/RayTree.Core/Tracking/EntityChangeTracker.cs index 335bbe0..b8ffeb4 100644 --- a/src/RayTree.Core/Tracking/EntityChangeTracker.cs +++ b/src/RayTree.Core/Tracking/EntityChangeTracker.cs @@ -79,6 +79,9 @@ internal async Task InitializeAsync(CancellationToken cancellationToken = defaul } catch { + // No exception payload: inner publisher/subscriber/plugin layers already logged the + // root cause at Error. A tracker-level Error would double-log; this Warning marks + // the abort point so operators can find it without losing the inner context. if (_logger.IsEnabled(LogLevel.Warning)) _logger.LogWarning("ChangeTracking: tracker initialization aborted"); throw; diff --git a/src/RayTree.Hosting/ChangeTrackingHostedService.cs b/src/RayTree.Hosting/ChangeTrackingHostedService.cs index e874f6f..18dd251 100644 --- a/src/RayTree.Hosting/ChangeTrackingHostedService.cs +++ b/src/RayTree.Hosting/ChangeTrackingHostedService.cs @@ -14,7 +14,7 @@ public class ChangeTrackingHostedService : IHostedService public ChangeTrackingHostedService( EntityChangeTracker tracker, ILogger logger, - ChangeTrackingDiContext? diContext = null) + ChangeTrackingDiContext? diContext) { _tracker = tracker ?? throw new ArgumentNullException(nameof(tracker)); _logger = logger ?? throw new ArgumentNullException(nameof(logger)); diff --git a/tests/RayTree.Core.Tests/Logging/ConfigurationLoggingTests.cs b/tests/RayTree.Core.Tests/Logging/ConfigurationLoggingTests.cs index 14020ed..09bcab2 100644 --- a/tests/RayTree.Core.Tests/Logging/ConfigurationLoggingTests.cs +++ b/tests/RayTree.Core.Tests/Logging/ConfigurationLoggingTests.cs @@ -1,6 +1,8 @@ using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Abstractions; +using RayTree.Core.Models; using RayTree.Core.Plugins.Compression; +using RayTree.Core.Plugins.Publisher; using RayTree.Core.Tracking; using RayTree.Hosting; using RayTree.Plugins.InMemory; @@ -266,11 +268,12 @@ public void InitializeAsync_OnFailure_LogsWarningBeforeRethrow() Assert.That(aborted, Is.Not.Null); } - private sealed class InitFailingPublisher : RayTree.Core.Plugins.Publisher.IQueuePublisher + private sealed class InitFailingPublisher : IQueuePublisher { public Task InitializeAsync(CancellationToken cancellationToken = default) => throw new InvalidOperationException("Simulated init failure"); - public Task PublishAsync(RayTree.Core.Models.MessageEnvelope envelope, CancellationToken cancellationToken = default) + + public Task PublishAsync(MessageEnvelope envelope, CancellationToken cancellationToken = default) => Task.CompletedTask; } From 01b5f8500e39a9aac122d55ea78f27edb8edfdaf Mon Sep 17 00:00:00 2001 From: bitc0der <59016822+bitc0der@users.noreply.github.com> Date: Sat, 23 May 2026 15:10:51 +0700 Subject: [PATCH 7/8] Fix on review --- src/RayTree.Hosting/ChangeTrackingHostedService.cs | 2 +- .../ChangeTrackingHostedServiceTests.cs | 8 ++------ 2 files changed, 3 insertions(+), 7 deletions(-) diff --git a/src/RayTree.Hosting/ChangeTrackingHostedService.cs b/src/RayTree.Hosting/ChangeTrackingHostedService.cs index 18dd251..e874f6f 100644 --- a/src/RayTree.Hosting/ChangeTrackingHostedService.cs +++ b/src/RayTree.Hosting/ChangeTrackingHostedService.cs @@ -14,7 +14,7 @@ public class ChangeTrackingHostedService : IHostedService public ChangeTrackingHostedService( EntityChangeTracker tracker, ILogger logger, - ChangeTrackingDiContext? diContext) + ChangeTrackingDiContext? diContext = null) { _tracker = tracker ?? throw new ArgumentNullException(nameof(tracker)); _logger = logger ?? throw new ArgumentNullException(nameof(logger)); diff --git a/tests/RayTree.Core.Tests/ChangeTrackingHostedServiceTests.cs b/tests/RayTree.Core.Tests/ChangeTrackingHostedServiceTests.cs index 18156a1..9577190 100644 --- a/tests/RayTree.Core.Tests/ChangeTrackingHostedServiceTests.cs +++ b/tests/RayTree.Core.Tests/ChangeTrackingHostedServiceTests.cs @@ -79,9 +79,7 @@ public async Task StartAsync_IsolatedMode_StartsOneLoopPerHandlerName() Assert.That(consumers.Keys, Is.EquivalentTo(new[] { "read-model", "notifier" }), "factory must be called once per distinct handler name at Build()"); - var svc = new ChangeTrackingHostedService( - tracker, - NullLogger.Instance); + var svc = new ChangeTrackingHostedService(tracker, NullLogger.Instance); await svc.StartAsync(CancellationToken.None); @@ -126,9 +124,7 @@ public async Task StartAsync_NoSubscriber_CompletesWithoutError() .Build(); // No consumer registered → tracker has no subscriber → StartAsync must be a no-op - var svc = new ChangeTrackingHostedService( - tracker, - NullLogger.Instance); + var svc = new ChangeTrackingHostedService(tracker, NullLogger.Instance); Assert.DoesNotThrowAsync(() => svc.StartAsync(CancellationToken.None)); await svc.StopAsync(CancellationToken.None); From a6cd702394e6f468660afac05c0ded8be71bb22e Mon Sep 17 00:00:00 2001 From: bitc0der <59016822+bitc0der@users.noreply.github.com> Date: Sat, 23 May 2026 15:17:08 +0700 Subject: [PATCH 8/8] Archive spec and update all the docs --- AGENTS.md | 9 ++ CHANGELOG.md | 106 ++++++++++++++++++ Directory.Build.props | 2 +- docs/README.md | 2 +- docs/configuration.md | 58 ++++++++++ .../.openspec.yaml | 0 .../design.md | 0 .../proposal.md | 0 .../specs/structured-logging/spec.md | 0 .../tasks.md | 0 openspec/specs/structured-logging/spec.md | 63 +++++++++++ 11 files changed, 238 insertions(+), 2 deletions(-) rename openspec/changes/{add-tracker-config-logging => archive/2026-05-23-add-tracker-config-logging}/.openspec.yaml (100%) rename openspec/changes/{add-tracker-config-logging => archive/2026-05-23-add-tracker-config-logging}/design.md (100%) rename openspec/changes/{add-tracker-config-logging => archive/2026-05-23-add-tracker-config-logging}/proposal.md (100%) rename openspec/changes/{add-tracker-config-logging => archive/2026-05-23-add-tracker-config-logging}/specs/structured-logging/spec.md (100%) rename openspec/changes/{add-tracker-config-logging => archive/2026-05-23-add-tracker-config-logging}/tasks.md (100%) diff --git a/AGENTS.md b/AGENTS.md index 8de595e..1f96dce 100644 --- a/AGENTS.md +++ b/AGENTS.md @@ -126,6 +126,15 @@ See `CLAUDE.md` for deep architecture documentation, plugin contracts, and key d methods. - All runtime service classes require a non-nullable `ILoggerFactory` / `ILogger` constructor parameter — no internal fallback. +- Each class owns its own `ILogger` (created from the injected `ILoggerFactory`) so log entries carry the + emitter's category and per-category filtering works as expected. Do not pass a shared `ILogger` instance across + multiple classes. +- Configuration- and lifecycle-time log calls (those added by the `add-tracker-config-logging` change in + `ChangeTrackingBuilder`, `EntityBuilder`, `SharedHandlerBuilder`, `IsolatedHandlerBuilder`, and + `EntityChangeTracker.InitializeAsync`) MUST be guarded with `if (_logger.IsEnabled()) ...` so + `NullLoggerFactory` produces zero allocations and zero output. +- See [docs/configuration.md#what-gets-logged](docs/configuration.md#what-gets-logged) for the full per-class log + inventory (level, trigger, structured properties). ### Testing Conventions diff --git a/CHANGELOG.md b/CHANGELOG.md index 2f85607..466aa54 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,6 +10,112 @@ The format follows [Keep a Changelog](https://keepachangelog.com/en/1.1.0/). ### Added +#### Configuration- and lifecycle-time logging on the tracker builder (`RayTree.Core`, `RayTree.Hosting`) + +Before this release the builder and tracker were almost silent during configuration and +startup: operators bringing up a new service had no visible evidence of which plugins were +registered, which entity types were configured, or which defaults were applied. +Misconfigurations (forgotten outbox, wrong consumer factory, mismatched serializer) only +surfaced as runtime errors later that were hard to trace back to the build step. + +The change adds structured `Information` / `Debug` / `Warning` logs through the entire +configuration and initialization path. No code change is required to opt in — the new logs +flow automatically through the `ILoggerFactory` already supplied to `ChangeTrackingBuilder` +(directly, or via `AddChangeTracking` from the DI container). + +**Builder configuration logs** — emitted from `ChangeTrackingBuilder` and from per-entity +builders (`EntityBuilder`, `SharedHandlerBuilder`, +`IsolatedHandlerBuilder`): + +| Level | When | Properties | +|---|---|---| +| `Information` | Each global `Use*` call | `{Plugin}` | +| `Information` | `ForEntity` invocation | `{EntityType}` | +| `Debug` | Default `RayTreeMeter` fallback in `BuildInternal` | — | +| `Information` | "ChangeTracker built" summary at the end of `Build()` / `BuildAsync()` | `{EntityTypes}`, `{Plugins}`, `{HasCustomMeter}`, `{HasCustomDeduplicationStore}`, `{HasCustomLoggerFactory}` | +| `Debug` | Per-entity plugin override (`UseOutbox`, `UsePublisher`, `UseSerializer`, `UseCompressor`, `UseRepository`, `UseConsumer`, `UseConsumerFactory`, `UseSubscriberOptions`) | `{EntityType}`, `{Override}`, `{Plugin}` | +| `Debug` | Handler registration (`OnInsert` / `OnUpdate` / `OnDelete` / `OnChange`, both Shared and Isolated modes) | `{EntityType}`, `{Override}` (e.g. `OnInsert:audit`), `{Plugin}` | + +For lambda handlers, `{Plugin}` walks past compiler-generated closure types +(`<>c__DisplayClass…`) and reports the user's outer class — so logs show +`Plugin=MyService` instead of `Plugin=<>c__DisplayClass3_0`. + +**Tracker initialization lifecycle** — emitted from `EntityChangeTracker.InitializeAsync`: + +| Level | When | Properties | +|---|---|---| +| `Information` | "tracker initialization started" | — | +| `Debug` | Publisher initialization complete | `{EntityTypeCount}` | +| `Debug` | Consumer connections initialized | `{ConsumerCount}` | +| `Information` | "tracker initialization completed" — success | — | +| `Warning` | "tracker initialization aborted" — abort marker on failure; the inner publisher/subscriber/plugin's own `Error` carries the exception payload | — | + +The Warning on failure deliberately omits the exception to avoid double-logging — inner +service layers already log the root cause at `Error`. Operators can grep for the abort line +and follow it back to the inner Error immediately above in the log stream. + +**Tracker disposal on failed init** — `Build()` and `BuildAsync()` now wrap +`InitializeAsync` in try/catch and call `tracker.Dispose()` before rethrowing. +Previously a partially-initialized tracker (owned `RayTreeMeter`, publisher background +services started inside `ChangePublisher.InitializeAsync`, dedup store, etc.) leaked when +init threw, because the caller never received a reference. + +**DI startup log** — emitted from `ChangeTrackingHostedService.StartAsync`: + +| Level | When | Properties | +|---|---|---| +| `Information` | "ChangeTracking starting" — once per host instance | `{ConfigurationBound}` | + +A new internal `ChangeTrackingDiContext` record captures `configuration != null` at +`AddChangeTracking` registration time and flows it to the hosted service via DI. +Registration is idempotent (`TryAddSingleton`), so calling `AddChangeTracking` twice +no longer appends duplicate registrations. + +**Per-category log filtering** + +Each builder owns an `ILogger` (not a shared logger), so the category attached to +every log entry matches the type that actually emitted it. Operators can filter per category +in their log sink — for example `RayTree.Core.Handling.SharedHandlerBuilder*` to see only +handler-registration events, or silence `Debug` from a specific builder without affecting +others. + +**Zero overhead under `NullLoggerFactory`** + +Every new log call is guarded by `ILogger.IsEnabled()`. Because +`NullLogger.IsEnabled` always returns `false`, the entire log body — including the +build-summary's `EntityTypes` array and `Plugins` string interpolation — is skipped under +`NullLoggerFactory.Instance`. Callers who opt out of logging pay zero allocation at startup. + +**Example output** for a tracker with two entities: + +```text +info: RayTree.Core.Tracking.ChangeTrackingBuilder[0] + ChangeTracking: registered global serializer JsonSerializerPlugin +info: RayTree.Core.Tracking.ChangeTrackingBuilder[0] + ChangeTracking: configuring entity Order +dbug: RayTree.Core.Tracking.EntityBuilder`1[Order][0] + ChangeTracking: entity override applied EntityType=Order Override=Outbox Plugin=PostgreSqlOutbox`1 +dbug: RayTree.Core.Handling.SharedHandlerBuilder`1[Order][0] + ChangeTracking: entity override applied EntityType=Order Override=OnInsert Plugin=MyService +info: RayTree.Core.Tracking.ChangeTrackingBuilder[0] + ChangeTracker built. EntityTypes=["Order", "Customer"] Plugins=Outbox= Publisher= Serializer=JsonSerializerPlugin Compressor=NoOpCompressorPlugin Repository= HasCustomMeter=False HasCustomDeduplicationStore=False HasCustomLoggerFactory=True +info: RayTree.Core.Tracking.EntityChangeTracker[0] + ChangeTracking: tracker initialization started +dbug: RayTree.Core.Tracking.EntityChangeTracker[0] + ChangeTracking: publisher initialized EntityTypeCount=2 +dbug: RayTree.Core.Tracking.EntityChangeTracker[0] + ChangeTracking: consumers initialized ConsumerCount=1 +info: RayTree.Core.Tracking.EntityChangeTracker[0] + ChangeTracking: tracker initialization completed +info: RayTree.Hosting.ChangeTrackingHostedService[0] + ChangeTracking starting. ConfigurationBound=True +``` + +See [`docs/configuration.md`](docs/configuration.md#what-gets-logged) for the full +log-entry reference. + +--- + #### Topology wait — opt-in startup retry for externally-owned RabbitMQ topology (`RayTree.Plugins.RabbitMQ`) In microservice deployments the exchange or queue that a publisher or consumer depends on is diff --git a/Directory.Build.props b/Directory.Build.props index d368ee9..06ba5de 100644 --- a/Directory.Build.props +++ b/Directory.Build.props @@ -7,7 +7,7 @@ true nullable - 0.0.15 + 0.0.16 pre-release bitc0der diff --git a/docs/README.md b/docs/README.md index 6912034..3e490e1 100644 --- a/docs/README.md +++ b/docs/README.md @@ -11,7 +11,7 @@ A modular .NET 10 entity change tracking system with outbox pattern support, que - **Modular Plugins** - Each serializer and compressor in its own package - **In-Memory Testing** - Full in-memory implementation for development and testing - **Auto-Initialization** - Automatic database schema initialization on `Build()` / `BuildAsync()` -- **Structured Logging** - `Microsoft.Extensions.Logging` throughout; pass `ILoggerFactory` to `EntityChangeTracker.Create()` or let `AddChangeTracking` wire it from DI automatically +- **Structured Logging** - `Microsoft.Extensions.Logging` throughout; pass `ILoggerFactory` to `EntityChangeTracker.Create()` or let `AddChangeTracking` wire it from DI automatically. Covers configuration-time events (`Use*` calls, `ForEntity` overrides, build summary), tracker initialization lifecycle (`InitializeAsync` started / sub-steps / completed / aborted), and runtime events (publish retries, dedup hits, handler failures). Every call is guarded by `IsEnabled(...)` for zero overhead under `NullLoggerFactory`. See [Configuration → What gets logged](configuration.md#what-gets-logged). - **OpenTelemetry Metrics** - `System.Diagnostics.Metrics` instruments on a `"RayTree"` meter for outbox writes, publish/subscribe latency, payload size, queue depth, and retry shape. Zero OTel SDK dependency unless the optional `RayTree.OpenTelemetry` package is referenced. See [OpenTelemetry Metrics Guide](opentelemetry-metrics.md). - **RabbitMQ Topology Wait** - Opt-in startup retry for `RabbitMqPublisher` and `RabbitMqConsumer` when the exchange or queue is owned by another service. Probes with AMQP passive declares and retries on `NOT_FOUND` until the topology appears, the cancellation token fires, or a configurable timeout elapses. diff --git a/docs/configuration.md b/docs/configuration.md index 98897ec..3d6cd12 100644 --- a/docs/configuration.md +++ b/docs/configuration.md @@ -501,6 +501,31 @@ When using the `.UseKafka(...)` / `.UseRabbitMq(...)` extension methods inside a ### What gets logged +**Configuration & build phase** + +| Class | Level | When | Structured properties | +|---|---|---|---| +| `ChangeTrackingBuilder` | `Information` | Each global `Use*` call (`UseOutbox`, `UsePublisher`, `UseSerializer`, `UseCompressor`, `UseRepository`, `UseDeduplicationStore`, `UseMeter`, `UsePublisherOptions`, `UseSubscriberOptions`) | `{Plugin}` | +| `ChangeTrackingBuilder` | `Information` | `ForEntity` invocation | `{EntityType}` | +| `ChangeTrackingBuilder` | `Debug` | `BuildInternal` falls back to a default `RayTreeMeter` (no `UseMeter`) | — | +| `ChangeTrackingBuilder` | `Information` | "ChangeTracker built" summary, once per `Build()` / `BuildAsync()` | `{EntityTypes}`, `{Plugins}`, `{HasCustomMeter}`, `{HasCustomDeduplicationStore}`, `{HasCustomLoggerFactory}` | +| `EntityBuilder` | `Debug` | Per-entity publisher overrides (`UseOutbox`, `UsePublisher`, `UseSerializer`, `UseCompressor`, `UseRepository`, `UseSubscriberOptions`, `UseConsumer`, `UseConsumerFactory`) | `{EntityType}`, `{Override}`, `{Plugin}` | +| `SharedHandlerBuilder` | `Debug` | `OnInsert` / `OnUpdate` / `OnDelete` / `OnChange` handler registrations | `{EntityType}`, `{Override}`, `{Plugin}` | +| `IsolatedHandlerBuilder` | `Debug` | Named handler registrations | `{EntityType}`, `{Override}` (e.g. `OnInsert:audit`), `{Plugin}` | + +**Tracker lifecycle** + +| Class | Level | When | Structured properties | +|---|---|---|---| +| `EntityChangeTracker` | `Information` | "tracker initialization started" — entered `InitializeAsync` | — | +| `EntityChangeTracker` | `Debug` | Publisher init completed | `{EntityTypeCount}` | +| `EntityChangeTracker` | `Debug` | Consumer connections initialized | `{ConsumerCount}` | +| `EntityChangeTracker` | `Information` | "tracker initialization completed" — success | — | +| `EntityChangeTracker` | `Warning` | "tracker initialization aborted" — abort point marker; inner plugin's `Error` carries the exception payload | — | +| `ChangeTrackingHostedService` | `Information` | "ChangeTracking starting" — DI startup, once per host | `{ConfigurationBound}` | + +**Runtime** + | Class | Level | When | |---|---|---| | `OutboxPublisherService` | `Information` | Polling loop start / stop | @@ -519,6 +544,39 @@ When using the `.UseKafka(...)` / `.UseRabbitMq(...)` extension methods inside a | `KafkaConsumer` | `Warning` | Consume error; envelope parse failure | | `RabbitMqConsumer` | `Warning` | Message processing error (before requeue) | +All configuration- and lifecycle-time log calls are guarded by `ILogger.IsEnabled(...)`, so under `NullLoggerFactory.Instance` they produce zero allocations and zero output. Each builder owns an `ILogger` so per-category filtering works as expected (e.g. silence `Debug` from `IsolatedHandlerBuilder` while keeping `Information` from `ChangeTrackingBuilder`). + +#### Example startup output + +For a tracker configured with one global serializer + compressor and two entities, the captured log stream looks like: + +```text +info: RayTree.Core.Tracking.ChangeTrackingBuilder[0] + ChangeTracking: registered global serializer JsonSerializerPlugin +info: RayTree.Core.Tracking.ChangeTrackingBuilder[0] + ChangeTracking: registered global compressor NoOpCompressorPlugin +info: RayTree.Core.Tracking.ChangeTrackingBuilder[0] + ChangeTracking: configuring entity Order +dbug: RayTree.Core.Tracking.EntityBuilder`1[Order][0] + ChangeTracking: entity override applied EntityType=Order Override=Outbox Plugin=PostgreSqlOutbox`1 +dbug: RayTree.Core.Handling.SharedHandlerBuilder`1[Order][0] + ChangeTracking: entity override applied EntityType=Order Override=OnInsert Plugin=MyService +info: RayTree.Core.Tracking.ChangeTrackingBuilder[0] + ChangeTracker built. EntityTypes=["Order", "Customer"] Plugins=Outbox= Publisher= Serializer=JsonSerializerPlugin Compressor=NoOpCompressorPlugin Repository= HasCustomMeter=False HasCustomDeduplicationStore=False HasCustomLoggerFactory=True +info: RayTree.Core.Tracking.EntityChangeTracker[0] + ChangeTracking: tracker initialization started +dbug: RayTree.Core.Tracking.EntityChangeTracker[0] + ChangeTracking: publisher initialized EntityTypeCount=2 +dbug: RayTree.Core.Tracking.EntityChangeTracker[0] + ChangeTracking: consumers initialized ConsumerCount=1 +info: RayTree.Core.Tracking.EntityChangeTracker[0] + ChangeTracking: tracker initialization completed +info: RayTree.Hosting.ChangeTrackingHostedService[0] + ChangeTracking starting. ConfigurationBound=True +``` + +On failure, the inner plugin emits the `Error` with the exception, and the tracker emits a single `Warning` marking the abort point so operators can grep back to the cause without losing context. + ## Observability — OpenTelemetry Metrics RayTree emits `System.Diagnostics.Metrics` instruments on a `Meter` named `"RayTree"` (counters, histograms, and an observable gauge for outbox depth). Instrument calls are silent no-ops when no listener is attached, so there is no overhead for consumers that opt out. diff --git a/openspec/changes/add-tracker-config-logging/.openspec.yaml b/openspec/changes/archive/2026-05-23-add-tracker-config-logging/.openspec.yaml similarity index 100% rename from openspec/changes/add-tracker-config-logging/.openspec.yaml rename to openspec/changes/archive/2026-05-23-add-tracker-config-logging/.openspec.yaml diff --git a/openspec/changes/add-tracker-config-logging/design.md b/openspec/changes/archive/2026-05-23-add-tracker-config-logging/design.md similarity index 100% rename from openspec/changes/add-tracker-config-logging/design.md rename to openspec/changes/archive/2026-05-23-add-tracker-config-logging/design.md diff --git a/openspec/changes/add-tracker-config-logging/proposal.md b/openspec/changes/archive/2026-05-23-add-tracker-config-logging/proposal.md similarity index 100% rename from openspec/changes/add-tracker-config-logging/proposal.md rename to openspec/changes/archive/2026-05-23-add-tracker-config-logging/proposal.md diff --git a/openspec/changes/add-tracker-config-logging/specs/structured-logging/spec.md b/openspec/changes/archive/2026-05-23-add-tracker-config-logging/specs/structured-logging/spec.md similarity index 100% rename from openspec/changes/add-tracker-config-logging/specs/structured-logging/spec.md rename to openspec/changes/archive/2026-05-23-add-tracker-config-logging/specs/structured-logging/spec.md diff --git a/openspec/changes/add-tracker-config-logging/tasks.md b/openspec/changes/archive/2026-05-23-add-tracker-config-logging/tasks.md similarity index 100% rename from openspec/changes/add-tracker-config-logging/tasks.md rename to openspec/changes/archive/2026-05-23-add-tracker-config-logging/tasks.md diff --git a/openspec/specs/structured-logging/spec.md b/openspec/specs/structured-logging/spec.md index f162371..8e25c20 100644 --- a/openspec/specs/structured-logging/spec.md +++ b/openspec/specs/structured-logging/spec.md @@ -69,3 +69,66 @@ When `ChangeSubscriber.ProcessMessageAsync` receives an envelope whose `EntityTy #### Scenario: Graceful shutdown is logged - **WHEN** `StopAsync` completes (including the expected `OperationCanceledException`) - **THEN** an `Information` log confirms the service has stopped + +### Requirement: Builder configuration calls emit structured logs +`ChangeTrackingBuilder` SHALL emit a structured `Information` log for each top-level configuration call made by the caller: `UseOutbox`, `UsePublisher`, `UseSerializer`, `UseCompressor`, `UseRepository`, `UseDeduplicationStore`, `UseMeter`, `UsePublisherOptions`, and `UseSubscriberOptions`. Each log entry SHALL include the registered plugin's CLR type name (or the options class name for option-configurers) as a structured property so that the log stream documents how the tracker was wired up. + +#### Scenario: Outbox registration is logged +- **WHEN** a caller invokes `builder.UseOutbox(factory)` +- **THEN** an `Information` log is emitted with `{Plugin}` equal to `"MyOutbox"` and a message identifying it as an outbox registration + +#### Scenario: Each Use* method emits exactly one log entry +- **WHEN** a caller chains `UseOutbox`, `UsePublisher`, `UseSerializer`, `UseCompressor`, `UseRepository`, `UseDeduplicationStore`, and `UseMeter` +- **THEN** seven distinct `Information` log entries are captured, one per call, each with the corresponding plugin type name + +#### Scenario: Null logger factory produces no configuration output +- **WHEN** a caller builds without supplying an `ILoggerFactory` (defaulting to `NullLoggerFactory.Instance`) +- **THEN** no configuration log entries are emitted and the builder still completes successfully + +### Requirement: Per-entity configuration is logged +`ChangeTrackingBuilder.ForEntity` SHALL emit an `Information` log naming the configured entity type before invoking the configure delegate, and SHALL emit `Debug` logs for each per-entity plugin override (`UseOutbox`, `UsePublisher`, `UseSerializer`, `UseCompressor`, `UseRepository`, `UseConsumer`, `UseConsumerFactory`, `UseSubscriberOptions`, `OnInsert`/`OnUpdate`/`OnDelete`/`OnChange`) applied inside the delegate. + +#### Scenario: ForEntity logs the entity type at Information +- **WHEN** a caller invokes `builder.ForEntity(b => { /* ... */ })` +- **THEN** an `Information` log is emitted with `{EntityType}` equal to `"Order"` + +#### Scenario: Per-entity plugin overrides log at Debug +- **WHEN** the configure delegate calls `b.UseOutbox(...)` and `b.OnInsert("name", handler)` +- **THEN** a `Debug` log is emitted for each override with `{EntityType}` and the override kind (e.g. `{Override}` = `"Outbox"`, `"OnInsert:name"`) as structured properties + +### Requirement: Tracker build emits a summary log +When `ChangeTrackingBuilder.Build()` or `BuildAsync()` completes the `BuildInternal` step, the builder SHALL emit a single `Information` log entry summarising the configured tracker. The log entry SHALL include the following structured properties: `{EntityTypes}` (the list of configured entity-type names), `{HasCustomMeter}` (bool), `{HasCustomDeduplicationStore}` (bool), `{HasCustomLoggerFactory}` (bool), and `{Plugins}` containing the registered global outbox, publisher, serializer, and compressor type names (or `""` when not registered). + +#### Scenario: Build summary is emitted once +- **WHEN** `builder.Build()` is called +- **THEN** exactly one `Information` "tracker built" log entry is captured containing the listed structured properties + +#### Scenario: Build summary reflects unconfigured plugins +- **WHEN** the builder is built without a global serializer registration +- **THEN** the build summary's `{Plugins}` property contains `Serializer = ""` + +### Requirement: Builder default-meter decision is logged +When `ChangeTrackingBuilder.BuildInternal` falls back to a default `RayTreeMeter` (because `UseMeter` was not called) it SHALL emit a `Debug` log indicating that a default meter was created and is owned by the tracker. (The `NullLoggerFactory` fallback path is already covered by the existing "Logger factory opt-in on the unified builder" requirement and is not restated here.) + +#### Scenario: Default meter creation is logged +- **WHEN** `Build()` is called without a prior `UseMeter` call +- **THEN** a `Debug` log is emitted stating that a default `RayTreeMeter` was created and is owned by the tracker + +### Requirement: Tracker initialization lifecycle is logged +`EntityChangeTracker.InitializeAsync` SHALL log at `Information` level when initialization begins and when it completes successfully, and SHALL log at `Debug` level after each major sub-step: publisher initialization complete, and consumer connections initialized. On failure, an `Error` log SHALL be emitted with the exception before re-throwing. + +#### Scenario: Successful initialization emits start and complete logs +- **WHEN** `InitializeAsync` is called and completes without error +- **THEN** an `Information` "tracker initialization started" log is captured followed by an `Information` "tracker initialization completed" log +- **THEN** exactly one `Debug` "publisher initialized" log is captured with `{EntityTypeCount}` structured property, and exactly one `Debug` "consumers initialized" log is captured with `{ConsumerCount}` structured property + +#### Scenario: Initialization failure is logged before re-throw +- **WHEN** `InitializeAsync` throws because a plugin's `InitializeAsync` fails +- **THEN** an `Error` log is emitted with the exception details and the failing sub-step before the exception propagates + +### Requirement: ChangeTrackingHostedService logs DI startup details +When `ChangeTrackingHostedService.StartAsync` runs (guaranteed one-shot per host instance), it SHALL emit a single `Information` "ChangeTracking starting" log with `{ConfigurationBound}` (bool — captured at `AddChangeTracking` registration time and stored on the hosted service) indicating whether configuration was bound from `IConfiguration`. This is additive to the existing hosted-service lifecycle logs and consolidates DI-registration visibility with the host start event. + +#### Scenario: Hosted service startup emits a registration-context log +- **WHEN** the host starts and `ChangeTrackingHostedService.StartAsync` is invoked +- **THEN** exactly one `Information` "ChangeTracking starting" log is emitted with `{ConfigurationBound}` matching whether `AddChangeTracking` received a non-null `IConfiguration`