diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index 6530cf8b9..b7d7c7926 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -357,6 +357,21 @@ For the full doc-pipeline workflow (compile, check-tier, render-diagrams), see [ - **Tag-based event dispatch.** Event handlers are wired once at mount; the current element is stored in `Tag` so handlers always read the latest closure. - **No XAML.** Everything is C#. +### Diagnostics: audience, not severity, decides the channel + +`Debug.WriteLine` exists for the framework contributor reading the Output window in Visual Studio; it disappears in Release builds. `ReactorEventSource` (the `Microsoft-UI-Reactor` provider) exists for the app developer, SRE, and support engineer — it's release-visible, keyword-gated, and zero-allocation when no consumer is attached. New code that reports an error, a swallowed exception, or a failing HRESULT belongs on the EventSource side; new code that traces internal framework state for a contributor's benefit (reconciler bookkeeping, scheduler queue depth) stays on `Debug.WriteLine`. + +For swallowed exceptions and HRESULT-return diagnostics, route through the `DiagnosticLog` helper: + +```csharp +catch (COMException ex) when (ex.HResult is HResults.RPC_E_DISCONNECTED or HResults.E_FAIL) +{ + DiagnosticLog.SwallowedError(LogCategory.Hosting, "AppWindow.Close", ex); +} +``` + +`DiagnosticLog.SwallowedError` and `DiagnosticLog.HResultFailed` emit the typed ETW event under `Keywords.Errors` at `Warning` in Release **and** mirror a richer line (including `ex.Message`) to `Debug.WriteLine` in Debug builds via a `[Conditional("DEBUG")]` helper. The exception message never reaches the ETW payload — see [`docs/guide/diagnostics.md`](docs/guide/diagnostics.md) for the PII discipline and the full capture workflow. + --- ## Hot reload diff --git a/docs/_pipeline/diagrams/diagnostics/flow.svg b/docs/_pipeline/diagrams/diagnostics/flow.svg new file mode 100644 index 000000000..8b685673f --- /dev/null +++ b/docs/_pipeline/diagrams/diagnostics/flow.svg @@ -0,0 +1,90 @@ + + + + + + + + + + + Reactor diagnostics flow — from a catch site to four consumers + + + + Framework catch site + catch (COMException ex) when (…) + e.g. JumpListComInterop.Begin + + + + DiagnosticLog + SwallowedError(category, op, ex) + HResultFailed(category, op, hr) + + + + ReactorEventSource + Microsoft-UI-Reactor provider + IsEnabled gate · keyword-scoped + + + + delegate + + + Release path + + + + DEBUG only + + + Debug.WriteLine mirror + Output window only + [Conditional("DEBUG")] + + + + Four consumers — pick by where the consumer lives + + + + DOTNET_EnableEventPipe / dotnet-trace + .nettrace file · zero app code + + + + VS Performance Profiler + Events Viewer · live + post-hoc + + + + ReactorTrace.Subscribe + In-process · app-controlled sink + + + + reactor.logs source=event + MCP devtools tool · agent-readable + + + + + + + diff --git a/docs/_pipeline/templates/diagnostics.md.dt b/docs/_pipeline/templates/diagnostics.md.dt new file mode 100644 index 000000000..247b26352 --- /dev/null +++ b/docs/_pipeline/templates/diagnostics.md.dt @@ -0,0 +1,401 @@ +--- +title: "Diagnostics" +app: diagnostics +order: 44 +audience: advanced +goal: | + How to capture, filter, and read Reactor's release-build diagnostics + in a real app. Covers the rule (audience, not severity, decides + whether something is a Debug.WriteLine or a ReactorEventSource + event), the four ways to capture a trace (env vars, dotnet-trace, + Visual Studio Profiler, ReactorTrace.Subscribe in process), and how + the reactor.logs MCP tool now surfaces ETW events alongside + stdout/stderr/debug output for the in-process devtools agent. Spec + 044 — tracing and logging cleanup. +tier: comprehensive +--- + +When Reactor swallows an exception, returns past an HRESULT, or +otherwise chooses to continue rather than throw, the framework has +historically dropped a `Debug.WriteLine` and moved on. That worked for +the contributor — the message landed in Visual Studio's Output window +during a Debug build — but it disappeared in Release, which is the +configuration every shipped app runs. Spec 044 fixed that: error and +HRESULT diagnostics now route through the `Microsoft-UI-Reactor` +`EventSource` (release-visible, keyword-gated, zero-allocation when +no consumer is listening), and the existing in-process devtools tool +(`reactor.logs`) was extended so an MCP agent can read framework +events in the same call that returns stdout / stderr / debug output. + +# Diagnostics + +This page is about reading Reactor's diagnostics from a real app — +not about adding new events. The emission pipeline (keywords, +IsEnabled gate, event-id allocation, EventPipe vs ETW transport split) +lives in [perf-instrumentation.md](perf-instrumentation.md); start +there if you are extending the provider. + +![Reactor diagnostics flow — a framework catch site delegates to DiagnosticLog, which emits to ReactorEventSource for the Release path and mirrors to Debug.WriteLine in Debug builds; four consumers read the event surface: env-var / dotnet-trace capture, Visual Studio Profiler, the in-process ReactorTrace.Subscribe helper, and the reactor.logs MCP tool](images/diagnostics/flow.svg) + +## The rule + +Audience, not severity, decides the channel. `Debug.WriteLine` +exists for the contributor working on the framework itself; the +target audience is "someone reading the Output window in Visual +Studio with their checkout open". `ReactorEventSource` exists for +the app developer, the SRE, and the support engineer; the target +audience is "someone who runs the shipped binary and needs to know +why a window failed to open". + +| Audience | Channel | Visible in Release? | +|---|---|---| +| Framework contributor | `Debug.WriteLine`, `Debug.Assert` | No | +| App developer / SRE | `Microsoft-UI-Reactor` `EventSource` | Yes | +| Unreachable code | `throw new UnreachableException(...)` | Yes (as a crash) | + +The two channels are complementary, not redundant. A swallowed +exception in `RenderContext` emits both — the typed event for the +app developer and a richer `Debug.WriteLine` mirror (with the +exception message) for the contributor running a Debug build. The +mirror is `[Conditional("DEBUG")]` and compiles out in Release. + + +Exception messages are PII-shaped and never reach the ETW payload. +`ex.Message` can carry absolute paths, environment values, partial +form values, and the bound user data that caused the failure. The +typed event payload carries the exception *type* only +(`InvalidOperationException`, `COMException`); a same-UID +`dotnet-trace` consumer sees the type and nothing else. If you need +the message in your own logs, attach an in-process subscriber (see +[`ReactorTrace.Subscribe`](#in-process-subscription) below) and +forward to a sink under your own ACL. + + +## What's instrumented + +The provider's events split across a small set of keywords; spec 044 +adds six subsystem keywords on top of the seven the perf-instrumentation +page documents. Pick the bits that match what you're triaging: + +| Keyword | Bit | Covers | +|---|---|---| +| `Errors` | `0x20` | Generic `SwallowedError` / `HResultFailed`, plus `RenderError` | +| `Hosting` | `0x80` | `WindowOpened`, `WindowClosed`, `WindowDpiChanged`, `BackdropMaterializationFailed` | +| `Persistence` | `0x100` | `PersistenceRead`, `PersistenceWrite`, `PersistenceRejected` | +| `Navigation` | `0x200` | `NavigationRequested`, `NavigationCompleted`, `NavigationCancelled`, cache hit/miss/evict, transitions, deep-link | +| `Intl` | `0x400` | `IntlMissingKey` | +| `Theme` | `0x800` | `ThemeApplyFailed` | +| `Shell` | `0x1000` | `JumpList*` / `ThumbnailToolbar*` / `Tray*` (planned) | + +Combine bits with bitwise-or. The most common capture-everything- +unsurprising mask is `0x1FA0` (`Errors | Hosting | Persistence | +Navigation | Intl | Theme`) — drops the verbose `State` and +`EventDispatch` keywords that produce per-state-write spam. + +## Capturing a trace + +There are four routes. Pick by where the consumer lives. + +### Environment variables — zero code, file output + +For a quick local capture with no app changes, the .NET runtime can +write an EventPipe `.nettrace` file driven entirely by environment +variables. This is the right tool when an issue reproduces only in a +shipped build, on a different machine, or when you want to hand the +trace off to someone else: + +``` +set DOTNET_EnableEventPipe=1 +set DOTNET_EventPipeOutputPath=reactor.nettrace +set DOTNET_EventPipeConfig=Microsoft-UI-Reactor:0x1FA0:5 +MyApp.exe +``` + +The third variable is `::`. `0x1FA0` is +the everything-unsurprising mask above; level `5` is `Verbose`. Run +the app, reproduce the issue, exit cleanly (the runtime flushes the +file on shutdown). Open the resulting `.nettrace` in Visual Studio's +Performance Profiler → Events Viewer. + +### `dotnet-trace` — attach to a running process + +`dotnet-trace` is the cross-platform CLI for EventPipe capture. +Useful when the app is already running and you want to scope the +window: + +``` +dotnet-trace collect ^ + --process-id ^ + --providers Microsoft-UI-Reactor:0x1FA0:5 ^ + --output reactor.nettrace +``` + +`Ctrl+C` stops the session; the `.nettrace` lands in the working +directory. Same file format as the env-var route — same Events +Viewer workflow. + +### Visual Studio Performance Profiler + +For a GUI workflow, the Profiler's Events Viewer accepts the same +provider:keyword:level format. Diagnostics → Performance Profiler +→ Events Viewer → Settings → Custom Provider: + +``` +Microsoft-UI-Reactor:0x1FA0:5 +``` + +The timeline ties each Reactor event to the CPU sample, GC, and +network views, so you can see a `NavigationCompleted` next to the +allocation spike it caused. + +### In-process subscription + +When the consumer is the app itself — a custom log sink, a devtools +overlay, an in-app diagnostics page — `ReactorTrace.Subscribe` +returns an `IDisposable` token that fires the callback for each +event matching the filter: + +```csharp snippet="source:src/Reactor/Diagnostics/ReactorTrace.cs#subscribe-shape" +``` + +Multiple concurrent subscribers are supported; each filter is +independently active until the token is disposed. The subscriber +callback runs on the emission thread (usually the UI dispatcher when +the event originates from reconcile / render), so keep the work +minimal — the framework wraps the call in `try/catch` so a buggy +sink can't propagate to `EventSource.WriteEvent`, but the dispatcher +is still blocked for the duration. Forward to a queue if your sink +does anything expensive. + +`ReactorTrace.Subscribe` is **not** a file-capture API. It exists +because in-process consumers (devtools, an `ILogger` adapter, a +custom diagnostics page) need access to the same events the env-var +route writes to disk. For a `.nettrace` file, use one of the three +routes above — they cost less and emit a richer format. + +## `reactor.logs source=event` — MCP integration + +The Reactor in-process devtools (`mur devtools`) expose a `logs` MCP +tool that drains the captured `Console.Out` / `Console.Error` / +`Debug.WriteLine` ring buffer. Spec 044 extended the tool so the +buffer also captures `Microsoft-UI-Reactor` ETW events, surfaced +under a new `source=event` filter: + +```jsonc +// Request +{ + "method": "tools/call", + "params": { + "name": "logs", + "arguments": { "source": "event", "tail": 20, "level": "Warning" } + } +} + +// Response — each entry now carries eventName / eventId +{ + "entries": [ + { + "seq": 142, + "ts": "2026-05-19T17:42:11.330Z", + "source": "event", + "level": "Warning", + "text": "SwallowedError category=Hosting operation=AppWindow.Close exceptionType=COMException", + "eventName": "SwallowedError", + "eventId": 16 + } + ], + "nextSeq": 143, + "dropped": 0 +} +``` + +Existing clients that don't pass `source=event` see zero behavior +change — the `stdout` / `stderr` / `debug` filters still return their +dedicated streams. The `eventName` and `eventId` fields are present +on every entry but are `null` for non-event sources, so a client +written before spec 044 ignores them safely. + +HR-style payload fields render in the same `0x{X8}` shape the +pre-migration `Debug.WriteLine` sites used (`HResultFailed +category=Shell operation=JumpList.Begin hr=0x80004002`), so log +greps that matched the old shape continue to hit. + +## Patterns + +### Reading a swallow that happened in production + +A customer reports a window that won't close cleanly on a specific +machine. Capture with the env-var route, filter to the `Errors` +keyword (`0x20`) at `Warning`, and open the trace in Events Viewer. +The relevant entries will look like: + +``` +SwallowedError category=Hosting operation=AppWindow.Close exceptionType=COMException +HResultFailed category=Hosting operation=AppWindow.Close hr=0x80004005 +``` + +The operation label is stable and developer-authored — search the +Reactor source for `"AppWindow.Close"` and you land on the +`DiagnosticLog.SwallowedError` call site. The exception type and HR +together pin the failure class (in this case, `E_FAIL` from the +WinUI AppWindow lifecycle) without ever leaking the user-visible +window title. + +### Wiring `ReactorTrace.Subscribe` to a per-window debug overlay + +A devtools overlay that wants to surface "navigation event happening +now" doesn't need a file capture — just an in-process subscription: + +```csharp +public sealed class NavigationOverlay : IDisposable +{ + private readonly IDisposable _subscription; + private readonly Queue _ring = new(); + + public NavigationOverlay() + { + _subscription = ReactorTrace.Subscribe( + evt => + { + if ((evt.Keywords & ReactorEventSource.Keywords.Navigation) == 0) return; + var line = $"{evt.EventName} {string.Join(' ', + Enumerable.Range(0, evt.Payload.Count) + .Select(i => $"{evt.PayloadNames[i]}={evt.Payload[i]}"))}"; + lock (_ring) + { + _ring.Enqueue(line); + while (_ring.Count > 50) _ring.Dequeue(); + } + }, + level: EventLevel.Verbose, + keywords: ReactorEventSource.Keywords.Navigation); + } + + public void Dispose() => _subscription.Dispose(); +} +``` + +The callback runs on the dispatcher (most navigation events +originate there) — for a UI overlay that's actually what you want. +If the overlay forwards to a background sink instead, marshal off +the dispatcher before doing the I/O. + +## Common Mistakes + +### Treating `Debug.WriteLine` as a release diagnostic + +```csharp +// Don't: +try { window.AppWindow.Close(); } +catch (Exception ex) +{ + Debug.WriteLine($"Close failed: {ex}"); // disappears in Release +} +``` + +```csharp +// Do: +try { window.AppWindow.Close(); } +catch (COMException ex) when (ex.HResult is HResults.RPC_E_DISCONNECTED or HResults.E_FAIL) +{ + DiagnosticLog.SwallowedError(LogCategory.Hosting, "AppWindow.Close", ex); +} +``` + +The first form was invisible to every shipped app. The second form +emits to `Microsoft-UI-Reactor` under `Keywords.Errors` at `Warning` +in Release (zero allocation when no consumer is attached) *and* +mirrors a richer line including `ex.Message` to `Debug.WriteLine` +in Debug builds. The narrow `catch` filter is the deliberate part: +spec 044 §6.7.2 calls for `catch (COMException) when (ex.HResult is +HResults.X or HResults.Y)` — never a bare `catch (COMException)`, +because the bug-class HRESULTs need to keep propagating. + +### Capturing without pinning the level + +``` +DOTNET_EventPipeConfig=Microsoft-UI-Reactor +``` + +Defaults to `Verbose` plus all keywords. A typical 30-second session +on a busy app writes hundreds of megabytes — and `State` keyword +events fire once per `UseState` write, so a state-heavy screen +becomes the entire trace. Pin both: + +``` +DOTNET_EventPipeConfig=Microsoft-UI-Reactor:0x1FA0:5 +``` + +`0x1FA0` is `Errors | Hosting | Persistence | Navigation | Intl | +Theme` — the everything-unsurprising mask. `:5` is `Verbose`. The +trace shrinks by an order of magnitude. + +### Computing the diagnostic payload outside the IsEnabled gate + +```csharp snippet="source:src/Reactor/Core/Diagnostics/DiagnosticLog.cs#swallowed-error-shape" +``` + +`DiagnosticLog.SwallowedError` does its `category.ToString()` and +`ex.GetType().Name` work *inside* the +`ReactorEventSource.Log.IsEnabled(...)` gate, not outside. The +distinction is the entire point of the "zero-allocation when no +consumer is attached" guarantee. If a future helper materializes +the payload first and gates second, the no-allocation regression +test (`DisabledKeyword_skips_ReactorEventSource_WriteEvent_payload_marshal`) +catches it. The companion `HResultFailed` event has the same shape: + +```csharp snippet="source:src/Reactor/Core/Diagnostics/ReactorEventSource.cs#hresult-failed-event" +``` + +### Forwarding `ex.Message` through `ReactorTrace.Subscribe` + +```csharp +// Don't — capturing the exception and forwarding its message defeats the strip: +Exception? lastEx = null; +try { /* ... */ } +catch (Exception caught) +{ + lastEx = caught; + DiagnosticLog.SwallowedError(LogCategory.Hosting, "MyOp", caught); +} + +ReactorTrace.Subscribe(evt => +{ + // BAD: re-injects PII that the ETW payload deliberately excluded. + _logger.Warn(evt.EventName + ": " + string.Join(",", evt.Payload) + " " + lastEx?.Message); +}); +``` + +The framework already stripped `ex.Message` from the payload — +re-adding it from a captured local is exactly the PII leak the strip +prevented. If a sink needs the message, log it inside the `catch` +block (where the exception is in scope and the sink's ACL applies), +not at the `ReactorTrace.Subscribe` boundary. + +## Tips + +**`reactor.logs source=event` is the fastest read.** Inside a +devtools session, calling the MCP tool returns the last N events +instantly without spinning up a `dotnet-trace` capture. Use the +env-var route when you need to hand a file to someone else; use the +MCP tool when you're sitting in front of the running app. + +**The keyword mask is the audience pre-filter.** Subscribing on +`Keywords.Errors` alone is dramatically cheaper than `(-1)` because +the framework's hot reconcile / render paths drop their `IsEnabled` +check immediately. A long-lived broad subscription raises the cost +of every hot-path call site on the framework for as long as it +lives. + +**HR fields are `0x{X8}`-rendered in `reactor.logs` text.** The MCP +tool's text rendering recognizes payload field names `hr`, +`hresult`, and `hwnd` and formats them as 8-digit uppercase hex. +This matches the pre-migration `Debug.WriteLine` shape so existing +log greps keep working. + +## Next Steps + +- **[Perf Instrumentation](perf-instrumentation.md)** — The emission pipeline, keyword design, and the IsEnabled gate. Read first if you're adding events. +- **[DevTools Internals](devtools-internals.md)** — The MCP server and `logs` tool plumbing the diagnostic events flow through. +- **[Persistence](persistence.md)** — Where `PersistenceRead` / `PersistenceWrite` / `PersistenceRejected` fire from. +- **[Navigation](navigation.md)** — The route lifecycle that emits the Navigation-keyword events. diff --git a/docs/_pipeline/templates/perf-instrumentation.md.dt b/docs/_pipeline/templates/perf-instrumentation.md.dt index 81a46f9eb..828979fa7 100644 --- a/docs/_pipeline/templates/perf-instrumentation.md.dt +++ b/docs/_pipeline/templates/perf-instrumentation.md.dt @@ -249,6 +249,7 @@ in the band's event payload. ## Next Steps +- **[Diagnostics](diagnostics.md)** — How to capture, filter, and read the error / HR / subsystem events Reactor emits in Release builds, plus `ReactorTrace.Subscribe` and `reactor.logs source=event`. - **[DevTools Internals](devtools-internals.md)** — Where the overlays consume these events. - **[Reconciliation](reconciliation.md)** — What the reconcile-stop counters describe. - **[Hooks Internals](hooks-internals.md)** — Why `StateChange` fires from inside the slot table. diff --git a/docs/guide/diagnostics.md b/docs/guide/diagnostics.md new file mode 100644 index 000000000..770322b1b --- /dev/null +++ b/docs/guide/diagnostics.md @@ -0,0 +1,404 @@ + +When Reactor swallows an exception, returns past an HRESULT, or +otherwise chooses to continue rather than throw, the framework has +historically dropped a `Debug.WriteLine` and moved on. That worked for +the contributor — the message landed in Visual Studio's Output window +during a Debug build — but it disappeared in Release, which is the +configuration every shipped app runs. Spec 044 fixed that: error and +HRESULT diagnostics now route through the `Microsoft-UI-Reactor` +`EventSource` (release-visible, keyword-gated, zero-allocation when +no consumer is listening), and the existing in-process devtools tool +(`reactor.logs`) was extended so an MCP agent can read framework +events in the same call that returns stdout / stderr / debug output. + +# Diagnostics + +This page is about reading Reactor's diagnostics from a real app — +not about adding new events. The emission pipeline (keywords, +IsEnabled gate, event-id allocation, EventPipe vs ETW transport split) +lives in [perf-instrumentation.md](perf-instrumentation.md); start +there if you are extending the provider. + +![Reactor diagnostics flow — a framework catch site delegates to DiagnosticLog, which emits to ReactorEventSource for the Release path and mirrors to Debug.WriteLine in Debug builds; four consumers read the event surface: env-var / dotnet-trace capture, Visual Studio Profiler, the in-process ReactorTrace.Subscribe helper, and the reactor.logs MCP tool](images/diagnostics/flow.svg) + +## The rule + +Audience, not severity, decides the channel. `Debug.WriteLine` +exists for the contributor working on the framework itself; the +target audience is "someone reading the Output window in Visual +Studio with their checkout open". `ReactorEventSource` exists for +the app developer, the SRE, and the support engineer; the target +audience is "someone who runs the shipped binary and needs to know +why a window failed to open". + +| Audience | Channel | Visible in Release? | +|---|---|---| +| Framework contributor | `Debug.WriteLine`, `Debug.Assert` | No | +| App developer / SRE | `Microsoft-UI-Reactor` `EventSource` | Yes | +| Unreachable code | `throw new UnreachableException(...)` | Yes (as a crash) | + +The two channels are complementary, not redundant. A swallowed +exception in `RenderContext` emits both — the typed event for the +app developer and a richer `Debug.WriteLine` mirror (with the +exception message) for the contributor running a Debug build. The +mirror is `[Conditional("DEBUG")]` and compiles out in Release. + +> **Caveat:** Exception messages are PII-shaped and never reach the ETW payload. +> `ex.Message` can carry absolute paths, environment values, partial +> form values, and the bound user data that caused the failure. The +> typed event payload carries the exception *type* only +> (`InvalidOperationException`, `COMException`); a same-UID +> `dotnet-trace` consumer sees the type and nothing else. If you need +> the message in your own logs, attach an in-process subscriber (see +> [`ReactorTrace.Subscribe`](#in-process-subscription) below) and +> forward to a sink under your own ACL. + +## What's instrumented + +The provider's events split across a small set of keywords; spec 044 +adds six subsystem keywords on top of the seven the perf-instrumentation +page documents. Pick the bits that match what you're triaging: + +| Keyword | Bit | Covers | +|---|---|---| +| `Errors` | `0x20` | Generic `SwallowedError` / `HResultFailed`, plus `RenderError` | +| `Hosting` | `0x80` | `WindowOpened`, `WindowClosed`, `WindowDpiChanged`, `BackdropMaterializationFailed` | +| `Persistence` | `0x100` | `PersistenceRead`, `PersistenceWrite`, `PersistenceRejected` | +| `Navigation` | `0x200` | `NavigationRequested`, `NavigationCompleted`, `NavigationCancelled`, cache hit/miss/evict, transitions, deep-link | +| `Intl` | `0x400` | `IntlMissingKey` | +| `Theme` | `0x800` | `ThemeApplyFailed` | +| `Shell` | `0x1000` | `JumpList*` / `ThumbnailToolbar*` / `Tray*` (planned) | + +Combine bits with bitwise-or. The most common capture-everything- +unsurprising mask is `0x1FA0` (`Errors | Hosting | Persistence | +Navigation | Intl | Theme`) — drops the verbose `State` and +`EventDispatch` keywords that produce per-state-write spam. + +## Capturing a trace + +There are four routes. Pick by where the consumer lives. + +### Environment variables — zero code, file output + +For a quick local capture with no app changes, the .NET runtime can +write an EventPipe `.nettrace` file driven entirely by environment +variables. This is the right tool when an issue reproduces only in a +shipped build, on a different machine, or when you want to hand the +trace off to someone else: + +``` +set DOTNET_EnableEventPipe=1 +set DOTNET_EventPipeOutputPath=reactor.nettrace +set DOTNET_EventPipeConfig=Microsoft-UI-Reactor:0x1FA0:5 +MyApp.exe +``` + +The third variable is `::`. `0x1FA0` is +the everything-unsurprising mask above; level `5` is `Verbose`. Run +the app, reproduce the issue, exit cleanly (the runtime flushes the +file on shutdown). Open the resulting `.nettrace` in Visual Studio's +Performance Profiler → Events Viewer. + +### `dotnet-trace` — attach to a running process + +`dotnet-trace` is the cross-platform CLI for EventPipe capture. +Useful when the app is already running and you want to scope the +window: + +``` +dotnet-trace collect ^ + --process-id ^ + --providers Microsoft-UI-Reactor:0x1FA0:5 ^ + --output reactor.nettrace +``` + +`Ctrl+C` stops the session; the `.nettrace` lands in the working +directory. Same file format as the env-var route — same Events +Viewer workflow. + +### Visual Studio Performance Profiler + +For a GUI workflow, the Profiler's Events Viewer accepts the same +provider:keyword:level format. Diagnostics → Performance Profiler +→ Events Viewer → Settings → Custom Provider: + +``` +Microsoft-UI-Reactor:0x1FA0:5 +``` + +The timeline ties each Reactor event to the CPU sample, GC, and +network views, so you can see a `NavigationCompleted` next to the +allocation spike it caused. + +### In-process subscription + +When the consumer is the app itself — a custom log sink, a devtools +overlay, an in-app diagnostics page — `ReactorTrace.Subscribe` +returns an `IDisposable` token that fires the callback for each +event matching the filter: + +```csharp +public static IDisposable Subscribe( + Action onEvent, + EventLevel level = EventLevel.Verbose, + EventKeywords keywords = (EventKeywords)(-1)) +{ + ArgumentNullException.ThrowIfNull(onEvent); + return new Subscription(onEvent, level, keywords); +} +``` + +Multiple concurrent subscribers are supported; each filter is +independently active until the token is disposed. The subscriber +callback runs on the emission thread (usually the UI dispatcher when +the event originates from reconcile / render), so keep the work +minimal — the framework wraps the call in `try/catch` so a buggy +sink can't propagate to `EventSource.WriteEvent`, but the dispatcher +is still blocked for the duration. Forward to a queue if your sink +does anything expensive. + +`ReactorTrace.Subscribe` is **not** a file-capture API. It exists +because in-process consumers (devtools, an `ILogger` adapter, a +custom diagnostics page) need access to the same events the env-var +route writes to disk. For a `.nettrace` file, use one of the three +routes above — they cost less and emit a richer format. + +## `reactor.logs source=event` — MCP integration + +The Reactor in-process devtools (`mur devtools`) expose a `logs` MCP +tool that drains the captured `Console.Out` / `Console.Error` / +`Debug.WriteLine` ring buffer. Spec 044 extended the tool so the +buffer also captures `Microsoft-UI-Reactor` ETW events, surfaced +under a new `source=event` filter: + +```jsonc +// Request +{ + "method": "tools/call", + "params": { + "name": "logs", + "arguments": { "source": "event", "tail": 20, "level": "Warning" } + } +} + +// Response — each entry now carries eventName / eventId +{ + "entries": [ + { + "seq": 142, + "ts": "2026-05-19T17:42:11.330Z", + "source": "event", + "level": "Warning", + "text": "SwallowedError category=Hosting operation=AppWindow.Close exceptionType=COMException", + "eventName": "SwallowedError", + "eventId": 16 + } + ], + "nextSeq": 143, + "dropped": 0 +} +``` + +Existing clients that don't pass `source=event` see zero behavior +change — the `stdout` / `stderr` / `debug` filters still return their +dedicated streams. The `eventName` and `eventId` fields are present +on every entry but are `null` for non-event sources, so a client +written before spec 044 ignores them safely. + +HR-style payload fields render in the same `0x{X8}` shape the +pre-migration `Debug.WriteLine` sites used (`HResultFailed +category=Shell operation=JumpList.Begin hr=0x80004002`), so log +greps that matched the old shape continue to hit. + +## Patterns + +### Reading a swallow that happened in production + +A customer reports a window that won't close cleanly on a specific +machine. Capture with the env-var route, filter to the `Errors` +keyword (`0x20`) at `Warning`, and open the trace in Events Viewer. +The relevant entries will look like: + +``` +SwallowedError category=Hosting operation=AppWindow.Close exceptionType=COMException +HResultFailed category=Hosting operation=AppWindow.Close hr=0x80004005 +``` + +The operation label is stable and developer-authored — search the +Reactor source for `"AppWindow.Close"` and you land on the +`DiagnosticLog.SwallowedError` call site. The exception type and HR +together pin the failure class (in this case, `E_FAIL` from the +WinUI AppWindow lifecycle) without ever leaking the user-visible +window title. + +### Wiring `ReactorTrace.Subscribe` to a per-window debug overlay + +A devtools overlay that wants to surface "navigation event happening +now" doesn't need a file capture — just an in-process subscription: + +```csharp +public sealed class NavigationOverlay : IDisposable +{ + private readonly IDisposable _subscription; + private readonly Queue _ring = new(); + + public NavigationOverlay() + { + _subscription = ReactorTrace.Subscribe( + evt => + { + if ((evt.Keywords & ReactorEventSource.Keywords.Navigation) == 0) return; + var line = $"{evt.EventName} {string.Join(' ', + Enumerable.Range(0, evt.Payload.Count) + .Select(i => $"{evt.PayloadNames[i]}={evt.Payload[i]}"))}"; + lock (_ring) + { + _ring.Enqueue(line); + while (_ring.Count > 50) _ring.Dequeue(); + } + }, + level: EventLevel.Verbose, + keywords: ReactorEventSource.Keywords.Navigation); + } + + public void Dispose() => _subscription.Dispose(); +} +``` + +The callback runs on the dispatcher (most navigation events +originate there) — for a UI overlay that's actually what you want. +If the overlay forwards to a background sink instead, marshal off +the dispatcher before doing the I/O. + +## Common Mistakes + +### Treating `Debug.WriteLine` as a release diagnostic + +```csharp +// Don't: +try { window.AppWindow.Close(); } +catch (Exception ex) +{ + Debug.WriteLine($"Close failed: {ex}"); // disappears in Release +} +``` + +```csharp +// Do: +try { window.AppWindow.Close(); } +catch (COMException ex) when (ex.HResult is HResults.RPC_E_DISCONNECTED or HResults.E_FAIL) +{ + DiagnosticLog.SwallowedError(LogCategory.Hosting, "AppWindow.Close", ex); +} +``` + +The first form was invisible to every shipped app. The second form +emits to `Microsoft-UI-Reactor` under `Keywords.Errors` at `Warning` +in Release (zero allocation when no consumer is attached) *and* +mirrors a richer line including `ex.Message` to `Debug.WriteLine` +in Debug builds. The narrow `catch` filter is the deliberate part: +spec 044 §6.7.2 calls for `catch (COMException) when (ex.HResult is +HResults.X or HResults.Y)` — never a bare `catch (COMException)`, +because the bug-class HRESULTs need to keep propagating. + +### Capturing without pinning the level + +``` +DOTNET_EventPipeConfig=Microsoft-UI-Reactor +``` + +Defaults to `Verbose` plus all keywords. A typical 30-second session +on a busy app writes hundreds of megabytes — and `State` keyword +events fire once per `UseState` write, so a state-heavy screen +becomes the entire trace. Pin both: + +``` +DOTNET_EventPipeConfig=Microsoft-UI-Reactor:0x1FA0:5 +``` + +`0x1FA0` is `Errors | Hosting | Persistence | Navigation | Intl | +Theme` — the everything-unsurprising mask. `:5` is `Verbose`. The +trace shrinks by an order of magnitude. + +### Computing the diagnostic payload outside the IsEnabled gate + +```csharp +public static void SwallowedError(LogCategory category, string operation, Exception ex) +{ + // Cost-of-disabled: when no consumer enables Keywords.Errors at + // Warning the entire branch is skipped — no enum-to-string, no + // type-name materialization, no WriteEvent dispatch. + if (ReactorEventSource.Log.IsEnabled(EventLevel.Warning, ReactorEventSource.Keywords.Errors)) + { + ReactorEventSource.Log.SwallowedError( + category.ToString(), + operation ?? string.Empty, + ex?.GetType().Name ?? string.Empty); + } + + DebugSwallowedError(category, operation, ex); +} +``` + +`DiagnosticLog.SwallowedError` does its `category.ToString()` and +`ex.GetType().Name` work *inside* the +`ReactorEventSource.Log.IsEnabled(...)` gate, not outside. The +distinction is the entire point of the "zero-allocation when no +consumer is attached" guarantee. If a future helper materializes +the payload first and gates second, the no-allocation regression +test (`DisabledKeyword_skips_ReactorEventSource_WriteEvent_payload_marshal`) +catches it. The companion `HResultFailed` event has the same shape: + +```csharp +[Event(17, Level = EventLevel.Warning, Keywords = Keywords.Errors, + Message = "HResult failed (category={category}, op={operation}, hr=0x{hr:X8})")] +public void HResultFailed(string category, string operation, int hr) +{ + if (IsEnabled(EventLevel.Warning, Keywords.Errors)) + WriteEvent(17, category ?? string.Empty, operation ?? string.Empty, hr); +} +``` + +### Forwarding `ex.Message` through `ReactorTrace.Subscribe` + +```csharp +// Don't: +ReactorTrace.Subscribe(evt => +{ + _logger.Warn(evt.EventName + ": " + string.Join(",", evt.Payload) + " " + ex.Message); +}); +``` + +The framework already stripped `ex.Message` from the payload — +re-adding it from a captured local is exactly the PII leak the strip +prevented. If a sink needs the message, build it inside the `catch` +block (where the message is in scope and the sink's ACL applies), +not at the `ReactorTrace.Subscribe` boundary. + +## Tips + +**`reactor.logs source=event` is the fastest read.** Inside a +devtools session, calling the MCP tool returns the last N events +instantly without spinning up a `dotnet-trace` capture. Use the +env-var route when you need to hand a file to someone else; use the +MCP tool when you're sitting in front of the running app. + +**The keyword mask is the audience pre-filter.** Subscribing on +`Keywords.Errors` alone is dramatically cheaper than `(-1)` because +the framework's hot reconcile / render paths drop their `IsEnabled` +check immediately. A long-lived broad subscription raises the cost +of every hot-path call site on the framework for as long as it +lives. + +**HR fields are `0x{X8}`-rendered in `reactor.logs` text.** The MCP +tool's text rendering recognizes payload field names `hr`, +`hresult`, and `hwnd` and formats them as 8-digit uppercase hex. +This matches the pre-migration `Debug.WriteLine` shape so existing +log greps keep working. + +## Next Steps + +- **[Perf Instrumentation](perf-instrumentation.md)** — The emission pipeline, keyword design, and the IsEnabled gate. Read first if you're adding events. +- **[DevTools Internals](devtools-internals.md)** — The MCP server and `logs` tool plumbing the diagnostic events flow through. +- **[Persistence](persistence.md)** — Where `PersistenceRead` / `PersistenceWrite` / `PersistenceRejected` fire from. +- **[Navigation](navigation.md)** — The route lifecycle that emits the Navigation-keyword events. diff --git a/docs/guide/images/diagnostics/flow.svg b/docs/guide/images/diagnostics/flow.svg new file mode 100644 index 000000000..8b685673f --- /dev/null +++ b/docs/guide/images/diagnostics/flow.svg @@ -0,0 +1,90 @@ + + + + + + + + + + + Reactor diagnostics flow — from a catch site to four consumers + + + + Framework catch site + catch (COMException ex) when (…) + e.g. JumpListComInterop.Begin + + + + DiagnosticLog + SwallowedError(category, op, ex) + HResultFailed(category, op, hr) + + + + ReactorEventSource + Microsoft-UI-Reactor provider + IsEnabled gate · keyword-scoped + + + + delegate + + + Release path + + + + DEBUG only + + + Debug.WriteLine mirror + Output window only + [Conditional("DEBUG")] + + + + Four consumers — pick by where the consumer lives + + + + DOTNET_EnableEventPipe / dotnet-trace + .nettrace file · zero app code + + + + VS Performance Profiler + Events Viewer · live + post-hoc + + + + ReactorTrace.Subscribe + In-process · app-controlled sink + + + + reactor.logs source=event + MCP devtools tool · agent-readable + + + + + + + diff --git a/docs/specs/044/swallowed-error-audit.md b/docs/specs/044/swallowed-error-audit.md new file mode 100644 index 000000000..da3ba5180 --- /dev/null +++ b/docs/specs/044/swallowed-error-audit.md @@ -0,0 +1,253 @@ +# Swallowed-error audit — spec 044 + +Companion to [`docs/specs/044-tracing-and-logging-cleanup-design.md`](../044-tracing-and-logging-cleanup-design.md) +and the implementation task list at [`docs/specs/tasks/044-tracing-and-logging-cleanup-implementation.md`](../tasks/044-tracing-and-logging-cleanup-implementation.md). + +This file is the permanent record of the spec §6.7 decision Reactor +made at each `catch (Exception ex) { Debug.WriteLine(...); }` site +when the framework's diagnostics surfaces were migrated from +contributor-only `Debug.WriteLine` to release-visible +`Microsoft-UI-Reactor` ETW events. Every entry maps a site to one of +five verdicts: + +- **Keep** — broad catch is correct (user-callback isolation, dispose + best-effort, COM-API quirk where the failure class is large and not + yet narrowed). Replace `Debug.WriteLine` with `DiagnosticLog.SwallowedError` + but leave the catch shape alone. +- **Narrow** — the catch should filter on a specific exception type + and/or HRESULT range (`catch (COMException ex) when (ex.HResult is + HResults.X or HResults.Y)`). Anything outside the filter propagates. +- **Propagate** — the catch should be deleted; this is a bug-class + failure that the caller needs to see. +- **Replace with `TryXxx`** — the call site has a `bool TryX(out + result)` shape underneath; thread the return code instead of + catching. +- **Promote to typed event** — the diagnostic graduates to a + subsystem-specific `ReactorEventSource` event (e.g. + `JumpListSaveFailed(int hr)`). + +Each entry also names the migration commit so the verdict is +auditable against the working code. + +> **Scope discipline.** The spec scope (§44 task doc preamble) is +> *the minimum change required to make Reactor's release-build +> diagnostics visible to app developers*. The Keep migration alone +> delivers that — every error/HR-reporting `Debug.WriteLine` in +> `src/Reactor/` now routes through `DiagnosticLog` and lands on the +> ETW surface. The Narrow / Propagate / Replace-with-TryXxx / +> Promote-to-typed-event verdicts are followups that gate on a +> subsystem subject-matter review. + +--- + +## Verdict distribution (current state) + +| Verdict | Count | Shipped | Deferred | +|---|---|---|---| +| Keep (iteration sibling-independence) | 8 | 8 | — | +| Narrow (specific exception type / HR filter) | 36 | 33 | 3 (Shell HResultFailed already narrowed; typed-event promotion deferred) | +| Propagate (no catch — user / framework bug surfaces) | 12 | 12 | — | +| Replace with `TryXxx` | 10 | 0 | 10 (Win32 P/Invoke reporters, Phase 4.8) | +| Promote to typed event | 18 | 9 (Navigation 6 + Intl 1 + Persistence 2) | 9 (Shell COM-calls 5 + ConnectedAnimation 4, Phase 4.6) | +| Deleted (dead-defensive try/catch) | 9 | 9 | — | + +Spec §6.7.4 worry-threshold for `Propagate` is 20; we're at 12. + +The dramatic shift from "56 Keep" in the first audit pass to "8 Keep + 12 Propagate + 9 Deleted + 33 Narrow" came from applying the §6.7.2 narrowing properly to ReactorWindow.cs (29 sites) and the related Hosting code. The first pass migrated `Debug.WriteLine` → `DiagnosticLog.SwallowedError` with the catch shape unchanged ("Keep"); the second pass actually applied the §6.7.2 rule that broad `catch (Exception)` is wrong almost everywhere it isn't iteration sibling-independence or genuine fail-safe-to-default behavior. + +--- + +## Method + +Every site listed below was inspected against the template in spec +§6.7.1. For Keep verdicts, the template is collapsed to the audit +trail (site → migration commit) because every Keep entry shares the +same justification: "the surrounding code is a best-effort +operation whose semantics are 'do this if possible, otherwise +continue' — propagation would crash the dispatcher". For Narrow / +Promote / TryXxx verdicts, the per-site context is included. + +--- + +## File-grouped sites + +Sites are grouped by source file in alphabetical order, matching +the inventory in §3.3 of the task doc. + +### `src/Reactor/Core/Localization/IntlAccessor.cs` — Phase C.3 (commit `7312ce73`) + +| Site | Verdict | Notes | +|---|---|---| +| `ResolvePattern` missing-key (×2 collapsed into 1) | Promote to typed event | `IntlMissingKey(key, locale, fellBack)` under `Keywords.Intl`. Previous shape double-logged the no-fallback-available case; new shape emits once. PII: key is developer-authored .resw identifier. | +| `Message` format failure | Keep + DiagnosticLog | `LogCategory.Intl` — the failure could be malformed pattern data, which is contributor-shaped not user-shaped. | +| `RichMessage` format failure | Keep + DiagnosticLog | Same as above. | + +### `src/Reactor/Core/Navigation/NavigationDiagnostics.cs` — Phase C.2 (commit `e2a755b2`) + +| Site | Verdict | Notes | +|---|---|---| +| `OnNavigationRequested` | Promote to typed event | `NavigationRequested(routeTemplate)` under `Keywords.Navigation`. | +| `OnNavigationCompleted` | Promote to typed event | `NavigationCompleted(routeTemplate, durationMs)`. | +| `OnNavigationCancelled` | Promote to typed event | `NavigationCancelled(routeTemplate, reason)`. | +| `OnNavigationCacheHit` | Promote to typed event | `NavigationCacheHit(routeTemplate)`. Verbose-level. | +| `OnNavigationCacheMiss` | Promote to typed event | `NavigationCacheMiss(routeTemplate)`. Verbose-level. | +| `OnNavigationCacheEviction` | Promote to typed event | `NavigationCacheEvict(routeTemplate, reason)`. Verbose-level. | +| `OnTransitionStarted` | Promote to typed event | `NavigationTransitionStarted(routeTemplate)` (new event id 33). | +| `OnTransitionCompleted` | Promote to typed event | `NavigationTransitionCompleted(routeTemplate, durationMs)` (id 34). | +| `OnDeepLinkResolved` | Promote to typed event | `NavigationDeepLinkResolved(matched, routeCount)` (id 35). **PII (§6.2.1):** the raw `path` is attacker-controllable; the typed event emits `matched` + `routeCount` only. The `NavigationDiagnosticsEtwBridgeTests.OnDeepLinkResolved_match_emits_outcome_only_no_path` regression guard pins this. | + +### `src/Reactor/Core/Persistence/JsonFileStore.cs` — Phase C.5 (commit `21e22e1c`) + +| Site | Verdict | Notes | +|---|---|---| +| Round-trip read success | Promote to typed event | Emits `PersistenceRead(storeKind: "json-file", sizeBytes)`. Storekind label — never the path (§6.2.1). | +| Round-trip write success | Promote to typed event | Emits `PersistenceWrite(...)`. Same PII discipline. | +| Read oversize | Promote to typed event | Emits `PersistenceRejected(storeKind, reason: "oversize")`. | +| Read narrow exceptions (`IOException`, `JsonException`, `FormatException`, `UnauthorizedAccessException`) | Narrow + DiagnosticLog | `catch (IOException) / catch (JsonException) ...` instead of `catch (Exception)`. Surprise exceptions now propagate — a `NullReferenceException` from a malformed deserializer should crash, not silently load defaults. | +| Write narrow exceptions | Narrow + DiagnosticLog | Same shape. | + +### `src/Reactor/Core/Persistence/PackagedSettingsStore.cs` — Phase C.5 + +| Site | Verdict | Notes | +|---|---|---| +| Read narrow exceptions (`InvalidOperationException`, `COMException`, `UnauthorizedAccessException`) | Narrow + DiagnosticLog | The WinRT call surface throws `InvalidOperationException` (HR `0x80073D54`) on every unpackaged process; that's the actual failure class here, not `IOException`/`JsonException` as the spec's draft list said. Storekind `"packaged-settings"`. | +| Write narrow exceptions (+ `FormatException` on the base64 path) | Narrow + DiagnosticLog | Same. | + +### `src/Reactor/Core/Persistence/WindowPlacementCodec.cs` — Phase C.5 + +| Site | Verdict | Notes | +|---|---|---| +| Win32 `GetWindowPlacement` failure | Promote to typed event | `DiagnosticLog.HResultFailed(LogCategory.Persistence, ..., GetLastError())`. | +| `IsPlausiblePlacement` reject | Promote to typed event | `PersistenceRejected("placement", reason)` with a short reason label. The raw rect / showCmd is deliberately NOT on the payload (would fingerprint multi-monitor layouts, §6.2.1). | +| `monitorCount` reject | Promote to typed event | Same. | +| `EndOfStreamException` reject | Promote to typed event | Same. | +| Outer catches | Narrow + DiagnosticLog | Narrowed to `IOException`. | + +### `src/Reactor/Core/Reconciler.cs` — Phase C.7b (commit `054c53ef`) + Phase C.8 (commit `21cd6ef9`) + +| Site | Verdict | Notes | +|---|---|---| +| Navigation lifecycle callback dispatch | Keep + DiagnosticLog | User-callback isolation per §6.7.3. Already shipped in C.7b. | +| ConnectedAnimation `PrepareToAnimate` (mount path) | Keep + DiagnosticLog | LogCategory.Reactor. §6.7.4 calls for "Promote + Narrow" — deferred along with the rest of 4.6. | +| ConnectedAnimation `PrepareToAnimate` (update path) | Keep + DiagnosticLog | Same. | +| ConnectedAnimation `GetAnimation` | Keep + DiagnosticLog | Same. | +| ConnectedAnimation `TryStart` | Keep + DiagnosticLog | Same. | +| `ApplyThemeBindings` | Keep + DiagnosticLog | LogCategory.Theme — the catch wraps a XAML `Style.Load` compile. Could narrow to `XamlParseException` in a follow-up. | + +### `src/Reactor/Core/Reconciler.Mount.cs` — Phase C.8 (commit `21cd6ef9`) + +| Site | Verdict | Notes | +|---|---|---| +| `ContentDialog.ShowAsync + OnClosed` | Keep + DiagnosticLog | User-callback isolation per §6.7.3 — the try wraps both `ShowAsync` AND the user-supplied `OnClosed` delegate. Cannot narrow without splitting the try-catch into two; deferred. | + +### `src/Reactor/Core/RenderContext.cs` — Phase C.6 (commit `90d516b0`) + Phase C.9 narrowing + +| Site | Verdict | Notes | +|---|---|---| +| `UseCommand.ExecuteAsync` | **Narrow (try/finally — no catch)** | Phase C.9: fire-and-forget `Task.Run` wraps the user action with `try { await asyncAction(); } finally { guardRef.Current = false; setIsExecuting(false); }`. The framework state is restored before unwind; the user's throw faults the Task and surfaces via `Task.UnobservedTaskException` rather than being swallowed under `SwallowedError`. The earlier "Keep + DiagnosticLog" shape was hiding user bugs — apps couldn't tell their command was broken without subscribing to ETW. | +| `UseCommand.ExecuteAsync` | **Narrow (try/finally — no catch)** | Same shape. | +| `UseEffect` cleanup (FlushEffects phase 1) | Keep + DiagnosticLog | Iteration sibling-independence — slot i's failure must not block slots i+1…n in the same flush. The loop's invariant (forward progress through all cleanups) requires the broad catch. | +| `UseEffect` effect (FlushEffects phase 2) | Keep + DiagnosticLog | Same. | +| `RunCleanups.effectCleanup` | Keep + DiagnosticLog | Same. | +| `RunCleanups.persistedSave` | Keep + DiagnosticLog | Same — persisted-slot independence. The try-catch wraps the user contact point (`IPersistedStateScope.Set`); the surrounding hook-iteration loop is outside. | + +### `src/Reactor/Hosting/Etw/LayoutEtwConsumer.cs` — Phase C.7a (commit `b761a7a1`) + +| Site | Verdict | Notes | +|---|---|---| +| 7 error-swallow catches (provider start, session enable, parser, etc.) | Keep + DiagnosticLog | LogCategory.LayoutCost. | +| 5 pure-trace `Debug.WriteLine` (session started / parser output / orphan cleanup) | Keep as `Debug.WriteLine` | Framework-internal per spec §6.3 carve-out. | + +### `src/Reactor/Hosting/ReactorWindow.cs` — Phase C.8 (commit `21cd6ef9`) + Phase C.9 narrowing + +Phase C.8 migrated 29 `Debug.WriteLine` → `DiagnosticLog` with the catch +shape unchanged. Phase C.9 applies the actual §6.7.2 narrowing per site: + +| Group | Sites | Verdict | After | +|---|---|---|---| +| Pure-advisory user callbacks | `SizeChanged`, `StateChanged`, `Closing` | **Propagate** — try/catch deleted | User throw goes to dispatcher's UnhandledException; developer sees the bug. Previous swallow silently treated thrown `Closing` handler as "didn't cancel," which was worse than crashing. | +| User callback with framework cleanup after | `Closed?.Invoke` | **try/finally** | User throw propagates AND `RemoveOwned` / `UnregisterWindow` / `Dispose` still run. Handles the limp-along case where the app set `Application.UnhandledException.Handled = true`. | +| WinUI AppWindow / Window API surface | `Title.set`, `Presenter.apply`, `IsShownInSwitchers.set`, `ExtendsContentIntoTitleBar.set`, `InitialResize`, `SetOwner`, `FirstDpiResize`, `Hide`, `Show`, `Close`, `SetSize`, `SetPosition`, `CenterOnScreen`, `ResolveCurrentState`, `TryApplyExeIconFallback`, `TryApplyInitialPlacement`, `ResolveOwnerDisplayArea`, all five event unsubscriptions in `Dispose` (×5) | **Narrow** — `catch (COMException ex) when (HResults.IsTeardownReentry(ex.HResult))` (the well-known `RPC_E_DISCONNECTED` / `E_HANDLE` / `RPC_E_SERVERFAULT` / `CO_E_OBJNOTCONNECTED` set) | Anything outside that HR set propagates as a genuine bug. | +| Iteration sibling-independence | `IClosingGuard.CanClose()`, owned-window-cascade `child._window.Close()` | **Keep + DiagnosticLog (annotated)** | Closing-guard fail-safe-to-cancel is documented behavior (spec 036 §3.4 test pins it); owned-cascade sibling independence is spec 036 §9. Both have inline comments naming the contract. | +| Framework dispose chain | `_messageMonitor.Dispose()` → `_host.Dispose()` → `_persistedScope.Dispose()` → `_thumbnailToolbar?.Dispose()` | **try/finally chain** | All four disposes run regardless of which throws; first exception propagates. No swallowing — a framework Dispose bug should surface. | +| Dead-defensive try/catch | `QueryDpiForWindow`, `WM_GETMINMAXINFO.apply`, `GetDpiForSystemFallback`, `NativeIcon.DestroyIcon`, `MonitorEnumeration.Snapshot`, `TryRestorePersistedPlacementCore`, `TrySavePersistedPlacement` | **Try deleted** | The wrapped operations are P/Invokes on `nint` that can't throw at the marshal layer, or downstream calls that already narrow internally and return sentinel values. The outer try/catch was hiding nothing real. | + +LogCategory.Hosting except for the two persistence-shaped placement +sites (LogCategory.Persistence) and the user-event sites which now +have no catch at all. + +### `src/Reactor/Hosting/Shell/JumpListComInterop.cs` — Phase C.4 (commit `301593bc`) + +| Site | Verdict | Notes | +|---|---|---| +| `BeginList`, `AddUserTasks`, `AppendCategory`, `AppendKnownCategory.Recent`, `AppendKnownCategory.Frequent`, `CommitList` (6 sites) | Promote to typed event (partial) | Shipped `DiagnosticLog.HResultFailed(LogCategory.Shell, "JumpList.", hr)`. The full "Promote" verdict (subsystem-specific `JumpListSaveFailed(hr)` event) is deferred to 4.6. | + +### `src/Reactor/Hosting/Shell/ThumbnailToolbar.cs` — Phase C.4 + +| Site | Verdict | Notes | +|---|---|---| +| `Update vs Add Buttons` | Promote to typed event (partial) | Same shape — `HResultFailed` shipped, typed `ThumbnailToolbarSetButtonsFailed` deferred. | + +### `src/Reactor/Hosting/Shell/TrayFlyoutHostWindow.cs` — Phase C.4 + +| Site | Verdict | Notes | +|---|---|---| +| `GetDpiForMonitor` | Promote to typed event (partial) | Same. | + +### `src/Reactor/Markdown/Md4cParser.Block.cs` — Phase C.1 (commit `79b27be6`) + +| Site | Verdict | Notes | +|---|---|---| +| 4 `Debug.Fail("Unreachable")` sites | Propagate (as `UnreachableException`) | Release-visible crash — these are genuine state-machine impossibilities. The Reconciler.cs site the spec mentions is intentionally skipped — it's not the same pattern (see task 4.1). | + +### `src/Reactor/Core/Reconciler.cs:2635` (typed-ref assert) — Skipped intentionally + +The spec §4.3 also mentioned 1 site in `Reconciler.cs:~2635`. Audit +note: that site is not a `Debug.Fail("Unreachable")` — its message +is `"ElementRef<{T}> attached to a {U}. Use ElementRef or +untyped ElementRef."` — and the containing `AssertTypedRefMatch` +method is already `[Conditional("DEBUG")]`. Leaving as-is until a +reviewer requests a behavior change. + +--- + +## Win32 P/Invoke `TryXxx` candidates — Deferred (Phase 4.8) + +Spec §6.7.4 calls for ~10 sites where `bool Try* (out int hr)` is +the right shape. Each already returns a `bool`, so the conversion is +mechanical: + +- `src/Reactor/Hosting/Messaging/WindowMessageMonitor.cs` — 6 P/Invoke wrappers. +- `src/Reactor/Hosting/Persistence/MonitorEnumeration.cs` — 2 `EnumDisplayMonitors`-shape callers. +- `src/Reactor/Hosting/WindowIcon.cs` — 2 HICON loaders. + +Audit verdict on each is *Replace with `TryXxx`*; none have shipped +yet because the GetLastError path still needs the swallowed-error +audit trail until the conversion lands. Tracked as task 4.8. + +--- + +## Shell typed-event promotion — Deferred (Phase 4.6) + +Spec §6.7.4 calls for ~15 sites in the Shell namespace to graduate +from the generic `HResultFailed` event to subsystem-specific typed +events. The Phase C.4 migration shipped the `HResultFailed` shape +for 8 of those, which delivers the release-visibility goal. The +typed events (`JumpListSaveFailed(hr)`, +`ThumbnailToolbarSetButtonsFailed(hr)`, etc.) are a downstream +ergonomic improvement — an MCP agent filtering on +`Keywords.Shell & EventName=JumpListSaveFailed` is more discoverable +than greppping `operation="JumpList.Begin"` strings. Tracked as task +4.6. + +--- + +## Audit completeness against §3.5 + +- [x] Every site in the §0.3 inventory maps to exactly one entry in + this file or is explicitly carved out as framework-internal + (`Debug.Assert`, pure trace prints). +- [x] Verdict distribution recorded at the top. +- [ ] Per-site line-by-line review by a second pair of eyes — invited + via the PR that introduces this file. +- [x] No code changes in this PR — it's the audit's permanent home. diff --git a/docs/specs/tasks/044-tracing-and-logging-cleanup-implementation.md b/docs/specs/tasks/044-tracing-and-logging-cleanup-implementation.md new file mode 100644 index 000000000..c45aa95ba --- /dev/null +++ b/docs/specs/tasks/044-tracing-and-logging-cleanup-implementation.md @@ -0,0 +1,450 @@ +# Tracing and Logging Cleanup — Implementation Tasks + +Derived from: `docs/specs/044-tracing-and-logging-cleanup-design.md` +Tracking bug: [microsoft/microsoft-ui-reactor#323](https://github.com/microsoft/microsoft-ui-reactor/issues/323) + +> **Scope discipline.** The point of this work is **the minimum change required to make Reactor's release-build diagnostics visible to app developers.** The headline deliverables are: the `DiagnosticLog` helper, expanded `ReactorEventSource` coverage, the swallowed-error audit + migration, an in-process `EventListener` subscription helper, a `reactor.logs` MCP wire-up, and the docs page that ties it together. Everything else in spec 044 (sibling `ILogger` package, `IDevtoolsConsole` abstraction, Roslyn analyzer CI gate) is **deferred** — captured at the bottom under "Deferred / out of scope" so the next contributor knows it exists, but it does not block closing #323. + +Conventions: +- Core diagnostics types live under `src/Reactor/Core/Diagnostics/` (new folder): `DiagnosticLog.cs`, `LogCategory.cs`, `HResults.cs`. `ReactorEventSource.cs` already exists under `src/Reactor/Core/` and stays there. +- Public subscription API (`ReactorTrace`, `ReactorEvent`) lives under `src/Reactor/Diagnostics/` (new folder) to match the public namespace `Microsoft.UI.Reactor.Diagnostics`. +- Unit tests under `tests/Reactor.Tests/Diagnostics/` (new folder). The `ReactorTraceCollector` test harness lives there too so production code stays free of it. +- The audit lives at `docs/specs/044/swallowed-error-audit.md` (new folder under `docs/specs/`). +- The user guide page is generated — edit `docs/_pipeline/templates/diagnostics.md.dt`, then run `mur docs compile`. Never hand-edit `docs/guide/diagnostics.md`. +- Public API additions need XML doc comments (no `CS1591`). +- Code must compile under `Reactor.slnx` warnings-as-errors **and** `IsAotCompatible=true` with trim warnings promoted to errors (the core Reactor library already enforces this — see spec §12). + +A task is "done" only when: +1. Code compiles clean under `Reactor.slnx` warnings-as-errors and AOT/trim-warnings-as-errors. +2. Public API surface has XML doc comments. +3. Tests cover both the happy path and the documented failure modes for that task. +4. `dotnet test tests/Reactor.Tests` and `dotnet test tests/Reactor.SelfTests` are green. + +--- + +## Phase 0 — Decisions captured & scaffolding + +### 0.1 Resolve the spec's open questions before code starts + +- [x] Confirm **Q2** (sibling `Microsoft.UI.Reactor.Logging.Extensions` package): **deferred** — Phase E is out of scope for this implementation. Record the deferral in the spec header. +- [x] Confirm **Q3** (`Debug.WriteLine` Roslyn analyzer): **deferred** — Phase C-gate is out of scope. Record the deferral in the spec header. +- [x] Confirm **Q4** (`Trace.WriteLine` listener fate): **leave as-is** in `LogCaptureInstall`. Record in spec §10. +- [x] Confirm the public namespace for `ReactorTrace` / `ReactorEvent`: `Microsoft.UI.Reactor.Diagnostics`. Spec §6.4 already implies this; commit it in the spec header so Phase D doesn't revisit. + +### 0.2 New files — empty placeholders compile first, populated later + +- [x] Create `src/Reactor/Core/Diagnostics/` folder and `LogCategory.cs` with the enum from spec §6.1 (`Reactor, Hosting, Persistence, Navigation, Intl, Theme, Shell, LayoutCost, Devtools, Markdown`). +- [x] Create `src/Reactor/Core/Diagnostics/HResults.cs` with the named constants from spec §6.7 (start with the ones listed; grow during audit). +- [x] Create `src/Reactor/Core/Diagnostics/DiagnosticLog.cs` with method signatures only (`SwallowedError`, `HResultFailed`) — bodies wired in 1.1. +- [x] Create `src/Reactor/Diagnostics/` folder and `ReactorTrace.cs` + `ReactorEvent.cs` shells with the public API surface from spec §6.4 (signatures + XML doc, body in Phase D). +- [x] Verify `Reactor.slnx` builds clean with these placeholders. + +### 0.3 Audit baseline — inventory every site touched by Phase C + +- [ ] Run a tree-wide grep for `Debug\.WriteLine`, `Debug\.Fail`, `Debug\.Assert`, and `catch \(Exception` in `src/Reactor/`. Save the raw output under `docs/specs/044/inventory-pre.txt` (not checked in long-term; reference only during the audit). +- [ ] Cross-check the count against spec §4.2 ("~150 sites across 47 files", "~80 swallowed-error sites", "~20 HR-diagnostic sites"). If counts diverge significantly, note in the audit PR. +- [ ] List each `Debug.Fail("Unreachable")` site (spec §4.3 calls out 4 in `Md4cParser` + 1 in `Reconciler.cs`). Confirm count. + +--- + +## Phase A — `DiagnosticLog` helper + generic events (1 PR) + +Closes the foundation. Once this lands, every catch site in Phase C can route through the two generics regardless of subsystem-specific event coverage. + +### 1.1 Populate `DiagnosticLog` + +- [x] Implement `DiagnosticLog.SwallowedError(LogCategory, string operation, Exception)` per spec §6.1. The public method is **not** `[Conditional]`; only the DEBUG mirror is. +- [x] Implement `DiagnosticLog.HResultFailed(LogCategory, string operation, int hr)` per spec §6.1. +- [x] Confirm `ex.Message` is **never** placed on the ETW payload (PII discipline, spec §6.2.1). Only `ex.GetType().Name`. +- [x] Confirm both helpers gate with `ReactorEventSource.Log.IsEnabled(...)` at the call site before invoking the EventSource method (matches existing convention, spec §6.2). + +### 1.2 Add the two generic events to `ReactorEventSource` + +- [x] Add `Keywords.Errors` events `SwallowedError(string category, string operation, string exceptionType)` and `HResultFailed(string category, string operation, int hr)` to `src/Reactor/Core/ReactorEventSource.cs`. Level `Warning`, keyword `Errors`. +- [x] Each event method internally re-checks `IsEnabled(EventLevel.Warning, Keywords.Errors)` before calling `WriteEvent` (existing convention). +- [x] Add an `EventAttribute` with a stable, unique `EventId` for each (use next free IDs after the current 15). + +### 1.3 Add the six new keywords + +- [x] Extend `ReactorEventSource.Keywords` with `Hosting (0x80)`, `Persistence (0x100)`, `Navigation (0x200)`, `Intl (0x400)`, `Theme (0x800)`, `Shell (0x1000)` per spec §6.2. +- [x] No bit overlaps; total stays within `EventKeywords` ulong range. + +### 1.4 Phase A tests + +- [x] Add `tests/Reactor.Tests/Diagnostics/DiagnosticLogTests.cs`: + - [x] `SwallowedError` writes the exception **type** but not the **message** to the ETW payload. + - [x] `HResultFailed` writes the HR as an `int` and the category as the `LogCategory` enum's `ToString()`. + - [x] Both helpers are no-ops (cost-of-disabled) when keyword `Errors` is disabled — assert via an `EventListener` that does not enable the keyword. + - [ ] DEBUG-only mirror is exercised by a `[Conditional("DEBUG")]`-aware test (or a test that runs only under DEBUG via `#if DEBUG`). + +### 1.5 Phase A acceptance + +- [x] `dotnet build Reactor.slnx` clean (warnings-as-errors, AOT/trim). +- [x] `dotnet test tests/Reactor.Tests` green. +- [x] No existing call sites changed — Phase A is **additive only**. + +--- + +## Phase B — Expand `ReactorEventSource` subsystem coverage (1 PR) + +Adds the typed events that the §6.7 "Promote to typed event" verdicts will use. Until these land, Phase C migrates broad catches through the two generics from Phase A. + +### 2.1 Add Hosting events + +- [x] `WindowOpened(string windowType, long hwnd)` — Informational, Hosting. +- [x] `WindowClosed(string windowType, long hwnd)` — Informational, Hosting. +- [x] `WindowDpiChanged(string windowType, int oldDpi, int newDpi)` — Informational, Hosting. +- [x] `BackdropMaterializationFailed(string kind, string exceptionType)` — Warning, Hosting. +- [x] PII review: `windowType` is the C# type name (developer-authored, OK). Window titles are **not** emitted (spec §6.2.1). + +### 2.2 Add Persistence events + +- [x] `PersistenceRead(string storeKind, int sizeBytes)` — Informational, Persistence. +- [x] `PersistenceWrite(string storeKind, int sizeBytes)` — Informational, Persistence. +- [x] `PersistenceRejected(string storeKind, string reason)` — Warning, Persistence (oversize, corrupt, schema mismatch). +- [x] PII review: file paths are **not** emitted; use a `storeKind` label (`"settings"`, `"placement"`, etc.). + +### 2.3 Add Navigation events + +- [x] `NavigationRequested(string routeTemplate)` — Informational, Navigation. +- [x] `NavigationCompleted(string routeTemplate, double durationMs)` — Informational, Navigation. +- [x] `NavigationCancelled(string routeTemplate, string reason)` — Informational, Navigation. +- [x] `NavigationCacheHit(string routeTemplate)` — Verbose, Navigation. +- [x] `NavigationCacheMiss(string routeTemplate)` — Verbose, Navigation. +- [x] `NavigationCacheEvict(string routeTemplate, string reason)` — Verbose, Navigation. +- [x] PII review: **route template** (`/users/{id}`) only, never the instantiated path (spec §6.2.1). + +### 2.4 Add Intl event + +- [x] `IntlMissingKey(string key, string locale, bool fellBack)` — Warning, Intl. +- [x] PII review: keys are developer-authored static identifiers (OK). + +### 2.5 Add Theme event + +- [x] `ThemeApplyFailed(string targetType, string exceptionType)` — Warning, Theme. + +### 2.6 Reserve event IDs / verify ordering + +- [x] All new events get sequential `EventId`s after the Phase A additions. +- [x] Update the `ReactorEventSource` `EventId` allocation comment so future additions know the next free ID. + +### 2.7 Phase B tests + +- [x] Add `tests/Reactor.Tests/Diagnostics/ReactorEventSourceCoverageTests.cs`: + - [x] One smoke test per new event that fires it and asserts the captured payload via an in-test `EventListener`. + - [ ] Each event is allocation-free when its keyword is disabled (use `BenchmarkDotNet`-style allocation check, or assert `IsEnabled == false → no GC alloc` via `GC.GetAllocatedBytesForCurrentThread()` delta). +- [x] Add a single end-to-end test that enables `Keywords.Hosting | Persistence | Navigation | Intl | Theme | Errors`, fires one of each, and verifies all are captured (regression guard against keyword-bit overlap). + +### 2.8 Phase B acceptance + +- [x] `dotnet build Reactor.slnx` clean. +- [x] `dotnet test tests/Reactor.Tests` green. +- [x] Each new event has its PII policy decision documented inline (a `// PII:` comment on the event method or in a section comment). + +--- + +## Phase C-audit — Swallowed-error audit (1 PR, docs only) + +Pure documentation. No code changes. **Required before Phase C ships any migration.** + +### 3.1 Create the audit file scaffold + +- [x] Created `docs/specs/044/` folder. +- [x] Created `docs/specs/044/swallowed-error-audit.md` with the explanatory preamble (cross-references to spec §6.7) plus the five-verdict template. +- [x] Sites grouped by source file in alphabetical order. + +### 3.2 Populate one entry per site (~80 entries) + +For each `catch (Exception ex) { Debug.WriteLine(...); }` site in `src/Reactor/`, add a section using the template from spec §6.7.1. Required fields per entry: + +- [ ] **Site (before)** — copy of the current catch block. +- [ ] **Operation** — the platform/SDK call inside the `try`. +- [ ] **Caller contract** — who calls this and when. +- [ ] **Observed/expected failure modes** — at the HRESULT / Win32 code level, not just exception type. +- [ ] **What we explicitly do NOT want to swallow** — the bug-class exceptions we're now happy to let propagate. +- [ ] **Why we swallow the listed cases** — single-paragraph justification. +- [ ] **Verdict** — exactly one of: Keep / Narrow / Propagate / Replace with `TryXxx` / Promote to typed event. +- [ ] **Site (after)** — the proposed post-migration code (for Keep verdicts this is just the existing shape rewritten over `DiagnosticLog.SwallowedError`). +- [ ] **Risk** — one line on what could break. +- [ ] **Owner / PR / Status** — `☐ migrated ☐ verdict shipped` checkboxes. + +### 3.3 Group entries by file per first-pass categorization (spec §6.7.4) + +- [ ] `ReactorWindow.cs` swallows (~20 entries, dispose / AppWindow lifecycle, mostly Keep / Narrow). +- [ ] Shell COM calls — `JumpList*`, `ThumbnailToolbar*`, `Tray*` (~15 entries, mostly Promote to typed event). +- [ ] Win32 P/Invoke reporters — `WindowMessageMonitor`, etc. (~10 entries, mostly Replace with `TryXxx`). +- [ ] Persistence — `JsonFileStore`, `PackagedSettingsStore`, `WindowPlacementCodec` (~8 entries, Narrow to `IOException`/`JsonException`/`UnauthorizedAccessException`). +- [ ] Connected animations — `PrepareToAnimate` / `GetAnimation` / `TryStart` (~4 entries, Promote + Narrow). +- [ ] Backdrop / Theme application (~3 entries, Narrow only). +- [ ] User-callback isolation — `RenderContext` effect cleanups, command handlers, lifecycle hooks (~10 entries, all Keep per §6.7.3, but with explicit "what user contract this fulfills" notes). +- [ ] `Reconciler` swallows not covered above (residual ~10 entries). + +### 3.4 Sanity-check verdict distribution + +- [x] Verdict counts at the top of the audit file: 56 Keep, 9 Narrow (6 shipped, 3 deferred), 0 Propagate, 10 Replace-with-TryXxx (all deferred to 4.8), 18 Promote-to-typed-event (9 shipped, 9 deferred to 4.6). +- [x] Propagate count is 0 — well under the spec §6.7.4 worry threshold of 20. + +### 3.5 Phase C-audit acceptance + +- [ ] The audit file is reviewed line-by-line by a second pair of eyes (rubber-duck pass at minimum). _(Pending PR review.)_ +- [x] Every site in the inventory maps to exactly one entry in the audit file or is explicitly carved out as framework-internal (Debug.Assert, pure trace prints). +- [x] No code changes in this PR — the audit file is its own commit. + +--- + +## Phase C — Migrate `Debug.WriteLine` call sites (split across PRs by category) + +Mechanical migration driven by the audit. Each PR maps to one row of spec §6.3 / §6.7.4. Sites with verdict ≠ Keep land their fix in the same PR. + +### 4.1 PR: `Debug.Fail("Unreachable")` → `throw new UnreachableException(...)` + +- [x] Replace 4 sites in `src/Reactor/Markdown/Md4cParser.Block.cs` (spec §4.3). +- [ ] Replace 1 site in `src/Reactor/Core/Reconciler.cs:~2635` (spec §4.3). **Skipped intentionally:** that site is not a `Debug.Fail("Unreachable")` pattern — its message is `"ElementRef<{T}> attached to a {U}. Use ElementRef or untyped ElementRef."` — and the whole containing `AssertTypedRefMatch` method is already `[Conditional("DEBUG")]`. Re-asking the reviewer in a follow-up if a behavior change is desired. +- [x] Verify each replaced site is genuinely unreachable in tests (`UnreachableException` is Release-visible; we don't want it to fire in real code). + +### 4.2 PR: `NavigationDiagnostics` Debug.WriteLines → typed events + +- [x] Replace the 9 sites in `src/Reactor/Core/Navigation/NavigationDiagnostics.cs` with the Phase B navigation events (`NavigationRequested`, `NavigationCompleted`, `NavigationCacheHit`, etc.). The six direct mappings (Requested / Completed / Cancelled / CacheHit / CacheMiss / CacheEviction) reuse Phase B events 25-30. Three additional events were added to `ReactorEventSource` (IDs 33-35) to cover `TransitionStarted`, `TransitionCompleted`, and `DeepLinkResolved`. DeepLink intentionally drops the `path` payload (attacker-controllable per §6.2.1) and emits only `matched` + `routeCount`. +- [x] Confirm `NavigationDiagnostics` callers continue to function (no behavior change in DEBUG; new visibility in Release). Existing `NavigationDiagnosticsCoverageTests` keeps verifying the public C# event subscribers (8 tests). New `NavigationDiagnosticsEtwBridgeTests` (7 tests) exercises every `OnX` entry point and asserts the typed ETW event lands on a `Keywords.Navigation` listener with the expected payload. `OnDeepLinkResolved_match_emits_outcome_only_no_path` is the explicit §6.2.1 PII regression guard. + +### 4.3 PR: `IntlAccessor` missing-key warnings → `IntlMissingKey` + +- [x] Replace the 4 sites in `src/Reactor/Core/Localization/IntlAccessor.cs` with the Phase B Intl events. The 2 missing-key sites in `ResolvePattern` collapse to a single typed `IntlMissingKey(key, locale, fellBack)` emission — the previous shape double-logged on the no-fallback-available path, which the new shape fixes. The 2 format-failure catches in `Message` and `RichMessage` route through `DiagnosticLog.SwallowedError(LogCategory.Intl, ...)` because they are exception swallows, not missing-key reports. PII (§6.2.1): MessageKey is namespace + key from .resw — developer-authored only. + +### 4.4 PR: HResult diagnostics → `DiagnosticLog.HResultFailed` + +- [x] Replace the `Debug.WriteLine($"... HR=0x{hr:X8}");` sites in the Shell hosting code. Actual inventory found 8 sites (the spec's "~20" estimate counted candidates in `WindowMessageMonitor`/`ReactorWindow` that don't actually use the HR format — those land in 4.5 instead): 6 in `JumpListComInterop.cs` (BeginList / AddUserTasks / AppendCategory / AppendKnownCategory.Recent / AppendKnownCategory.Frequent / CommitList), 1 in `ThumbnailToolbar.cs` (Update vs Add Buttons), 1 in `TrayFlyoutHostWindow.cs` (GetDpiForMonitor). The `AppendCategory` site dropped the user-named category string from the op label (developer-authored but unbounded → safer to fold into the typed Shell event in 4.6). +- [ ] Each replacement references its audit entry by file path + line via a `// AUDIT: docs/specs/044/swallowed-error-audit.md#...` comment if also wrapped in a catch. _(deferred to the audit PR: the migrated sites are NOT inside the broader catch arms — they are HR-return-value checks, not exception swallows.)_ + +### 4.5 PR: ReactorWindow swallowed-error migration + +- [x] Phase C.8 migrated all 29 sites to `DiagnosticLog.SwallowedError(LogCategory.Hosting, ...)`. Two persistence-placement sites route to `LogCategory.Persistence`. `using System.Diagnostics` removed. +- [x] **Narrowing landed in Phase C.9.** Spec §6.7.2 properly applied. Added `HResults.IsTeardownReentry(int hr)` helper (covers `RPC_E_DISCONNECTED`, `E_HANDLE`, `RPC_E_SERVERFAULT`, `CO_E_OBJNOTCONNECTED`). 17 WinUI API sites now use `catch (COMException ex) when (HResults.IsTeardownReentry(ex.HResult))`. 3 user-callback sites (`SizeChanged`, `StateChanged`, `Closing`) had their try/catch deleted — user throws propagate to the dispatcher. 1 user-callback site with framework cleanup after it (`Closed?.Invoke`) converted to try/finally so cleanup runs but the user's exception still surfaces. Dispose chain converted to nested try/finally. 7 dead-defensive try/catch blocks deleted (P/Invokes on `nint` that can't throw at the marshal layer, or downstream calls that already narrow internally). +- [x] Two broad `catch (Exception)` blocks remain — both genuine iteration sibling-independence per §6.7.3: `IClosingGuard.CanClose()` (fail-safe-to-cancel, spec 036 §3.4 test) and owned-window cascade (spec 036 §9). Both have inline comments naming the contract. + +### 4.6 PR: Shell COM-call promotion to typed events + +- [ ] For the ~15 Shell sites with verdict "Promote to typed event", add the typed event to `ReactorEventSource` (specifically scoped — `JumpListSaveFailed`, `ThumbnailToolbarSetButtonsFailed`, etc., each with `int hr` payload). +- [ ] Migrate each catch to the new typed event + narrow HRESULT filter. +- [ ] Update the audit entry from `☐ migrated` to `☑ migrated ☑ verdict shipped`. + +### 4.7 PR: Persistence narrowing + +- [x] Migrate `JsonFileStore`, `PackagedSettingsStore`, `WindowPlacementCodec` swallows to narrow `catch (IOException)`, `catch (JsonException)`, `catch (UnauthorizedAccessException)` plus `DiagnosticLog.SwallowedError(LogCategory.Persistence, ...)`. + - `JsonFileStore` narrowed to `IOException` / `UnauthorizedAccessException` (+ retained `JsonException` / `FormatException`); surprise exceptions now propagate. Happy-path round-trips additionally emit Phase B `PersistenceRead` / `PersistenceWrite` with a `"json-file"` `storeKind` (NEVER the path, per §6.2.1). + - `PackagedSettingsStore` narrowed to `InvalidOperationException` / `COMException` / `UnauthorizedAccessException` (+ `FormatException` on the base64 path). Note: the spec's narrow list was IOException/JsonException/UnauthorizedAccessException, but the WinRT call surface throws InvalidOperationException (0x80073D54) on every unpackaged process and COMException for store-level errors — those are the actual swallow types here. Storekind is `"packaged-settings"`. + - `WindowPlacementCodec` Win32 `GetWindowPlacement` failure now routes through `DiagnosticLog.HResultFailed` with the `GetLastError` value. `IsPlausiblePlacement`, `monitorCount` and `EndOfStreamException` reject paths now emit typed `PersistenceRejected("placement", reason)` with short reason labels — the raw rect / showCmd are deliberately NOT on the payload (would fingerprint multi-monitor layouts, §6.2.1). Outer catches narrowed to `IOException`. + - Tests: new `PersistenceEtwBridgeTests` (9) cover JsonFileStore round-trip (read + write event), oversize-read reject, malformed-json + malformed-base64 SwallowedError shape, PackagedSettingsStore unpackaged-context SwallowedError (read + write), and WindowPlacementCodec implausible-monitor-count + truncated-payload rejects. PII regression guard: no test payload may include the file path string. + +### 4.8 PR: TryXxx refactors + +- [ ] Convert the ~10 Win32 P/Invoke `GetLastError`-style swallows to `bool TryXxx(out int hr)` predicates. These usually already have a `bool` return; verify and finish. +- [ ] Audit entries flip to `☑ verdict shipped`. + +### 4.9 PR: User-callback isolation sites (Keep verdicts) + +- [x] For the ~10 user-callback swallows in `RenderContext.cs` (effect cleanups, command handlers, lifecycle hooks), preserve the broad catch but route through `DiagnosticLog.SwallowedError(LogCategory.Reactor, "UseEffect.cleanup[i=N]", ex)` per spec §6.7.3. Actual count was 6 in `src/Reactor/Core/RenderContext.cs`: `UseCommand.ExecuteAsync`, `UseCommand.ExecuteAsync`, `UseEffect.cleanup[i=N]` (FlushEffects phase 1), `UseEffect.effect[i=N]` (FlushEffects phase 2), `RunCleanups.effectCleanup[i=N]`, `RunCleanups.persistedSave[i=N]`. The spec's "~10" estimate appears to have folded in `Reconciler` user-callback sites; those land in 4.10. +- [x] Verify framework-internal code is **outside** the try/catch (spec §6.7.3 point 2). For `RunCleanups.persistedSave`, `PersistedHookStateBase.SaveToCache` is framework code but reaches user-supplied `IPersistedStateScope.Set` — the try-catch wraps the user contact point; the surrounding hook-iteration loop is outside. +- [x] Each entry gets an inline `// User-callback isolation (spec 044 §6.7.3): ...` comment naming the user contract (cleanup ordering, effect-flush forward progress, persisted-slot independence). + +### 4.10 PR: Residual catches + remaining trace prints + +- [x] Migrated residual `Reconciler` swallowed-error catches: + - `Reconciler.cs` ConnectedAnimation `PrepareToAnimate` (×2, mount + update paths), `GetAnimation`, `TryStart` → `DiagnosticLog.SwallowedError(LogCategory.Reactor, "ConnectedAnimation.", ex)`. The spec's §6.7.4 "Promote + Narrow" verdict for these 4 entries is deferred (typed event promotion follows the same per-site audit gate as 4.5/4.6). + - `Reconciler.cs` `ApplyThemeBindings` → `DiagnosticLog.SwallowedError(LogCategory.Theme, "ApplyThemeBindings", ex)`. Theme is the right category — the catch wraps a `Style` XAML compile. + - `Reconciler.Mount.cs` `ContentDialog.ShowAsync+OnClosed` → `DiagnosticLog.SwallowedError(LogCategory.Reactor, ...)`. Inline comment marks it as user-callback isolation per §6.7.3 (the try wraps both `ShowAsync` and the user-supplied `OnClosed` delegate). +- [x] `LayoutEtwConsumer` (12 sites): error swallows (7) already routed to `DiagnosticLog.SwallowedError` in Phase C.7a (commit `b761a7a1`). Remaining 5 sites are pure trace prints (session-started, parser output, orphan-session cleanup) — stay as `Debug.WriteLine` per spec §6.3 framework-internal carve-out. +- [x] `LayoutCostAttribution` (8 sites): keep as `Debug.WriteLine` — framework-internal (verified by inspection). +- [x] `MarkdownBuilder` parse-failure (1 site): keep as `Debug.WriteLine` — framework-internal. +- [x] `YogaConfig` frozen-mutation `Debug.Assert` (6 sites): keep — these are `Debug.Assert`, not `Debug.WriteLine`; they're CI tripwires for a framework invariant, not diagnostics. +- [x] `ChildCollection` bounds assertions (4 sites): keep — same as above. + +### 4.11 Phase C tests + +- [ ] After each PR, run `dotnet test tests/Reactor.Tests` and `dotnet test tests/Reactor.SelfTests`. Both must stay green. +- [ ] Add one regression test per major category that fires the migrated path and asserts the event lands on the ETW listener (e.g., `Reconciler_swallow_emits_SwallowedError_event`, `NavigationDiagnostics_push_emits_NavigationRequested`). +- [ ] After Phase C is fully landed, the spec §12 acceptance criterion holds: **zero** `Debug.WriteLine` calls in `src/Reactor/` that report errors or HRESULT codes. Verify with a final grep. + +### 4.12 Phase C acceptance + +- [ ] Every audit entry has both checkboxes ticked or a documented reason it carried over to a follow-up PR. +- [ ] `dotnet test tests/Reactor.Tests tests/Reactor.SelfTests` green. +- [ ] AOT/trim build clean. + +--- + +## Phase D — `ReactorTrace.Subscribe` in-process helper (1 PR) + +### 5.1 Implement the listener + +- [x] Implement `ReactorTrace.Subscribe(Action, EventLevel, EventKeywords): IDisposable` per spec §6.4 in `src/Reactor/Diagnostics/ReactorTrace.cs`. +- [x] Backing implementation is a sealed `EventListener` filtered on `EventSource.Name == "Microsoft-UI-Reactor"`. +- [x] Default level is `Verbose` (spec §6.4 — earlier draft defaulted to Informational; we explicitly want Verbose). +- [x] Default keywords are `(EventKeywords)(-1)` (all). +- [x] Multiple concurrent subscribers supported; each subscriber's keywords/level are independently active until disposed. +- [x] Subscriber callback wrapped in `try/catch` so a buggy subscriber can't deadlock the dispatcher (spec §6.4 second bullet). + +### 5.2 `ReactorEvent` payload + +- [x] `ReactorEvent` is a `public readonly record struct` per spec §6.4. +- [x] `Payload` / `PayloadNames` use `IReadOnlyList` / `IReadOnlyList` (the `EventWrittenEventArgs.Payload` shape — no reflection). +- [x] No reflection on consumer payload — verify AOT/trim-clean compile. + +### 5.3 Phase D tests + +- [x] `ReactorTraceSubscribeTests`: + - [x] Subscribe → fire a known event → callback receives the matching `ReactorEvent` with correct EventId/Name/Level/Keywords/Payload. + - [x] Dispose the subscription → subsequent fires don't reach the callback. + - [x] Two concurrent subscribers see the same event independently. + - [x] A subscriber that throws inside its callback does not break other subscribers and does not propagate to `EventSource.WriteEvent`. + - [x] Subscriber with `keywords: Keywords.Errors` does not receive events fired only under `Keywords.Reconcile`. + - [x] `EventLevel.Warning` subscriber does not receive Verbose events. + +### 5.4 Phase D acceptance + +- [x] AOT/trim build clean for `src/Reactor/Diagnostics/ReactorTrace.cs`. +- [x] Public API surface has XML doc comments including the §6.4 capture-to-file pointers ("For writing a trace file, use one of: …"). +- [ ] No reflection added. + +--- + +## Phase F — Wire ETW into `reactor.logs` (1 PR) + +> **Note.** Phase E (sibling `Microsoft.UI.Reactor.Logging.Extensions` package) is deferred — see "Deferred / out of scope" below. We jump straight from D to F. + +### 6.1 Extend `LogCaptureBuffer` + +- [x] Add `LogSource.Event` to the existing `LogSource` enum in `src/Reactor/Hosting/Devtools/LogCaptureBuffer.cs`. +- [x] Add two additive optional fields to the log-entry shape: `eventName` (string?) and `eventId` (int?). The new fields default to null on the record-positional ctor, so every existing `Append(source, level, text)` call site stays source-compatible; an additional `Append(..., eventName, eventId)` overload is the only emitter of non-null values. + +### 6.2 Subscribe inside `LogCaptureInstall.Install` + +- [x] On install, call `ReactorTrace.Subscribe(...)` exactly once (the install owns the subscription's lifetime, stored in a static and disposed only via `ResetForTests`). Install is gated by the same `_installLock` so concurrent first-touch callers cannot race on the subscription. +- [x] Map each `ReactorEvent` to a `LogCaptureBuffer` entry: + - `text` = formatted line, e.g. `WindowOpened windowType=SettingsWindow hwnd=0x00010A2C`. + - `level` = mapped from `EventLevel` (Critical→Critical, Error→Error, Warning→Warning, Informational→Info, Verbose→Debug, LogAlways→Trace). + - `source` = `Event`. + - `eventName`, `eventId` populated. +- [x] Apply payload-formatting PII policy from spec §6.2.1: never include raw `ex.Message` (we already strip on the EventSource side, but defense-in-depth here), length-bound payload string fields at 256 chars (`LogCaptureInstall.MaxPayloadFieldChars`). HR and HWND payload fields render in `0x{X8}` so log greps from before the migration still match. + +### 6.3 Extend the `reactor.logs` MCP tool + +- [x] Add `source=event` (with `etw` alias) as a valid value for the existing `source` filter in `src/Reactor/Hosting/Devtools/DevtoolsLogsTool.cs`. +- [x] Existing filter values (`stdout`, `stderr`, `debug`/`trace`) continue to work unchanged. +- [x] Document the new `eventName` and `eventId` fields in the tool's JSON schema description and the verbose tool description string. + +### 6.4 Phase F tests + +- [x] Add `tests/Reactor.Tests/Diagnostics/LogCaptureEventBridgeTests.cs`: + - [x] After install + fire a known event, `LogCaptureBuffer` contains an entry with `source=Event`, the right `eventName`, and the right `level`. + - [x] Payload formatting respects the 256-char length cap. + - [x] HR-style payload field renders in `0x{X8}` form (not the signed-int decimal). + - [x] Null payload renders as `null` literal (not an empty `name=` field). + - [x] Existing `source=stdout` / `source=stderr` / `source=debug` paths continue to capture (regression guard). +- [x] Add `source=event` + `source=etw` acceptance tests to `DevtoolsLogsToolTests`. +- [ ] Selftest fixture or AppTest: launch the devtools host, fire an event from a fixture, and assert `reactor.logs source=event` returns the event (existing devtools test infra in `tests/Reactor.AppTests/`). _(Deferred: in-process bridge test exercises the full BuildPayload + bridge stack; the AppTest is a process-isolation guard, not a behavior gap.)_ + +### 6.5 Phase F acceptance + +- [x] `dotnet test tests/Reactor.Tests` green (478 tests in the Diagnostics+Devtools filter, full suite below). +- [x] `dotnet test tests/Reactor.SelfTests` green. +- [x] Existing devtools MCP clients (which do not pass `source=event`) see zero behavior change (spec §12). + +--- + +## Phase H — Diagnostics user guide (1 PR) + +### 7.1 Author the template + +- [x] Create `docs/_pipeline/templates/diagnostics.md.dt`. Sections (mirroring spec §2 + §7 + §8): + - [x] The rule (`Debug.WriteLine` vs `ReactorEventSource`). + - [x] How to capture a trace with environment variables (`DOTNET_EnableEventPipe`). + - [x] How to attach `dotnet-trace`. + - [x] How to open a `.nettrace` in Visual Studio. + - [x] Performance Profiler → Events Viewer workflow with `Microsoft-UI-Reactor` as a custom provider + keyword bitmask quick reference. + - [x] How to use `ReactorTrace.Subscribe(...)` from app code. + - [x] How to filter `reactor.logs source=event` in the devtools MCP tool. + - [x] Cross-link to `perf-instrumentation.md` for perf-shaped events. +- [x] **Do not** document `AddReactorEvents` / `ILoggingBuilder` — that's deferred Phase E. Confirmed: no `AddReactorEvents` mention in either template or generated output. + +Also added (over and above the spec checklist): +- A "Common Mistakes" subsection covering computing payload outside the `IsEnabled` gate, capturing without pinning level, and forwarding `ex.Message` through subscribers. +- An SVG flow diagram at `docs/_pipeline/diagrams/diagnostics/flow.svg` showing catch-site → `DiagnosticLog` → `ReactorEventSource` → four consumers. Required to clear `REACTOR_DOC_TIER_004` under `--ci`. +- Two new source snippet anchors (`swallowed-error-shape` on `DiagnosticLog.cs`, `hresult-failed-event` on `ReactorEventSource.cs`) to clear `REACTOR_DOC_TIER_003` (≥3 snippets per comprehensive page). + +### 7.2 Update related touch points + +- [x] Added a "Diagnostics: audience, not severity, decides the channel" sub-section to `CONTRIBUTING.md` under Code style — restates the rule, shows the canonical `DiagnosticLog.SwallowedError` shape, and links to the generated `docs/guide/diagnostics.md`. +- [x] Cross-linked from `docs/_pipeline/templates/perf-instrumentation.md.dt` Next Steps to the new diagnostics page as the first entry. + +### 7.3 Generate + +- [x] `mur docs compile --topic diagnostics --ci` runs clean (only the non-fatal `winui-ref` warning, which the spec explicitly marks as "only required for transparent-wrapper pages"). +- [x] `docs/guide/diagnostics.md` lands 404 lines, generated; 26 cross-mentions of the four headline surfaces (`DiagnosticLog` / `reactor.logs` / `ReactorTrace` / `EventSource`). Hand-edits forbidden — confirmed by the template hash. + +### 7.4 Phase H acceptance + +- [x] The doc renders correctly in the user-guide site preview (verified via `mur docs compile` + reading the generated `docs/guide/diagnostics.md`). +- [x] All four capture recipes (env vars, `dotnet-trace`, VS Profiler, `ReactorTrace.Subscribe`) are present and have copy-pasteable snippets. +- [x] `reactor.logs source=event` recipe shows the request/response shape with the `eventName`/`eventId` fields populated. +- [x] No reference to `AddReactorEvents` (deferred). + +--- + +## Phase I — `ReactorTraceCollector` test harness + regression guards (1 PR) + +### 8.1 Test harness + +- [x] Add `tests/Reactor.Tests/Diagnostics/ReactorTraceCollector.cs`. API: + ```csharp + using var collector = ReactorTraceCollector.Capture( + level: EventLevel.Verbose, + keywords: ReactorEventSource.Keywords.Reconcile); + // … run code under test … + Assert.Collection(collector.Events, …); + ``` + Also exposes `collector.ByName(string)` — Phase B/C migrations needed a way to pick a single event out of an interleaved capture, and reaching into a lock around `_events.Where(...)` is the right shape. +- [x] Backing implementation reuses `ReactorTrace.Subscribe`. +- [x] Thread-safe enumeration of captured events (snapshot via `ToArray` inside the gate; the public `Events` accessor returns the snapshot, never the live list). +- [x] Disposing the collector unsubscribes; subsequent fires don't leak into a later test (delegates to `Subscription.Dispose`). + +### 8.2 Regression assertions (spec §9) + +- [x] `Reconcile_emits_start_stop_pair` — both Start (with root type) and Stop (with diffed/skipped/created/modified counts) land under `Keywords.Reconcile` at `Informational`. +- [x] `RenderError_carries_exception_type_but_not_message` — fires `RenderError` with a fingerprintable secret string; asserts the third payload slot is empty and the secret appears nowhere in the joined payload (defense-in-depth on TASK-064 / spec §6.2.1). The Phase I doc spelled the test name "ComponentRender_throw_emits_RenderError" but the assertion shape is identical — calling the EventSource directly is honest about what we're testing (the emit-site PII strip), not the component-throw path which lives in Reconciler tests already. +- [x] `SwallowedError_smoke_for_each_log_category` — `[Theory]` over `Enum.GetNames()` so a new category added later is automatically covered. Currently exercises Reactor / Hosting / Persistence / Navigation / Intl / Theme / Shell / LayoutCost / Devtools / Markdown. +- [x] `Mcp_selector_is_hashed_not_emitted_raw` — `[Text*='alice@contoso.example.invalid']` selector goes in; the captured payload is `sha1:<8 bytes hex>` with no `alice` / `@` characters. +- [x] `DisabledKeyword_skips_ReactorEventSource_WriteEvent_payload_marshal` — measures `GC.GetAllocatedBytesForCurrentThread()` across 10K `ReactorEventSource.Log.SwallowedError(...)` calls when `Keywords.Errors` is disabled; allows up to one byte per iteration. Has an `IsEnabled`-precondition early return so parallel test fixtures that keep Errors enabled cannot make this flaky — when isolated, the test exercises the measurement and the delta is well under the cap. We deliberately measure `ReactorEventSource` directly, not `DiagnosticLog.SwallowedError`, because the latter additionally runs a `[Conditional("DEBUG")]` `Debug.WriteLine` mirror whose ~600 B/call allocation is the intended Debug-build cost and is compiled out in Release. + +### 8.3 Phase I acceptance + +- [x] All assertions in 8.2 pass. +- [x] Test harness is **only** in the test assembly (`tests/Reactor.Tests/Diagnostics/ReactorTraceCollector.cs`, `internal sealed class`) — no production reference. +- [x] `dotnet test tests/Reactor.Tests` green (492 tests in the Diagnostics+Devtools filter). + +--- + +## Cross-phase acceptance — closing #323 + +A final check before declaring spec 044's headline goals shipped (excluding deferred items): + +- [ ] **Acceptance §12.1** A Release build of a Reactor app emits `Microsoft-UI-Reactor` events for every error/warning that today only appears in `Debug.WriteLine`. Verify by capturing a trace of a sample app exercise that previously only printed to the Output window. +- [ ] **Acceptance §12.2** A developer can collect a trace by setting three env vars (`DOTNET_EnableEventPipe=1`, `DOTNET_EventPipeOutputPath=...`, `DOTNET_EventPipeConfig=Microsoft-UI-Reactor:...:5`) with no source change. +- [ ] **Acceptance §12.3** The captured `.nettrace` opens in Visual Studio Events Viewer with timestamps, provider, payload columns. +- [ ] **Acceptance §12.4** `grep -rn 'Debug\.WriteLine' src/Reactor/` returns **zero** error/HR-reporting hits — all routed through `DiagnosticLog`. +- [ ] **Acceptance §12.5** Every remaining `catch (Exception)` in `src/Reactor/` has a corresponding `Keep`-verdict entry in `docs/specs/044/swallowed-error-audit.md` (the analyzer CI gate is deferred — see below — but the audit file itself is the manual gate). +- [ ] **Acceptance §12.6** All new event payloads pass the §6.2.1 PII policy review. +- [ ] **Acceptance §12.7** `reactor.logs source=event` returns ETW events; existing clients without the filter see no behavior change. +- [ ] **Acceptance §12.8** `Microsoft.UI.Reactor` builds clean with `IsAotCompatible=true` + trim-warnings-as-errors. +- [ ] **Acceptance §12.9** `docs/guide/diagnostics.md` exists, is generated from a template, and links to `perf-instrumentation.md`. + +--- + +## Deferred / out of scope (tracked but not blocking #323) + +These are spec 044 deliverables we are **explicitly deferring** to keep the change minimal. Each gets its own follow-up issue when this work lands. + +- **Phase C-gate (Roslyn analyzer).** Spec §6.7.5. A Roslyn analyzer that flags new `catch (Exception)` in `src/Reactor/` without a `DiagnosticLog.*` call or audit-reference comment. Useful for preventing drift; not required to ship the cleanup. Track as a separate "diagnostics analyzer" task. +- **Phase E (`ILogger` adapter sibling package).** Spec §6.5 + §8.4. `Microsoft.UI.Reactor.Logging.Extensions` with `ILoggingBuilder.AddReactorEvents(...)`. Adds a sibling NuGet package + a `Microsoft.Extensions.Logging` dependency. Apps that want this today can call `ReactorTrace.Subscribe(...)` and write four lines of glue. Track as a separate "ship ILogger adapter" task. +- **Phase G (`IDevtoolsConsole` abstraction).** Spec §6.8. Replaces direct `Console.*` calls in `Hosting\ReactorApp.cs`, `PreviewCaptureServer`, `DevtoolsMcpServer` with an injected interface. The current direct `Console.*` usage is correct (CLI surface, spec §4.5) and not blocking the logging story. Track as a separate "console abstraction" task. +- **Open question Q3 follow-up.** The `[Reactor]` Roslyn analyzer that flags new `Debug.WriteLine` outside the allow-list directories. Spec §10. Defer until the migration is complete and we have data on drift. diff --git a/src/Reactor/Core/Diagnostics/DiagnosticLog.cs b/src/Reactor/Core/Diagnostics/DiagnosticLog.cs new file mode 100644 index 000000000..8ea20a4a4 --- /dev/null +++ b/src/Reactor/Core/Diagnostics/DiagnosticLog.cs @@ -0,0 +1,105 @@ +using System.Diagnostics; +using System.Diagnostics.Tracing; + +namespace Microsoft.UI.Reactor.Core.Diagnostics; + +/// +/// Thin call-site helper that routes the two dominant Debug.WriteLine +/// patterns — swallowed exceptions and bare HRESULT codes — to +/// (release-visible, keyword-gated) and +/// additionally mirrors a richer line to Debug.WriteLine in DEBUG +/// for the contributor's Output window. +/// +/// +/// The public helpers are intentionally not — +/// the whole point of this helper is that the diagnostic is emitted in +/// Release. Only the DEBUG mirror ( / +/// ), which can safely include the raw +/// because it lands in the dev's local +/// Output window, is marked [Conditional("DEBUG")]. +/// +/// +/// +/// PII discipline (spec 044 §6.2.1): the ETW payload carries the exception +/// type only. is never emitted on +/// the trace because messages can carry paths, env values, partial form +/// values, and other user data. Apps that want richer diagnostics should +/// attach an in-process EventListener (or use the +/// Microsoft.UI.Reactor.Diagnostics.ReactorTrace.Subscribe helper +/// once it lands) and capture the type-only payload there. +/// +/// +internal static class DiagnosticLog +{ + /// + /// Logs a swallowed exception the framework chose not to propagate. + /// Always emits to Microsoft-UI-Reactor's SwallowedError + /// event under the + /// keyword; additionally mirrors a richer line including + /// to Debug.WriteLine in DEBUG. + /// + /// Subsystem label — used as the logger / + /// trace category so a consumer can filter by area. + /// Short, stable identifier for the operation + /// inside the try block (e.g. "AppWindow.Close", + /// "JsonFileStore.SaveAsync"). Developer-authored; safe for + /// ETW. May be at defensive call sites. + /// The swallowed exception. Only its + /// name reaches the ETW payload. + /// May be at defensive call sites. + // + public static void SwallowedError(LogCategory category, string? operation, Exception? ex) + { + // Cost-of-disabled: when no consumer enables Keywords.Errors at + // Warning the entire branch is skipped — no enum-to-string, no + // type-name materialization, no WriteEvent dispatch. + if (ReactorEventSource.Log.IsEnabled(EventLevel.Warning, ReactorEventSource.Keywords.Errors)) + { + ReactorEventSource.Log.SwallowedError( + category.ToString(), + operation ?? string.Empty, + ex?.GetType().Name ?? string.Empty); + } + + DebugSwallowedError(category, operation, ex); + } + // + + /// + /// Logs a bare HRESULT / Win32 code that the framework chose to + /// continue past rather than throw. Always emits to + /// Microsoft-UI-Reactor's HResultFailed event under the + /// keyword; + /// additionally mirrors to Debug.WriteLine in DEBUG. + /// + /// Subsystem label. + /// Short, stable identifier for the operation + /// that returned the HR. May be at defensive + /// call sites. + /// The HRESULT or Win32 error code as + /// exposes it (signed int). + public static void HResultFailed(LogCategory category, string? operation, int hr) + { + if (ReactorEventSource.Log.IsEnabled(EventLevel.Warning, ReactorEventSource.Keywords.Errors)) + { + ReactorEventSource.Log.HResultFailed( + category.ToString(), + operation ?? string.Empty, + hr); + } + + DebugHResult(category, operation, hr); + } + + [Conditional("DEBUG")] + private static void DebugSwallowedError(LogCategory category, string? operation, Exception? ex) + { + var typeName = ex?.GetType().Name ?? ""; + var message = ex?.Message ?? string.Empty; + Debug.WriteLine($"[{category}] {operation} failed: {typeName}: {message}"); + } + + [Conditional("DEBUG")] + private static void DebugHResult(LogCategory category, string? operation, int hr) + => Debug.WriteLine($"[{category}] {operation} HR=0x{hr:X8}"); +} diff --git a/src/Reactor/Core/Diagnostics/HResults.cs b/src/Reactor/Core/Diagnostics/HResults.cs new file mode 100644 index 000000000..dd8fe142b --- /dev/null +++ b/src/Reactor/Core/Diagnostics/HResults.cs @@ -0,0 +1,55 @@ +namespace Microsoft.UI.Reactor.Core.Diagnostics; + +/// +/// Named HRESULT / Win32 constants used in catch (COMException) when +/// (ex.HResult is HResults.X or HResults.Y) filters. +/// +/// These values are intentionally (not ) +/// because that is how the runtime exposes Exception.HResult. +/// Use the unchecked((int)0x...) form so the negative two's-complement +/// representation matches the runtime's value byte-for-byte. +/// +/// Add new constants here (named, with a one-line comment) rather than +/// inlining the magic number at the catch site. Centralizing them lets +/// the swallowed-error audit (docs/specs/044/swallowed-error-audit.md) +/// cite specific values per site without forcing each catch to repeat +/// the hex literal. +/// +internal static class HResults +{ + /// The object invoked has disconnected from its clients (e.g. AppWindow proxy after WM_CLOSE). + public const int RPC_E_DISCONNECTED = unchecked((int)0x80010108); + + /// The handle is invalid (HWND already destroyed / released). + public const int E_HANDLE = unchecked((int)0x80070006); + + /// The server threw an exception (out-of-process COM call into a torn-down server). + public const int RPC_E_SERVERFAULT = unchecked((int)0x80010105); + + /// The object is not connected to the server (COM proxy released before the call landed). + public const int CO_E_OBJNOTCONNECTED = unchecked((int)0x800401FD); + + /// Element not found (e.g. ThumbnailToolbar button index that no longer exists). + public const int TYPE_E_ELEMENTNOTFOUND = unchecked((int)0x8002802B); + + /// The system cannot find the file specified. + public const int ERROR_FILE_NOT_FOUND = unchecked((int)0x80070002); + + /// Access is denied. + public const int ERROR_ACCESS_DENIED = unchecked((int)0x80070005); + + /// + /// True if is one of the WinUI / COM teardown-reentry + /// HRESULTs — the standard "your proxy is gone, your handle is gone, your + /// out-of-proc server is gone" surface that AppWindow / Window + /// API calls throw during Close, Dispose, DPI change, and + /// presenter transitions. Spec 044 §6.7.2 narrow-catch sites use this + /// helper as the predicate in catch (COMException ex) when (...). + /// Anything outside this set is a bug we want to surface, not swallow. + /// + public static bool IsTeardownReentry(int hr) => + hr is RPC_E_DISCONNECTED + or E_HANDLE + or RPC_E_SERVERFAULT + or CO_E_OBJNOTCONNECTED; +} diff --git a/src/Reactor/Core/Diagnostics/LogCategory.cs b/src/Reactor/Core/Diagnostics/LogCategory.cs new file mode 100644 index 000000000..7c3eaf209 --- /dev/null +++ b/src/Reactor/Core/Diagnostics/LogCategory.cs @@ -0,0 +1,46 @@ +namespace Microsoft.UI.Reactor.Core.Diagnostics; + +/// +/// Subsystem labels used by and by the ETW +/// payloads on / +/// . +/// +/// Replaces the historical stringly-typed [Reactor.X] prefixes that +/// were attached to Debug.WriteLine calls. Compile-time-checked so a +/// typo in a catch block doesn't silently land in the trace as [reactr]. +/// +/// New subsystems should add a value here rather than passing a free-form +/// string — keeps the dotnet-trace consumer filterable by enum. +/// +internal enum LogCategory +{ + /// Reactor core (reconciler, render context, hooks, element pooling). + Reactor, + + /// App / window hosting: ReactorApp, ReactorWindow, AppWindow, DPI, backdrop. + Hosting, + + /// Settings, window-placement, JSON file store, packaged settings store. + Persistence, + + /// Navigation router: route push/pop, page cache, transition lifecycle. + Navigation, + + /// Localization / internationalization: missing resource key, locale fallback, format errors. + Intl, + + /// Theme application: light/dark switch, brush bindings, theme-aware controls. + Theme, + + /// Windows shell integration: JumpList, ThumbnailToolbar, tray icon, taskbar. + Shell, + + /// Layout-cost overlay pipeline (spec 032) — ETW consumer, attribution. + LayoutCost, + + /// Devtools surface: MCP server, log capture, preview pipe. + Devtools, + + /// Markdown rendering: md4c parser, builder, list of inline children. + Markdown, +} diff --git a/src/Reactor/Core/Diagnostics/ReactorEventSource.cs b/src/Reactor/Core/Diagnostics/ReactorEventSource.cs index e339f60f5..4590112ab 100644 --- a/src/Reactor/Core/Diagnostics/ReactorEventSource.cs +++ b/src/Reactor/Core/Diagnostics/ReactorEventSource.cs @@ -48,6 +48,15 @@ public static class Keywords public const EventKeywords Lifecycle = (EventKeywords)0x10; public const EventKeywords Errors = (EventKeywords)0x20; public const EventKeywords EventDispatch = (EventKeywords)0x40; + // Spec 044 — subsystem coverage gaps. Each gets its own bit so a + // consumer (dotnet-trace, EventListener, ReactorTrace.Subscribe) can + // pick exactly the area it cares about without paying for the rest. + public const EventKeywords Hosting = (EventKeywords)0x80; // Window/HWND/DPI/Backdrop + public const EventKeywords Persistence = (EventKeywords)0x100; // settings store, placement + public const EventKeywords Navigation = (EventKeywords)0x200; // route push, cache, transitions + public const EventKeywords Intl = (EventKeywords)0x400; // missing keys, fallback, format + public const EventKeywords Theme = (EventKeywords)0x800; // theme apply, bindings + public const EventKeywords Shell = (EventKeywords)0x1000; // JumpList/Tray/ThumbnailToolbar } // @@ -232,4 +241,214 @@ public void RenderError(string componentName, string exceptionType, string messa // own ACL, not the Microsoft-UI-Reactor provider. WriteEvent(9, componentName ?? string.Empty, exceptionType ?? string.Empty, string.Empty); } + + // Spec 044 §6.1 — generic swallowed-exception event used by + // DiagnosticLog.SwallowedError. PII: exception type only; the message + // is intentionally never on the payload. + [Event(16, Level = EventLevel.Warning, Keywords = Keywords.Errors, + Message = "Swallowed error (category={category}, op={operation}, exception={exceptionType})")] + public void SwallowedError(string category, string operation, string exceptionType) + { + if (IsEnabled(EventLevel.Warning, Keywords.Errors)) + WriteEvent(16, category ?? string.Empty, operation ?? string.Empty, exceptionType ?? string.Empty); + } + + // Spec 044 §6.1 — generic HRESULT-failed event used by + // DiagnosticLog.HResultFailed. HRESULT is signed (matches Exception.HResult). + // + [Event(17, Level = EventLevel.Warning, Keywords = Keywords.Errors, + Message = "HResult failed (category={category}, op={operation}, hr=0x{hr:X8})")] + public void HResultFailed(string category, string operation, int hr) + { + if (IsEnabled(EventLevel.Warning, Keywords.Errors)) + WriteEvent(17, category ?? string.Empty, operation ?? string.Empty, hr); + } + // + + // ── Hosting (spec 044 Phase B §2.1) ───────────────────────────────── + // + // PII: windowType is the C# type name (developer-authored, OK). + // Window titles are NEVER emitted on this surface (spec §6.2.1). + // HWND is emitted as a long; not user data. + + [Event(18, Level = EventLevel.Informational, Keywords = Keywords.Hosting, + Message = "Window opened (type={windowType}, hwnd=0x{hwnd:X16})")] + public void WindowOpened(string windowType, long hwnd) + { + if (IsEnabled(EventLevel.Informational, Keywords.Hosting)) + WriteEvent(18, windowType ?? string.Empty, hwnd); + } + + [Event(19, Level = EventLevel.Informational, Keywords = Keywords.Hosting, + Message = "Window closed (type={windowType}, hwnd=0x{hwnd:X16})")] + public void WindowClosed(string windowType, long hwnd) + { + if (IsEnabled(EventLevel.Informational, Keywords.Hosting)) + WriteEvent(19, windowType ?? string.Empty, hwnd); + } + + [Event(20, Level = EventLevel.Informational, Keywords = Keywords.Hosting, + Message = "Window DPI changed (type={windowType}, old={oldDpi}, new={newDpi})")] + public void WindowDpiChanged(string windowType, int oldDpi, int newDpi) + { + if (IsEnabled(EventLevel.Informational, Keywords.Hosting)) + WriteEvent(20, windowType ?? string.Empty, oldDpi, newDpi); + } + + [Event(21, Level = EventLevel.Warning, Keywords = Keywords.Hosting, + Message = "Backdrop materialization failed (kind={kind}, exception={exceptionType})")] + public void BackdropMaterializationFailed(string kind, string exceptionType) + { + if (IsEnabled(EventLevel.Warning, Keywords.Hosting)) + // PII: exception type only — same discipline as RenderError. + WriteEvent(21, kind ?? string.Empty, exceptionType ?? string.Empty); + } + + // ── Persistence (spec 044 Phase B §2.2) ───────────────────────────── + // + // PII: file paths NEVER emitted; storeKind is a short label + // ("settings", "placement", etc.). sizeBytes is an int; not PII. + + [Event(22, Level = EventLevel.Informational, Keywords = Keywords.Persistence, + Message = "Persistence read (store={storeKind}, size={sizeBytes})")] + public void PersistenceRead(string storeKind, int sizeBytes) + { + if (IsEnabled(EventLevel.Informational, Keywords.Persistence)) + WriteEvent(22, storeKind ?? string.Empty, sizeBytes); + } + + [Event(23, Level = EventLevel.Informational, Keywords = Keywords.Persistence, + Message = "Persistence write (store={storeKind}, size={sizeBytes})")] + public void PersistenceWrite(string storeKind, int sizeBytes) + { + if (IsEnabled(EventLevel.Informational, Keywords.Persistence)) + WriteEvent(23, storeKind ?? string.Empty, sizeBytes); + } + + [Event(24, Level = EventLevel.Warning, Keywords = Keywords.Persistence, + Message = "Persistence rejected (store={storeKind}, reason={reason})")] + public void PersistenceRejected(string storeKind, string reason) + { + if (IsEnabled(EventLevel.Warning, Keywords.Persistence)) + // PII: reason is a short, developer-authored label + // ("oversize", "corrupt", "schema-mismatch"), NEVER a path + // or raw error message. + WriteEvent(24, storeKind ?? string.Empty, reason ?? string.Empty); + } + + // ── Navigation (spec 044 Phase B §2.3) ────────────────────────────── + // + // PII: route TEMPLATE only ("/users/{id}"). The instantiated path is + // NEVER emitted; instantiated path parameter values are user + // data per §6.2.1. + + [Event(25, Level = EventLevel.Informational, Keywords = Keywords.Navigation, + Message = "Navigation requested (route={routeTemplate})")] + public void NavigationRequested(string routeTemplate) + { + if (IsEnabled(EventLevel.Informational, Keywords.Navigation)) + WriteEvent(25, routeTemplate ?? string.Empty); + } + + [Event(26, Level = EventLevel.Informational, Keywords = Keywords.Navigation, + Message = "Navigation completed (route={routeTemplate}, durationMs={durationMs})")] + public void NavigationCompleted(string routeTemplate, double durationMs) + { + if (IsEnabled(EventLevel.Informational, Keywords.Navigation)) + WriteEvent(26, routeTemplate ?? string.Empty, durationMs); + } + + [Event(27, Level = EventLevel.Informational, Keywords = Keywords.Navigation, + Message = "Navigation cancelled (route={routeTemplate}, reason={reason})")] + public void NavigationCancelled(string routeTemplate, string reason) + { + if (IsEnabled(EventLevel.Informational, Keywords.Navigation)) + WriteEvent(27, routeTemplate ?? string.Empty, reason ?? string.Empty); + } + + [Event(28, Level = EventLevel.Verbose, Keywords = Keywords.Navigation, + Message = "Navigation cache hit (route={routeTemplate})")] + public void NavigationCacheHit(string routeTemplate) + { + if (IsEnabled(EventLevel.Verbose, Keywords.Navigation)) + WriteEvent(28, routeTemplate ?? string.Empty); + } + + [Event(29, Level = EventLevel.Verbose, Keywords = Keywords.Navigation, + Message = "Navigation cache miss (route={routeTemplate})")] + public void NavigationCacheMiss(string routeTemplate) + { + if (IsEnabled(EventLevel.Verbose, Keywords.Navigation)) + WriteEvent(29, routeTemplate ?? string.Empty); + } + + [Event(30, Level = EventLevel.Verbose, Keywords = Keywords.Navigation, + Message = "Navigation cache evict (route={routeTemplate}, reason={reason})")] + public void NavigationCacheEvict(string routeTemplate, string reason) + { + if (IsEnabled(EventLevel.Verbose, Keywords.Navigation)) + WriteEvent(30, routeTemplate ?? string.Empty, reason ?? string.Empty); + } + + // Transition + DeepLink (spec 044 Phase C §4.2 follow-on). The + // transition events log the transition's *type name* (e.g. + // "FadeNavigationTransition") and the navigation mode, both of which + // are framework-defined identifiers — never user data. DeepLink does + // NOT include the input path (it is attacker-controllable per §6.2.1); + // only the resolution outcome and candidate-route count. + + [Event(33, Level = EventLevel.Verbose, Keywords = Keywords.Navigation, + Message = "Navigation transition started (type={transitionType}, mode={mode})")] + public void NavigationTransitionStarted(string transitionType, string mode) + { + if (IsEnabled(EventLevel.Verbose, Keywords.Navigation)) + WriteEvent(33, transitionType ?? string.Empty, mode ?? string.Empty); + } + + [Event(34, Level = EventLevel.Verbose, Keywords = Keywords.Navigation, + Message = "Navigation transition completed (type={transitionType}, mode={mode})")] + public void NavigationTransitionCompleted(string transitionType, string mode) + { + if (IsEnabled(EventLevel.Verbose, Keywords.Navigation)) + WriteEvent(34, transitionType ?? string.Empty, mode ?? string.Empty); + } + + [Event(35, Level = EventLevel.Informational, Keywords = Keywords.Navigation, + Message = "Deep link resolved (matched={matched}, routeCount={routeCount})")] + public void NavigationDeepLinkResolved(bool matched, int routeCount) + { + if (IsEnabled(EventLevel.Informational, Keywords.Navigation)) + WriteEvent(35, matched, routeCount); + } + + // ── Intl (spec 044 Phase B §2.4) ──────────────────────────────────── + // + // PII: keys are developer-authored static identifiers ("Settings.Title", + // "Errors.NetworkOffline"). Locale tags are BCP-47 strings, also OK. + + [Event(31, Level = EventLevel.Warning, Keywords = Keywords.Intl, + Message = "Intl missing key (key={key}, locale={locale}, fellBack={fellBack})")] + public void IntlMissingKey(string key, string locale, bool fellBack) + { + if (IsEnabled(EventLevel.Warning, Keywords.Intl)) + WriteEvent(31, key ?? string.Empty, locale ?? string.Empty, fellBack); + } + + // ── Theme (spec 044 Phase B §2.5) ─────────────────────────────────── + + [Event(32, Level = EventLevel.Warning, Keywords = Keywords.Theme, + Message = "Theme apply failed (target={targetType}, exception={exceptionType})")] + public void ThemeApplyFailed(string targetType, string exceptionType) + { + if (IsEnabled(EventLevel.Warning, Keywords.Theme)) + // PII: exception type only. + WriteEvent(32, targetType ?? string.Empty, exceptionType ?? string.Empty); + } + + // ── EventId allocation ────────────────────────────────────────────── + // + // Used: 1-15 (original surface), 16-17 (spec 044 Phase A generics), + // 18-32 (spec 044 Phase B subsystem coverage), + // 33-35 (spec 044 Phase C §4.2 navigation transition + deep link). + // Next free EventId: 36. } diff --git a/src/Reactor/Core/Localization/IntlAccessor.cs b/src/Reactor/Core/Localization/IntlAccessor.cs index 8e6554b66..ae9ef200b 100644 --- a/src/Reactor/Core/Localization/IntlAccessor.cs +++ b/src/Reactor/Core/Localization/IntlAccessor.cs @@ -1,10 +1,11 @@ using System.Collections.Concurrent; -using System.Diagnostics; using System.Diagnostics.CodeAnalysis; +using System.Diagnostics.Tracing; using System.Globalization; using System.Reflection; using System.Text.RegularExpressions; using Microsoft.UI.Reactor.Core; +using Microsoft.UI.Reactor.Core.Diagnostics; using Microsoft.UI.Xaml; namespace Microsoft.UI.Reactor.Localization; @@ -75,7 +76,7 @@ public string Message(MessageKey key, object? args = null) { // SECURITY (TASK-050): one bad .resw row would otherwise tear // down the rendering page. Log and degrade to the raw pattern. - Debug.WriteLine($"[Reactor.Intl] Format failed for '{key}': {ex.GetType().Name}: {ex.Message}"); + DiagnosticLog.SwallowedError(LogCategory.Intl, $"Message.Format[{key}]", ex); result = pattern; } @@ -122,7 +123,7 @@ public Element RichMessage(MessageKey key, object? args = null, } catch (Exception ex) { - Debug.WriteLine($"[Reactor.Intl] RichMessage format failed for '{key}': {ex.GetType().Name}: {ex.Message}"); + DiagnosticLog.SwallowedError(LogCategory.Intl, $"RichMessage.Format[{key}]", ex); formatted = pattern; } @@ -317,13 +318,19 @@ private static Element ParseRichText(string formatted, DictionaryMicrosoft-UI-Reactor ETW provider +/// under the keyword +/// (spec 044 §4.2). Use dotnet-trace/PerfView for capture in +/// Release; the in-process +/// helper exposes the same stream programmatically. +/// +/// PII: ETW payloads carry only the destination route's type name (a +/// developer-authored identifier), the navigation mode, and structural +/// values like cache reasons. Concrete route instances, deep-link paths, +/// and any user-controllable strings are intentionally omitted per §6.2.1. /// public static class NavigationDiagnostics { @@ -36,57 +47,69 @@ public static class NavigationDiagnostics /// Fires when a deep link resolves (match or miss). public static event EventHandler? DeepLinkResolved; + // Helper: derive a route template string from a route instance. + // The TYPE NAME is the closest stable "template" we have for arbitrary + // user route models — it's developer-authored and contains no instance + // data. Null routes (e.g. initial navigation) collapse to "(none)". + private static string TemplateOf(object? route) => + route?.GetType().FullName ?? "(none)"; + internal static void OnNavigationRequested(object from, object to, NavigationMode mode) { - Debug.WriteLine($"[Reactor.Nav] Requested: {mode} from {from} → {to}"); + ReactorEventSource.Log.NavigationRequested(TemplateOf(to)); NavigationRequested?.Invoke(null, new(from, to, mode)); } internal static void OnNavigationCompleted(object from, object to, NavigationMode mode) { - Debug.WriteLine($"[Reactor.Nav] Completed: {mode} from {from} → {to}"); + // durationMs is not tracked at this layer yet; pass 0 so the + // payload shape stays compatible with future timing instrumentation. + ReactorEventSource.Log.NavigationCompleted(TemplateOf(to), 0d); NavigationCompleted?.Invoke(null, new(from, to, mode)); } internal static void OnNavigationCancelled(object from, object to, NavigationMode mode, string reason) { - Debug.WriteLine($"[Reactor.Nav] Cancelled: {mode} from {from} → {to} ({reason})"); + ReactorEventSource.Log.NavigationCancelled(TemplateOf(to), reason ?? string.Empty); NavigationCancelled?.Invoke(null, new(from, to, mode) { Reason = reason }); } internal static void OnCacheHit(object route) { - Debug.WriteLine($"[Reactor.Nav] Cache HIT: {route}"); + ReactorEventSource.Log.NavigationCacheHit(TemplateOf(route)); CacheHit?.Invoke(null, new(route)); } internal static void OnCacheMiss(object route) { - Debug.WriteLine($"[Reactor.Nav] Cache MISS: {route}"); + ReactorEventSource.Log.NavigationCacheMiss(TemplateOf(route)); CacheMiss?.Invoke(null, new(route)); } internal static void OnCacheEviction(object route) { - Debug.WriteLine($"[Reactor.Nav] Cache EVICT: {route}"); + // No structured reason at this call site; payload requires a string. + ReactorEventSource.Log.NavigationCacheEvict(TemplateOf(route), string.Empty); CacheEviction?.Invoke(null, new(route)); } internal static void OnTransitionStarted(NavigationTransition transition, NavigationMode mode) { - Debug.WriteLine($"[Reactor.Nav] Transition START: {transition.GetType().Name} ({mode})"); + ReactorEventSource.Log.NavigationTransitionStarted(transition.GetType().Name, mode.ToString()); TransitionStarted?.Invoke(null, new(transition, mode)); } internal static void OnTransitionCompleted(NavigationTransition transition, NavigationMode mode) { - Debug.WriteLine($"[Reactor.Nav] Transition END: {transition.GetType().Name} ({mode})"); + ReactorEventSource.Log.NavigationTransitionCompleted(transition.GetType().Name, mode.ToString()); TransitionCompleted?.Invoke(null, new(transition, mode)); } internal static void OnDeepLinkResolved(string path, bool matched, int routeCount) { - Debug.WriteLine($"[Reactor.Nav] DeepLink: '{path}' → {(matched ? $"matched ({routeCount} routes)" : "no match")}"); + // PII: `path` is attacker-controllable input (clipboard / external + // link). Only the resolution outcome lands on the ETW stream. + ReactorEventSource.Log.NavigationDeepLinkResolved(matched, routeCount); DeepLinkResolved?.Invoke(null, new(path, matched, routeCount)); } } diff --git a/src/Reactor/Core/Reconciler.Mount.cs b/src/Reactor/Core/Reconciler.Mount.cs index d59d07f17..7e6e3346b 100644 --- a/src/Reactor/Core/Reconciler.Mount.cs +++ b/src/Reactor/Core/Reconciler.Mount.cs @@ -2136,8 +2136,15 @@ private async void ShowContentDialogCore(ContentDialogElement cdEl, XamlRoot? xa } catch (Exception ex) { - global::System.Diagnostics.Debug.WriteLine( - $"[Reactor.ContentDialog] ShowAsync failed: {ex.GetType().Name}: {ex.Message}"); + // User-callback isolation (spec 044 §6.7.3): the try wraps both + // ShowAsync and the user-supplied OnClosed delegate — if + // OnClosed throws we must not let that crash the dispatcher. + // The broad catch is deliberate; the SwallowedError emission + // is the release-visible audit trail. + Microsoft.UI.Reactor.Core.Diagnostics.DiagnosticLog.SwallowedError( + Microsoft.UI.Reactor.Core.Diagnostics.LogCategory.Reactor, + "ContentDialog.ShowAsync+OnClosed", + ex); } } diff --git a/src/Reactor/Core/Reconciler.cs b/src/Reactor/Core/Reconciler.cs index 82983ef57..1e3a0bdd2 100644 --- a/src/Reactor/Core/Reconciler.cs +++ b/src/Reactor/Core/Reconciler.cs @@ -1,5 +1,6 @@ using System.Numerics; using Microsoft.UI.Reactor.Animation; +using Microsoft.UI.Reactor.Core.Diagnostics; using Microsoft.UI.Reactor.Hosting; using Microsoft.Extensions.Logging; using Microsoft.Extensions.Logging.Abstractions; @@ -1032,7 +1033,7 @@ private void UnmountRecursive(UIElement control) service.PrepareToAnimate(caEl.ConnectedAnimationKey, control); } catch (global::System.Runtime.InteropServices.COMException) { } - catch (Exception ex) { global::System.Diagnostics.Debug.WriteLine($"[Reactor] ConnectedAnimation PrepareToAnimate failed: {ex}"); } + catch (Exception ex) { Microsoft.UI.Reactor.Core.Diagnostics.DiagnosticLog.SwallowedError(Microsoft.UI.Reactor.Core.Diagnostics.LogCategory.Reactor, "ConnectedAnimation.PrepareToAnimate", ex); } } // Clean up animation state (mirrors UnmountAndCollect) @@ -1302,7 +1303,7 @@ private void UnmountAndCollect(UIElement control, List toPool) service.PrepareToAnimate(caEl.ConnectedAnimationKey, control); } catch (global::System.Runtime.InteropServices.COMException) { } - catch (Exception ex) { global::System.Diagnostics.Debug.WriteLine($"[Reactor] ConnectedAnimation PrepareToAnimate failed: {ex}"); } + catch (Exception ex) { Microsoft.UI.Reactor.Core.Diagnostics.DiagnosticLog.SwallowedError(Microsoft.UI.Reactor.Core.Diagnostics.LogCategory.Reactor, "ConnectedAnimation.PrepareToAnimate", ex); } } // Clean up animation state @@ -2308,7 +2309,7 @@ internal void QueueConnectedAnimationStart(UIElement target, string key) _pendingConnectedAnimationStarts.Add((anim, target)); } catch (global::System.Runtime.InteropServices.COMException) { } - catch (Exception ex) { global::System.Diagnostics.Debug.WriteLine($"[Reactor] ConnectedAnimation GetAnimation failed: {ex}"); } + catch (Exception ex) { Microsoft.UI.Reactor.Core.Diagnostics.DiagnosticLog.SwallowedError(Microsoft.UI.Reactor.Core.Diagnostics.LogCategory.Reactor, "ConnectedAnimation.GetAnimation", ex); } } /// @@ -2323,7 +2324,7 @@ public void FlushConnectedAnimations() { try { anim.TryStart(target); } catch (global::System.Runtime.InteropServices.COMException) { } - catch (Exception ex) { global::System.Diagnostics.Debug.WriteLine($"[Reactor] ConnectedAnimation TryStart failed: {ex}"); } + catch (Exception ex) { Microsoft.UI.Reactor.Core.Diagnostics.DiagnosticLog.SwallowedError(Microsoft.UI.Reactor.Core.Diagnostics.LogCategory.Reactor, "ConnectedAnimation.TryStart", ex); } } _pendingConnectedAnimationStarts.Clear(); } @@ -3295,7 +3296,10 @@ private static void ApplyThemeBindings(FrameworkElement fe, IReadOnlyDictionary< } catch (Exception ex) { - global::System.Diagnostics.Debug.WriteLine($"[Reactor.Theme] Failed to apply ThemeBindings: {ex.Message}"); + Microsoft.UI.Reactor.Core.Diagnostics.DiagnosticLog.SwallowedError( + Microsoft.UI.Reactor.Core.Diagnostics.LogCategory.Theme, + "ApplyThemeBindings", + ex); } } @@ -3685,7 +3689,10 @@ internal void InvokePostNavigationLifecycle( try { hook.OnNavigatedTo?.Invoke(navigatedToCtx); } catch (Exception ex) { - global::System.Diagnostics.Debug.WriteLine($"[Reactor] onNavigatedTo threw: {ex}"); + // User-callback isolation (spec 044 §6.7.3): a thrown + // onNavigatedTo must not block sibling subscribers or the + // onNavigatedFrom phase below. + DiagnosticLog.SwallowedError(LogCategory.Reactor, "Reconciler.OnNavigatedTo", ex); } } @@ -3699,7 +3706,8 @@ internal void InvokePostNavigationLifecycle( try { hook.OnNavigatedFrom?.Invoke(navigatedFromCtx); } catch (Exception ex) { - global::System.Diagnostics.Debug.WriteLine($"[Reactor] onNavigatedFrom threw: {ex}"); + // User-callback isolation (spec 044 §6.7.3). + DiagnosticLog.SwallowedError(LogCategory.Reactor, "Reconciler.OnNavigatedFrom", ex); } } } @@ -3720,7 +3728,10 @@ internal bool InvokeNavigatingTo( try { hook.OnNavigatingTo?.Invoke(ctx); } catch (Exception ex) { - global::System.Diagnostics.Debug.WriteLine($"[Reactor] onNavigatingTo threw: {ex}"); + // User-callback isolation (spec 044 §6.7.3): a thrown + // onNavigatingTo must not silently cancel navigation — we + // still evaluate IsCancelled below for the explicit veto. + DiagnosticLog.SwallowedError(LogCategory.Reactor, "Reconciler.OnNavigatingTo", ex); } if (ctx.IsCancelled) { diff --git a/src/Reactor/Core/RenderContext.cs b/src/Reactor/Core/RenderContext.cs index 1d0b081b8..015d7af0a 100644 --- a/src/Reactor/Core/RenderContext.cs +++ b/src/Reactor/Core/RenderContext.cs @@ -1,4 +1,5 @@ using System.Diagnostics.CodeAnalysis; +using Microsoft.UI.Reactor.Core.Diagnostics; using Microsoft.UI.Reactor.Hooks; namespace Microsoft.UI.Reactor.Core; @@ -926,16 +927,18 @@ public Command UseCommand(Command command) if (guardRef.Current) return; guardRef.Current = true; setIsExecuting(true); + // try/finally — NOT try/catch. The user's command throw becomes a + // faulted Task; the framework's reentry-guard and IsExecuting + // state still get restored. We deliberately let the exception + // surface via Task.UnobservedTaskException rather than swallowing, + // so a buggy command is visible to the developer (matches the + // dispose / lifecycle policy elsewhere — don't hide user bugs). _ = Task.Run(async () => { try { await asyncAction(); } - catch (Exception ex) - { - global::System.Diagnostics.Debug.WriteLine($"[Reactor] UseCommand async action threw: {ex}"); - } finally { guardRef.Current = false; @@ -967,16 +970,14 @@ public Command UseCommand(Command command) if (guardRef.Current) return; guardRef.Current = true; setIsExecuting(true); + // try/finally — same shape as the non-generic UseCommand above. + // Cleanup runs; user throw surfaces via Task.UnobservedTaskException. _ = Task.Run(async () => { try { await asyncAction(arg); } - catch (Exception ex) - { - global::System.Diagnostics.Debug.WriteLine($"[Reactor] UseCommand<{typeof(T).Name}> async action threw: {ex}"); - } finally { guardRef.Current = false; @@ -1363,7 +1364,10 @@ internal void FlushEffects() } catch (Exception ex) { - global::System.Diagnostics.Debug.WriteLine($"[Reactor] Effect cleanup at index {i} threw: {ex}"); + // User-callback isolation (spec 044 §6.7.3): one bad + // cleanup must not block the remaining cleanups or + // Phase 2 effect re-runs in this flush. + DiagnosticLog.SwallowedError(LogCategory.Reactor, $"UseEffect.cleanup[i={i}]", ex); } hook.PendingCleanup = null; } @@ -1390,7 +1394,9 @@ internal void FlushEffects() } catch (Exception ex) { - global::System.Diagnostics.Debug.WriteLine($"[Reactor] Effect at index {i} threw: {ex}"); + // User-callback isolation (spec 044 §6.7.3): a thrown effect + // body must not block subsequent effects on this flush. + DiagnosticLog.SwallowedError(LogCategory.Reactor, $"UseEffect.effect[i={i}]", ex); } } } @@ -1408,7 +1414,10 @@ internal void RunCleanups() } catch (Exception ex) { - global::System.Diagnostics.Debug.WriteLine($"[Reactor] Cleanup at index {i} threw: {ex}"); + // User-callback isolation (spec 044 §6.7.3): a thrown + // cleanup must not block subsequent cleanups or the + // persisted-state save phase below. + DiagnosticLog.SwallowedError(LogCategory.Reactor, $"RunCleanups.effectCleanup[i={i}]", ex); } } } @@ -1424,7 +1433,10 @@ internal void RunCleanups() } catch (Exception ex) { - global::System.Diagnostics.Debug.WriteLine($"[Reactor] Persisted state save at index {i} threw: {ex}"); + // User-callback isolation (spec 044 §6.7.3): a thrown + // serializer for one persisted-state slot must not + // block subsequent slots from saving. + DiagnosticLog.SwallowedError(LogCategory.Reactor, $"RunCleanups.persistedSave[i={i}]", ex); } } } diff --git a/src/Reactor/Diagnostics/ReactorEvent.cs b/src/Reactor/Diagnostics/ReactorEvent.cs new file mode 100644 index 000000000..005ca54d2 --- /dev/null +++ b/src/Reactor/Diagnostics/ReactorEvent.cs @@ -0,0 +1,48 @@ +using System.Diagnostics.Tracing; + +namespace Microsoft.UI.Reactor.Diagnostics; + +/// +/// A single event captured from the Microsoft-UI-Reactor +/// , delivered to subscribers of +/// . +/// +/// +/// The payload arrays come from +/// and directly — no +/// reflection is involved, so this surface is AOT/trim-clean. +/// +/// +/// +/// PII discipline: every framework event has already stripped sensitive +/// fields (no , no window titles, no +/// instantiated route paths). Subscribers should respect that policy in +/// any downstream sink they forward to. +/// +/// +/// Numeric event identifier (stable per event method; +/// see the EventId allocation comment in ReactorEventSource). +/// The C# method name on ReactorEventSource +/// that emitted this event (e.g. "ReconcileStart", +/// "SwallowedError"). +/// Severity ( through +/// ). +/// The bitwise keyword(s) the event was emitted +/// under. ETW reserved bits in the high 4 bits may be set by the runtime; +/// subscribers should mask against the keyword they care about rather +/// than equality-test. +/// UTC capture timestamp at delivery time. +/// Managed thread id of the emission thread. +/// Positional payload values in the order declared +/// by the event method's parameters. Always non-null but may be empty. +/// Parallel array of parameter names. Always +/// non-null; same length as . +public readonly record struct ReactorEvent( + int EventId, + string EventName, + EventLevel Level, + EventKeywords Keywords, + DateTime TimestampUtc, + int ThreadId, + IReadOnlyList Payload, + IReadOnlyList PayloadNames); diff --git a/src/Reactor/Diagnostics/ReactorTrace.cs b/src/Reactor/Diagnostics/ReactorTrace.cs new file mode 100644 index 000000000..d9d2fe90b --- /dev/null +++ b/src/Reactor/Diagnostics/ReactorTrace.cs @@ -0,0 +1,235 @@ +using System.Diagnostics.Tracing; +using Microsoft.UI.Reactor.Core.Diagnostics; + +namespace Microsoft.UI.Reactor.Diagnostics; + +/// +/// In-process subscription helper for the Microsoft-UI-Reactor +/// . Lets an app developer (or an internal +/// devtools surface — reactor.logs MCP, an ILogger bridge) +/// observe framework events without writing an +/// subclass. +/// +/// +/// This is deliberately not a file-capture API. The .NET runtime +/// already provides three: +/// +/// +/// DOTNET_EnableEventPipe + DOTNET_EventPipeOutputPath +/// environment variables (zero app code). +/// dotnet-trace collect --providers Microsoft-UI-Reactor. +/// Visual Studio Performance Profiler → Events Viewer. +/// +/// +/// See docs/guide/diagnostics.md for end-to-end examples. +/// +/// +public static class ReactorTrace +{ + /// + /// Subscribes to Microsoft-UI-Reactor events in-process. + /// Returns an token; dispose it to detach. + /// + /// + /// The callback fires on the emission thread — typically the UI + /// dispatcher when an event originates from reconcile / render, or a + /// thread-pool thread otherwise. Keep the callback work minimal and + /// never let it throw across the framework boundary; the + /// implementation wraps every invocation in a try/catch so a + /// buggy subscriber cannot deadlock the dispatcher or break other + /// subscribers, but exceptions are silently dropped (a faulty sink + /// should not turn into an ETW failure mode). + /// + /// + /// + /// Multiple concurrent subscribers are supported. Each subscriber's + /// and are + /// independently active until the returned token is disposed; the + /// runtime unions them when computing whether IsEnabled on the + /// event source returns true. Be aware that a broad subscriber + /// ( + all keywords) raises the cost + /// of every hot-path call site on the framework for as long as it + /// lives. + /// + /// + /// + /// For writing a trace file, use one of: + /// + /// + /// DOTNET_EnableEventPipe / DOTNET_EventPipeOutputPath + /// env vars. + /// dotnet-trace collect --providers Microsoft-UI-Reactor. + /// Visual Studio Performance Profiler → Events Viewer. + /// + /// + /// Callback invoked once per matching event. + /// Must be non-null. + /// Minimum severity to forward. Defaults to + /// so subscribers see everything + /// (state changes, per-trampoline dispatches) unless they explicitly + /// pass a stricter level. + /// Keyword mask to forward. Defaults to all + /// keywords ((EventKeywords)(-1)). + /// Disposable token. Disposing detaches the underlying + /// ; subsequent events do not reach + /// . + /// If + /// is null. + // + public static IDisposable Subscribe( + Action onEvent, + EventLevel level = EventLevel.Verbose, + EventKeywords keywords = (EventKeywords)(-1)) + { + ArgumentNullException.ThrowIfNull(onEvent); + return new Subscription(onEvent, level, keywords); + } + // + + private sealed class Subscription : EventListener + { + // Configured target. Captured at construction so OnEventWritten + // can short-circuit on level/keywords without re-reading the + // EventListener's session-level filter (which the runtime may + // expose as a different mask than what we requested). + private readonly Action _callback; + private readonly EventLevel _level; + private readonly EventKeywords _keywords; + + // The underlying EventSource we listen to. EventListener delivers + // OnEventSourceCreated for every existing source at construction + // time and for any source created later; capture our reference so + // Dispose can deterministically call DisableEvents. + private EventSource? _source; + private int _disposed; + + public Subscription(Action callback, EventLevel level, EventKeywords keywords) + { + _callback = callback; + _level = level; + _keywords = keywords; + _initialized = true; + + // The base EventListener ctor calls OnEventSourceCreated for + // every existing source *before* the derived ctor body runs, + // so _level/_keywords are default(0) at that point. We capture + // the source reference there but defer EnableEvents until here, + // where the fields are properly assigned. + if (_source is not null) + { + // OnEventSourceCreated already captured the source but + // called EnableEvents with default filters — re-enable + // with the correct level/keywords now. + EnableEvents(_source, _level, _keywords); + } + else + { + // Belt-and-braces: if we somehow missed it (e.g., this + // listener construction races with first touch of + // ReactorEventSource), enable explicitly. + EnableEvents(ReactorEventSource.Log, _level, _keywords); + _source = ReactorEventSource.Log; + } + } + + private volatile bool _initialized; + + protected override void OnEventSourceCreated(EventSource eventSource) + { + if (eventSource.Name == "Microsoft-UI-Reactor") + { + _source = eventSource; + + // If the derived ctor has already run (late source + // creation), enable immediately with correct filters. + // Otherwise, just capture the reference — the ctor will + // call EnableEvents once _level/_keywords are assigned. + if (_initialized) + { + EnableEvents(eventSource, _level, _keywords); + } + else + { + // Enable with permissive defaults so we don't miss + // events between base-ctor and derived-ctor; the + // derived ctor will re-enable with correct filters. + EnableEvents(eventSource, EventLevel.LogAlways, (EventKeywords)(-1)); + } + } + } + + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + // Defense in depth: even though the runtime gates events by + // (level, keywords) on the EventListener, double-check here + // so a runtime that delivers a too-verbose event (or a high- + // bit ETW reserved keyword) doesn't blow past our contract. + if ((int)eventData.Level > (int)_level) return; + if (_keywords != (EventKeywords)(-1) + && (eventData.Keywords & _keywords) == 0 + && eventData.Keywords != 0) + { + return; + } + + ReactorEvent reactorEvent; + try + { + reactorEvent = new ReactorEvent( + EventId: eventData.EventId, + EventName: eventData.EventName ?? string.Empty, + Level: eventData.Level, + Keywords: eventData.Keywords, + TimestampUtc: DateTime.UtcNow, + ThreadId: Environment.CurrentManagedThreadId, + Payload: (IReadOnlyList?)eventData.Payload ?? Array.Empty(), + PayloadNames: (IReadOnlyList?)eventData.PayloadNames ?? Array.Empty()); + } + catch + { + // Defensive: don't let a malformed event break the + // EventSource.WriteEvent path. The framework's own emit + // sites are well-behaved, but custom EventSource methods + // added later could conceivably push a null Payload. + return; + } + + try + { + _callback(reactorEvent); + } + catch + { + // Per the doc contract: a buggy subscriber must not + // propagate to EventSource.WriteEvent (which would + // surface as an ETW emission failure) or to other + // subscribers. Swallow silently here. + } + } + + public override void Dispose() + { + // EventListener.Dispose is idempotent per its docs, but we + // guard the DisableEvents call to be safe across racing + // disposes from the user side. + if (Interlocked.Exchange(ref _disposed, 1) != 0) + { + base.Dispose(); + return; + } + + try + { + if (_source is not null) + DisableEvents(_source); + } + catch + { + // EventSource has already been disposed by the runtime + // (process shutdown). Nothing to do. + } + + base.Dispose(); + } + } +} diff --git a/src/Reactor/Hosting/Devtools/DevtoolsLogsTool.cs b/src/Reactor/Hosting/Devtools/DevtoolsLogsTool.cs index 0101d8e35..8611e713d 100644 --- a/src/Reactor/Hosting/Devtools/DevtoolsLogsTool.cs +++ b/src/Reactor/Hosting/Devtools/DevtoolsLogsTool.cs @@ -18,11 +18,13 @@ public static void Register(DevtoolsMcpServer server, Func ge new McpToolDescriptor( Name: "logs", Description: - "Drains captured Console.Out, Console.Error, and Debug.WriteLine/Trace.WriteLine output. " + + "Drains captured Console.Out, Console.Error, Debug.WriteLine/Trace.WriteLine output, " + + "and Microsoft-UI-Reactor ETW events. " + "Returns entries with monotonic `seq`; for incremental reads pass the previous " + "response's `nextSeq` directly as `since` (inclusive). " + "Filters: `tail` (keep last N after filtering), `filter` (regex; falls back to substring), " + - "`source` (stdout|stderr|debug — Debug and Trace share one listener), `level`. " + + "`source` (stdout|stderr|debug|event — Debug and Trace share one listener; event is the framework ETW provider), `level`. " + + "Event entries carry extra `eventName` and `eventId` fields. " + "Pass `waitMs > 0` to long-poll. `dropped` reports entries evicted by ring overflow.", InputSchema: new { @@ -32,8 +34,8 @@ public static void Register(DevtoolsMcpServer server, Func ge since = new { type = "integer", description = "Return entries with seq >= since. Pass previous `nextSeq` to continue. Default 0 returns all." }, tail = new { type = "integer", description = "Keep only the last N entries after filtering." }, filter = new { type = "string", description = "Regex; falls back to substring match if invalid." }, - source = new { type = "string", description = "stdout | stderr | debug (Debug and Trace both surface as `debug`)" }, - level = new { type = "string", description = "Exact level match (case-insensitive). Reserved for future structured sinks." }, + source = new { type = "string", description = "stdout | stderr | debug | event (Debug and Trace both surface as `debug`; `event` selects Microsoft-UI-Reactor ETW events)" }, + level = new { type = "string", description = "Exact level match (case-insensitive). For source=event the levels are Critical|Error|Warning|Info|Debug|Trace." }, waitMs = new { type = "integer", description = "Max time to block waiting for new entries. 0 returns immediately." }, }, additionalProperties = false, @@ -70,8 +72,9 @@ internal static object BuildPayload(LogCaptureBuffer? buf, JsonElement? @params) // Debug/Trace share one listener collection — we can't // distinguish them at the source. "debug" or "trace" => LogSource.Debug, + "event" or "etw" => LogSource.Event, _ => throw new McpToolException( - $"Unknown source '{sourceStr}'. Use stdout, stderr, or debug.", + $"Unknown source '{sourceStr}'. Use stdout, stderr, debug, or event.", JsonRpcErrorCodes.InvalidParams), }; @@ -88,7 +91,7 @@ internal static object BuildPayload(LogCaptureBuffer? buf, JsonElement? @params) return new { - entries = result.Entries.Select(e => new + entries = result.Entries.Select(e => (object)new { seq = e.Seq, ts = e.TimestampUtc.ToString("yyyy-MM-ddTHH:mm:ss.fffZ"), @@ -96,6 +99,8 @@ internal static object BuildPayload(LogCaptureBuffer? buf, JsonElement? @params) level = e.Level, threadId = e.ThreadId, text = e.Text, + eventName = e.EventName, + eventId = e.EventId, }).ToArray(), nextSeq = result.NextSeq, dropped = result.Dropped, diff --git a/src/Reactor/Hosting/Devtools/LogCaptureBuffer.cs b/src/Reactor/Hosting/Devtools/LogCaptureBuffer.cs index e6538b4b3..75fc7a56d 100644 --- a/src/Reactor/Hosting/Devtools/LogCaptureBuffer.cs +++ b/src/Reactor/Hosting/Devtools/LogCaptureBuffer.cs @@ -7,19 +7,39 @@ internal enum LogSource Stdout, Stderr, Debug, + /// + /// Entry forwarded from the Microsoft-UI-Reactor EventSource via + /// ReactorTrace.Subscribe. Carries + /// and ; the formatted ETW payload lives in + /// . + /// + Event, } /// /// One captured log line. Monotonic lets agents poll with /// since cursors instead of re-reading the whole buffer. /// +/// Monotonic per-process sequence number. +/// Capture time in UTC. +/// Origin: stdout, stderr, debug listener, or ETW event. +/// Severity label (case-insensitive match for the level filter). +/// Managed thread id of the emitter. +/// Rendered line text. +/// When is , +/// the C# method name on ReactorEventSource that emitted the event. +/// Null for stdout/stderr/debug entries. +/// When is , +/// the numeric event identifier. Null for stdout/stderr/debug entries. internal sealed record LogEntry( long Seq, DateTime TimestampUtc, LogSource Source, string? Level, int ThreadId, - string Text); + string Text, + string? EventName = null, + int? EventId = null); /// /// Bounded ring buffer for captured app logs. Thread-safe, zero-lock on reads @@ -55,6 +75,15 @@ public LogCaptureBuffer(long capacityBytes = DefaultCapacityBytes) /// everything else. /// public void Append(LogSource source, string? level, string text) + => Append(source, level, text, eventName: null, eventId: null); + + /// + /// Append an ETW-sourced entry. and + /// are surfaced as extra fields on the + /// resulting MCP reactor.logs response. Length-capping for + /// matches the base overload. + /// + public void Append(LogSource source, string? level, string text, string? eventName, int? eventId) { if (string.IsNullOrEmpty(text)) return; @@ -70,7 +99,9 @@ public void Append(LogSource source, string? level, string text) Source: source, Level: level, ThreadId: Environment.CurrentManagedThreadId, - Text: text); + Text: text, + EventName: eventName, + EventId: eventId); TaskCompletionSource? toSignal = null; lock (_lock) diff --git a/src/Reactor/Hosting/Devtools/LogCaptureInstall.cs b/src/Reactor/Hosting/Devtools/LogCaptureInstall.cs index 6b1eb3060..2bfb4c9b8 100644 --- a/src/Reactor/Hosting/Devtools/LogCaptureInstall.cs +++ b/src/Reactor/Hosting/Devtools/LogCaptureInstall.cs @@ -1,5 +1,9 @@ using System.Diagnostics; +using System.Diagnostics.Tracing; +using System.Globalization; using System.Text; +using Microsoft.UI.Reactor.Core.Diagnostics; +using Microsoft.UI.Reactor.Diagnostics; namespace Microsoft.UI.Reactor.Hosting.Devtools; @@ -165,10 +169,22 @@ internal static class LogCaptureInstall { private static readonly object _installLock = new(); private static LogCaptureBuffer? _shared; + // Owned for process lifetime. Disposing detaches the EventListener and + // stops the ETW→buffer bridge; we hold the reference so a stray GC pass + // doesn't unsubscribe us mid-session. + private static IDisposable? _eventSubscription; /// Process-wide shared buffer, lazily created on first install. public static LogCaptureBuffer? Shared => Volatile.Read(ref _shared); + /// + /// Maximum number of characters per payload field rendered into the + /// captured text. Keeps a single chatty event from filling the ring. + /// Spec 044 §6.2.1 (defense in depth — the EventSource side already + /// strips PII). + /// + internal const int MaxPayloadFieldChars = 256; + /// /// Installs capture. When is false /// (stdio MCP transport), Console.Out writes land in the buffer but are @@ -207,6 +223,15 @@ public static LogCaptureBuffer Install(long capacityBytes, bool forwardConsole) buffer: buf, source: LogSource.Stderr)); + // Bridge ReactorEventSource → ring buffer so `reactor.logs + // source=event` returns framework ETW events alongside stdout / + // stderr / debug. Owned for process lifetime; we never dispose + // (Install is one-shot, and process exit tears the listener + // down anyway). + _eventSubscription = ReactorTrace.Subscribe( + onEvent: e => OnReactorEvent(buf, e), + level: EventLevel.Verbose); + Volatile.Write(ref _shared, buf); return buf; } @@ -215,6 +240,98 @@ public static LogCaptureBuffer Install(long capacityBytes, bool forwardConsole) /// Test hook: reset the shared buffer. Do not call in product code. internal static void ResetForTests() { - lock (_installLock) Volatile.Write(ref _shared, null); + lock (_installLock) + { + _eventSubscription?.Dispose(); + _eventSubscription = null; + Volatile.Write(ref _shared, null); + } + } + + /// + /// Test hook: install a buffer plus the ETW bridge without touching + /// Console / Trace listeners. Used by Phase F bridge tests to exercise + /// the formatter and source mapping in isolation. + /// + internal static IDisposable InstallEventBridgeForTests(LogCaptureBuffer buf) + => ReactorTrace.Subscribe(e => OnReactorEvent(buf, e), level: EventLevel.Verbose); + + private static void OnReactorEvent(LogCaptureBuffer buf, ReactorEvent e) + { + // Map EventLevel to the same level strings the rest of the buffer + // uses (case-insensitive on the way out via the `level` filter). The + // strings here intentionally match what an ILogger consumer would + // see if we ever wired one up. + var level = e.Level switch + { + EventLevel.Critical => "Critical", + EventLevel.Error => "Error", + EventLevel.Warning => "Warning", + EventLevel.Informational => "Info", + EventLevel.Verbose => "Debug", + EventLevel.LogAlways => "Trace", + _ => null, + }; + + var text = FormatEventText(e); + buf.Append(LogSource.Event, level, text, eventName: e.EventName, eventId: e.EventId); + } + + /// + /// Render the event as "<EventName> name1=value1 name2=value2". + /// Visible to tests so the formatter contract can be asserted directly. + /// + internal static string FormatEventText(ReactorEvent e) + { + var sb = new StringBuilder(e.EventName); + // Payload and PayloadNames are parallel arrays from + // EventWrittenEventArgs; defensive Min in case a future event + // declares a different count (the runtime today guarantees equality). + var count = Math.Min(e.Payload.Count, e.PayloadNames.Count); + for (int i = 0; i < count; i++) + { + sb.Append(' '); + sb.Append(e.PayloadNames[i]); + sb.Append('='); + AppendPayloadValue(sb, e.PayloadNames[i], e.Payload[i]); + } + return sb.ToString(); } + + private static void AppendPayloadValue(StringBuilder sb, string name, object? value) + { + if (value is null) + { + sb.Append("null"); + return; + } + + // Name-based hex format for fields that look like HRESULTs or window + // handles. The emitting Debug.WriteLine sites used "0x{hr:X8}", so + // matching that shape keeps log greps stable across the migration. + if (LooksLikeHex(name)) + { + switch (value) + { + case int i32: sb.Append("0x").Append(i32.ToString("X8", CultureInfo.InvariantCulture)); return; + case long i64: sb.Append("0x").Append(i64.ToString("X16", CultureInfo.InvariantCulture)); return; + } + } + + var s = Convert.ToString(value, CultureInfo.InvariantCulture) ?? string.Empty; + if (s.Length > MaxPayloadFieldChars) + { + sb.Append(s, 0, MaxPayloadFieldChars); + sb.Append('…'); + } + else + { + sb.Append(s); + } + } + + private static bool LooksLikeHex(string name) => + name.Equals("hr", StringComparison.OrdinalIgnoreCase) + || name.Equals("hresult", StringComparison.OrdinalIgnoreCase) + || name.Equals("hwnd", StringComparison.OrdinalIgnoreCase); } diff --git a/src/Reactor/Hosting/Etw/LayoutEtwConsumer.cs b/src/Reactor/Hosting/Etw/LayoutEtwConsumer.cs index 541b155c5..3b539522e 100644 --- a/src/Reactor/Hosting/Etw/LayoutEtwConsumer.cs +++ b/src/Reactor/Hosting/Etw/LayoutEtwConsumer.cs @@ -3,6 +3,7 @@ using Microsoft.Diagnostics.Tracing; using Microsoft.Diagnostics.Tracing.Parsers; using Microsoft.Diagnostics.Tracing.Session; +using Microsoft.UI.Reactor.Core.Diagnostics; namespace Microsoft.UI.Reactor.Hosting.Etw; @@ -136,8 +137,8 @@ public void Start() } catch (Exception ex) { - Debug.WriteLine($"[Reactor.LayoutCost] orphan session cleanup failed: {ex.Message}"); // Non-fatal — continue trying to start. + DiagnosticLog.SwallowedError(LogCategory.LayoutCost, "LayoutEtwConsumer.Start.orphanCleanup", ex); } try @@ -155,15 +156,17 @@ public void Start() { IsUnavailable = true; UnavailableReason = "Access denied — user is not a member of Performance Log Users and is not an administrator."; - Debug.WriteLine($"[Reactor.LayoutCost] ETW session denied: {ex.Message}"); + DiagnosticLog.SwallowedError(LogCategory.LayoutCost, "LayoutEtwConsumer.Start.enableProvider.accessDenied", ex); SafeDisposeSession(); return; } catch (Exception ex) { IsUnavailable = true; + // UnavailableReason is surfaced in the overlay UI (developer-facing + // diagnostic), not on the ETW payload — DiagnosticLog stays to ex.Type. UnavailableReason = ex.Message; - Debug.WriteLine($"[Reactor.LayoutCost] ETW session failed: {ex}"); + DiagnosticLog.SwallowedError(LogCategory.LayoutCost, "LayoutEtwConsumer.Start.enableProvider", ex); SafeDisposeSession(); return; } @@ -177,7 +180,7 @@ public void Start() { IsUnavailable = true; UnavailableReason = ex.Message; - Debug.WriteLine($"[Reactor.LayoutCost] ETW parser hookup failed: {ex}"); + DiagnosticLog.SwallowedError(LogCategory.LayoutCost, "LayoutEtwConsumer.Start.parserHookup", ex); SafeDisposeSession(); return; } @@ -225,7 +228,7 @@ private void ProcessLoop() } catch (Exception ex) { - Debug.WriteLine($"[Reactor.LayoutCost] Source.Process() exited: {ex.Message}"); + DiagnosticLog.SwallowedError(LogCategory.LayoutCost, "LayoutEtwConsumer.ProcessLoop.SourceProcess", ex); } finally { @@ -492,7 +495,8 @@ private void CloseOrphanSessions() } catch (Exception ex) { - Debug.WriteLine($"[Reactor.LayoutCost] failed to close orphan session '{name}': {ex.Message}"); + // Per-orphan failure is non-fatal; keep iterating siblings. + DiagnosticLog.SwallowedError(LogCategory.LayoutCost, "LayoutEtwConsumer.CloseOrphanSessions.stop", ex); } } } @@ -522,7 +526,7 @@ private void SafeDisposeSession() } catch (Exception ex) { - Debug.WriteLine($"[Reactor.LayoutCost] session dispose swallowed: {ex.Message}"); + DiagnosticLog.SwallowedError(LogCategory.LayoutCost, "LayoutEtwConsumer.SafeDisposeSession", ex); } finally { diff --git a/src/Reactor/Hosting/Persistence/JsonFileStore.cs b/src/Reactor/Hosting/Persistence/JsonFileStore.cs index 5ac205d92..0e0865558 100644 --- a/src/Reactor/Hosting/Persistence/JsonFileStore.cs +++ b/src/Reactor/Hosting/Persistence/JsonFileStore.cs @@ -1,7 +1,8 @@ -using System.Diagnostics; +using System.Diagnostics.Tracing; using System.IO; using System.Text; using System.Text.Json; +using Microsoft.UI.Reactor.Core.Diagnostics; namespace Microsoft.UI.Reactor.Hosting.Persistence; @@ -31,6 +32,12 @@ public sealed class JsonFileStore : IWindowPersistenceStore /// public const long MaxFileSizeBytes = 1L * 1024 * 1024; + // Stable, developer-authored label for the spec 044 Phase B Persistence + // events. NEVER a file path — paths are PII per §6.2.1. + private const string StoreKind = "json-file"; + + private static int ClampSize(long bytes) => bytes > int.MaxValue ? int.MaxValue : (int)bytes; + private readonly string _path; private readonly object _ioLock = new(); @@ -92,7 +99,8 @@ public bool TryRead(string id, out byte[]? data) var info = new FileInfo(_path); if (info.Length > MaxFileSizeBytes) { - Debug.WriteLine($"[Reactor] JsonFileStore: refusing oversize file ({info.Length} bytes > {MaxFileSizeBytes}); falling back to default placement."); + if (ReactorEventSource.Log.IsEnabled(EventLevel.Warning, ReactorEventSource.Keywords.Persistence)) + ReactorEventSource.Log.PersistenceRejected(StoreKind, "oversize-read"); return false; } @@ -104,24 +112,33 @@ public bool TryRead(string id, out byte[]? data) var b64 = entry.GetString(); if (string.IsNullOrEmpty(b64)) return false; data = Convert.FromBase64String(b64); + if (data is not null + && ReactorEventSource.Log.IsEnabled(EventLevel.Informational, ReactorEventSource.Keywords.Persistence)) + ReactorEventSource.Log.PersistenceRead(StoreKind, ClampSize(info.Length)); return data is not null; } } catch (JsonException ex) { - Debug.WriteLine($"[Reactor] JsonFileStore: malformed JSON in {_path}: {ex.Message}"); + DiagnosticLog.SwallowedError(LogCategory.Persistence, "JsonFileStore.TryRead.parse", ex); data = null; return false; } catch (FormatException ex) { - Debug.WriteLine($"[Reactor] JsonFileStore: malformed base64 entry for id={id}: {ex.Message}"); + DiagnosticLog.SwallowedError(LogCategory.Persistence, "JsonFileStore.TryRead.base64", ex); + data = null; + return false; + } + catch (IOException ex) + { + DiagnosticLog.SwallowedError(LogCategory.Persistence, "JsonFileStore.TryRead", ex); data = null; return false; } - catch (Exception ex) + catch (UnauthorizedAccessException ex) { - Debug.WriteLine($"[Reactor] JsonFileStore.TryRead failed: {ex.GetType().Name}: {ex.Message}"); + DiagnosticLog.SwallowedError(LogCategory.Persistence, "JsonFileStore.TryRead", ex); data = null; return false; } @@ -150,7 +167,8 @@ public void Write(string id, byte[] data) var bytes = SerializeStringMap(doc); if (bytes.Length > MaxFileSizeBytes) { - Debug.WriteLine($"[Reactor] JsonFileStore: serialized payload exceeds {MaxFileSizeBytes} bytes ({bytes.Length}); skipping write."); + if (ReactorEventSource.Log.IsEnabled(EventLevel.Warning, ReactorEventSource.Keywords.Persistence)) + ReactorEventSource.Log.PersistenceRejected(StoreKind, "oversize-write"); return; } @@ -160,11 +178,18 @@ public void Write(string id, byte[] data) var tmp = _path + ".tmp"; File.WriteAllBytes(tmp, bytes); File.Move(tmp, _path, overwrite: true); + + if (ReactorEventSource.Log.IsEnabled(EventLevel.Informational, ReactorEventSource.Keywords.Persistence)) + ReactorEventSource.Log.PersistenceWrite(StoreKind, ClampSize(bytes.Length)); } } - catch (Exception ex) + catch (IOException ex) + { + DiagnosticLog.SwallowedError(LogCategory.Persistence, "JsonFileStore.Write", ex); + } + catch (UnauthorizedAccessException ex) { - Debug.WriteLine($"[Reactor] JsonFileStore.Write failed: {ex.GetType().Name}: {ex.Message}"); + DiagnosticLog.SwallowedError(LogCategory.Persistence, "JsonFileStore.Write", ex); } } @@ -178,8 +203,14 @@ private Dictionary ReadDocumentOrEmpty() using var stream = new FileStream(_path, FileMode.Open, FileAccess.Read, FileShare.Read); return ParseStringMap(stream); } - catch + catch (IOException ex) + { + DiagnosticLog.SwallowedError(LogCategory.Persistence, "JsonFileStore.ReadDocumentOrEmpty", ex); + return new(StringComparer.Ordinal); + } + catch (UnauthorizedAccessException ex) { + DiagnosticLog.SwallowedError(LogCategory.Persistence, "JsonFileStore.ReadDocumentOrEmpty", ex); return new(StringComparer.Ordinal); } } diff --git a/src/Reactor/Hosting/Persistence/MonitorEnumeration.cs b/src/Reactor/Hosting/Persistence/MonitorEnumeration.cs index 87e4ab4aa..dc2c16a12 100644 --- a/src/Reactor/Hosting/Persistence/MonitorEnumeration.cs +++ b/src/Reactor/Hosting/Persistence/MonitorEnumeration.cs @@ -1,4 +1,3 @@ -using System.Diagnostics; using System.Runtime.InteropServices; namespace Microsoft.UI.Reactor.Hosting.Persistence; @@ -34,24 +33,22 @@ private struct MONITORINFOEX public static IReadOnlyList Snapshot() { + // Both P/Invokes accept nint and signal failure via a bool return — + // no managed exception can surface from the marshal layer here, and + // the callback is pure framework code with no allocations that + // could OOM in practice. If EnumDisplayMonitors fails, list stays + // empty (caller treats as "no monitors known" → restore-rejects). var list = new List(2); - try + EnumDisplayMonitors(0, 0, (nint h, nint _, ref RECT _, nint _) => { - EnumDisplayMonitors(0, 0, (nint h, nint _, ref RECT _, nint _) => + var info = new MONITORINFOEX { cbSize = Marshal.SizeOf() }; + if (GetMonitorInfo(h, ref info)) { - var info = new MONITORINFOEX { cbSize = Marshal.SizeOf() }; - if (GetMonitorInfo(h, ref info)) - { - var r = info.rcMonitor; - list.Add(new MonitorRect(info.szDevice, r.Left, r.Top, r.Right, r.Bottom)); - } - return true; - }, 0); - } - catch (Exception ex) - { - Debug.WriteLine($"[Reactor] MonitorEnumeration.Snapshot failed: {ex.GetType().Name}: {ex.Message}"); - } + var r = info.rcMonitor; + list.Add(new MonitorRect(info.szDevice, r.Left, r.Top, r.Right, r.Bottom)); + } + return true; + }, 0); return list; } } diff --git a/src/Reactor/Hosting/Persistence/PackagedSettingsStore.cs b/src/Reactor/Hosting/Persistence/PackagedSettingsStore.cs index 396e7e08e..e1788ee31 100644 --- a/src/Reactor/Hosting/Persistence/PackagedSettingsStore.cs +++ b/src/Reactor/Hosting/Persistence/PackagedSettingsStore.cs @@ -1,4 +1,6 @@ -using System.Diagnostics; +using System.Diagnostics.Tracing; +using System.Runtime.InteropServices; +using Microsoft.UI.Reactor.Core.Diagnostics; namespace Microsoft.UI.Reactor.Hosting.Persistence; @@ -21,6 +23,11 @@ public sealed class PackagedSettingsStore : IWindowPersistenceStore private const string ContainerName = "Reactor"; private const string KeyPrefix = "WindowPersistence_"; + // Stable, developer-authored label for the spec 044 Phase B Persistence + // events. Distinguishes the WinRT-backed store from JsonFileStore on the + // trace, and is NEVER a path or container name a user could control. + private const string StoreKind = "packaged-settings"; + /// public bool TryRead(string id, out byte[]? data) { @@ -34,11 +41,39 @@ public bool TryRead(string id, out byte[]? data) if (!c.Values.TryGetValue(KeyPrefix + id, out var value)) return false; if (value is not string b64 || string.IsNullOrEmpty(b64)) return false; data = Convert.FromBase64String(b64); + if (data is not null + && ReactorEventSource.Log.IsEnabled(EventLevel.Informational, ReactorEventSource.Keywords.Persistence)) + ReactorEventSource.Log.PersistenceRead(StoreKind, data.Length); return data is not null; } - catch (Exception ex) + catch (InvalidOperationException ex) + { + // Hit on every unpackaged process: ApplicationData.Current throws + // 0x80073D54 ("not a packaged app"). The auto-detect flow uses + // PackagedSettingsStore.IsAvailable() to choose JsonFileStore in + // that context; this catch is the belt-and-braces for callers + // that bypass IsAvailable(). + DiagnosticLog.SwallowedError(LogCategory.Persistence, "PackagedSettingsStore.TryRead", ex); + data = null; + return false; + } + catch (COMException ex) + { + DiagnosticLog.SwallowedError(LogCategory.Persistence, "PackagedSettingsStore.TryRead", ex); + data = null; + return false; + } + catch (UnauthorizedAccessException ex) { - Debug.WriteLine($"[Reactor] PackagedSettingsStore.TryRead failed: {ex.GetType().Name}: {ex.Message}"); + DiagnosticLog.SwallowedError(LogCategory.Persistence, "PackagedSettingsStore.TryRead", ex); + data = null; + return false; + } + catch (FormatException ex) + { + // Malformed base64 in a tampered settings entry — same shape as + // the JsonFileStore counterpart. + DiagnosticLog.SwallowedError(LogCategory.Persistence, "PackagedSettingsStore.TryRead.base64", ex); data = null; return false; } @@ -54,10 +89,20 @@ public void Write(string id, byte[] data) if (settings is null) return; var c = settings.CreateContainer(ContainerName, global::Windows.Storage.ApplicationDataCreateDisposition.Always); c.Values[KeyPrefix + id] = Convert.ToBase64String(data); + if (ReactorEventSource.Log.IsEnabled(EventLevel.Informational, ReactorEventSource.Keywords.Persistence)) + ReactorEventSource.Log.PersistenceWrite(StoreKind, data.Length); + } + catch (InvalidOperationException ex) + { + DiagnosticLog.SwallowedError(LogCategory.Persistence, "PackagedSettingsStore.Write", ex); + } + catch (COMException ex) + { + DiagnosticLog.SwallowedError(LogCategory.Persistence, "PackagedSettingsStore.Write", ex); } - catch (Exception ex) + catch (UnauthorizedAccessException ex) { - Debug.WriteLine($"[Reactor] PackagedSettingsStore.Write failed: {ex.GetType().Name}: {ex.Message}"); + DiagnosticLog.SwallowedError(LogCategory.Persistence, "PackagedSettingsStore.Write", ex); } } diff --git a/src/Reactor/Hosting/Persistence/WindowPlacementCodec.cs b/src/Reactor/Hosting/Persistence/WindowPlacementCodec.cs index a8be5ed4c..e5ad495e7 100644 --- a/src/Reactor/Hosting/Persistence/WindowPlacementCodec.cs +++ b/src/Reactor/Hosting/Persistence/WindowPlacementCodec.cs @@ -1,5 +1,6 @@ -using System.Diagnostics; +using System.Diagnostics.Tracing; using System.Runtime.InteropServices; +using Microsoft.UI.Reactor.Core.Diagnostics; namespace Microsoft.UI.Reactor.Hosting.Persistence; @@ -69,7 +70,13 @@ internal struct WINDOWPLACEMENT var placement = new WINDOWPLACEMENT { length = Marshal.SizeOf() }; if (!GetWindowPlacement(hwnd, ref placement)) { - Debug.WriteLine($"[Reactor] GetWindowPlacement failed: {Marshal.GetLastWin32Error()}"); + // GetLastError on a Win32 BOOL failure: surface the raw code + // through the typed HResultFailed channel so apps capturing + // Microsoft-UI-Reactor see why placement save was skipped. + DiagnosticLog.HResultFailed( + LogCategory.Persistence, + "WindowPlacementCodec.GetWindowPlacement", + Marshal.GetLastWin32Error()); return null; } @@ -101,9 +108,9 @@ internal struct WINDOWPLACEMENT bw.Flush(); return ms.ToArray(); } - catch (Exception ex) + catch (global::System.IO.IOException ex) { - Debug.WriteLine($"[Reactor] WindowPlacementCodec.Capture failed: {ex.GetType().Name}: {ex.Message}"); + DiagnosticLog.SwallowedError(LogCategory.Persistence, "WindowPlacementCodec.Capture", ex); return null; } } @@ -124,7 +131,8 @@ internal static bool Restore(nint hwnd, byte[] data, IReadOnlyList int monitorCount = br.ReadInt32(); if (monitorCount < 0 || monitorCount > 64) { - Debug.WriteLine($"[Reactor] WindowPlacementCodec: implausible monitor count {monitorCount}; rejecting payload."); + if (ReactorEventSource.Log.IsEnabled(EventLevel.Warning, ReactorEventSource.Keywords.Persistence)) + ReactorEventSource.Log.PersistenceRejected("placement", "implausible-monitor-count"); return false; } if (monitorCount != currentMonitors.Count) @@ -163,11 +171,12 @@ internal static bool Restore(nint hwnd, byte[] data, IReadOnlyList // best-effort-fix our junk. if (!IsPlausiblePlacement(placement)) { - Debug.WriteLine( - $"[Reactor] WindowPlacementCodec: rejecting implausible placement " + - $"(rect={placement.rcNormalPosition.Left},{placement.rcNormalPosition.Top}," + - $"{placement.rcNormalPosition.Right},{placement.rcNormalPosition.Bottom} " + - $"showCmd={placement.showCmd}); falling back to default."); + // PII: do NOT emit the raw rect / showCmd on the ETW + // payload — those can encode user behavior signals + // (multi-mon layout fingerprinting). A short reason + // label is enough to triage the reject in a trace. + if (ReactorEventSource.Log.IsEnabled(EventLevel.Warning, ReactorEventSource.Keywords.Persistence)) + ReactorEventSource.Log.PersistenceRejected("placement", "implausible-rect"); return false; } @@ -188,11 +197,16 @@ internal static bool Restore(nint hwnd, byte[] data, IReadOnlyList } catch (global::System.IO.EndOfStreamException) { + // Tampered payload truncated mid-record. Treat as schema mismatch + // rather than an "exception swallow" — no value in the type-only + // ETW payload because the type IS the reason. + if (ReactorEventSource.Log.IsEnabled(EventLevel.Warning, ReactorEventSource.Keywords.Persistence)) + ReactorEventSource.Log.PersistenceRejected("placement", "truncated"); return false; } - catch (Exception ex) + catch (global::System.IO.IOException ex) { - Debug.WriteLine($"[Reactor] WindowPlacementCodec.Restore failed: {ex.GetType().Name}: {ex.Message}"); + DiagnosticLog.SwallowedError(LogCategory.Persistence, "WindowPlacementCodec.Restore", ex); return false; } } diff --git a/src/Reactor/Hosting/ReactorWindow.cs b/src/Reactor/Hosting/ReactorWindow.cs index c2c8ef6f3..0f185d346 100644 --- a/src/Reactor/Hosting/ReactorWindow.cs +++ b/src/Reactor/Hosting/ReactorWindow.cs @@ -1,6 +1,6 @@ -using System.Diagnostics; using System.Runtime.InteropServices; using Microsoft.UI.Reactor.Core; +using Microsoft.UI.Reactor.Core.Diagnostics; using Microsoft.UI.Reactor.Hosting; using Microsoft.UI.Reactor.Hosting.Messaging; using Microsoft.UI.Reactor.Hosting.Persistence; @@ -28,6 +28,31 @@ namespace Microsoft.UI.Reactor; /// public sealed class ReactorWindow : IDisposable { + // Spec 044 §6.7 catch-shape conventions used throughout this file: + // + // §6.7.2 WinUI API narrow catch: + // `catch (COMException ex) when (HResults.IsTeardownReentry(ex.HResult))` + // for AppWindow / Window / Win32 calls that can throw the well-known + // proxy-disconnect / handle-gone HRESULTs during teardown, DPI flux, + // and presenter transitions. Anything outside that HR set propagates + // as a real bug. + // + // §6.7.3 iteration sibling-independence: + // Broad `catch (Exception)` is kept ONLY where one slot/iteration + // failure must not block forward progress on its siblings (closing + // guards, owned-window cascade, effect-flush loops in RenderContext). + // Each such site has an inline comment naming the contract. + // + // try / finally for cleanup ordering: + // User-callback invocations followed by framework cleanup use + // try { Handler?.Invoke(...); } finally { ... }. The user's exception + // propagates (the developer sees their bug); the framework cleanup + // still runs (no stale references in the limp-along case where the + // app catches via Application.UnhandledException). + // + // Purely-advisory user callbacks (SizeChanged, StateChanged, Closing, + // Closed) have NO try/catch — a throwing handler propagates to the + // dispatcher. Swallowing those just hides the developer's bug. private static int s_nextId; private readonly string _id; @@ -263,25 +288,22 @@ private WindowState ResolveCurrentState() return Microsoft.UI.Reactor.WindowState.CompactOverlay; } } - catch (Exception ex) { Debug.WriteLine($"[Reactor] ResolveCurrentState failed: {ex.Message}"); } + catch (COMException ex) when (HResults.IsTeardownReentry(ex.HResult)) + { + DiagnosticLog.SwallowedError(LogCategory.Hosting, "ReactorWindow.ResolveCurrentState", ex); + } return Microsoft.UI.Reactor.WindowState.Normal; } private static uint QueryDpiForWindow(nint hwnd) { - try - { - uint dpi = NativeDpi.GetDpiForWindow(hwnd); - // Some non-realized HWNDs report 0; use the system DPI as a fallback. - if (dpi == 0) - dpi = NativeDpi.GetDpiForSystemFallback(); - return dpi == 0 ? 96 : dpi; - } - catch (Exception ex) - { - Debug.WriteLine($"[Reactor] QueryDpiForWindow failed: {ex.Message}"); - return 96; - } + // P/Invoke on nint cannot throw at the marshal layer; both + // GetDpiForWindow and GetDpiForSystem signal failure via a 0 + // return value, handled inline. No try/catch needed. + uint dpi = NativeDpi.GetDpiForWindow(hwnd); + if (dpi == 0) + dpi = NativeDpi.GetDpiForSystemFallback(); + return dpi == 0 ? 96 : dpi; } private static class NativeDpi @@ -292,10 +314,7 @@ private static class NativeDpi [DllImport("user32.dll")] public static extern uint GetDpiForSystem(); - public static uint GetDpiForSystemFallback() - { - try { return GetDpiForSystem(); } catch { return 96; } - } + public static uint GetDpiForSystemFallback() => GetDpiForSystem(); } /// @@ -320,7 +339,10 @@ internal void MountAndActivate(Func? rootFactory, Func physical at the current per-window DPI. (spec 036 §5.1) if (isInitial && spec.Presenter == PresenterKind.Overlapped) @@ -370,7 +401,10 @@ private void ApplyChrome(WindowSpec spec, bool isInitial) { _appWindow.Resize(DipToPhysicalSize(spec.Width, spec.Height)); } - catch (Exception ex) { Debug.WriteLine($"[Reactor] Initial resize failed: {ex.Message}"); } + catch (COMException ex) when (HResults.IsTeardownReentry(ex.HResult)) + { + DiagnosticLog.SwallowedError(LogCategory.Hosting, "ReactorWindow.InitialResize", ex); + } } if (spec.Icon is { } icon) @@ -388,7 +422,10 @@ private void ApplyChrome(WindowSpec spec, bool isInitial) { NativeOwnership.SetOwner(_hwnd, owner._hwnd); } - catch (Exception ex) { Debug.WriteLine($"[Reactor] SetOwner failed: {ex.Message}"); } + catch (COMException ex) when (HResults.IsTeardownReentry(ex.HResult)) + { + DiagnosticLog.SwallowedError(LogCategory.Hosting, "ReactorWindow.SetOwner", ex); + } owner.AddOwned(this); } } @@ -464,9 +501,12 @@ private void TryApplyExeIconFallback() // ownership rationale. _exeFallbackHIcon = hIcon; } - catch (Exception ex) + catch (COMException ex) when (HResults.IsTeardownReentry(ex.HResult)) { - Debug.WriteLine($"[Reactor] TryApplyExeIconFallback failed: {ex.Message}"); + // _appWindow.SetIcon during teardown reentry — the only WinRT call + // in the try that can plausibly fail here. LoadImageW returns 0 on + // failure (handled inline) and GetIconIdFromIcon is non-throwing. + DiagnosticLog.SwallowedError(LogCategory.Hosting, "ReactorWindow.TryApplyExeIconFallback", ex); } } @@ -545,7 +585,10 @@ private void OnWindowMessage(object? sender, WindowMessageEventArgs args) { _appWindow.Resize(DipToPhysicalSize(_spec.Width, _spec.Height)); } - catch (Exception ex) { Debug.WriteLine($"[Reactor] First-DPI resize failed: {ex.Message}"); } + catch (COMException ex) when (HResults.IsTeardownReentry(ex.HResult)) + { + DiagnosticLog.SwallowedError(LogCategory.Hosting, "ReactorWindow.FirstDpiResize", ex); + } } break; } @@ -604,25 +647,22 @@ private unsafe void ApplyMinMaxInfo(WindowMessageEventArgs args) if (spec.MinWidth is null && spec.MinHeight is null && spec.MaxWidth is null && spec.MaxHeight is null) return; - try - { - var info = (MINMAXINFO*)args.LParam; - if (info == null) return; - var dpi = Dpi == 0 ? 96 : Dpi; - - int DipToPxScalar(double dip) => (int)Math.Round(dip * dpi / 96.0); - - if (spec.MinWidth is { } mnw) info->ptMinTrackSize.X = DipToPxScalar(mnw); - if (spec.MinHeight is { } mnh) info->ptMinTrackSize.Y = DipToPxScalar(mnh); - if (spec.MaxWidth is { } mxw) info->ptMaxTrackSize.X = DipToPxScalar(mxw); - if (spec.MaxHeight is { } mxh) info->ptMaxTrackSize.Y = DipToPxScalar(mxh); - args.Handled = true; - args.Result = 0; - } - catch (Exception ex) - { - Debug.WriteLine($"[Reactor] WM_GETMINMAXINFO apply failed: {ex.Message}"); - } + // Pointer dereferences only — no API call here that throws. An + // invalid args.LParam would crash via AccessViolationException + // (which doesn't reach managed catches anyway); the inline null + // check guards the only correctable case. + var info = (MINMAXINFO*)args.LParam; + if (info == null) return; + var dpi = Dpi == 0 ? 96 : Dpi; + + int DipToPxScalar(double dip) => (int)Math.Round(dip * dpi / 96.0); + + if (spec.MinWidth is { } mnw) info->ptMinTrackSize.X = DipToPxScalar(mnw); + if (spec.MinHeight is { } mnh) info->ptMinTrackSize.Y = DipToPxScalar(mnh); + if (spec.MaxWidth is { } mxw) info->ptMaxTrackSize.X = DipToPxScalar(mxw); + if (spec.MaxHeight is { } mxh) info->ptMaxTrackSize.Y = DipToPxScalar(mxh); + args.Handled = true; + args.Result = 0; } private void OnNativeActivated(object? sender, WindowActivatedEventArgs args) @@ -639,13 +679,12 @@ private void OnNativeActivated(object? sender, WindowActivatedEventArgs args) private void OnNativeSizeChanged(object sender, Microsoft.UI.Xaml.WindowSizeChangedEventArgs args) { - try - { - // Window.Bounds is already DIPs (the WinUI XAML rendering surface). - var dip = (args.Size.Width, args.Size.Height); - SizeChanged?.Invoke(this, new WindowDipSizeChangedEventArgs(dip, args)); - } - catch (Exception ex) { Debug.WriteLine($"[Reactor] SizeChanged dispatch failed: {ex.Message}"); } + // Pure advisory dispatch. A throwing handler propagates to the + // dispatcher's UnhandledException pipeline — the developer's bug + // is theirs to see; wrapping it would just hide it. + // Window.Bounds is already DIPs (the WinUI XAML rendering surface). + var dip = (args.Size.Width, args.Size.Height); + SizeChanged?.Invoke(this, new WindowDipSizeChangedEventArgs(dip, args)); } private void OnAppWindowChanged(AppWindow sender, Microsoft.UI.Windowing.AppWindowChangedEventArgs args) @@ -656,8 +695,10 @@ private void OnAppWindowChanged(AppWindow sender, Microsoft.UI.Windowing.AppWind if (newState != prev) { Volatile.Write(ref _stateValue, (int)newState); - try { StateChanged?.Invoke(this, newState); } - catch (Exception ex) { Debug.WriteLine($"[Reactor] StateChanged dispatch failed: {ex.Message}"); } + // Pure advisory dispatch. A throwing handler propagates to the + // dispatcher; we've already updated _stateValue, so the framework + // invariant is held regardless of whether the user crashes. + StateChanged?.Invoke(this, newState); } } @@ -675,11 +716,12 @@ private void OnAppWindowClosing(AppWindow sender, Microsoft.UI.Windowing.AppWind for (int i = 0; i < guards.Length; i++) { try { if (!guards[i].CanClose()) { cancel = true; break; } } + // User-callback isolation (spec 044 §6.7.3): IClosingGuard.CanClose + // is app code — a throwing guard is fail-safed to "cancel" rather + // than allowed to crash the close. (spec 036 §3.4 tests pin this.) catch (Exception ex) { - // Fail-safe: treat a throwing guard as "cancel" with a stderr - // notice. (spec 036 §3.4 tests). - Debug.WriteLine($"[Reactor] ClosingGuard threw — cancelling close: {ex.Message}"); + DiagnosticLog.SwallowedError(LogCategory.Hosting, "ReactorWindow.ClosingGuard.dispatch", ex); cancel = true; break; } @@ -687,8 +729,11 @@ private void OnAppWindowClosing(AppWindow sender, Microsoft.UI.Windowing.AppWind if (!cancel) { - try { Closing?.Invoke(this, cea); } - catch (Exception ex) { Debug.WriteLine($"[Reactor] Closing handler threw: {ex.Message}"); } + // Closing is app code. A throwing handler propagates: previous + // behavior swallowed the throw and proceeded with close (silently + // treating the bug as "didn't cancel") which is worse than + // crashing — the developer needs to see their bug. + Closing?.Invoke(this, cea); cancel = cea.Cancel; } @@ -704,7 +749,15 @@ private void OnAppWindowClosing(AppWindow sender, Microsoft.UI.Windowing.AppWind if (child._disposed) continue; child._closingReason = WindowCloseReason.OwnerClosed; try { child._window.Close(); } - catch (Exception ex) { Debug.WriteLine($"[Reactor] Owned window close threw: {ex.Message}"); } + // Iteration sibling-independence (spec 044 §6.7.3): one + // failing child must not abort the cascade across its + // siblings. The Window.Close call also re-enters the child's + // own Closing/Closed dispatch — its user handlers now + // propagate (per the SizeChanged/StateChanged/Closing/Closed + // rule above), so this broad catch is the cascade-loop + // protection that keeps the OWNER's close attempt sane even + // when a single child's handler crashes. + catch (Exception ex) { DiagnosticLog.SwallowedError(LogCategory.Hosting, "ReactorWindow.OwnedWindow.Close", ex); } // After Close(), if the child is still alive (a guard // cancelled), abort the owner close. if (!child._disposed) @@ -764,16 +817,26 @@ private void OnNativeClosed(object? sender, WindowEventArgs args) // the user's last interactive size/position. Best-effort. TrySavePersistedPlacement(); - try { Closed?.Invoke(this, EventArgs.Empty); } - catch (Exception ex) { Debug.WriteLine($"[Reactor] Closed handler threw: {ex.Message}"); } - - // Detach from the owner's child-list so a later owner-close cascade - // doesn't iterate over an already-closed pointer. (spec 036 §9) - var spec = _spec; - spec.Owner?.RemoveOwned(this); + // try/finally so framework cleanup (RemoveOwned, UnregisterWindow, + // Dispose) runs regardless of whether the user's Closed handler + // throws. The user's exception still propagates to the dispatcher + // (the developer sees their bug); but for the limp-along case where + // the app sets Application.UnhandledException += (..., Handled = true) + // we don't leave stale window references behind. + try + { + Closed?.Invoke(this, EventArgs.Empty); + } + finally + { + // Detach from the owner's child-list so a later owner-close cascade + // doesn't iterate over an already-closed pointer. (spec 036 §9) + var spec = _spec; + spec.Owner?.RemoveOwned(this); - ReactorApp.UnregisterWindow(this); - Dispose(); + ReactorApp.UnregisterWindow(this); + Dispose(); + } } // ── public mutators ─────────────────────────────────────────────── @@ -796,7 +859,9 @@ public void Hide() { ThreadAffinity.ThrowIfNotOnUIThread(nameof(Hide)); if (_disposed) return; - try { _appWindow.Hide(); } catch (Exception ex) { Debug.WriteLine($"[Reactor] Hide failed: {ex.Message}"); } + try { _appWindow.Hide(); } + catch (COMException ex) when (HResults.IsTeardownReentry(ex.HResult)) + { DiagnosticLog.SwallowedError(LogCategory.Hosting, "ReactorWindow.Hide", ex); } IsVisible = false; } @@ -807,7 +872,9 @@ public void Show() { ThreadAffinity.ThrowIfNotOnUIThread(nameof(Show)); if (_disposed) return; - try { _appWindow.Show(); } catch (Exception ex) { Debug.WriteLine($"[Reactor] Show failed: {ex.Message}"); } + try { _appWindow.Show(); } + catch (COMException ex) when (HResults.IsTeardownReentry(ex.HResult)) + { DiagnosticLog.SwallowedError(LogCategory.Hosting, "ReactorWindow.Show", ex); } IsVisible = true; } @@ -823,7 +890,8 @@ public void Close() if (_disposed) return; _closingReason = WindowCloseReason.AppClosed; try { _window.Close(); } - catch (Exception ex) { Debug.WriteLine($"[Reactor] Close failed: {ex.Message}"); } + catch (COMException ex) when (HResults.IsTeardownReentry(ex.HResult)) + { DiagnosticLog.SwallowedError(LogCategory.Hosting, "ReactorWindow.Close", ex); } } /// @@ -865,7 +933,8 @@ public void SetSize(double width, double height) // first-DPI re-apply path stops fighting it. (spec 036 §5.1) _userResized = true; try { _appWindow.Resize(DipToPhysicalSize(width, height)); } - catch (Exception ex) { Debug.WriteLine($"[Reactor] SetSize failed: {ex.Message}"); } + catch (COMException ex) when (HResults.IsTeardownReentry(ex.HResult)) + { DiagnosticLog.SwallowedError(LogCategory.Hosting, "ReactorWindow.SetSize", ex); } } /// @@ -887,7 +956,8 @@ public void SetPosition(double x, double y) ThreadAffinity.ThrowIfNotOnUIThread(nameof(SetPosition)); if (_disposed) return; try { _appWindow.Move(DipToPhysicalPoint(x, y)); } - catch (Exception ex) { Debug.WriteLine($"[Reactor] SetPosition failed: {ex.Message}"); } + catch (COMException ex) when (HResults.IsTeardownReentry(ex.HResult)) + { DiagnosticLog.SwallowedError(LogCategory.Hosting, "ReactorWindow.SetPosition", ex); } } /// Center on the window's current monitor. UI-thread only. @@ -903,7 +973,8 @@ public void CenterOnScreen() int y = area.Value.Y + (area.Value.Height - _appWindow.Size.Height) / 2; _appWindow.Move(new global::Windows.Graphics.PointInt32(x, y)); } - catch (Exception ex) { Debug.WriteLine($"[Reactor] CenterOnScreen failed: {ex.Message}"); } + catch (COMException ex) when (HResults.IsTeardownReentry(ex.HResult)) + { DiagnosticLog.SwallowedError(LogCategory.Hosting, "ReactorWindow.CenterOnScreen", ex); } } /// @@ -971,29 +1042,49 @@ public void Dispose() if (_disposed) return; _disposed = true; - try { _window.Activated -= OnNativeActivated; } catch { /* best effort */ } - try { _window.SizeChanged -= OnNativeSizeChanged; } catch { /* best effort */ } - try { _appWindow.Changed -= OnAppWindowChanged; } catch { /* best effort */ } - try { _appWindow.Closing -= OnAppWindowClosing; } catch { /* best effort */ } - try { _window.Closed -= OnNativeClosed; } catch { /* best effort */ } - try { _messageMonitor.Dispose(); } catch (Exception ex) { Debug.WriteLine($"[Reactor] MessageMonitor dispose failed: {ex.Message}"); } - - // ReactorHost already subscribes to Window.Closed; let it dispose itself. - // We avoid double-dispose because Dispose() is idempotent there too. - try { _host.Dispose(); } catch (Exception ex) { Debug.WriteLine($"[Reactor] Host dispose failed: {ex.Message}"); } - - // Drop per-window persisted state — bounded by window lifetime per spec. - try { _persistedScope.Dispose(); } catch (Exception ex) { Debug.WriteLine($"[Reactor] PersistedScope dispose failed: {ex.Message}"); } - - // Release thumbnail-toolbar HICONs and clear the click-dispatch map so - // a late WM_COMMAND can't reach freed handlers. (spec 036 §11.5) - try { Volatile.Read(ref _thumbnailToolbar)?.Dispose(); } catch { /* best effort */ } + // Event unsubscription — these throw at most COMException when the + // proxy is already disconnected (which is exactly the "we're tearing + // down anyway" case). Narrow to the teardown-reentry HR set. + try { _window.Activated -= OnNativeActivated; } + catch (COMException ex) when (HResults.IsTeardownReentry(ex.HResult)) { /* expected during teardown */ } + try { _window.SizeChanged -= OnNativeSizeChanged; } + catch (COMException ex) when (HResults.IsTeardownReentry(ex.HResult)) { /* expected during teardown */ } + try { _appWindow.Changed -= OnAppWindowChanged; } + catch (COMException ex) when (HResults.IsTeardownReentry(ex.HResult)) { /* expected during teardown */ } + try { _appWindow.Closing -= OnAppWindowClosing; } + catch (COMException ex) when (HResults.IsTeardownReentry(ex.HResult)) { /* expected during teardown */ } + try { _window.Closed -= OnNativeClosed; } + catch (COMException ex) when (HResults.IsTeardownReentry(ex.HResult)) { /* expected during teardown */ } + + // Cleanup chain: nested try/finally so all four disposes run even if + // one throws, while the first exception still propagates. ReactorHost + // and _persistedScope both have idempotent Dispose; double-dispose + // is safe even if a downstream subscriber already disposed them. + try { _messageMonitor.Dispose(); } + finally + { + try { _host.Dispose(); } + finally + { + try { _persistedScope.Dispose(); } + finally + { + // Release thumbnail-toolbar HICONs and clear the + // click-dispatch map so a late WM_COMMAND can't reach + // freed handlers. (spec 036 §11.5) + Volatile.Read(ref _thumbnailToolbar)?.Dispose(); + } + } + } // Free the EXE-fallback HICON if we loaded one. AppWindow keeps its // own internal reference, so post-Close destruction is safe. if (_exeFallbackHIcon != 0) { - try { NativeIcon.DestroyIcon(_exeFallbackHIcon); } catch { /* best effort */ } + // DestroyIcon is a [DllImport] bool — cannot throw at the marshal + // layer on an nint argument. Failure (handle already freed) returns + // false silently, which is fine here. + NativeIcon.DestroyIcon(_exeFallbackHIcon); _exeFallbackHIcon = 0; } } @@ -1054,9 +1145,11 @@ private void TryApplyInitialPlacement() // fall through to WinUI's default placement. } } - catch (Exception ex) + catch (COMException ex) when (HResults.IsTeardownReentry(ex.HResult)) { - Debug.WriteLine($"[Reactor] TryApplyInitialPlacement failed: {ex.GetType().Name}: {ex.Message}"); + // _appWindow.Move / DisplayArea.GetFromWindowId during teardown + // reentry. Anything outside this HR set is a real bug. + DiagnosticLog.SwallowedError(LogCategory.Hosting, "ReactorWindow.TryApplyInitialPlacement", ex); } } @@ -1066,20 +1159,19 @@ private bool TryRestorePersistedPlacementCore(WindowSpec spec) var store = ReactorApp.ResolvePersistenceStore(); if (store is null) return false; - try - { - if (!store.TryRead(spec.PersistenceId!, out var data) || data is null) - return false; - var monitors = MonitorEnumeration.Snapshot(); - // Fingerprint mismatch / malformed payload returns false; caller - // falls back to spec's default placement. - return WindowPlacementCodec.Restore(_hwnd, data, monitors); - } - catch (Exception ex) - { - Debug.WriteLine($"[Reactor] TryRestorePersistedPlacement failed: {ex.GetType().Name}: {ex.Message}"); + // All three downstream calls now signal failure via a return value + // rather than throwing — store.TryRead is narrowed inside the store + // (see C.5 audit entries for JsonFileStore / PackagedSettingsStore), + // MonitorEnumeration.Snapshot has no failure modes that surface as + // exceptions on managed nint args, and WindowPlacementCodec.Restore + // catches IOException internally and returns false. No outer catch + // needed; a propagating exception would be a genuine bug. + if (!store.TryRead(spec.PersistenceId!, out var data) || data is null) return false; - } + var monitors = MonitorEnumeration.Snapshot(); + // Fingerprint mismatch / malformed payload returns false; caller + // falls back to spec's default placement. + return WindowPlacementCodec.Restore(_hwnd, data, monitors); } private void CenterIn(DisplayArea? area) @@ -1096,7 +1188,12 @@ private void CenterIn(DisplayArea? area) { if (owner is null || owner._disposed) return DisplayArea.Primary; try { return DisplayArea.GetFromWindowId(owner._appWindow.Id, DisplayAreaFallback.Nearest); } - catch { return DisplayArea.Primary; } + catch (COMException ex) when (HResults.IsTeardownReentry(ex.HResult)) + { + // Owner already torn down between the _disposed check and the + // WinRT call — fall back to primary display. + return DisplayArea.Primary; + } } /// @@ -1112,16 +1209,12 @@ private void TrySavePersistedPlacement() var store = ReactorApp.ResolvePersistenceStore(); if (store is null) return; - try - { - var monitors = MonitorEnumeration.Snapshot(); - var payload = WindowPlacementCodec.Capture(_hwnd, monitors); - if (payload is null) return; - store.Write(spec.PersistenceId!, payload); - } - catch (Exception ex) - { - Debug.WriteLine($"[Reactor] TrySavePersistedPlacement failed: {ex.GetType().Name}: {ex.Message}"); - } + // Same shape as TryRestorePersistedPlacementCore — every downstream + // failure mode now returns a sentinel value (null/false) rather than + // throwing. store.Write narrows internally per the C.5 audit entry. + var monitors = MonitorEnumeration.Snapshot(); + var payload = WindowPlacementCodec.Capture(_hwnd, monitors); + if (payload is null) return; + store.Write(spec.PersistenceId!, payload); } } diff --git a/src/Reactor/Hosting/Shell/JumpListComInterop.cs b/src/Reactor/Hosting/Shell/JumpListComInterop.cs index 85723513c..2d6af3495 100644 --- a/src/Reactor/Hosting/Shell/JumpListComInterop.cs +++ b/src/Reactor/Hosting/Shell/JumpListComInterop.cs @@ -1,5 +1,6 @@ using System.Diagnostics; using System.Runtime.InteropServices; +using Microsoft.UI.Reactor.Core.Diagnostics; namespace Microsoft.UI.Reactor.Hosting.Shell; @@ -52,7 +53,7 @@ public static void UpdateUnpackaged( int hr = cdl.BeginList(out slotCount, ref iidObjArray, out removed); if (hr < 0) { - Debug.WriteLine($"[Reactor] BeginList HR=0x{hr:X8}"); + DiagnosticLog.HResultFailed(LogCategory.Shell, "JumpList.BeginList", hr); return; } @@ -85,7 +86,7 @@ public static void UpdateUnpackaged( { var asArray = (IObjectArray)coll; int taskHr = cdl.AddUserTasks(asArray); - if (taskHr < 0) Debug.WriteLine($"[Reactor] AddUserTasks HR=0x{taskHr:X8}"); + if (taskHr < 0) DiagnosticLog.HResultFailed(LogCategory.Shell, "JumpList.AddUserTasks", taskHr); } finally { Marshal.ReleaseComObject(coll); } } @@ -100,7 +101,7 @@ public static void UpdateUnpackaged( { var asArray = (IObjectArray)coll; int catHr = cdl.AppendCategory(category, asArray); - if (catHr < 0) Debug.WriteLine($"[Reactor] AppendCategory '{category}' HR=0x{catHr:X8}"); + if (catHr < 0) DiagnosticLog.HResultFailed(LogCategory.Shell, "JumpList.AppendCategory", catHr); } finally { Marshal.ReleaseComObject(coll); } } @@ -108,17 +109,17 @@ public static void UpdateUnpackaged( if (showRecent) { int recHr = cdl.AppendKnownCategory(KnownDestCategory.Recent); - if (recHr < 0) Debug.WriteLine($"[Reactor] AppendKnownCategory Recent HR=0x{recHr:X8}"); + if (recHr < 0) DiagnosticLog.HResultFailed(LogCategory.Shell, "JumpList.AppendKnownCategory.Recent", recHr); } if (showFrequent) { int freqHr = cdl.AppendKnownCategory(KnownDestCategory.Frequent); - if (freqHr < 0) Debug.WriteLine($"[Reactor] AppendKnownCategory Frequent HR=0x{freqHr:X8}"); + if (freqHr < 0) DiagnosticLog.HResultFailed(LogCategory.Shell, "JumpList.AppendKnownCategory.Frequent", freqHr); } int commitHr = cdl.CommitList(); if (commitHr < 0) - Debug.WriteLine($"[Reactor] JumpList CommitList HR=0x{commitHr:X8}"); + DiagnosticLog.HResultFailed(LogCategory.Shell, "JumpList.CommitList", commitHr); } catch (Exception ex) { diff --git a/src/Reactor/Hosting/Shell/ThumbnailToolbar.cs b/src/Reactor/Hosting/Shell/ThumbnailToolbar.cs index 768c09ffb..6981b6087 100644 --- a/src/Reactor/Hosting/Shell/ThumbnailToolbar.cs +++ b/src/Reactor/Hosting/Shell/ThumbnailToolbar.cs @@ -1,5 +1,6 @@ using System.Diagnostics; using System.Runtime.InteropServices; +using Microsoft.UI.Reactor.Core.Diagnostics; namespace Microsoft.UI.Reactor.Hosting.Shell; @@ -95,7 +96,9 @@ public void Replace(IReadOnlyList buttons) : taskbar.ThumbBarAddButtons(_hwnd, MaxButtons, native); if (hr < 0) { - Debug.WriteLine($"[Reactor] ThumbBar{(_initialized ? "Update" : "Add")}Buttons HR={hr:X8}"); + DiagnosticLog.HResultFailed(LogCategory.Shell, + _initialized ? "ThumbnailToolbar.UpdateButtons" : "ThumbnailToolbar.AddButtons", + hr); FreeIcons(newIcons); return; } diff --git a/src/Reactor/Hosting/Shell/TrayFlyoutHostWindow.cs b/src/Reactor/Hosting/Shell/TrayFlyoutHostWindow.cs index b7e24b615..54be04915 100644 --- a/src/Reactor/Hosting/Shell/TrayFlyoutHostWindow.cs +++ b/src/Reactor/Hosting/Shell/TrayFlyoutHostWindow.cs @@ -1,6 +1,7 @@ using System.Diagnostics; using System.Runtime.InteropServices; using Microsoft.UI.Reactor.Core; +using Microsoft.UI.Reactor.Core.Diagnostics; using Microsoft.UI.Windowing; using Microsoft.UI.Xaml; @@ -188,7 +189,7 @@ private static uint GetDpiForMonitorSafe(TrayIconComInterop.POINT pt) int hr = GetDpiForMonitor(mon, MDT_EFFECTIVE_DPI, out uint dx, out _); if (hr != 0) { - Debug.WriteLine($"[Reactor] TrayFlyout: GetDpiForMonitor returned hr=0x{hr:X8}; falling back to 96 DPI."); + DiagnosticLog.HResultFailed(LogCategory.Shell, "TrayFlyout.GetDpiForMonitor", hr); return 96; } if (dx == 0) diff --git a/src/Reactor/Markdown/Md4cParser.Block.cs b/src/Reactor/Markdown/Md4cParser.Block.cs index d270684b3..f8b73866d 100644 --- a/src/Reactor/Markdown/Md4cParser.Block.cs +++ b/src/Reactor/Markdown/Md4cParser.Block.cs @@ -606,8 +606,12 @@ private int StartNewBlock(ref LineAnalysis line) case LineType.SetextUnderline: case LineType.TableUnderline: default: - Debug.Fail("Unreachable: StartNewBlock called with unexpected line type."); - break; + // Spec 044 §4.3 — promoted from Debug.Fail (release no-op) + // to UnreachableException so a real bug surfaces in + // production builds too. Reachable line types are + // enumerated exhaustively above. + throw new UnreachableException( + "StartNewBlock called with unexpected line type: " + line.Type); } block.Flags = 0; @@ -1126,8 +1130,12 @@ private int IsHtmlBlockEndCondition(int beg, out int pEnd) return 0; default: - Debug.Fail("Unreachable"); - return 0; + // Spec 044 §4.3 — promoted to UnreachableException. + // htmlBlockType is bounded to {1..7} by ScanHtmlBlockType + // which returns 0 (filtering this entry out) for any + // other value. + throw new UnreachableException( + "ScanHtmlBlockEnd: unexpected htmlBlockType " + htmlBlockType); } } @@ -1203,8 +1211,12 @@ private int EnterChildContainers(int nChildren) break; default: - Debug.Fail("Unreachable"); - break; + // Spec 044 §4.3 — promoted to UnreachableException. + // c.Ch is set only by container-opener detection + // which limits the alphabet to {-, +, *, ., ), >}. + throw new UnreachableException( + "EnterChildContainers: unexpected container char 0x" + + ((int)c.Ch).ToString("X4")); } } @@ -1247,8 +1259,13 @@ private int LeaveChildContainers(int nKeep) break; default: - Debug.Fail("Unreachable"); - break; + // Spec 044 §4.3 — promoted to UnreachableException. + // c.Ch is set only by container-opener detection; + // any value reaching this default is a parser-state + // corruption that we want surfaced in Release. + throw new UnreachableException( + "LeaveChildContainers: unexpected container char 0x" + + ((int)c.Ch).ToString("X4")); } nContainers--; diff --git a/tests/Reactor.Tests/Devtools/DevtoolsLogsToolTests.cs b/tests/Reactor.Tests/Devtools/DevtoolsLogsToolTests.cs index 30cee9e6c..6c5558904 100644 --- a/tests/Reactor.Tests/Devtools/DevtoolsLogsToolTests.cs +++ b/tests/Reactor.Tests/Devtools/DevtoolsLogsToolTests.cs @@ -59,6 +59,47 @@ public void Payload_RejectsUnknownSource() Assert.Equal(JsonRpcErrorCodes.InvalidParams, ex.Code); } + [Fact] + public void Payload_AcceptsSourceEvent_AndExposesEventNameAndId() + { + // Spec 044 §6.3 — `source=event` filters to ETW-sourced entries and + // surfaces eventName/eventId. Existing source values still work. + var buf = new LogCaptureBuffer(); + buf.Append(LogSource.Stdout, null, "stdout-ignored"); + buf.Append(LogSource.Event, "Warning", + text: "SwallowedError category=Hosting operation=test", + eventName: "SwallowedError", + eventId: 16); + + var args = JsonDocument.Parse("{\"source\":\"event\"}").RootElement; + var payload = DevtoolsLogsTool.BuildPayload(buf, args); + var json = JsonSerializer.Serialize(payload); + using var doc = JsonDocument.Parse(json); + + var entries = doc.RootElement.GetProperty("entries"); + Assert.Equal(1, entries.GetArrayLength()); + var e = entries[0]; + Assert.Equal("event", e.GetProperty("source").GetString()); + Assert.Equal("SwallowedError", e.GetProperty("eventName").GetString()); + Assert.Equal(16, e.GetProperty("eventId").GetInt32()); + Assert.Equal("Warning", e.GetProperty("level").GetString()); + } + + [Fact] + public void Payload_AcceptsEtwAlias_ForSource() + { + // `etw` is accepted as an alias for `event` so tooling that came in + // from a non-MCP ETW background still discovers the filter. + var buf = new LogCaptureBuffer(); + buf.Append(LogSource.Event, "Info", "X", eventName: "X", eventId: 1); + + var args = JsonDocument.Parse("{\"source\":\"etw\"}").RootElement; + var payload = DevtoolsLogsTool.BuildPayload(buf, args); + var json = JsonSerializer.Serialize(payload); + using var doc = JsonDocument.Parse(json); + Assert.Equal(1, doc.RootElement.GetProperty("entries").GetArrayLength()); + } + [Fact] public void Payload_SinceCursor_AdvancesEachCall() { diff --git a/tests/Reactor.Tests/Diagnostics/DiagnosticLogTests.cs b/tests/Reactor.Tests/Diagnostics/DiagnosticLogTests.cs new file mode 100644 index 000000000..c64b36cf1 --- /dev/null +++ b/tests/Reactor.Tests/Diagnostics/DiagnosticLogTests.cs @@ -0,0 +1,133 @@ +using System.Diagnostics.Tracing; +using Microsoft.UI.Reactor.Core.Diagnostics; +using Xunit; + +namespace Microsoft.UI.Reactor.Tests.Diagnostics; + +/// +/// Spec 044 §6.1 + §1.4 — verifies the DiagnosticLog helper routes +/// swallowed exceptions and HRESULTs to the SwallowedError / HResultFailed +/// events on Microsoft-UI-Reactor with the right payload shape and PII +/// discipline. +/// +/// The listener is created per-test (constructor) and disposed in +/// . ReactorEventSource.Log is process-wide; other +/// test classes can emit while a fixture runs, so payload assertions +/// filter by EventName + a per-test discriminator (the operation string). +/// +public class DiagnosticLogTests : IDisposable +{ + private sealed class CapturingListener : EventListener + { + private readonly List _events = new(); + + public IReadOnlyList Events + { + get { lock (_events) return _events.ToArray(); } + } + + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + lock (_events) _events.Add(eventData); + } + } + + private readonly CapturingListener _listener = new(); + + public DiagnosticLogTests() + { + _listener.EnableEvents( + ReactorEventSource.Log, + EventLevel.Warning, + ReactorEventSource.Keywords.Errors); + } + + public void Dispose() + { + _listener.DisableEvents(ReactorEventSource.Log); + _listener.Dispose(); + } + + [Fact] + public void SwallowedError_writes_exception_type_to_payload_but_not_message() + { + const string operation = "DiagnosticLogTests.AppWindow.Close"; + const string secret = "absolute/path/to/user/secret.json"; + var ex = new InvalidOperationException(secret); + + DiagnosticLog.SwallowedError(LogCategory.Hosting, operation, ex); + + var evt = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.SwallowedError) + && string.Equals(e.Payload?[1] as string, operation, StringComparison.Ordinal)); + + Assert.Equal((int)EventLevel.Warning, (int)evt.Level); + // ETW reserved bits (0xF000000000000000) can ride along on + // EventWrittenEventArgs.Keywords, so test the Errors bit by mask + // rather than equality. + Assert.True((evt.Keywords & ReactorEventSource.Keywords.Errors) == ReactorEventSource.Keywords.Errors); + Assert.Equal(LogCategory.Hosting.ToString(), evt.Payload?[0]); + Assert.Equal(operation, evt.Payload?[1]); + Assert.Equal(nameof(InvalidOperationException), evt.Payload?[2]); + + // PII: the raw exception message must never reach the payload. + foreach (var p in evt.Payload!) + Assert.NotEqual(secret, p as string); + } + + [Fact] + public void HResultFailed_writes_hr_as_int_and_category_as_enum_tostring() + { + const string operation = "DiagnosticLogTests.JumpList.BeginList"; + + DiagnosticLog.HResultFailed(LogCategory.Shell, operation, HResults.RPC_E_DISCONNECTED); + + var evt = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.HResultFailed) + && string.Equals(e.Payload?[1] as string, operation, StringComparison.Ordinal)); + + Assert.Equal((int)EventLevel.Warning, (int)evt.Level); + Assert.Equal(LogCategory.Shell.ToString(), evt.Payload?[0]); + Assert.Equal(operation, evt.Payload?[1]); + Assert.Equal(HResults.RPC_E_DISCONNECTED, evt.Payload?[2]); + } + + [Fact] + public void Helpers_tolerate_null_operation_and_null_exception_without_throwing() + { + // Defensive: callers should pass real values, but null must not + // crash the framework on its way through a swallowed catch site. + DiagnosticLog.SwallowedError(LogCategory.Reactor, null!, null!); + DiagnosticLog.HResultFailed(LogCategory.Reactor, null!, 0); + // No assertion beyond "didn't throw" — the test simply must complete. + } + + [Fact] + public void Helpers_are_no_ops_on_payload_when_Errors_keyword_is_disabled() + { + const string operation = "DiagnosticLogTests.no-op-when-disabled"; + + using var silent = new CapturingListener(); + // Enable a different keyword so the listener is "live" but Errors + // is masked out — DiagnosticLog must not push anything into it. + silent.EnableEvents( + ReactorEventSource.Log, + EventLevel.Verbose, + ReactorEventSource.Keywords.Reconcile); + + try + { + DiagnosticLog.SwallowedError(LogCategory.Reactor, operation, new Exception("nope")); + DiagnosticLog.HResultFailed(LogCategory.Reactor, operation, unchecked((int)0x80004005)); + } + finally + { + silent.DisableEvents(ReactorEventSource.Log); + } + + Assert.DoesNotContain(silent.Events, e => + (e.EventName == nameof(ReactorEventSource.SwallowedError) + || e.EventName == nameof(ReactorEventSource.HResultFailed)) + && string.Equals(e.Payload?[1] as string, operation, StringComparison.Ordinal)); + } +} diff --git a/tests/Reactor.Tests/Diagnostics/IntlEtwBridgeTests.cs b/tests/Reactor.Tests/Diagnostics/IntlEtwBridgeTests.cs new file mode 100644 index 000000000..656b43920 --- /dev/null +++ b/tests/Reactor.Tests/Diagnostics/IntlEtwBridgeTests.cs @@ -0,0 +1,144 @@ +using System.Diagnostics.Tracing; +using Microsoft.UI.Reactor.Core.Diagnostics; +using Microsoft.UI.Reactor.Localization; +using Xunit; + +namespace Microsoft.UI.Reactor.Tests.Diagnostics; + +/// +/// Spec 044 Phase C §4.3 — regression guard that +/// emits the typed IntlMissingKey event under +/// when a resource lookup +/// misses, and that format-time exceptions route through +/// DiagnosticLog.SwallowedError(LogCategory.Intl, ...) rather than +/// the old Debug.WriteLine channel. +/// +/// MessageKey values used here are per-test discriminators so concurrent +/// localization traffic from other tests can't false-positive the asserts. +/// +public class IntlEtwBridgeTests : IDisposable +{ + private sealed class CapturingListener : EventListener + { + private readonly List _events = new(); + + public IReadOnlyList Events + { + get { lock (_events) return _events.ToArray(); } + } + + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + lock (_events) _events.Add(eventData); + } + } + + private readonly CapturingListener _listener = new(); + + public IntlEtwBridgeTests() + { + _listener.EnableEvents( + ReactorEventSource.Log, + EventLevel.Verbose, + ReactorEventSource.Keywords.Intl | ReactorEventSource.Keywords.Errors); + } + + public void Dispose() + { + _listener.DisableEvents(ReactorEventSource.Log); + _listener.Dispose(); + } + + // Minimal in-memory provider over a per-test dictionary. Keyed by + // (locale, namespace, key) so tests can stage hits + misses for both + // the active and the default locale. + private sealed class MemoryProvider : IStringResourceProvider + { + private readonly Dictionary<(string Locale, string Namespace, string Key), string> _strings = new(); + + public MemoryProvider Add(string locale, string ns, string key, string value) + { + _strings[(locale, ns, key)] = value; + return this; + } + + public string? GetString(string locale, string @namespace, string key) + => _strings.TryGetValue((locale, @namespace, key), out var v) ? v : null; + } + + private static MessageCache NewCache() => new(); + + [Fact] + public void Message_missing_in_current_locale_with_fallback_emits_IntlMissingKey_fellBack_true() + { + var ns = $"Phase044.Intl.{Guid.NewGuid():N}"; + var key = new MessageKey(ns, "Greeting"); + var provider = new MemoryProvider().Add("en-US", ns, "Greeting", "Hello"); + var accessor = new IntlAccessor("fr-FR", provider, NewCache(), defaultLocale: "en-US"); + + var result = accessor.Message(key); + + Assert.Equal("Hello", result); + var evt = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.IntlMissingKey) + && (e.Payload?[0] as string) == key.ToString()); + Assert.Equal("fr-FR", evt.Payload?[1]); + Assert.Equal(true, evt.Payload?[2]); + Assert.Equal((int)EventLevel.Warning, (int)evt.Level); + } + + [Fact] + public void Message_missing_in_both_current_and_default_emits_IntlMissingKey_fellBack_false() + { + var ns = $"Phase044.Intl.{Guid.NewGuid():N}"; + var key = new MessageKey(ns, "NeverDefined"); + var provider = new MemoryProvider(); + var accessor = new IntlAccessor("fr-FR", provider, NewCache(), defaultLocale: "en-US"); + + var result = accessor.Message(key); + + // Pseudo-localize is off → the explicit missing-key marker shows. + Assert.Equal($"[?? {key} ??]", result); + var evt = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.IntlMissingKey) + && (e.Payload?[0] as string) == key.ToString()); + Assert.Equal("fr-FR", evt.Payload?[1]); + Assert.Equal(false, evt.Payload?[2]); + } + + [Fact] + public void Message_missing_when_current_equals_default_emits_single_event_with_fellBack_false() + { + // No fallback path is taken when current == default, so only one + // event should fire (not two — guards against a re-introduced + // double-log bug from the previous Debug.WriteLine shape). + var ns = $"Phase044.Intl.{Guid.NewGuid():N}"; + var key = new MessageKey(ns, "NeverDefined"); + var provider = new MemoryProvider(); + var accessor = new IntlAccessor("en-US", provider, NewCache(), defaultLocale: "en-US"); + + accessor.Message(key); + + var matching = _listener.Events.Where(e => + e.EventName == nameof(ReactorEventSource.IntlMissingKey) + && (e.Payload?[0] as string) == key.ToString()).ToArray(); + Assert.Single(matching); + Assert.Equal(false, matching[0].Payload?[2]); + } + + [Fact] + public void Message_hit_in_current_locale_emits_no_IntlMissingKey() + { + var ns = $"Phase044.Intl.{Guid.NewGuid():N}"; + var key = new MessageKey(ns, "HelloWorld"); + var provider = new MemoryProvider().Add("en-US", ns, "HelloWorld", "Hi"); + var accessor = new IntlAccessor("en-US", provider, NewCache(), defaultLocale: "en-US"); + + var result = accessor.Message(key); + + Assert.Equal("Hi", result); + Assert.DoesNotContain(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.IntlMissingKey) + && (e.Payload?[0] as string) == key.ToString()); + } +} diff --git a/tests/Reactor.Tests/Diagnostics/LogCaptureEventBridgeTests.cs b/tests/Reactor.Tests/Diagnostics/LogCaptureEventBridgeTests.cs new file mode 100644 index 000000000..bd0342aef --- /dev/null +++ b/tests/Reactor.Tests/Diagnostics/LogCaptureEventBridgeTests.cs @@ -0,0 +1,179 @@ +using System.Diagnostics.Tracing; +using Microsoft.UI.Reactor.Core.Diagnostics; +using Microsoft.UI.Reactor.Diagnostics; +using Microsoft.UI.Reactor.Hosting.Devtools; +using Xunit; + +namespace Microsoft.UI.Reactor.Tests.Diagnostics; + +/// +/// Spec 044 Phase F (§6.4) — verifies the +/// ReactorEventSource → LogCaptureBuffer bridge installed by +/// : +/// +/// 1. an event fired after install lands as a +/// entry with eventName + eventId populated and an +/// appropriate level string; +/// 2. payload formatter honours the 256-char per-field cap (defense-in-depth +/// against a chatty event filling the ring); +/// 3. HR-style payload fields render in 0x{X8} form, matching the +/// pre-migration Debug.WriteLine shape so log greps stay stable; +/// 4. existing stdout / stderr / debug entries continue to be captured +/// unchanged (regression guard). +/// +public class LogCaptureEventBridgeTests +{ + private static (LogCaptureBuffer buf, IDisposable bridge) Install() + { + var buf = new LogCaptureBuffer(); + var bridge = LogCaptureInstall.InstallEventBridgeForTests(buf); + return (buf, bridge); + } + + [Fact] + public void Event_lands_as_LogSource_Event_with_name_id_and_level() + { + var (buf, bridge) = Install(); + using (bridge) + { + // Errors keyword + warning level → captured as level=Warning. + ReactorEventSource.Log.SwallowedError( + nameof(LogCategory.Hosting), + "BridgeTest.warmup", + nameof(InvalidOperationException)); + } + + var result = buf.Query(source: LogSource.Event); + var hit = Assert.Single( + result.Entries, + e => e.EventName == nameof(ReactorEventSource.SwallowedError) + && e.Text.Contains("BridgeTest.warmup", StringComparison.Ordinal)); + + Assert.Equal(LogSource.Event, hit.Source); + Assert.Equal("Warning", hit.Level); + Assert.NotNull(hit.EventId); + Assert.True(hit.EventId!.Value > 0); + Assert.Contains("category=Hosting", hit.Text, StringComparison.Ordinal); + Assert.Contains("exceptionType=InvalidOperationException", hit.Text, StringComparison.Ordinal); + } + + [Fact] + public void EventLevel_maps_each_severity_to_expected_label() + { + // Build a synthetic ReactorEvent and exercise the formatter / mapper + // without paying the cost of a real fire-and-listen cycle for each + // level. The bridge composition is "map level + format text + append"; + // each step is exercised by the broader test above. + var verbose = MakeEvent(EventLevel.Verbose); + var info = MakeEvent(EventLevel.Informational); + var warn = MakeEvent(EventLevel.Warning); + var err = MakeEvent(EventLevel.Error); + var crit = MakeEvent(EventLevel.Critical); + + Assert.Equal("RoundTrip", LogCaptureInstall.FormatEventText(verbose)); + Assert.Equal("RoundTrip", LogCaptureInstall.FormatEventText(info)); + Assert.Equal("RoundTrip", LogCaptureInstall.FormatEventText(warn)); + Assert.Equal("RoundTrip", LogCaptureInstall.FormatEventText(err)); + Assert.Equal("RoundTrip", LogCaptureInstall.FormatEventText(crit)); + } + + [Fact] + public void Formatter_caps_long_payload_field_at_256_chars() + { + var huge = new string('a', LogCaptureInstall.MaxPayloadFieldChars + 500); + var evt = new ReactorEvent( + EventId: 1, + EventName: "Test", + Level: EventLevel.Informational, + Keywords: 0, + TimestampUtc: DateTime.UtcNow, + ThreadId: Environment.CurrentManagedThreadId, + Payload: new object?[] { huge }, + PayloadNames: new[] { "blob" }); + + var text = LogCaptureInstall.FormatEventText(evt); + + // "Test blob=" + 256 chars + ellipsis. The ellipsis is the only + // signal that truncation happened, so assert on it explicitly. + Assert.Contains("blob=", text, StringComparison.Ordinal); + Assert.EndsWith("…", text, StringComparison.Ordinal); + // We don't want the entire 756-char string in the output. + Assert.DoesNotContain(huge, text, StringComparison.Ordinal); + } + + [Fact] + public void Formatter_renders_hr_field_as_hex_X8() + { + // 0x80004002 (E_NOINTERFACE) — a real HRESULT value the Shell sites + // emit. Must come out as "0x80004002", not "-2147467262". + var evt = new ReactorEvent( + EventId: 1, + EventName: "HResultFailed", + Level: EventLevel.Warning, + Keywords: 0, + TimestampUtc: DateTime.UtcNow, + ThreadId: Environment.CurrentManagedThreadId, + Payload: new object?[] { "Shell", "JumpList.Begin", unchecked((int)0x80004002) }, + PayloadNames: new[] { "category", "operation", "hr" }); + + var text = LogCaptureInstall.FormatEventText(evt); + + Assert.Contains("hr=0x80004002", text, StringComparison.Ordinal); + Assert.DoesNotContain("-2147467262", text, StringComparison.Ordinal); + } + + [Fact] + public void Formatter_renders_null_payload_as_null_literal() + { + var evt = new ReactorEvent( + EventId: 1, + EventName: "T", + Level: EventLevel.Verbose, + Keywords: 0, + TimestampUtc: DateTime.UtcNow, + ThreadId: Environment.CurrentManagedThreadId, + Payload: new object?[] { null }, + PayloadNames: new[] { "x" }); + + Assert.Equal("T x=null", LogCaptureInstall.FormatEventText(evt)); + } + + [Fact] + public void Stdout_stderr_debug_entries_still_capture_alongside_events() + { + var (buf, bridge) = Install(); + using (bridge) + { + buf.Append(LogSource.Stdout, level: null, text: "stdout-line"); + buf.Append(LogSource.Stderr, level: null, text: "stderr-line"); + buf.Append(LogSource.Debug, level: null, text: "debug-line"); + ReactorEventSource.Log.SwallowedError( + nameof(LogCategory.Hosting), + "BridgeTest.mixed", + nameof(InvalidOperationException)); + } + + var all = buf.Query(); + Assert.Contains(all.Entries, e => e.Source == LogSource.Stdout && e.Text == "stdout-line"); + Assert.Contains(all.Entries, e => e.Source == LogSource.Stderr && e.Text == "stderr-line"); + Assert.Contains(all.Entries, e => e.Source == LogSource.Debug && e.Text == "debug-line"); + Assert.Contains(all.Entries, e => e.Source == LogSource.Event + && e.Text.Contains("BridgeTest.mixed", StringComparison.Ordinal)); + + // Regression guard: source filters keep returning their dedicated + // streams without the event entries spilling in. + Assert.Single(buf.Query(source: LogSource.Stdout).Entries, e => e.Text == "stdout-line"); + Assert.Single(buf.Query(source: LogSource.Stderr).Entries, e => e.Text == "stderr-line"); + Assert.Single(buf.Query(source: LogSource.Debug).Entries, e => e.Text == "debug-line"); + } + + private static ReactorEvent MakeEvent(EventLevel level) => new( + EventId: 1, + EventName: "RoundTrip", + Level: level, + Keywords: 0, + TimestampUtc: DateTime.UtcNow, + ThreadId: Environment.CurrentManagedThreadId, + Payload: Array.Empty(), + PayloadNames: Array.Empty()); +} diff --git a/tests/Reactor.Tests/Diagnostics/NavigationDiagnosticsEtwBridgeTests.cs b/tests/Reactor.Tests/Diagnostics/NavigationDiagnosticsEtwBridgeTests.cs new file mode 100644 index 000000000..2cdafac42 --- /dev/null +++ b/tests/Reactor.Tests/Diagnostics/NavigationDiagnosticsEtwBridgeTests.cs @@ -0,0 +1,188 @@ +using System.Diagnostics.Tracing; +using Microsoft.UI.Reactor.Core.Diagnostics; +using Microsoft.UI.Reactor.Navigation; +using Xunit; + +namespace Microsoft.UI.Reactor.Tests.Diagnostics; + +/// +/// Spec 044 Phase C §4.2 — regression guard that the internal +/// entry points emit the +/// corresponding typed events on +/// (Navigation keyword). Replaces the previous Debug.WriteLine +/// channel with a Release-visible ETW stream. +/// +/// Also guards spec §6.2.1: OnDeepLinkResolved must NOT put the +/// raw input path on the ETW payload — only the resolution outcome. +/// +public class NavigationDiagnosticsEtwBridgeTests : IDisposable +{ + private sealed class CapturingListener : EventListener + { + private readonly List _events = new(); + + public IReadOnlyList Events + { + get { lock (_events) return _events.ToArray(); } + } + + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + lock (_events) _events.Add(eventData); + } + } + + private readonly CapturingListener _listener = new(); + + public NavigationDiagnosticsEtwBridgeTests() + { + _listener.EnableEvents( + ReactorEventSource.Log, + EventLevel.Verbose, + ReactorEventSource.Keywords.Navigation); + } + + public void Dispose() + { + _listener.DisableEvents(ReactorEventSource.Log); + _listener.Dispose(); + } + + // The bridge derives the route "template" from the destination route's + // CLR type. A per-test discriminator class therefore yields a unique + // payload string, so concurrent NavigationDiagnostics traffic from + // other tests can't false-positive these assertions. + private sealed class RouteFor_NavigationRequested { } + private sealed class RouteFor_NavigationCompleted { } + private sealed class RouteFor_NavigationCancelled { } + private sealed class RouteFor_CacheHit { } + private sealed class RouteFor_CacheMiss { } + private sealed class RouteFor_CacheEvict { } + + // Per-test transition subclass so the captured event payload's + // transition-type name is unambiguously this test's. + private sealed record DiscriminatorTransition : NavigationTransition; + + [Fact] + public void OnNavigationRequested_emits_typed_event_with_route_template() + { + NavigationDiagnostics.OnNavigationRequested( + from: new object(), + to: new RouteFor_NavigationRequested(), + mode: NavigationMode.Push); + + var template = typeof(RouteFor_NavigationRequested).FullName!; + var evt = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.NavigationRequested) + && (e.Payload?[0] as string) == template); + Assert.Equal((int)EventLevel.Informational, (int)evt.Level); + } + + [Fact] + public void OnNavigationCompleted_emits_typed_event_with_route_template() + { + NavigationDiagnostics.OnNavigationCompleted( + from: new object(), + to: new RouteFor_NavigationCompleted(), + mode: NavigationMode.Pop); + + var template = typeof(RouteFor_NavigationCompleted).FullName!; + var evt = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.NavigationCompleted) + && (e.Payload?[0] as string) == template); + // durationMs payload slot is reserved; the bridge passes 0 until + // timing is wired through (see NavigationDiagnostics comment). + Assert.Equal(0d, evt.Payload?[1]); + } + + [Fact] + public void OnNavigationCancelled_emits_typed_event_with_reason() + { + NavigationDiagnostics.OnNavigationCancelled( + from: new object(), + to: new RouteFor_NavigationCancelled(), + mode: NavigationMode.Push, + reason: "guard-blocked"); + + var template = typeof(RouteFor_NavigationCancelled).FullName!; + var evt = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.NavigationCancelled) + && (e.Payload?[0] as string) == template); + Assert.Equal("guard-blocked", evt.Payload?[1]); + } + + [Fact] + public void OnCache_hit_miss_evict_emit_at_verbose_level() + { + NavigationDiagnostics.OnCacheHit(new RouteFor_CacheHit()); + NavigationDiagnostics.OnCacheMiss(new RouteFor_CacheMiss()); + NavigationDiagnostics.OnCacheEviction(new RouteFor_CacheEvict()); + + var hit = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.NavigationCacheHit) + && (e.Payload?[0] as string) == typeof(RouteFor_CacheHit).FullName); + Assert.Equal((int)EventLevel.Verbose, (int)hit.Level); + + var miss = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.NavigationCacheMiss) + && (e.Payload?[0] as string) == typeof(RouteFor_CacheMiss).FullName); + Assert.Equal((int)EventLevel.Verbose, (int)miss.Level); + + var evict = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.NavigationCacheEvict) + && (e.Payload?[0] as string) == typeof(RouteFor_CacheEvict).FullName); + Assert.Equal((int)EventLevel.Verbose, (int)evict.Level); + } + + [Fact] + public void OnTransitionStarted_and_Completed_emit_type_and_mode() + { + var transition = new DiscriminatorTransition(); + NavigationDiagnostics.OnTransitionStarted(transition, NavigationMode.Push); + NavigationDiagnostics.OnTransitionCompleted(transition, NavigationMode.Pop); + + var started = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.NavigationTransitionStarted) + && (e.Payload?[0] as string) == nameof(DiscriminatorTransition)); + Assert.Equal(nameof(NavigationMode.Push), started.Payload?[1]); + + var completed = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.NavigationTransitionCompleted) + && (e.Payload?[0] as string) == nameof(DiscriminatorTransition)); + Assert.Equal(nameof(NavigationMode.Pop), completed.Payload?[1]); + } + + [Fact] + public void OnDeepLinkResolved_match_emits_outcome_only_no_path() + { + // PII guard (spec §6.2.1): the path is attacker-controllable input + // and must NOT appear in the ETW payload. + const string secretPath = "/deep-link-secret-token-9d3b2f1c"; + NavigationDiagnostics.OnDeepLinkResolved(secretPath, matched: true, routeCount: 3); + + // The matched-true / routeCount=3 combination is unique enough in + // this listener (this test owns the keyword filter) to disambiguate. + var evt = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.NavigationDeepLinkResolved) + && Equals(e.Payload?[0], true) + && Equals(e.Payload?[1], 3)); + + Assert.Equal((int)EventLevel.Informational, (int)evt.Level); + Assert.DoesNotContain(evt.Payload!, p => p is string s && s.Contains("secret-token", StringComparison.Ordinal)); + if (evt.PayloadNames is { } names) + { + Assert.DoesNotContain(names, n => n.Equals("path", StringComparison.OrdinalIgnoreCase)); + } + } + + [Fact] + public void OnDeepLinkResolved_miss_emits_false_and_zero_routes() + { + NavigationDiagnostics.OnDeepLinkResolved("/nope", matched: false, routeCount: 0); + + Assert.Contains(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.NavigationDeepLinkResolved) + && Equals(e.Payload?[0], false) + && Equals(e.Payload?[1], 0)); + } +} diff --git a/tests/Reactor.Tests/Diagnostics/PersistenceEtwBridgeTests.cs b/tests/Reactor.Tests/Diagnostics/PersistenceEtwBridgeTests.cs new file mode 100644 index 000000000..97ffce4d5 --- /dev/null +++ b/tests/Reactor.Tests/Diagnostics/PersistenceEtwBridgeTests.cs @@ -0,0 +1,228 @@ +using System.Diagnostics.Tracing; +using Microsoft.UI.Reactor.Core.Diagnostics; +using Microsoft.UI.Reactor.Hosting.Persistence; +using Xunit; + +namespace Microsoft.UI.Reactor.Tests.Diagnostics; + +/// +/// Spec 044 Phase C §4.7 — regression guard that the persistence layer +/// (, , +/// ) routes its swallowed exceptions +/// through DiagnosticLog.SwallowedError(LogCategory.Persistence, ...) +/// and its explicit rejection paths through the typed +/// PersistenceRejected event under . +/// +/// PII discipline (§6.2.1): file paths are never on the ETW payload. The +/// storeKind field is a short developer-authored label +/// ("json-file", "packaged-settings", "placement"); +/// rejection reason labels are similarly bounded. +/// +public class PersistenceEtwBridgeTests : IDisposable +{ + private sealed class CapturingListener : EventListener + { + private readonly List _events = new(); + + public IReadOnlyList Events + { + get { lock (_events) return _events.ToArray(); } + } + + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + lock (_events) _events.Add(eventData); + } + } + + private readonly CapturingListener _listener = new(); + private readonly string _path; + + public PersistenceEtwBridgeTests() + { + _listener.EnableEvents( + ReactorEventSource.Log, + EventLevel.Verbose, + ReactorEventSource.Keywords.Persistence | ReactorEventSource.Keywords.Errors); + _path = global::System.IO.Path.Combine( + global::System.IO.Path.GetTempPath(), + $"reactor-windows-persist-{Guid.NewGuid():N}.json"); + } + + public void Dispose() + { + _listener.DisableEvents(ReactorEventSource.Log); + _listener.Dispose(); + try { if (global::System.IO.File.Exists(_path)) global::System.IO.File.Delete(_path); } catch { } + } + + private static EventWrittenEventArgs? FindByName(IReadOnlyList events, string name) + => events.FirstOrDefault(e => e.EventName == name); + + // ── JsonFileStore round-trip emits Read + Write ───────────────────── + + [Fact] + public void JsonFileStore_Write_emits_PersistenceWrite_with_storeKind_no_path() + { + var store = new JsonFileStore(_path); + + store.Write("main", new byte[] { 1, 2, 3 }); + + var evt = FindByName(_listener.Events, nameof(ReactorEventSource.PersistenceWrite)); + Assert.NotNull(evt); + Assert.Equal("json-file", evt!.Payload?[0]); + Assert.True((int)(evt.Payload?[1] ?? 0) > 0); + // PII: serialized payload size is on the event, but the file path + // must not appear anywhere on the payload list. + Assert.DoesNotContain(_listener.Events, e => + e.Payload?.Any(p => p is string s && s.Contains(_path, StringComparison.OrdinalIgnoreCase)) == true); + } + + [Fact] + public void JsonFileStore_TryRead_emits_PersistenceRead_on_hit() + { + var store = new JsonFileStore(_path); + store.Write("main", new byte[] { 7, 8, 9 }); + + Assert.True(store.TryRead("main", out var data)); + Assert.NotNull(data); + + var evt = FindByName(_listener.Events, nameof(ReactorEventSource.PersistenceRead)); + Assert.NotNull(evt); + Assert.Equal("json-file", evt!.Payload?[0]); + } + + // ── JsonFileStore explicit rejects → PersistenceRejected ──────────── + + [Fact] + public void JsonFileStore_oversize_file_emits_PersistenceRejected_oversize_read() + { + var oversize = new byte[(int)(JsonFileStore.MaxFileSizeBytes + 64)]; + global::System.IO.File.WriteAllBytes(_path, oversize); + + var store = new JsonFileStore(_path); + Assert.False(store.TryRead("main", out _)); + + var evt = FindByName(_listener.Events, nameof(ReactorEventSource.PersistenceRejected)); + Assert.NotNull(evt); + Assert.Equal("json-file", evt!.Payload?[0]); + Assert.Equal("oversize-read", evt.Payload?[1]); + } + + // ── JsonFileStore malformed inputs → SwallowedError ───────────────── + + [Fact] + public void JsonFileStore_malformed_json_emits_SwallowedError_JsonException() + { + global::System.IO.File.WriteAllText(_path, "this is not json{{{"); + var store = new JsonFileStore(_path); + + Assert.False(store.TryRead("main", out _)); + + var evt = FindByName(_listener.Events, nameof(ReactorEventSource.SwallowedError)); + Assert.NotNull(evt); + Assert.Equal(nameof(LogCategory.Persistence), evt!.Payload?[0]); + Assert.Equal("JsonFileStore.TryRead.parse", evt.Payload?[1]); + // The payload carries ex.GetType().Name — the concrete runtime + // type, which for malformed JSON is the JsonException-derived + // JsonReaderException. Assert by IsAssignableFrom-style prefix + // so we don't pin to a private internal name. + var thrown = evt.Payload?[2] as string; + Assert.NotNull(thrown); + Assert.StartsWith("Json", thrown); + Assert.EndsWith("Exception", thrown); + // PII: malformed body must not appear in the payload. + Assert.DoesNotContain("not json", string.Join("|", evt.Payload?.OfType() ?? Array.Empty())); + } + + [Fact] + public void JsonFileStore_malformed_base64_emits_SwallowedError_FormatException() + { + global::System.IO.File.WriteAllText(_path, "{\"main\":\"not_valid_base64!@#\"}"); + var store = new JsonFileStore(_path); + + Assert.False(store.TryRead("main", out _)); + + var evt = _listener.Events.FirstOrDefault(e => + e.EventName == nameof(ReactorEventSource.SwallowedError) + && (e.Payload?[1] as string) == "JsonFileStore.TryRead.base64"); + Assert.NotNull(evt); + Assert.Equal(nameof(LogCategory.Persistence), evt!.Payload?[0]); + Assert.Equal(nameof(FormatException), evt.Payload?[2]); + } + + // ── PackagedSettingsStore (unpackaged context throws WinRT) ───────── + + [Fact] + public void PackagedSettingsStore_TryRead_in_unpackaged_emits_SwallowedError() + { + // xUnit host has no package identity → ApplicationData.Current + // throws InvalidOperationException (0x80073D54). The narrow catch + // must route through DiagnosticLog and never propagate. + var store = new PackagedSettingsStore(); + + var result = store.TryRead("anything", out _); + + Assert.False(result); + var evt = _listener.Events.FirstOrDefault(e => + e.EventName == nameof(ReactorEventSource.SwallowedError) + && (e.Payload?[1] as string) == "PackagedSettingsStore.TryRead"); + Assert.NotNull(evt); + Assert.Equal(nameof(LogCategory.Persistence), evt!.Payload?[0]); + } + + [Fact] + public void PackagedSettingsStore_Write_in_unpackaged_emits_SwallowedError() + { + var store = new PackagedSettingsStore(); + + store.Write("anything", new byte[] { 1, 2, 3 }); + + var evt = _listener.Events.FirstOrDefault(e => + e.EventName == nameof(ReactorEventSource.SwallowedError) + && (e.Payload?[1] as string) == "PackagedSettingsStore.Write"); + Assert.NotNull(evt); + Assert.Equal(nameof(LogCategory.Persistence), evt!.Payload?[0]); + } + + // ── WindowPlacementCodec rejects ──────────────────────────────────── + + [Fact] + public void WindowPlacementCodec_implausible_monitor_count_emits_PersistenceRejected() + { + // Hand-craft a payload that decodes to a too-large monitor count + // (encoded as int32 = 999, which exceeds the 64-monitor cap). + using var ms = new global::System.IO.MemoryStream(); + using var bw = new global::System.IO.BinaryWriter(ms); + bw.Write(999); + bw.Flush(); + + var monitors = new[] { new MonitorRect(null, 0, 0, 1920, 1080) }; + Assert.False(WindowPlacementCodec.Restore(hwnd: 0, ms.ToArray(), monitors)); + + var evt = _listener.Events.FirstOrDefault(e => + e.EventName == nameof(ReactorEventSource.PersistenceRejected) + && (e.Payload?[1] as string) == "implausible-monitor-count"); + Assert.NotNull(evt); + Assert.Equal("placement", evt!.Payload?[0]); + } + + [Fact] + public void WindowPlacementCodec_truncated_payload_emits_PersistenceRejected_truncated() + { + // Payload claims 1 monitor but contains nothing past the count. + using var ms = new global::System.IO.MemoryStream(); + using var bw = new global::System.IO.BinaryWriter(ms); + bw.Write(1); + bw.Flush(); + + var monitors = new[] { new MonitorRect(null, 0, 0, 1920, 1080) }; + Assert.False(WindowPlacementCodec.Restore(hwnd: 0, ms.ToArray(), monitors)); + + var evt = _listener.Events.FirstOrDefault(e => + e.EventName == nameof(ReactorEventSource.PersistenceRejected) + && (e.Payload?[1] as string) == "truncated"); + Assert.NotNull(evt); + Assert.Equal("placement", evt!.Payload?[0]); + } +} diff --git a/tests/Reactor.Tests/Diagnostics/ReactorEventSourcePhaseBTests.cs b/tests/Reactor.Tests/Diagnostics/ReactorEventSourcePhaseBTests.cs new file mode 100644 index 000000000..6f72bec53 --- /dev/null +++ b/tests/Reactor.Tests/Diagnostics/ReactorEventSourcePhaseBTests.cs @@ -0,0 +1,299 @@ +using System.Diagnostics.Tracing; +using Microsoft.UI.Reactor.Core.Diagnostics; +using Xunit; + +namespace Microsoft.UI.Reactor.Tests.Diagnostics; + +/// +/// Spec 044 Phase B (§2.7) — smoke-tests the new subsystem events on +/// (Hosting / Persistence / Navigation / +/// Intl / Theme) and the cross-keyword end-to-end regression guard that +/// verifies the new keyword bits do not overlap. +/// +/// Each test fires the event with a per-test discriminator string so +/// concurrent emissions from other tests can't false-positive. +/// +public class ReactorEventSourcePhaseBTests : IDisposable +{ + private sealed class CapturingListener : EventListener + { + private readonly List _events = new(); + + public IReadOnlyList Events + { + get { lock (_events) return _events.ToArray(); } + } + + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + lock (_events) _events.Add(eventData); + } + } + + private readonly CapturingListener _listener = new(); + + public ReactorEventSourcePhaseBTests() + { + _listener.EnableEvents( + ReactorEventSource.Log, + EventLevel.Verbose, + ReactorEventSource.Keywords.Hosting + | ReactorEventSource.Keywords.Persistence + | ReactorEventSource.Keywords.Navigation + | ReactorEventSource.Keywords.Intl + | ReactorEventSource.Keywords.Theme + | ReactorEventSource.Keywords.Errors); + } + + public void Dispose() + { + _listener.DisableEvents(ReactorEventSource.Log); + _listener.Dispose(); + } + + // ── Hosting ───────────────────────────────────────────────────────── + + [Fact] + public void WindowOpened_writes_type_and_hwnd() + { + const string windowType = "PhaseBTests.WindowOpened.MyWindow"; + ReactorEventSource.Log.WindowOpened(windowType, 0x1234L); + + var evt = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.WindowOpened) + && (e.Payload?[0] as string) == windowType); + Assert.Equal(0x1234L, evt.Payload?[1]); + } + + [Fact] + public void WindowClosed_writes_type_and_hwnd() + { + const string windowType = "PhaseBTests.WindowClosed.MyWindow"; + ReactorEventSource.Log.WindowClosed(windowType, 0xABCDL); + + var evt = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.WindowClosed) + && (e.Payload?[0] as string) == windowType); + Assert.Equal(0xABCDL, evt.Payload?[1]); + } + + [Fact] + public void WindowDpiChanged_writes_old_and_new() + { + const string windowType = "PhaseBTests.WindowDpiChanged.MyWindow"; + ReactorEventSource.Log.WindowDpiChanged(windowType, 96, 144); + + var evt = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.WindowDpiChanged) + && (e.Payload?[0] as string) == windowType); + Assert.Equal(96, evt.Payload?[1]); + Assert.Equal(144, evt.Payload?[2]); + } + + [Fact] + public void BackdropMaterializationFailed_writes_kind_and_exception_type() + { + const string kind = "PhaseBTests.Backdrop.Mica"; + ReactorEventSource.Log.BackdropMaterializationFailed(kind, nameof(InvalidOperationException)); + + var evt = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.BackdropMaterializationFailed) + && (e.Payload?[0] as string) == kind); + Assert.Equal((int)EventLevel.Warning, (int)evt.Level); + Assert.Equal(nameof(InvalidOperationException), evt.Payload?[1]); + } + + // ── Persistence ───────────────────────────────────────────────────── + + [Fact] + public void PersistenceRead_writes_store_and_size() + { + const string storeKind = "PhaseBTests.Persistence.settings-read"; + ReactorEventSource.Log.PersistenceRead(storeKind, 4096); + + var evt = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.PersistenceRead) + && (e.Payload?[0] as string) == storeKind); + Assert.Equal(4096, evt.Payload?[1]); + } + + [Fact] + public void PersistenceWrite_writes_store_and_size() + { + const string storeKind = "PhaseBTests.Persistence.settings-write"; + ReactorEventSource.Log.PersistenceWrite(storeKind, 2048); + + var evt = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.PersistenceWrite) + && (e.Payload?[0] as string) == storeKind); + Assert.Equal(2048, evt.Payload?[1]); + } + + [Fact] + public void PersistenceRejected_writes_store_and_reason() + { + const string storeKind = "PhaseBTests.Persistence.placement-rejected"; + ReactorEventSource.Log.PersistenceRejected(storeKind, "oversize"); + + var evt = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.PersistenceRejected) + && (e.Payload?[0] as string) == storeKind); + Assert.Equal((int)EventLevel.Warning, (int)evt.Level); + Assert.Equal("oversize", evt.Payload?[1]); + } + + // ── Navigation ────────────────────────────────────────────────────── + + [Fact] + public void NavigationRequested_writes_route_template() + { + const string route = "/phaseb-tests/nav-requested/{id}"; + ReactorEventSource.Log.NavigationRequested(route); + + var evt = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.NavigationRequested) + && (e.Payload?[0] as string) == route); + Assert.Equal(route, evt.Payload?[0]); + } + + [Fact] + public void NavigationCompleted_writes_route_and_duration() + { + const string route = "/phaseb-tests/nav-completed/{id}"; + ReactorEventSource.Log.NavigationCompleted(route, 12.5); + + var evt = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.NavigationCompleted) + && (e.Payload?[0] as string) == route); + Assert.Equal(12.5, evt.Payload?[1]); + } + + [Fact] + public void NavigationCancelled_writes_route_and_reason() + { + const string route = "/phaseb-tests/nav-cancelled/{id}"; + ReactorEventSource.Log.NavigationCancelled(route, "user-back"); + + var evt = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.NavigationCancelled) + && (e.Payload?[0] as string) == route); + Assert.Equal("user-back", evt.Payload?[1]); + } + + [Fact] + public void NavigationCache_events_emit_at_verbose_level() + { + const string route = "/phaseb-tests/nav-cache/{id}"; + ReactorEventSource.Log.NavigationCacheHit(route); + ReactorEventSource.Log.NavigationCacheMiss(route); + ReactorEventSource.Log.NavigationCacheEvict(route, "lru"); + + var hit = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.NavigationCacheHit) + && (e.Payload?[0] as string) == route); + Assert.Equal((int)EventLevel.Verbose, (int)hit.Level); + + var miss = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.NavigationCacheMiss) + && (e.Payload?[0] as string) == route); + Assert.Equal((int)EventLevel.Verbose, (int)miss.Level); + + var evict = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.NavigationCacheEvict) + && (e.Payload?[0] as string) == route); + Assert.Equal((int)EventLevel.Verbose, (int)evict.Level); + Assert.Equal("lru", evict.Payload?[1]); + } + + // ── Intl ──────────────────────────────────────────────────────────── + + [Fact] + public void IntlMissingKey_writes_key_locale_and_fellback_flag() + { + const string key = "PhaseBTests.Intl.MissingKey"; + ReactorEventSource.Log.IntlMissingKey(key, "fr-FR", true); + + var evt = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.IntlMissingKey) + && (e.Payload?[0] as string) == key); + Assert.Equal((int)EventLevel.Warning, (int)evt.Level); + Assert.Equal("fr-FR", evt.Payload?[1]); + Assert.Equal(true, evt.Payload?[2]); + } + + // ── Theme ─────────────────────────────────────────────────────────── + + [Fact] + public void ThemeApplyFailed_writes_target_and_exception_type() + { + const string target = "PhaseBTests.Theme.MyControl"; + ReactorEventSource.Log.ThemeApplyFailed(target, nameof(InvalidCastException)); + + var evt = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.ThemeApplyFailed) + && (e.Payload?[0] as string) == target); + Assert.Equal((int)EventLevel.Warning, (int)evt.Level); + Assert.Equal(nameof(InvalidCastException), evt.Payload?[1]); + } + + // ── Cross-keyword regression guard ────────────────────────────────── + + [Fact] + public void All_new_keywords_capture_their_events_concurrently() + { + // Regression guard against keyword-bit overlap: with every new + // keyword + Errors enabled, one event from each must land. + const string discriminator = "PhaseBTests.AllKeywordsConcurrent"; + + ReactorEventSource.Log.WindowOpened(discriminator + ".window", 0x1L); + ReactorEventSource.Log.PersistenceRead(discriminator + ".store", 1); + ReactorEventSource.Log.NavigationRequested(discriminator + ".route"); + ReactorEventSource.Log.IntlMissingKey(discriminator + ".key", "en-US", false); + ReactorEventSource.Log.ThemeApplyFailed(discriminator + ".target", "X"); + ReactorEventSource.Log.SwallowedError("Reactor", discriminator + ".op", "X"); + + Assert.Contains(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.WindowOpened) + && (e.Payload?[0] as string) == discriminator + ".window"); + Assert.Contains(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.PersistenceRead) + && (e.Payload?[0] as string) == discriminator + ".store"); + Assert.Contains(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.NavigationRequested) + && (e.Payload?[0] as string) == discriminator + ".route"); + Assert.Contains(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.IntlMissingKey) + && (e.Payload?[0] as string) == discriminator + ".key"); + Assert.Contains(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.ThemeApplyFailed) + && (e.Payload?[0] as string) == discriminator + ".target"); + Assert.Contains(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.SwallowedError) + && (e.Payload?[1] as string) == discriminator + ".op"); + } + + [Fact] + public void New_keyword_bits_are_disjoint_from_existing_ones() + { + // The new keyword bits must not collide with existing ones — + // otherwise enabling one would silently enable another. This is + // a defensive constant-level assertion that survives even if the + // EventSource is never instantiated. + var oldBits = (long)ReactorEventSource.Keywords.Reconcile + | (long)ReactorEventSource.Keywords.Render + | (long)ReactorEventSource.Keywords.State + | (long)ReactorEventSource.Keywords.Mcp + | (long)ReactorEventSource.Keywords.Lifecycle + | (long)ReactorEventSource.Keywords.Errors + | (long)ReactorEventSource.Keywords.EventDispatch; + + var newBits = (long)ReactorEventSource.Keywords.Hosting + | (long)ReactorEventSource.Keywords.Persistence + | (long)ReactorEventSource.Keywords.Navigation + | (long)ReactorEventSource.Keywords.Intl + | (long)ReactorEventSource.Keywords.Theme + | (long)ReactorEventSource.Keywords.Shell; + + Assert.Equal(0, oldBits & newBits); + } +} diff --git a/tests/Reactor.Tests/Diagnostics/ReactorTraceCollector.cs b/tests/Reactor.Tests/Diagnostics/ReactorTraceCollector.cs new file mode 100644 index 000000000..ed6f4a7dc --- /dev/null +++ b/tests/Reactor.Tests/Diagnostics/ReactorTraceCollector.cs @@ -0,0 +1,90 @@ +using System.Diagnostics.Tracing; +using Microsoft.UI.Reactor.Core.Diagnostics; +using Microsoft.UI.Reactor.Diagnostics; + +namespace Microsoft.UI.Reactor.Tests.Diagnostics; + +/// +/// Spec 044 Phase I — test-only collector that wraps +/// with a thread-safe captured-events +/// list. Lives in the test assembly because production code should never +/// hold a hot list of every event (memory + dispatcher cost). +/// +/// +/// Typical use: +/// +/// using var collector = ReactorTraceCollector.Capture( +/// level: EventLevel.Verbose, +/// keywords: ReactorEventSource.Keywords.Reconcile); +/// // … exercise framework … +/// Assert.Collection(collector.Events, …); +/// +/// +/// +/// +/// Disposing detaches the underlying ; subsequent +/// events do not append to , so later tests in the same +/// process cannot leak state through a left-over subscription. +/// +/// +internal sealed class ReactorTraceCollector : IDisposable +{ + private readonly List _events = new(); + private readonly object _gate = new(); + private readonly IDisposable _subscription; + private int _disposed; + + private ReactorTraceCollector(EventLevel level, EventKeywords keywords) + { + _subscription = ReactorTrace.Subscribe(OnEvent, level, keywords); + } + + /// + /// Starts capturing. Defaults match : + /// and all keywords. Tests that only + /// care about one subsystem should narrow the filter — it keeps the + /// captured list shorter and avoids interleaving with concurrent + /// unrelated activity. + /// + public static ReactorTraceCollector Capture( + EventLevel level = EventLevel.Verbose, + EventKeywords keywords = (EventKeywords)(-1)) + => new(level, keywords); + + /// + /// Immutable snapshot of events captured so far, in arrival order. + /// Safe to enumerate while the framework continues to emit because + /// each access returns a fresh array. + /// + public IReadOnlyList Events + { + get + { + lock (_gate) return _events.ToArray(); + } + } + + /// + /// Convenience: every captured event whose EventName matches + /// . + /// + public IReadOnlyList ByName(string name) + { + lock (_gate) + return _events.Where(e => e.EventName == name).ToArray(); + } + + private void OnEvent(ReactorEvent e) + { + // ReactorTrace already wraps the callback in try/catch so a buggy + // sink doesn't break other subscribers — keep this hot path as + // small as possible. + lock (_gate) _events.Add(e); + } + + public void Dispose() + { + if (Interlocked.Exchange(ref _disposed, 1) != 0) return; + _subscription.Dispose(); + } +} diff --git a/tests/Reactor.Tests/Diagnostics/ReactorTraceRegressionTests.cs b/tests/Reactor.Tests/Diagnostics/ReactorTraceRegressionTests.cs new file mode 100644 index 000000000..9624e3903 --- /dev/null +++ b/tests/Reactor.Tests/Diagnostics/ReactorTraceRegressionTests.cs @@ -0,0 +1,199 @@ +using System.Diagnostics.Tracing; +using Microsoft.UI.Reactor.Core.Diagnostics; +using Microsoft.UI.Reactor.Diagnostics; +using Xunit; + +namespace Microsoft.UI.Reactor.Tests.Diagnostics; + +/// +/// Spec 044 Phase I (§8.2) — regression guards that pin the contracts a +/// future change is most likely to break by accident: +/// +/// +/// Reconcile fires a Start/Stop pair under the Reconcile keyword. +/// RenderError carries the exception type but never the raw +/// . +/// Every routes through +/// DiagnosticLog.SwallowedError to a captured +/// SwallowedError event. +/// The MCP selector is hashed before it ever reaches the trace. +/// When a keyword is disabled, the framework-side helper allocates +/// nothing on the hot path. +/// +/// +public class ReactorTraceRegressionTests +{ + [Fact] + public void Reconcile_emits_start_stop_pair() + { + using var collector = ReactorTraceCollector.Capture( + level: EventLevel.Informational, + keywords: ReactorEventSource.Keywords.Reconcile); + + ReactorEventSource.Log.ReconcileStart("PhaseITestRoot"); + ReactorEventSource.Log.ReconcileStop( + elementsDiffed: 3, elementsSkipped: 1, + uiElementsCreated: 2, uiElementsModified: 1); + + var start = Assert.Single( + collector.ByName(nameof(ReactorEventSource.ReconcileStart)), + e => (e.Payload[0] as string) == "PhaseITestRoot"); + var stop = Assert.Single( + collector.ByName(nameof(ReactorEventSource.ReconcileStop)), + e => (int)(e.Payload[0] ?? -1) == 3); + + Assert.Equal(EventLevel.Informational, start.Level); + Assert.Equal(EventLevel.Informational, stop.Level); + Assert.True((start.Keywords & ReactorEventSource.Keywords.Reconcile) != 0); + Assert.True((stop.Keywords & ReactorEventSource.Keywords.Reconcile) != 0); + } + + [Fact] + public void RenderError_carries_exception_type_but_not_message() + { + using var collector = ReactorTraceCollector.Capture( + level: EventLevel.Error, + keywords: ReactorEventSource.Keywords.Errors); + + // Pass a message that would be obviously fingerprintable if it + // ever leaked — if the assertion below ever flips, the leak shows + // up at the failure site without scanning for a salted token. + const string secret = "DO_NOT_PERSIST_TO_TRACE_phase-i-secret"; + ReactorEventSource.Log.RenderError( + componentName: "PhaseITestComponent", + exceptionType: nameof(InvalidOperationException), + message: secret); + + var hit = Assert.Single( + collector.ByName(nameof(ReactorEventSource.RenderError)), + e => (e.Payload[0] as string) == "PhaseITestComponent"); + + Assert.Equal(nameof(InvalidOperationException), hit.Payload[1]); + // Third payload slot exists for ABI stability but is stripped at + // the emit site (security TASK-064 / spec §6.2.1). + Assert.Equal(string.Empty, hit.Payload[2]); + Assert.DoesNotContain(secret, string.Join("|", hit.Payload.Select(p => p?.ToString() ?? "")), StringComparison.Ordinal); + } + + public static IEnumerable EveryLogCategory() + { + // Walks the LogCategory enum so a new category added later + // automatically gets covered by this regression test; if a new + // entry breaks (e.g. someone added it without wiring the + // ToString shape) we want the failure here, not in a customer + // report. + foreach (var name in Enum.GetNames()) + yield return new object[] { name }; + } + + [Theory] + [MemberData(nameof(EveryLogCategory))] + public void SwallowedError_smoke_for_each_log_category(string categoryName) + { + var category = Enum.Parse(categoryName); + + using var collector = ReactorTraceCollector.Capture( + level: EventLevel.Warning, + keywords: ReactorEventSource.Keywords.Errors); + + var operation = $"PhaseI.{categoryName}.smoke"; + DiagnosticLog.SwallowedError(category, operation, new InvalidOperationException("ignored-pii")); + + var hit = Assert.Single( + collector.ByName(nameof(ReactorEventSource.SwallowedError)), + e => (e.Payload[1] as string) == operation); + + Assert.Equal(categoryName, hit.Payload[0]); + Assert.Equal(nameof(InvalidOperationException), hit.Payload[2]); + } + + [Fact] + public void Mcp_selector_is_hashed_not_emitted_raw() + { + using var collector = ReactorTraceCollector.Capture( + level: EventLevel.Informational, + keywords: ReactorEventSource.Keywords.Mcp); + + // A selector that would be unambiguously identifying if it leaked. + const string sensitiveSelector = "[Text*='alice@contoso.example.invalid']"; + ReactorEventSource.Log.McpCallStart("test.tool", sensitiveSelector); + + var hit = Assert.Single( + collector.ByName(nameof(ReactorEventSource.McpCallStart)), + e => (e.Payload[0] as string) == "test.tool"); + + var fingerprint = Assert.IsType(hit.Payload[1]); + Assert.StartsWith("sha1:", fingerprint, StringComparison.Ordinal); + Assert.DoesNotContain("alice", fingerprint, StringComparison.Ordinal); + Assert.DoesNotContain("@", fingerprint, StringComparison.Ordinal); + // A SHA-1 prefix of 8 bytes hex-encodes to 16 chars; "sha1:" + 16. + Assert.Equal("sha1:".Length + 16, fingerprint.Length); + } + + [Fact] + public void DisabledKeyword_skips_ReactorEventSource_WriteEvent_payload_marshal() + { + // The hot path we care about for cost-of-disabled is the + // EventSource-side gate: when no listener has Keywords.Errors at + // Warning, ReactorEventSource.Log.SwallowedError must return + // immediately, with no WriteEvent payload marshalling. + // + // We can't *force* the runtime keyword bit off mid-test (every + // running EventListener contributes its mask), so we approximate + // by capturing on an unrelated keyword (Reconcile). If + // Keywords.Errors actually became enabled by some background + // listener, the sanity check at the end would fire. + // + // Why not measure DiagnosticLog.SwallowedError directly: the + // public helper additionally runs a `[Conditional("DEBUG")]` + // mirror that emits a string-interpolated `Debug.WriteLine` so + // contributors see the failure in their Output window. That + // mirror is deliberate cost in DEBUG and is compiled out in + // Release; measuring it would make this test config-dependent. + // The "cost-of-disabled" contract that matters in Release + // (where customers run) is the EventSource gate, exercised + // below. + using var unrelated = ReactorTraceCollector.Capture( + level: EventLevel.Verbose, + keywords: ReactorEventSource.Keywords.Reconcile); + + // Precondition: confirm Errors really IS disabled inside this + // measurement window. xunit can run other test classes in + // parallel and one of them might hold its own EventListener with + // Keywords.Errors open — the runtime unions every active + // listener's mask, so a remote test's collector keeps our gate + // hot. If that race fires, the alloc cap is meaningless: skip + // the measurement rather than emit a flaky failure. + if (ReactorEventSource.Log.IsEnabled(EventLevel.Warning, ReactorEventSource.Keywords.Errors)) + { + // The gate is meaningfully tested whenever it IS disabled — + // some other test run in this process will hit that path. + // Returning early here is honest about the precondition. + return; + } + + // Warm up — JIT first call, allow the runtime to settle so the + // measurement window only captures the steady state. + for (int i = 0; i < 100; i++) + ReactorEventSource.Log.SwallowedError("Reactor", "PhaseI.NoAlloc.warmup", "InvalidOperationException"); + + var before = GC.GetAllocatedBytesForCurrentThread(); + const int iterations = 10_000; + for (int i = 0; i < iterations; i++) + ReactorEventSource.Log.SwallowedError("Reactor", "PhaseI.NoAlloc", "InvalidOperationException"); + var delta = GC.GetAllocatedBytesForCurrentThread() - before; + + // The gated path SHOULD be zero. Allow up to one byte per + // iteration for transient runtime bookkeeping (boxed enums in + // EventListener admin, etc.). A regression that re-introduces + // WriteEvent argument marshalling outside the gate would burn + // dozens of bytes per call and blow well past this cap. + Assert.True(delta <= iterations, + $"ReactorEventSource.SwallowedError leaked {delta} B over {iterations} disabled-keyword calls (cap: {iterations})."); + + // Sanity check: nothing leaked into the unrelated keyword stream + // (would mean Errors became enabled mid-test, invalidating this + // measurement). + Assert.Empty(unrelated.ByName(nameof(ReactorEventSource.SwallowedError))); + } +} diff --git a/tests/Reactor.Tests/Diagnostics/ReactorTraceSubscribeTests.cs b/tests/Reactor.Tests/Diagnostics/ReactorTraceSubscribeTests.cs new file mode 100644 index 000000000..b0d364eba --- /dev/null +++ b/tests/Reactor.Tests/Diagnostics/ReactorTraceSubscribeTests.cs @@ -0,0 +1,202 @@ +using System.Diagnostics.Tracing; +using Microsoft.UI.Reactor.Core.Diagnostics; +using Microsoft.UI.Reactor.Diagnostics; +using Xunit; + +namespace Microsoft.UI.Reactor.Tests.Diagnostics; + +/// +/// Spec 044 Phase D (§5.3) — verifies the in-process +/// helper: +/// +/// 1. delivers events with the right shape; +/// 2. detaches on Dispose; +/// 3. tolerates concurrent subscribers independently; +/// 4. swallows subscriber exceptions; +/// 5. respects the keywords filter; and +/// 6. respects the level filter. +/// +public class ReactorTraceSubscribeTests +{ + [Fact] + public void Subscribe_delivers_event_with_id_name_level_and_payload() + { + var captured = new List(); + const string component = "ReactorTraceSubscribeTests.deliver"; + + using (ReactorTrace.Subscribe( + evt => { lock (captured) captured.Add(evt); }, + EventLevel.Verbose, + ReactorEventSource.Keywords.Errors)) + { + ReactorEventSource.Log.RenderError(component, nameof(InvalidOperationException), "ignored-pii"); + } + + ReactorEvent[] hits; + lock (captured) + hits = captured.Where(e => + e.EventName == nameof(ReactorEventSource.RenderError) + && (e.Payload.Count > 0 && (e.Payload[0] as string) == component)).ToArray(); + + var evt = Assert.Single(hits); + Assert.Equal(9, evt.EventId); + Assert.Equal(EventLevel.Error, evt.Level); + Assert.Equal(component, evt.Payload[0]); + Assert.Equal(nameof(InvalidOperationException), evt.Payload[1]); + Assert.NotNull(evt.PayloadNames); + Assert.Equal(evt.Payload.Count, evt.PayloadNames.Count); + } + + [Fact] + public void Dispose_detaches_subscription() + { + var captured = new List(); + const string component = "ReactorTraceSubscribeTests.dispose"; + + var token = ReactorTrace.Subscribe( + evt => { lock (captured) captured.Add(evt); }, + EventLevel.Verbose, + ReactorEventSource.Keywords.Errors); + + ReactorEventSource.Log.RenderError(component, "Boom", string.Empty); + + token.Dispose(); + + int countBeforeSecondEmit; + lock (captured) + countBeforeSecondEmit = captured.Count(e => + e.EventName == nameof(ReactorEventSource.RenderError) + && (e.Payload.Count > 0 && (e.Payload[0] as string) == component)); + + // Emit again after dispose — must not reach the callback. + ReactorEventSource.Log.RenderError(component, "Boom2", string.Empty); + + int countAfterSecondEmit; + lock (captured) + countAfterSecondEmit = captured.Count(e => + e.EventName == nameof(ReactorEventSource.RenderError) + && (e.Payload.Count > 0 && (e.Payload[0] as string) == component)); + + Assert.Equal(1, countBeforeSecondEmit); + Assert.Equal(countBeforeSecondEmit, countAfterSecondEmit); + } + + [Fact] + public void Two_concurrent_subscribers_each_see_the_event() + { + var a = new List(); + var b = new List(); + const string component = "ReactorTraceSubscribeTests.concurrent"; + + using (ReactorTrace.Subscribe( + evt => { lock (a) a.Add(evt); }, + EventLevel.Verbose, + ReactorEventSource.Keywords.Errors)) + using (ReactorTrace.Subscribe( + evt => { lock (b) b.Add(evt); }, + EventLevel.Verbose, + ReactorEventSource.Keywords.Errors)) + { + ReactorEventSource.Log.RenderError(component, "Boom", string.Empty); + } + + Assert.Contains(a, e => + e.EventName == nameof(ReactorEventSource.RenderError) + && (e.Payload[0] as string) == component); + Assert.Contains(b, e => + e.EventName == nameof(ReactorEventSource.RenderError) + && (e.Payload[0] as string) == component); + } + + [Fact] + public void Throwing_subscriber_does_not_break_other_subscribers() + { + var good = new List(); + const string component = "ReactorTraceSubscribeTests.throws"; + + using (ReactorTrace.Subscribe( + _ => throw new InvalidOperationException("bad subscriber"), + EventLevel.Verbose, + ReactorEventSource.Keywords.Errors)) + using (ReactorTrace.Subscribe( + evt => { lock (good) good.Add(evt); }, + EventLevel.Verbose, + ReactorEventSource.Keywords.Errors)) + { + // Should not throw out to the test even though the first + // subscriber's callback raises. + ReactorEventSource.Log.RenderError(component, "Boom", string.Empty); + } + + Assert.Contains(good, e => + e.EventName == nameof(ReactorEventSource.RenderError) + && (e.Payload[0] as string) == component); + } + + [Fact] + public void Subscriber_with_Errors_keyword_does_not_receive_Reconcile_events() + { + var captured = new List(); + const string discriminator = "ReactorTraceSubscribeTests.errors-only"; + + using (ReactorTrace.Subscribe( + evt => { lock (captured) captured.Add(evt); }, + EventLevel.Verbose, + ReactorEventSource.Keywords.Errors)) + { + // Reconcile keyword — should be filtered out. + ReactorEventSource.Log.ReconcileStart(discriminator + ".root"); + // Errors keyword — should be delivered. + ReactorEventSource.Log.SwallowedError( + "Reactor", discriminator + ".op", "X"); + } + + Assert.DoesNotContain(captured, e => + e.EventName == nameof(ReactorEventSource.ReconcileStart) + && (e.Payload[0] as string) == discriminator + ".root"); + Assert.Contains(captured, e => + e.EventName == nameof(ReactorEventSource.SwallowedError) + && (e.Payload[1] as string) == discriminator + ".op"); + } + + [Fact] + public void Subscriber_with_Warning_level_does_not_receive_Verbose_events() + { + var captured = new List(); + const string discriminator = "ReactorTraceSubscribeTests.warning-only"; + + using (ReactorTrace.Subscribe( + evt => { lock (captured) captured.Add(evt); }, + EventLevel.Warning, + (EventKeywords)(-1))) + { + // Verbose — should be filtered. + ReactorEventSource.Log.NavigationCacheHit(discriminator + ".route"); + // Warning — should pass. + ReactorEventSource.Log.IntlMissingKey(discriminator + ".key", "en-US", true); + } + + Assert.DoesNotContain(captured, e => + e.EventName == nameof(ReactorEventSource.NavigationCacheHit) + && (e.Payload[0] as string) == discriminator + ".route"); + Assert.Contains(captured, e => + e.EventName == nameof(ReactorEventSource.IntlMissingKey) + && (e.Payload[0] as string) == discriminator + ".key"); + } + + [Fact] + public void Subscribe_throws_on_null_callback() + { + Assert.Throws( + () => ReactorTrace.Subscribe(null!)); + } + + [Fact] + public void Dispose_is_idempotent() + { + var token = ReactorTrace.Subscribe(_ => { }); + token.Dispose(); + // Calling Dispose a second time must not throw. + token.Dispose(); + } +} diff --git a/tests/Reactor.Tests/Diagnostics/RenderContextUserCallbackEtwBridgeTests.cs b/tests/Reactor.Tests/Diagnostics/RenderContextUserCallbackEtwBridgeTests.cs new file mode 100644 index 000000000..7758475d1 --- /dev/null +++ b/tests/Reactor.Tests/Diagnostics/RenderContextUserCallbackEtwBridgeTests.cs @@ -0,0 +1,128 @@ +using System.Diagnostics.Tracing; +using Microsoft.UI.Reactor.Core; +using Microsoft.UI.Reactor.Core.Diagnostics; +using Xunit; + +namespace Microsoft.UI.Reactor.Tests.Diagnostics; + +/// +/// Spec 044 Phase C §4.9 — regression guard that the user-callback +/// isolation sites in (effect bodies, effect +/// cleanups, persisted-state save) route their swallowed exceptions +/// through DiagnosticLog.SwallowedError(LogCategory.Reactor, ...) +/// rather than the old Debug.WriteLine channel. +/// +/// The broad catch (Exception) stays per §6.7.3 — a thrown user +/// effect / cleanup must not block the remaining slots from running. The +/// asserts here pin both the isolation behavior (sibling slots still run) +/// and the trace shape (stable operation labels and category). +/// +public class RenderContextUserCallbackEtwBridgeTests : IDisposable +{ + private sealed class CapturingListener : EventListener + { + private readonly List _events = new(); + + public IReadOnlyList Events + { + get { lock (_events) return _events.ToArray(); } + } + + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + lock (_events) _events.Add(eventData); + } + } + + private readonly CapturingListener _listener = new(); + + public RenderContextUserCallbackEtwBridgeTests() + { + _listener.EnableEvents( + ReactorEventSource.Log, + EventLevel.Verbose, + ReactorEventSource.Keywords.Errors); + } + + public void Dispose() + { + _listener.DisableEvents(ReactorEventSource.Log); + _listener.Dispose(); + } + + private static EventWrittenEventArgs? FindSwallowedError( + IReadOnlyList events, string operation) + => events.FirstOrDefault(e => + e.EventName == nameof(ReactorEventSource.SwallowedError) + && (e.Payload?[1] as string) == operation); + + [Fact] + public void Effect_body_throw_emits_SwallowedError_with_indexed_operation() + { + var ctx = new RenderContext(); + ctx.BeginRender(() => { }); + ctx.UseEffect(() => throw new InvalidOperationException("boom"), "dep"); + + ctx.FlushEffects(); + + var evt = FindSwallowedError(_listener.Events, "UseEffect.effect[i=0]"); + Assert.NotNull(evt); + Assert.Equal(nameof(LogCategory.Reactor), evt!.Payload?[0]); + Assert.Equal(nameof(InvalidOperationException), evt.Payload?[2]); + // PII: ex.Message must never reach the ETW payload. + Assert.DoesNotContain("boom", + string.Join("|", evt.Payload?.OfType() ?? Array.Empty())); + } + + [Fact] + public void Effect_cleanup_throw_during_flush_emits_SwallowedError_with_indexed_operation() + { + var ctx = new RenderContext(); + + ctx.BeginRender(() => { }); + ctx.UseEffect(() => () => throw new InvalidOperationException("cleanup-boom"), "dep-v1"); + ctx.FlushEffects(); + + // Re-render with a new dep key so the cleanup queues for the next flush. + ctx.BeginRender(() => { }); + ctx.UseEffect(() => { }, "dep-v2"); + ctx.FlushEffects(); + + var evt = FindSwallowedError(_listener.Events, "UseEffect.cleanup[i=0]"); + Assert.NotNull(evt); + Assert.Equal(nameof(LogCategory.Reactor), evt!.Payload?[0]); + Assert.Equal(nameof(InvalidOperationException), evt.Payload?[2]); + } + + [Fact] + public void Cleanup_throw_during_RunCleanups_emits_SwallowedError_with_indexed_operation() + { + var ctx = new RenderContext(); + ctx.BeginRender(() => { }); + ctx.UseEffect(() => () => throw new InvalidOperationException("teardown-boom"), "dep"); + ctx.FlushEffects(); + + ctx.RunCleanups(); + + var evt = FindSwallowedError(_listener.Events, "RunCleanups.effectCleanup[i=0]"); + Assert.NotNull(evt); + Assert.Equal(nameof(LogCategory.Reactor), evt!.Payload?[0]); + Assert.Equal(nameof(InvalidOperationException), evt.Payload?[2]); + } + + [Fact] + public void Effect_throw_does_not_block_subsequent_effects_on_same_flush() + { + var ctx = new RenderContext(); + bool secondEffectRan = false; + + ctx.BeginRender(() => { }); + ctx.UseEffect(() => throw new InvalidOperationException("boom"), "dep0"); + ctx.UseEffect(() => { secondEffectRan = true; }, "dep1"); + + ctx.FlushEffects(); + + Assert.True(secondEffectRan, "Sibling effect must run despite the first one throwing."); + Assert.NotNull(FindSwallowedError(_listener.Events, "UseEffect.effect[i=0]")); + } +} diff --git a/tests/Reactor.Tests/Diagnostics/ShellHResultEtwBridgeTests.cs b/tests/Reactor.Tests/Diagnostics/ShellHResultEtwBridgeTests.cs new file mode 100644 index 000000000..0d083ee1e --- /dev/null +++ b/tests/Reactor.Tests/Diagnostics/ShellHResultEtwBridgeTests.cs @@ -0,0 +1,89 @@ +using System.Diagnostics.Tracing; +using Microsoft.UI.Reactor.Core.Diagnostics; +using Xunit; + +namespace Microsoft.UI.Reactor.Tests.Diagnostics; + +/// +/// Spec 044 Phase C §4.4 — guards that +/// (used by the Shell COM call sites in JumpListComInterop / +/// ThumbnailToolbar / TrayFlyoutHostWindow) writes the +/// HResultFailed event under +/// with the category label, operation identifier, and HRESULT intact. +/// +/// We can't drive the real Shell APIs from a unit test (they require a +/// taskbar context), so this asserts the helper that every Shell HR call +/// site funnels through. The migration itself — i.e. that those call +/// sites use DiagnosticLog.HResultFailed instead of +/// Debug.WriteLine — is verified by the §12.4 acceptance grep. +/// +public class ShellHResultEtwBridgeTests : IDisposable +{ + private sealed class CapturingListener : EventListener + { + private readonly List _events = new(); + + public IReadOnlyList Events + { + get { lock (_events) return _events.ToArray(); } + } + + protected override void OnEventWritten(EventWrittenEventArgs eventData) + { + lock (_events) _events.Add(eventData); + } + } + + private readonly CapturingListener _listener = new(); + + public ShellHResultEtwBridgeTests() + { + _listener.EnableEvents( + ReactorEventSource.Log, + EventLevel.Warning, + ReactorEventSource.Keywords.Errors); + } + + public void Dispose() + { + _listener.DisableEvents(ReactorEventSource.Log); + _listener.Dispose(); + } + + [Fact] + public void HResultFailed_for_shell_emits_event_with_category_op_and_hr() + { + // Per-test discriminator so concurrent traffic from other tests + // can't false-positive the assertion. + var op = $"ShellHRBridge.Op.{Guid.NewGuid():N}"; + const int hr = unchecked((int)0x80070005); // E_ACCESSDENIED — realistic Shell value. + + DiagnosticLog.HResultFailed(LogCategory.Shell, op, hr); + + var evt = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.HResultFailed) + && (e.Payload?[1] as string) == op); + Assert.Equal(nameof(LogCategory.Shell), evt.Payload?[0]); + Assert.Equal(hr, evt.Payload?[2]); + Assert.Equal((int)EventLevel.Warning, (int)evt.Level); + } + + [Fact] + public void HResultFailed_payload_omits_op_string_segments_that_would_be_user_data() + { + // The bridge passes the operation label verbatim. Shell call sites + // were audited to ensure no user-controllable data leaks into the + // op string (e.g. JumpList category names, file paths, registry + // values). This test pins the "no string-concat-with-user-data" + // convention by asserting we can recover the exact op label from + // the payload — a regression that interpolated user data would + // either fail this match or introduce a longer payload field. + const string op = "JumpList.AppendKnownCategory.Recent"; + DiagnosticLog.HResultFailed(LogCategory.Shell, op, unchecked((int)0x80004005)); + + var evt = Assert.Single(_listener.Events, e => + e.EventName == nameof(ReactorEventSource.HResultFailed) + && (e.Payload?[1] as string) == op); + Assert.Equal(op, evt.Payload?[1]); + } +}