diff --git a/.github/copilot-instructions.md b/.github/copilot-instructions.md index 3a1ad851a..96a354850 100644 --- a/.github/copilot-instructions.md +++ b/.github/copilot-instructions.md @@ -280,7 +280,7 @@ The workspace is organized into six top-level directories under `src/`: - The lower-level execution surface lives in `wxc_common::sandbox_process`: the `SandboxBackend` trait (`validate` + `spawn(request, logger, StdioMode) -> Box` + a `diagnose_exit` hook) and the generic `Runner` adapter that bridges any `SandboxBackend` to the run-to-completion `ScriptRunner` (via `spawn(StdioMode::Inherit)` then `wait()`). `SandboxProcess::output_metadata()` carries backend-produced structured outputs after terminal teardown without writing to process-global stdio. `StdioMode::Pipes` hands the caller live stdin/stdout/stderr (what the `mxc-sdk` streaming path uses); `StdioMode::Inherit` lets the child inherit the host's stdio (what the executor binaries use, preserving the TTY under a pty). `SandboxBackend` is implemented for Seatbelt, Bubblewrap, Windows ProcessContainer, and WSLC (on `wslc_common::WSLContainerRunner` itself, which shares one container lifecycle — `start_container` — between its streaming `SandboxBackend` and run-to-completion `ScriptRunner` impls, differing only in where the WSLC SDK's output callbacks write). - `mxc_ffi` (`ffi/mxc_ffi`, `crate-type = ["cdylib", "staticlib", "lib"]`) is a flat, panic-safe **C ABI over `mxc-sdk`** for language bindings. `mxc_run(policyJson, command, out)` runs a sandbox to completion, filling a `#[repr(C)] MxcRunResult` (status + exit_code + timed_out + owned stdout/stderr/error/output-metadata C strings); every entry point is `catch_unwind`-wrapped so a panic becomes a status code, never an unwind. Its `build.rs` runs **csbindgen** to generate the C# P/Invoke (`sdk/dotnet/Microsoft.Mxc.Sdk/Native/NativeMethods.g.cs`), gated behind the crate's **`dotnetsdk`** feature (off by default, so the whole-workspace backend build matrix doesn't compile csbindgen). The generated file is **not committed** (gitignored); the C# csproj regenerates it at build time and `scripts/check-dotnet-bindings-codegen.js` runs the codegen in CI and asserts the expected entry points are produced. The C ABI is **not a stable external contract** (native + binding are co-versioned and generated together; see the crate docs). It exposes three surfaces: **run-to-completion** (`mxc_run`), **streaming** (`mxc_spawn` → opaque `MxcSandbox` handle; `mxc_stream_read`/`write`/`flush`, `mxc_sandbox_take_stdin`/`stdout`/`stderr`, `mxc_sandbox_id`/`try_wait`/`wait`/`kill`/`output_metadata_json`/`free`, in `src/streaming.rs`), and the **state-aware lifecycle** (`mxc_state_aware` for the envelope phases + `mxc_state_aware_exec` returning a live streaming handle, in `src/state_aware.rs`). All three `.rs` files are csbindgen inputs in `build.rs`; the `MXC_STATUS_*` space already reserves the state-aware phase codes. - `mxc_pty` is the shared pty bridge used by the LXC backend (`lxc_common::lxc_bindings::attach_run`) so the inner shell sees a real TTY and host stdio is streamed live. (Seatbelt and Bubblewrap no longer use it: they spawn directly and let the child inherit the host's stdio — a TTY when the executor binary runs under a pty — via `SandboxBackend::spawn(StdioMode::Inherit)`.) -- `learning_mode_core` is the **cross-platform learning-mode / captureDenials model + output emitter**: `DeniedResource` (+ `ResourceType`/`AccessType`), `DenialSummary`, the `DenialAnalyzer` decode trait, and `emit` — which writes the on-disk denials deliverable as a **single JSON document** `{ "denials": [...], "summary": {...} }` (`write_document` / `DenialsDocument`) and defines the serializable `DenialsOutputPointer`. It carries no OS-specific code (must not depend on any `backends/*` crate); the Windows ETL decoder implementing `DenialAnalyzer` lives in `backends/learning_mode/windows`. When `processContainer.captureDenials` is set, native PSEC/V2 seals and decodes a managed ETL locally, while guarded WPR relogs its host-wide source into a process-scoped ETL before analysis; both routes write the same canonical JSON through shared output plumbing and return neutral `wxc_common` metadata. Explicit `retainEtl` preserves the native sealed trace or the guarded process-scoped relogged trace after a terminal wait; abandonment discards it. `wxc-exec` serializes the metadata as the one-line stderr pointer at the CLI boundary; Rust/C#/FFI callers receive it programmatically. Each denial's `resource` field holds the file path or the AppContainer capability name; capability denials resolve their capability SID to a friendly name via `backends/learning_mode/windows`'s `capability_names` (well-known `S-1-15-3-…` SID → policy name; custom hashed SIDs fall back to the SID string). +- `learning_mode_core` is the **cross-platform learning-mode / captureDenials model + output emitter**: `DeniedResource` (+ `ResourceType`/`AccessType`), `DenialSummary`, the `DenialAnalyzer` decode trait, canonical `DenialsDocument` emission, bounded sensitive-value-redacted `VerboseLoggingDocument` emission, and transactional paired-file write/relocation helpers. Every successful analysis writes the canonical policy artifact plus its deterministic `*.verbose.json` sibling; relocation reports destination commit separately from source-cleanup warnings so callers keep metadata truthful. The crate also defines the serializable `DenialsOutputPointer` and carries no OS-specific code (it must not depend on any `backends/*` crate). The Windows ETL decoder implementing `DenialAnalyzer` lives in `backends/learning_mode/windows`. When `processContainer.captureDenials` is set, native PSEC/V2 seals and decodes a managed ETL locally, while guarded WPR relogs its host-wide source into a process-scoped ETL before analysis; both routes write the same output pair through shared plumbing and return neutral `wxc_common` metadata. Explicit `retainEtl` preserves the native sealed trace or the guarded process-scoped relogged trace after a terminal wait; abandonment discards it. `wxc-exec` serializes the metadata as the one-line stderr pointer at the CLI boundary; Rust/C#/FFI callers receive it programmatically. Each canonical denial's `resource` field holds the file path, named object, UI category, or AppContainer capability name; capability denials resolve their capability SID to a friendly name via `backends/learning_mode/windows`'s `capability_names` (well-known `S-1-15-3-…` SID → policy name; custom hashed SIDs fall back to the SID string). - `mxc_build_common` is a build-time helper crate — all Windows binary crates use it in their `build.rs` to embed VersionInfo (ProductName, FileDescription, copyright, version+commit). When adding a new Windows binary crate, add `mxc_build_common` as a build-dependency and call `mxc_build_common::embed_version_info()` from `build.rs` - `nanvix_build_common` is a **build-only** helper crate (never linked into the runtime): it stages NanVix binaries next to the executable and resolves the `NANVIX_BIN` prefetch directory. The `nanvix_binaries`, `wxc`, and `lxc` build scripts consume it as a `[build-dependencies]` entry. Runtime constants it needs (binary/snapshot filenames) stay in `nanvix_common`. Keep build-only file-staging logic here, not in `nanvix_common` (which is a runtime dependency of `nanvix_runner`). - Platform-specific modules use `#[cfg(target_os = "windows")]` / `#[cfg(target_os = "linux")]` diff --git a/docs/learning-mode/capabilities.md b/docs/learning-mode/capabilities.md index 0ff90fc86..de1081697 100644 --- a/docs/learning-mode/capabilities.md +++ b/docs/learning-mode/capabilities.md @@ -105,9 +105,10 @@ stays enforced: hosts use native capture without PLM or UAC, while legacy or incompatible tiers use the session-scoped guarded-WPR fallback and elevate only its fixed-operation guardian. The CLI consumes the returned JSON and ETL paths, - relocates them to `denials.json` and `trace.etl`, and generates the source - snapshot and `Adjusted_*.json` from canonical denials without decoding ETL - again. Truncated analysis skips the adjusted config. + relocates the policy output, its verbose logging sibling, and the trace to + `denials.json`, `denials.verbose.json`, and `trace.etl`, and generates the + source snapshot and `Adjusted_*.json` from the policy denials without decoding + ETL again. Truncated analysis skips the adjusted config. ``` wxc-exec --audit --config @@ -171,8 +172,8 @@ ungranted access is handled while it is recorded: ### Output file the caller consumes After the sandboxed workload exits, MXC decodes the captured denials and writes -them to a **single JSON file** — the deliverable a host application reads to -regenerate its sandbox policy: +the policy JSON deliverable a host application reads to regenerate its +sandbox policy: ```json { @@ -203,14 +204,18 @@ regenerate its sandbox policy: - `denials` is already de-duplicated per `(resource, accessType)`, so `summary.totalDenials` equals `denials.length`. - Analysis retains at most 10,000 unique denials and processes at most - 1,000,000 ETW events. Reaching either bound stops further analysis and sets - `summary.deniedResourcesTruncated` to `true`. + 1,000,000 ETW events. Reaching the unique-denial bound stops adding policy + entries but continues bounded diagnostic accounting; reaching either bound + sets `summary.deniedResourcesTruncated` to `true`. - `resource` is the user-visible identifier for the denied resource, - interpreted by `resourceType`: a canonical `C:\…` path for `file`, the + interpreted by `resourceType`: an absolute `C:\…` path for `file`, the AppContainer **capability name** (e.g. `internetClient`) for `capability`, - and the raw resource identifier otherwise. Well-known capability SIDs are + and the raw resource identifier otherwise. Named Section, SymbolicLink, and + Timer access checks are emitted as `other`. Well-known capability SIDs are resolved to their policy name; custom (hashed) capability SIDs that can't be - reversed fall back to the `S-1-15-3-…` SID string. + reversed fall back to the `S-1-15-3-…` SID string. Event 28 is + schema-discriminated: UI-shaped `Category`/`Detail` payloads emit `ui` + resources instead of treating the package SID as a capability. - `resourceType` is one of `file`, `ui`, `network`, `capability`, `other`; `accessType` is one of `read`, `write`, `execute`, `unknown`. Capability denials are recorded under `block`; current `allow` traces expose capability @@ -219,6 +224,107 @@ regenerate its sandbox policy: - `filetime` is a decimal string containing the Windows `FILETIME` value, so JavaScript consumers retain all 64 bits without numeric precision loss. +### Verbose logging event signatures + +Every successful decode also writes a deterministic sibling file: +`denials..json` produces `denials..verbose.json`. This verbose +logging artifact is a bounded, sensitive-value-redacted superset containing +policy denial occurrences plus diagnostic outcomes omitted from the policy file: + +```json +{ + "version": 1, + "signatures": [ + { + "signature": { + "provider": "kernelGeneral", + "providerGuid": "{A68CA8B7-004F-D7B6-A698-07E2DE0F1F5D}", + "eventId": 14, + "reason": "canonicalDenial", + "pid": 4321, + "accessType": "read", + "resourceType": "file", + "properties": [ + ["PackageSid", "S-1-15-3-1"], + ["resource", ""] + ] + }, + "count": 37 + } + ], + "summary": { + "totalOccurrences": 37, + "overflowOccurrences": 0, + "canonicalOverflowOccurrences": 0, + "aggregateGroupsTruncated": false, + "processedEventsTruncated": false, + "canonicalDenialLimitReached": false + } +} +``` + +Signatures are keyed by symbolic provider category, provider GUID, +provider-scoped event ID, closed exclusion reason, PID, and sorted sanitized +properties. SIDs, capability names, GUIDs, PIDs/process identifiers, and +non-file resource values are retained. Complete file paths are replaced with +``; standalone user/account names remain replaced with +``. +Exact header timestamps and timestamp-like properties are omitted so otherwise +identical events deduplicate, and free-form decoder errors are never serialized. + +Every valid denial candidate is classified as `canonicalDenial` in the verbose +file, including its first occurrence, later duplicates, and candidates observed +after the policy file's unique-denial bound. Those occurrences deduplicate under the +same signature and increment its count. `accessType` and `resourceType` are +included when denial extraction determined them; diagnostic outcomes without +those classifications omit the fields. + +Candidates excluded from the policy output retain a closed diagnostic +reason and their sanitized event properties: + +- `unusableResourcePath` means a File access-check resource could not be + converted to a safe absolute DOS or UNC path. For example, + `\Device\MountPointManager` is useful Devices-namespace evidence, but it is + not a directly authorable filesystem grant. +- `unsupportedObjectType` means the event names a resource outside the + supported policy model. Observed Section, SymbolicLink, and Timer checks are + retained as `other` resources; remaining examples include + `\BaseNamedObjects` as a Directory, ALPC Ports such as + `ubpmtaskhostchannel`, and RPC Interface GUIDs. + +Property values longer than 256 characters retain bounded prefix and suffix +context plus a SHA-256 digest of the complete sanitized value. This keeps long +named-object resources individually identifiable when they share a prefix +without exceeding the per-property bound. Redaction occurs before the digest is computed, so neither retained context nor +a digest is derived from a sensitive value. + +Unknown event IDs from known Learning Mode providers are classified as +`unsupportedEventSchema`; the real ETL path retains their provider GUID and +PID without attempting an unsupported TDH payload decode. + +Per-event TDH failures use closed diagnostic reasons: +`eventPayloadMalformed` means the payload conflicts with its declared schema, +`decoderLimitReached` means a nesting/element/work safety bound stopped +decoding, and `unsupportedPropertyEncoding` means the decoder cannot consume +that property shape. When TDH exposes it, the schema-declared name is retained +as the bounded `EventName` signature property. Free-form decoder errors are +never serialized. Failure to obtain the event schema remains a fatal analysis +error rather than being represented as a verbose logging signature. + +To keep diagnostics bounded, verbose logging retains at most 4,096 distinct +signatures, 24 sorted properties per signature, and 256 characters per property +value. `overflowOccurrences` and `aggregateGroupsTruncated` indicate that +additional diagnostic groups were omitted. `canonicalOverflowOccurrences` +counts omitted policy-denial occurrences, while `processedEventsTruncated` +indicates that the 1,000,000-event limit prevented complete accounting. The +policy file itself is never reduced to make room for verbose logging. + +The policy and verbose logging files fail together: MXC stages both and reports +capture failure unless both final artifacts are committed. The verbose logging path +is intentionally absent from stderr pointers and Rust, Node, C#, and FFI output +metadata; callers derive it from the policy output path using the naming rule +above. + **Locating the file.** Set `captureDenials.outputPath` to name the file explicitly (its parent directory must already exist). MXC inserts a unique per-run identifier (process id plus random suffix) into the file stem @@ -232,8 +338,8 @@ so CLI callers can locate the deliverable without scanning the filesystem: {"type":"captureDenials","outputPath":"C:\\logs\\denials.4321_0123456789abcdef0123456789abcdef.json","exitCode":0,"totalDenials":2,"deniedResourcesTruncated":false} ``` -The pointer echoes the file's `summary`; the authoritative record is the file -itself. In-process Rust callers receive the same information through +The pointer echoes the policy file's `summary`; that file is the authoritative +record of denials. In-process Rust callers receive the same summary information through `Output::output_metadata` or `Sandbox::output_metadata()` after waiting. The C# SDK exposes it through `RunResult.OutputMetadata` and `MxcSandboxProcess.OutputMetadata`. diff --git a/src/Cargo.lock b/src/Cargo.lock index f0c9c9b62..944216ad2 100644 --- a/src/Cargo.lock +++ b/src/Cargo.lock @@ -1273,8 +1273,11 @@ checksum = "bbd2bcb4c963f2ddae06a2efc7e9f3591312473c50c6685e1f298068316e66fe" name = "learning_mode_core" version = "0.7.0" dependencies = [ + "same-file", "serde", "serde_json", + "sha2 0.10.9", + "tempfile", "thiserror", ] @@ -1285,6 +1288,7 @@ dependencies = [ "flatbuffers", "learning_mode_core", "process_security_environment_spec", + "sha2 0.10.9", "thiserror", "windows", "windows-core", diff --git a/src/Cargo.toml b/src/Cargo.toml index 85f0e8bea..950502a08 100644 --- a/src/Cargo.toml +++ b/src/Cargo.toml @@ -90,6 +90,7 @@ plm = { path = "host/plm" } quick-xml = "0.41" sandbox_spec = { path = "core/generated/base_container_specification" } seatbelt_common = { path = "backends/seatbelt/common" } +same-file = "1" serde = { version = "1", features = ["derive"] } serde_json = "1" serde_path_to_error = "0.1" diff --git a/src/backends/appcontainer/common/src/capture_output.rs b/src/backends/appcontainer/common/src/capture_output.rs index 00834e4bd..ed60aae41 100644 --- a/src/backends/appcontainer/common/src/capture_output.rs +++ b/src/backends/appcontainer/common/src/capture_output.rs @@ -7,20 +7,21 @@ //! decoding its own sealed ETL) and the guarded-WPR legacy-tier fallback //! (`appcontainer_runner`, consuming an already-decoded [`AnalysisResult`] //! handed back by the elevated PLM guardian) must emit byte-for-byte the same -//! [`DenialsDocument`] JSON shape, [`CaptureDenialsOutput`] summary, and -//! resolved output-path convention. Centralizing that here is what guarantees -//! the two paths can't drift. +//! [`DenialsDocument`] JSON shape, username-redacted verbose logging sibling, +//! [`CaptureDenialsOutput`] summary, and resolved output-path convention. +//! Centralizing that here is what guarantees the two paths can't drift. //! //! Deliberately free of any Windows API or [`ScriptResponse`] coupling so it //! can be shared by both runner modules without either owning the other's //! error type; callers map the plain `String` errors into their own error //! type at the call site. -use std::io::Write; use std::path::{Path, PathBuf}; use learning_mode_core::{ - write_document, AnalysisResult, DenialSummary, DenialsDocument, DenialsOutputPointer, + verbose_logging_sibling_path, write_document, write_paired_output_files, + write_verbose_logging_document, AnalysisResult, DenialSummary, DenialsDocument, + DenialsOutputPointer, ExistingOutputPolicy, VerboseLoggingDocument, }; use wxc_common::models::CaptureDenialsOutput; @@ -49,8 +50,9 @@ pub struct DenialsOutputPaths { pub etl: Option, } -/// Writes a bounded [`AnalysisResult`] to `output_path` as the JSON denials -/// document and returns the caller-facing [`CaptureDenialsOutput`] summary. +/// Writes a bounded [`AnalysisResult`] as the canonical denials document and +/// deterministic verbose logging sibling, then returns caller-facing metadata for +/// the canonical document. /// /// Never overwrites an existing file: a run whose output path collides with a /// leftover file from a previous run fails loudly rather than clobbering it. @@ -59,14 +61,23 @@ pub fn write_denials_document( exit_code: i32, output_path: &Path, ) -> std::io::Result { + let verbose_logging_path = verbose_logging_output_path(output_path)?; let summary = DenialSummary::new( exit_code, analysis.denials.len(), analysis.denied_resources_truncated, ); let document = DenialsDocument::new(analysis.denials, summary); + let verbose_logging_document = VerboseLoggingDocument::new(&analysis.verbose_logging); - write_denials_output_file(output_path, |writer| write_document(writer, &document))?; + write_paired_output_files( + "captureDenials", + output_path, + &verbose_logging_path, + ExistingOutputPolicy::CreateNew, + |writer| write_document(writer, &document), + |writer| write_verbose_logging_document(writer, &verbose_logging_document), + )?; let pointer = DenialsOutputPointer::new(output_path.to_string_lossy(), &document.summary); Ok(CaptureDenialsOutput { @@ -79,45 +90,10 @@ pub fn write_denials_document( }) } -/// Creates `output_path` (failing if it already exists) and writes through -/// `write`, cleaning up a partial file if `write` fails. -pub fn write_denials_output_file( - output_path: &Path, - write: impl FnOnce(&mut std::io::BufWriter) -> std::io::Result<()>, -) -> std::io::Result<()> { - let file = std::fs::OpenOptions::new() - .write(true) - .create_new(true) - .open(output_path) - .map_err(|error| { - std::io::Error::other(format!( - "captureDenials failed to create denials output file {}: {error}", - output_path.display() - )) - })?; - - let write_result = { - let mut writer = std::io::BufWriter::new(file); - write(&mut writer).and_then(|()| writer.flush()) - }; - if let Err(error) = write_result { - let write_error = std::io::Error::other(format!( - "captureDenials failed to write denials output file {}: {error}", - output_path.display() - )); - return match std::fs::remove_file(output_path) { - Ok(()) => Err(write_error), - Err(cleanup_error) if cleanup_error.kind() == std::io::ErrorKind::NotFound => { - Err(write_error) - } - Err(cleanup_error) => Err(std::io::Error::other(format!( - "{write_error}; additionally failed to remove incomplete output file {}: {cleanup_error}", - output_path.display() - ))), - }; - } - - Ok(()) +/// Derives the deterministic verbose logging sibling path for a denials output. +pub fn verbose_logging_output_path(output_path: &Path) -> std::io::Result { + verbose_logging_sibling_path(output_path) + .map_err(|error| std::io::Error::other(format!("captureDenials {error}"))) } /// Inserts a per-run identifier into a denials output path's file stem so @@ -305,7 +281,11 @@ pub fn write_stderr_line_best_effort(message: std::fmt::Arguments<'_>) { #[cfg(test)] mod tests { use super::*; - use learning_mode_core::{AccessType, DeniedResource, ResourceType}; + use learning_mode_core::{ + AccessType, DeniedResource, ResourceType, VerboseLoggingExclusionReason, + VerboseLoggingProvider, VerboseLoggingSignature, + }; + use std::io::Write; #[test] fn write_denials_document_writes_summary_and_document() { @@ -327,8 +307,13 @@ mod tests { assert_eq!(metadata.total_denials, 1); assert!(!metadata.denied_resources_truncated); let document: DenialsDocument = - serde_json::from_slice(&std::fs::read(output_path).unwrap()).unwrap(); + serde_json::from_slice(&std::fs::read(&output_path).unwrap()).unwrap(); assert_eq!(document.denials.len(), 1); + let verbose_logging: VerboseLoggingDocument = serde_json::from_slice( + &std::fs::read(verbose_logging_output_path(&output_path).unwrap()).unwrap(), + ) + .unwrap(); + assert_eq!(verbose_logging.version, VerboseLoggingDocument::VERSION); } #[test] @@ -342,35 +327,86 @@ mod tests { assert_eq!(metadata.total_denials, 0); assert!(output_path.exists()); + assert!(verbose_logging_output_path(&output_path).unwrap().exists()); } #[test] - fn failed_denials_write_removes_incomplete_output() { + fn write_denials_document_writes_verbose_logging_aggregates() { let directory = tempfile::tempdir().expect("temp directory"); let output_path = directory.path().join("denials.json"); + let mut analysis = AnalysisResult::complete(Vec::new()); + analysis.verbose_logging.record(VerboseLoggingSignature { + provider: VerboseLoggingProvider::KernelGeneral, + provider_guid: "{A68CA8B7-004F-D7B6-A698-07E2DE0F1F5D}".to_string(), + event_id: 14, + reason: VerboseLoggingExclusionReason::CanonicalDenial, + pid: 42, + access_type: Some(learning_mode_core::AccessType::Read), + resource_type: Some(learning_mode_core::ResourceType::File), + properties: vec![("Sid".to_string(), "S-1-15-3-1".to_string())], + }); - let error = write_denials_output_file(&output_path, |writer| { - std::io::Write::write_all(writer, b"{\"partial\":")?; - Err(std::io::Error::other("simulated write failure")) - }) - .expect_err("write should fail"); + write_denials_document(analysis, 0, &output_path).expect("write should succeed"); - assert!(error.to_string().contains("simulated write failure")); - assert!(!output_path.exists()); + let verbose_logging: VerboseLoggingDocument = serde_json::from_slice( + &std::fs::read(verbose_logging_output_path(&output_path).unwrap()).unwrap(), + ) + .unwrap(); + assert_eq!(verbose_logging.signatures.len(), 1); + assert_eq!(verbose_logging.signatures[0].count, 1); + assert_eq!(verbose_logging.signatures[0].signature.pid, 42); + } + + #[test] + fn verbose_logging_path_is_a_deterministic_json_sibling() { + assert_eq!( + verbose_logging_output_path(Path::new(r"C:\out\denials.123.json")).unwrap(), + PathBuf::from(r"C:\out\denials.123.verbose.json") + ); + assert_eq!( + verbose_logging_output_path(Path::new("denials")).unwrap(), + PathBuf::from("denials.verbose.json") + ); } #[test] - fn denials_output_does_not_overwrite_an_existing_file() { + fn verbose_logging_collision_leaves_canonical_output_absent() { let directory = tempfile::tempdir().expect("temp directory"); let output_path = directory.path().join("denials.json"); - std::fs::write(&output_path, b"existing").expect("seed output"); + let verbose_logging_path = verbose_logging_output_path(&output_path).unwrap(); + std::fs::write(&verbose_logging_path, b"existing").expect("seed verbose logging output"); - write_denials_output_file(&output_path, |_| Ok(())).expect_err("collision should fail"); + write_denials_document(AnalysisResult::complete(Vec::new()), 0, &output_path) + .expect_err("collision should fail"); - assert_eq!( - std::fs::read(&output_path).expect("read existing output"), - b"existing" - ); + assert!(!output_path.exists()); + assert_eq!(std::fs::read(verbose_logging_path).unwrap(), b"existing"); + } + + #[test] + fn second_staged_write_failure_leaves_no_final_output() { + let directory = tempfile::tempdir().expect("temp directory"); + let output_path = directory.path().join("denials.json"); + let verbose_logging_path = verbose_logging_output_path(&output_path).unwrap(); + + let error = write_paired_output_files( + "captureDenials", + &output_path, + &verbose_logging_path, + ExistingOutputPolicy::CreateNew, + |writer| writer.write_all(b"denials"), + |writer| { + writer.write_all(b"partial")?; + Err(std::io::Error::other("simulated verbose logging failure")) + }, + ) + .expect_err("paired write should fail"); + + assert!(error + .to_string() + .contains("simulated verbose logging failure")); + assert!(!output_path.exists()); + assert!(!verbose_logging_path.exists()); } #[test] diff --git a/src/backends/learning_mode/windows/Cargo.toml b/src/backends/learning_mode/windows/Cargo.toml index 3b45e78b2..861bcdd1b 100644 --- a/src/backends/learning_mode/windows/Cargo.toml +++ b/src/backends/learning_mode/windows/Cargo.toml @@ -9,6 +9,7 @@ thiserror = { workspace = true } learning_mode_core = { workspace = true } [target.'cfg(target_os = "windows")'.dependencies] +sha2 = { workspace = true } wxc_common = { workspace = true } windows = { workspace = true } windows-core = { workspace = true } diff --git a/src/backends/learning_mode/windows/src/capability_dacl.rs b/src/backends/learning_mode/windows/src/capability_dacl.rs index 059f656d9..bee880627 100644 --- a/src/backends/learning_mode/windows/src/capability_dacl.rs +++ b/src/backends/learning_mode/windows/src/capability_dacl.rs @@ -252,6 +252,12 @@ pub(crate) fn extract_denials( if !is_supported_event { return Vec::new(); } + // `is_supported_event` above only matches the two known Learning Mode + // providers, so this always resolves. + let Some(provider) = crate::extractors::verbose_logging_provider_for_guid(parts.provider) + else { + return Vec::new(); + }; let names = extract_names(parts, CAPABILITY_INDEX.get_or_init(build_capability_index)); names @@ -263,6 +269,8 @@ pub(crate) fn extract_denials( access_type: AccessType::Unknown, filetime, event_id: parts.event_id, + provider, + verbose_logging_properties: crate::extractors::sanitize_properties(&parts.props), }) .collect() } diff --git a/src/backends/learning_mode/windows/src/etl_decode.rs b/src/backends/learning_mode/windows/src/etl_decode.rs index 1ea867581..6f021869a 100644 --- a/src/backends/learning_mode/windows/src/etl_decode.rs +++ b/src/backends/learning_mode/windows/src/etl_decode.rs @@ -30,6 +30,8 @@ use std::path::Path; use learning_mode_core::{ AnalysisResult, AnalyzeError, DenialAnalyzer, DeniedResource, ProcessLifetime, + VerboseLoggingExclusionReason, VerboseLoggingProvider, VerboseLoggingSignature, + VerboseLoggingSummary, MAX_VERBOSE_LOGGING_SIGNATURE_BYTES, }; use windows::core::PWSTR; use windows::Win32::System::Diagnostics::Etw::{ @@ -76,6 +78,7 @@ pub(crate) struct ProcessLifetimeIndex { pub(crate) struct RelogSelection { pub(crate) selected_event_indices: Vec, + pub(crate) selected_event_pids: Vec, pub(crate) total_event_count: usize, } @@ -130,6 +133,7 @@ struct Accumulator<'visitor> { truncated: bool, raw_visitor: Option<&'visitor mut RawEventVisitor<'visitor>>, relog_selected_event_indices: Vec, + relog_selected_event_pids: Vec, relog_event_count: usize, raw_event_count: usize, processed_event_count: usize, @@ -138,6 +142,8 @@ struct Accumulator<'visitor> { decode_error: Option, panic_payload: Option>, schema_cache: tdh_decode::EventSchemaCache, + verbose_logging: VerboseLoggingSummary, + verbose_logging_signature_bytes: usize, } impl<'visitor> Accumulator<'visitor> { @@ -150,6 +156,7 @@ impl<'visitor> Accumulator<'visitor> { truncated: false, raw_visitor: None, relog_selected_event_indices: Vec::new(), + relog_selected_event_pids: Vec::new(), relog_event_count: 0, raw_event_count: 0, processed_event_count: 0, @@ -158,6 +165,8 @@ impl<'visitor> Accumulator<'visitor> { decode_error: None, panic_payload: None, schema_cache: tdh_decode::EventSchemaCache::default(), + verbose_logging: VerboseLoggingSummary::default(), + verbose_logging_signature_bytes: 0, } } @@ -177,6 +186,7 @@ impl<'visitor> Accumulator<'visitor> { truncated: false, raw_visitor: Some(visitor), relog_selected_event_indices: Vec::new(), + relog_selected_event_pids: Vec::new(), relog_event_count: 0, raw_event_count: 0, processed_event_count: 0, @@ -185,6 +195,8 @@ impl<'visitor> Accumulator<'visitor> { decode_error: None, panic_payload: None, schema_cache: tdh_decode::EventSchemaCache::default(), + verbose_logging: VerboseLoggingSummary::default(), + verbose_logging_signature_bytes: 0, } } @@ -197,6 +209,7 @@ impl<'visitor> Accumulator<'visitor> { truncated: false, raw_visitor: None, relog_selected_event_indices: Vec::new(), + relog_selected_event_pids: Vec::new(), relog_event_count: 0, raw_event_count: 0, processed_event_count: 0, @@ -205,38 +218,47 @@ impl<'visitor> Accumulator<'visitor> { decode_error: None, panic_payload: None, schema_cache: tdh_decode::EventSchemaCache::default(), + verbose_logging: VerboseLoggingSummary::default(), + verbose_logging_signature_bytes: 0, } } - /// Whether an event for `pid` at `filetime` falls within the attested - /// sandbox process lifetimes. Legacy full-trace analysis (no lifetime - /// index) treats every event as in scope. - fn in_analysis_scope(&self, pid: u32, filetime: u64) -> bool { - self.process_lifetimes - .as_ref() - .is_none_or(|lifetimes| lifetimes.contains(pid, filetime)) - } - fn add_raw_denial(&mut self, raw: RawDenial) { - if self - .process_lifetimes - .as_ref() - .is_some_and(|lifetimes| !lifetimes.contains(raw.pid, raw.filetime)) - { + if !self.event_in_scope(raw.pid, raw.filetime) { return; } let resource = if raw.resource_type == learning_mode_core::ResourceType::File { match path_norm::to_user_visible(&raw.object_name) { Some(resource) if path_norm::is_user_visible_absolute(&resource) => resource, - Some(_) => return, + Some(candidate) => { + self.record_raw_denial_outcome( + &raw, + &candidate, + VerboseLoggingExclusionReason::UnusableResourcePath, + ); + return; + } None if path_norm::is_user_visible_absolute(&raw.object_name) => { raw.object_name.clone() } - None => return, + None => { + let candidate = raw.object_name.clone(); + self.record_raw_denial_outcome( + &raw, + &candidate, + VerboseLoggingExclusionReason::UnusableResourcePath, + ); + return; + } } } else { path_norm::to_user_visible(&raw.object_name).unwrap_or_else(|| raw.object_name.clone()) }; + self.record_raw_denial_outcome( + &raw, + &resource, + VerboseLoggingExclusionReason::CanonicalDenial, + ); let dedup_resource = match raw.resource_type { learning_mode_core::ResourceType::File | learning_mode_core::ResourceType::Other => { resource.to_ascii_lowercase() @@ -249,9 +271,13 @@ impl<'visitor> Accumulator<'visitor> { { return; } + // The canonical unique-denial bound is reached: keep reading (up to + // the processed-event bound) so every remaining outcome is still + // aggregated into the verbose logging summary, rather than stopping the + // trace early. if self.denials.len() >= MAX_UNIQUE_DENIALS { self.truncated = true; - self.stop_requested = true; + self.verbose_logging.mark_canonical_denial_limit_reached(); return; } self.seen.insert((dedup_resource, raw.access_type)); @@ -264,10 +290,116 @@ impl<'visitor> Accumulator<'visitor> { }); } + /// Records an outcome for an already-built [`RawDenial`]. Retains the + /// resolved resource/capability identity plus the resource/access type, + /// redacting complete file paths and never retaining the exact + /// `filetime`. + fn record_raw_denial_outcome( + &mut self, + raw: &RawDenial, + resource: &str, + reason: VerboseLoggingExclusionReason, + ) { + let mut properties = raw + .verbose_logging_properties + .iter() + .cloned() + .collect::>(); + let has_object_name = properties + .keys() + .any(|name| name.eq_ignore_ascii_case("ObjectName")); + if raw.resource_type == learning_mode_core::ResourceType::File { + for (name, value) in &mut properties { + if name.eq_ignore_ascii_case("ObjectName") + || name.to_ascii_lowercase().contains("path") + || name.to_ascii_lowercase().ends_with("filename") + { + *value = crate::extractors::REDACTED_PATH.to_string(); + } + } + } + if !matches!( + raw.resource_type, + learning_mode_core::ResourceType::File | learning_mode_core::ResourceType::Other + ) || !has_object_name + { + properties.insert( + "resource".to_string(), + if raw.resource_type == learning_mode_core::ResourceType::File { + crate::extractors::REDACTED_PATH.to_string() + } else { + resource.to_string() + }, + ); + } + let properties = + crate::extractors::bound_properties(properties.into_iter().collect::>()); + self.record_outcome( + raw.provider, + raw.event_id, + reason, + raw.pid, + (Some(raw.access_type), Some(raw.resource_type)), + properties, + ); + } + + /// Records one excluded outcome as a deduplicated verbose logging signature: + /// symbolic provider, provider GUID, event ID, reason, PID, and the + /// already-sanitized/bounded property list all identify the group; + /// repeats of the same signature only increment its `count`. + fn record_exclusion( + &mut self, + provider: VerboseLoggingProvider, + event_id: u16, + reason: VerboseLoggingExclusionReason, + pid: u32, + properties: Vec<(String, String)>, + ) { + self.record_outcome(provider, event_id, reason, pid, (None, None), properties); + } + + fn record_outcome( + &mut self, + provider: VerboseLoggingProvider, + event_id: u16, + reason: VerboseLoggingExclusionReason, + pid: u32, + classification: ( + Option, + Option, + ), + properties: Vec<(String, String)>, + ) { + let (access_type, resource_type) = classification; + let signature = VerboseLoggingSignature { + provider, + provider_guid: crate::extractors::verbose_logging_provider_guid(provider), + event_id, + reason, + pid, + access_type, + resource_type, + properties, + }; + self.verbose_logging.record_with_byte_budget( + signature, + &mut self.verbose_logging_signature_bytes, + MAX_VERBOSE_LOGGING_SIGNATURE_BYTES, + ); + } + + fn event_in_scope(&self, pid: u32, filetime: u64) -> bool { + self.process_lifetimes + .as_ref() + .is_none_or(|lifetimes| lifetimes.contains(pid, filetime)) + } + fn begin_event(&mut self) -> bool { if self.processed_event_count >= MAX_PROCESSED_EVENTS { self.processing_limit_reached = true; self.truncated = true; + self.verbose_logging.mark_processed_events_truncated(); self.stop_requested = true; return false; } @@ -288,16 +420,69 @@ impl<'visitor> Accumulator<'visitor> { } } + /// Handles a TDH decode failure for one event. + /// + /// Schema-level failures (the event's manifest itself could not be + /// resolved) are fatal in every mode: they indicate the trace/schema + /// state is unreliable beyond this single event. Per-event decode + /// failures are fatal only for the raw diagnostic visitor (which needs + /// every event to succeed); in [`CollectionMode::Analyze`] they are + /// aggregated into the verbose logging summary for a known provider instead of + /// silently dropped. fn record_event_decode_error( &mut self, provider: windows::core::GUID, event_id: u16, + pid: u32, error: tdh_decode::DecodeError, ) { - if (matches!(self.mode, CollectionMode::Raw) || error.is_schema_error()) - && self.decode_error.is_none() - { - self.decode_error = Some(format!("provider {:?} event {event_id}: {error}", provider)); + let fatal = matches!(self.mode, CollectionMode::Raw) || error.is_schema_error(); + if fatal { + if self.decode_error.is_none() { + self.decode_error = + Some(format!("provider {:?} event {event_id}: {error}", provider)); + } + return; + } + if let Some(category) = crate::extractors::verbose_logging_provider_for_guid(provider) { + let reason = match error.event_kind() { + Some(tdh_decode::EventDecodeKind::PayloadMalformed) => { + VerboseLoggingExclusionReason::EventPayloadMalformed + } + Some(tdh_decode::EventDecodeKind::DecoderLimitReached) => { + VerboseLoggingExclusionReason::DecoderLimitReached + } + Some(tdh_decode::EventDecodeKind::UnsupportedPropertyEncoding) => { + VerboseLoggingExclusionReason::UnsupportedPropertyEncoding + } + None => return, + }; + // Retain only the bounded schema-declared name. The free-form + // decoder message can include property values and is never emitted. + let properties = error + .event_name() + .map(|name| vec![("EventName".to_string(), name.to_string())]) + .map(crate::extractors::bound_properties) + .unwrap_or_default(); + let classification = match event_id { + crate::extractors::LEARNING_MODE_VIOLATION_EVENT_ID => ( + Some(learning_mode_core::AccessType::Unknown), + Some(learning_mode_core::ResourceType::Ui), + ), + crate::extractors::CAPABILITY_DENIAL_EVENT_ID => match error.event_name() { + Some(name) if name.eq_ignore_ascii_case("CapabilityDenial") => ( + Some(learning_mode_core::AccessType::Unknown), + Some(learning_mode_core::ResourceType::Capability), + ), + Some(name) if name.eq_ignore_ascii_case("LearningModeViolation") => ( + Some(learning_mode_core::AccessType::Unknown), + Some(learning_mode_core::ResourceType::Ui), + ), + _ => (None, None), + }, + _ => (None, None), + }; + self.record_outcome(category, event_id, reason, pid, classification, properties); } } @@ -305,10 +490,22 @@ impl<'visitor> Accumulator<'visitor> { if let Some(error) = self.decode_error { return Err(AnalyzeError::Decode(error)); } - Ok(AnalysisResult { + let mut result = AnalysisResult { denials: self.denials, denied_resources_truncated: self.truncated, - }) + verbose_logging: self.verbose_logging, + }; + match result.fit_verbose_logging_within_serialized_bytes( + crate::guarded_wpr_protocol::MAX_ANALYSIS_BYTES as usize, + ) { + Ok(true) => Ok(result), + Ok(false) => Err(AnalyzeError::Decode( + "canonical Learning Mode analysis exceeds the guarded transport limit".to_string(), + )), + Err(error) => Err(AnalyzeError::Decode(format!( + "failed to size Learning Mode analysis: {error}" + ))), + } } } @@ -361,9 +558,10 @@ impl DenialAnalyzer for EtlDenialAnalyzer { } } -/// Runs the pure decode composition over already-collected events: -/// route each event through [`extract_denial`], then normalise + -/// de-duplicate into public [`DeniedResource`]s. Split out from +/// Runs the pure decode composition over already-collected events, using the +/// same event-classification path ([`handle_decoded_event`]) as the real ETW +/// callback: provider/vocabulary gating, extraction, capability-DACL +/// fallback, and verbose logging aggregation. Split out from /// [`EtlDenialAnalyzer::analyze`] so it can be tested with hand-built events /// that mirror real traces, without a live ETW/TDH read (which needs the /// provider manifests registered on the machine). @@ -377,30 +575,24 @@ fn resources_from_events_for_process_lifetimes( events: &[CollectedEvent], process_lifetimes: Option<&[ProcessLifetime]>, ) -> AnalysisResult { - let mut raws = Vec::new(); - for event in events { - if let Some(raw) = extract_denial(&event.parts, event.pid, event.filetime) { - raws.push(raw); - } - raws.extend(crate::capability_dacl::extract_denials( - &event.parts, - event.pid, - event.filetime, - )); - } let mut accumulator = match process_lifetimes { Some(lifetimes) => Accumulator::analyze_for_process_lifetimes(lifetimes), None => Accumulator::analyze(), }; - for raw in raws { - accumulator.add_raw_denial(raw); + accumulate_collected_events(events, &mut accumulator); + accumulator + .into_analysis() + .expect("pure denial accumulation cannot decode-fail") +} + +#[cfg(test)] +fn accumulate_collected_events(events: &[CollectedEvent], accumulator: &mut Accumulator<'_>) { + for event in events { + handle_decoded_event(&event.parts, event.pid, event.filetime, accumulator); if accumulator.stop_requested { break; } } - accumulator - .into_analysis() - .expect("pure denial accumulation cannot decode-fail") } /// Streams every decoded event in the ETL to `visitor` for schema discovery @@ -418,7 +610,8 @@ pub fn visit_raw_events( process_trace_file(source_path, &mut accumulator)?; if accumulator.processing_limit_reached { return Err(AnalyzeError::Decode(format!( - "trace exceeded the {MAX_PROCESSED_EVENTS}-event processing limit" + "trace exceeded the {MAX_PROCESSED_EVENTS}-event processing limit; \ + rerun a smaller workload or split it into multiple captureDenials runs" ))); } if let Some(error) = accumulator.decode_error { @@ -427,7 +620,7 @@ pub fn visit_raw_events( Ok(accumulator.raw_event_count) } -/// Builds a bounded decision vector for supported Learning Mode events in +/// Builds a bounded decision vector for known-provider Learning Mode events in /// source order. `ProcessTrace` normalizes each timestamp to FILETIME before /// the exact process-generation test, so Trace Relogger can replay these /// decisions without comparing its raw trace-clock timestamps. @@ -442,6 +635,7 @@ pub(crate) fn select_learning_mode_events_for_relogging( } Ok(RelogSelection { selected_event_indices: accumulator.relog_selected_event_indices, + selected_event_pids: accumulator.relog_selected_event_pids, total_event_count: accumulator.relog_event_count, }) } @@ -454,9 +648,6 @@ fn dedup_to_resources>(raws: I) -> AnalysisRes let mut accumulator = Accumulator::analyze(); for raw in raws { accumulator.add_raw_denial(raw); - if accumulator.stop_requested { - break; - } } accumulator .into_analysis() @@ -595,7 +786,7 @@ unsafe fn process_event_record(event_record: *mut EVENT_RECORD, acc: &mut Accumu let event_id = header.EventDescriptor.Id; if matches!(acc.mode, CollectionMode::SelectForRelogging) { - if !is_learning_mode_event(provider, event_id) { + if crate::extractors::verbose_logging_provider_for_guid(provider).is_none() { return; } let event_index = acc.relog_event_count; @@ -609,64 +800,259 @@ unsafe fn process_event_record(event_record: *mut EVENT_RECORD, acc: &mut Accumu let Some(filetime) = normalized_filetime(header.TimeStamp, acc) else { return; }; - if acc.in_analysis_scope(header.ProcessId, filetime) { - if acc.relog_selected_event_indices.len() >= MAX_PROCESSED_EVENTS { - acc.decode_error = Some(format!( - "trace exceeded the {MAX_PROCESSED_EVENTS}-event process-scoped relogging limit" - )); - acc.stop_requested = true; - return; - } - acc.relog_selected_event_indices.push(event_index); + if event_id == crate::extractors::CAPABILITY_DENIAL_EVENT_ID + && is_learning_mode_event(provider, event_id) + { + let process_id = unsafe { + tdh_decode::decode_event_property(event_record, &mut acc.schema_cache, "ProcessId") + }; + select_capability_decode_result_for_relogging( + acc, + event_index, + process_id, + header.ProcessId, + filetime, + ); + } else { + select_event_for_relogging(acc, event_index, header.ProcessId, filetime); } return; } - // Establish scope BEFORE charging the event against the shared processing - // budget. Provider, event id, PID and timestamp all live in the event - // header, so the scope test needs no (comparatively expensive) TDH decode. - // Out-of-scope host events — a foreign provider, or a PID/time outside the - // attested sandbox process lifetimes — must not consume the budget; - // otherwise a noisy host could exhaust the limit before a single in-scope - // sandbox denial is ever decoded, truncating the analysis of an innocent - // sandbox. + // Establish scope before charging the event against the shared processing + // budget. Brokered capability events are scoped after decoding their + // effective workload PID below; all other supported events can use the + // header PID directly. + let mut analyze_filetime = None; + if matches!(acc.mode, CollectionMode::Analyze) { - if !is_learning_mode_event(provider, event_id) { + let Some(category) = crate::extractors::verbose_logging_provider_for_guid(provider) else { + // Unrelated provider: unrelated host traffic, ignored entirely + // (not aggregated as an excluded Learning Mode outcome). return; - } + }; let Some(filetime) = normalized_filetime(header.TimeStamp, acc) else { return; }; - if !acc.in_analysis_scope(header.ProcessId, filetime) { - return; - } - if !acc.begin_event() { + analyze_filetime = Some(filetime); + if !is_learning_mode_event(provider, event_id) { + if !acc.event_in_scope(header.ProcessId, filetime) || !acc.begin_event() { + return; + } + // A known provider, but outside its supported event vocabulary: + // aggregate (as a signature with no decoded properties) without + // paying for a TDH decode. + acc.record_exclusion( + category, + event_id, + VerboseLoggingExclusionReason::UnsupportedEventSchema, + header.ProcessId, + Vec::new(), + ); return; } - match unsafe { tdh_decode::decode_event_parts(event_record, &mut acc.schema_cache) } { - Ok(parts) => { - if let Some(raw) = extract_denial(&parts, header.ProcessId, filetime) { - acc.add_raw_denial(raw); + } + + match unsafe { tdh_decode::decode_event_parts(event_record, &mut acc.schema_cache) } { + Ok(parts) => match acc.mode { + CollectionMode::Analyze => { + let filetime = analyze_filetime.expect("analyze mode has normalized FILETIME"); + handle_decoded_event(&parts, header.ProcessId, filetime, acc); + } + CollectionMode::Raw => { + if acc.begin_event() { + acc.visit_raw_event(&parts); } - for raw in - crate::capability_dacl::extract_denials(&parts, header.ProcessId, filetime) - { - acc.add_raw_denial(raw); + } + CollectionMode::SelectForRelogging => unreachable!("relogging returns before decode"), + }, + Err(error) => { + if matches!(acc.mode, CollectionMode::Analyze) { + if error.is_schema_error() { + acc.record_event_decode_error(provider, event_id, header.ProcessId, error); + return; } + let filetime = analyze_filetime.expect("analyze mode has normalized FILETIME"); + let pid = if event_id == crate::extractors::CAPABILITY_DENIAL_EVENT_ID { + let process_id = unsafe { + tdh_decode::decode_event_property( + event_record, + &mut acc.schema_cache, + "ProcessId", + ) + } + .ok() + .flatten(); + decode_error_effective_pid( + process_id.as_deref(), + header.ProcessId, + acc.event_in_scope(header.ProcessId, filetime), + ) + } else { + Some(header.ProcessId) + }; + let Some(pid) = pid else { + return; + }; + if !acc.event_in_scope(pid, filetime) || !acc.begin_event() { + return; + } + acc.record_event_decode_error(provider, event_id, pid, error); + return; + } else if !acc.begin_event() { + return; } - Err(error) => acc.record_event_decode_error(provider, event_id, error), + acc.record_event_decode_error(provider, event_id, header.ProcessId, error); + } + } +} + +fn decode_error_effective_pid( + process_id: Option<&str>, + header_pid: u32, + header_in_scope: bool, +) -> Option { + crate::extractors::effective_capability_event_pid(process_id) + .or_else(|| header_in_scope.then_some(header_pid)) +} + +fn select_capability_decode_result_for_relogging( + acc: &mut Accumulator<'_>, + event_index: usize, + process_id: Result, tdh_decode::DecodeError>, + header_pid: u32, + filetime: u64, +) { + match process_id { + Ok(process_id) => select_capability_event_for_relogging( + acc, + event_index, + process_id.as_deref(), + header_pid, + filetime, + ), + Err(error) if error.is_schema_error() => { + acc.decode_error = Some(format!( + "failed to decode brokered capability event while scoping guarded trace: {error}" + )); + acc.stop_requested = true; } + Err(_) => { + select_capability_event_for_relogging(acc, event_index, None, header_pid, filetime); + } + } +} + +fn select_capability_event_for_relogging( + acc: &mut Accumulator<'_>, + event_index: usize, + process_id: Option<&str>, + header_pid: u32, + filetime: u64, +) { + let Some(effective_pid) = crate::extractors::effective_capability_event_pid(process_id) else { + // The event cannot be attributed to a workload without its brokered + // payload PID. Retain it only when the emitter itself is in scope so + // the analysis pass can classify the malformed payload. + select_event_for_relogging(acc, event_index, header_pid, filetime); + return; + }; + select_event_for_relogging(acc, event_index, effective_pid, filetime); +} + +fn select_event_for_relogging( + acc: &mut Accumulator<'_>, + event_index: usize, + pid: u32, + filetime: u64, +) { + if !acc.event_in_scope(pid, filetime) { return; } + if acc.relog_selected_event_indices.len() >= MAX_PROCESSED_EVENTS { + acc.decode_error = Some(format!( + "trace exceeded the {MAX_PROCESSED_EVENTS}-event process-scoped relogging limit; \ + rerun a smaller workload or split it into multiple captureDenials runs" + )); + acc.stop_requested = true; + return; + } + acc.relog_selected_event_indices.push(event_index); + acc.relog_selected_event_pids.push(pid); +} - // Raw diagnostic mode has no provider/lifetime scoping, so every decoded - // event legitimately counts against the budget. - if !acc.begin_event() { +/// Extracts denials from one decoded, in-vocabulary event and feeds them +/// (or their closed exclusion reason) into `acc`. +/// +/// Re-checks the provider/event vocabulary so it stays a single source of +/// truth for both the real ETW path (which gates before decoding, above) +/// and pure-composition tests that hand this already-"decoded" fixtures. +fn handle_decoded_event( + parts: &DecodedEventParts, + header_pid: u32, + filetime: u64, + acc: &mut Accumulator<'_>, +) { + let Some(category) = crate::extractors::verbose_logging_provider_for_guid(parts.provider) + else { + return; + }; + if !is_learning_mode_event(parts.provider, parts.event_id) { + if acc.event_in_scope(header_pid, filetime) && acc.begin_event() { + acc.record_exclusion( + category, + parts.event_id, + VerboseLoggingExclusionReason::UnsupportedEventSchema, + header_pid, + crate::extractors::sanitize_properties(&parts.props), + ); + } return; } - match unsafe { tdh_decode::decode_event_parts(event_record, &mut acc.schema_cache) } { - Ok(parts) => acc.visit_raw_event(&parts), - Err(error) => acc.record_event_decode_error(provider, event_id, error), + let Some(pid) = crate::extractors::effective_event_pid(parts, header_pid) else { + if acc.event_in_scope(header_pid, filetime) && acc.begin_event() { + acc.record_outcome( + category, + parts.event_id, + VerboseLoggingExclusionReason::EventPayloadMalformed, + header_pid, + crate::extractors::verbose_logging_classification(parts), + crate::extractors::sanitize_properties(&parts.props), + ); + } + return; + }; + if !acc.event_in_scope(pid, filetime) || !acc.begin_event() { + return; + } + + let primary = extract_denial(parts, pid, filetime); + // Some permissive Event 14 capability checks leave `ObjectType` and + // `ObjectName` empty. `capability_dacl::KNOWN_CAPABILITIES` defines the + // capability names recoverable from ACE SIDs in the DACL payload. Each + // recovered candidate is fed independently, and the primary + // `UnresolvedCapability` outcome is counted only when none are recovered. + let capability_candidates = crate::capability_dacl::extract_denials(parts, pid, filetime); + for raw in capability_candidates.iter().cloned() { + acc.add_raw_denial(raw); + } + + match primary { + Ok(raw) => acc.add_raw_denial(raw), + Err(reason) => { + let recovered_by_dacl = reason == VerboseLoggingExclusionReason::UnresolvedCapability + && !capability_candidates.is_empty(); + if !recovered_by_dacl { + acc.record_outcome( + category, + parts.event_id, + reason, + pid, + crate::extractors::verbose_logging_classification(parts), + crate::extractors::sanitize_properties(&parts.props), + ); + } + } } } @@ -689,6 +1075,11 @@ mod tests { use super::*; use learning_mode_core::{AccessType, ResourceType}; + const SCOPED_PID: u32 = 42; + const SCOPED_START_FILETIME: u64 = 100; + const SCOPED_END_FILETIME: u64 = 200; + const SCOPED_EVENT_FILETIME: u64 = 150; + #[test] fn process_lifetime_index_matches_pid_and_merged_time_ranges() { let index = ProcessLifetimeIndex::new(&[ @@ -731,7 +1122,7 @@ mod tests { } #[test] - fn relog_selection_tracks_supported_event_ordinals_and_exact_lifetimes() { + fn relog_selection_tracks_known_provider_ordinals_and_exact_lifetimes() { let mut accumulator = Accumulator::select_for_relogging(&[ProcessLifetime { pid: 42, start_filetime: 100, @@ -739,9 +1130,8 @@ mod tests { }]); let mut visit = |provider, event_id, pid, filetime| { - // SAFETY: this zeroed record is used only by selection mode, which - // reads the initialized POD header fields below and never decodes - // payload pointers. + // SAFETY: these fixtures avoid the brokered capability event, so + // selection reads only the initialized POD header fields below. let mut record: EVENT_RECORD = unsafe { core::mem::zeroed() }; record.EventHeader.ProviderId = provider; record.EventHeader.EventDescriptor.Id = event_id; @@ -754,7 +1144,7 @@ mod tests { visit(crate::extractors::KERNEL_GENERAL_PROVIDER, 14, 42, 100); visit(windows::core::GUID::from_u128(1), 14, 42, 150); visit(crate::extractors::KERNEL_GENERAL_PROVIDER, 27, 42, 201); - visit(crate::extractors::KERNEL_GENERAL_PROVIDER, 28, 42, 200); + visit(crate::extractors::KERNEL_GENERAL_PROVIDER, 999, 42, 200); visit(crate::extractors::KERNEL_GENERAL_PROVIDER, 14, 43, 150); assert_eq!(accumulator.relog_event_count, 4); @@ -762,6 +1152,135 @@ mod tests { assert!(accumulator.decode_error.is_none()); } + #[test] + fn relog_selection_scopes_brokered_capability_events_by_payload_pid() { + let mut accumulator = Accumulator::select_for_relogging(&[ProcessLifetime { + pid: 42, + start_filetime: 100, + end_filetime: 200, + }]); + select_capability_event_for_relogging(&mut accumulator, 0, Some("42"), 9000, 150); + + assert_eq!(accumulator.relog_selected_event_indices, [0]); + } + + #[test] + fn relog_selection_skips_unscopable_brokered_capability_without_payload_pid() { + let mut accumulator = Accumulator::select_for_relogging(&[ProcessLifetime { + pid: 42, + start_filetime: 100, + end_filetime: 200, + }]); + select_capability_event_for_relogging(&mut accumulator, 0, None, 9000, 150); + + assert!(accumulator.relog_selected_event_indices.is_empty()); + assert!(!accumulator.stop_requested); + assert!(accumulator.decode_error.is_none()); + } + + #[test] + fn relog_selection_retains_malformed_capability_from_in_scope_emitter() { + let mut accumulator = Accumulator::select_for_relogging(&[ProcessLifetime { + pid: 42, + start_filetime: 100, + end_filetime: 200, + }]); + select_capability_event_for_relogging(&mut accumulator, 0, None, 42, 150); + + assert_eq!(accumulator.relog_selected_event_indices, [0]); + } + + #[test] + fn scoped_analysis_classifies_malformed_capability_from_in_scope_emitter() { + let mut accumulator = Accumulator::analyze_for_process_lifetimes(&[ProcessLifetime { + pid: SCOPED_PID, + start_filetime: SCOPED_START_FILETIME, + end_filetime: SCOPED_END_FILETIME, + }]); + let parts = DecodedEventParts { + provider: crate::extractors::KERNEL_GENERAL_PROVIDER, + event_id: crate::extractors::CAPABILITY_DENIAL_EVENT_ID, + props: Vec::new(), + }; + + handle_decoded_event(&parts, SCOPED_PID, SCOPED_EVENT_FILETIME, &mut accumulator); + let analysis = accumulator.into_analysis().unwrap(); + + assert_eq!( + find_signature( + &analysis.verbose_logging, + crate::extractors::CAPABILITY_DENIAL_EVENT_ID + ) + .signature + .reason, + VerboseLoggingExclusionReason::EventPayloadMalformed + ); + } + + #[test] + fn relog_selection_skips_payload_decode_failure_from_unrelated_emitter() { + let mut accumulator = Accumulator::select_for_relogging(&[ProcessLifetime { + pid: 42, + start_filetime: 100, + end_filetime: 200, + }]); + let error = tdh_decode::DecodeError::event( + tdh_decode::EventDecodeKind::PayloadMalformed, + "truncated ProcessId".to_string(), + None, + ); + + select_capability_decode_result_for_relogging(&mut accumulator, 0, Err(error), 9000, 150); + + assert!(accumulator.relog_selected_event_indices.is_empty()); + assert!(!accumulator.stop_requested); + assert!(accumulator.decode_error.is_none()); + } + + #[test] + fn relog_selection_stops_on_capability_schema_failure() { + let mut accumulator = Accumulator::select_for_relogging(&[ProcessLifetime { + pid: 42, + start_filetime: 100, + end_filetime: 200, + }]); + + select_capability_decode_result_for_relogging( + &mut accumulator, + 0, + Err(tdh_decode::DecodeError::Schema( + "manifest unavailable".to_string(), + )), + 9000, + 150, + ); + + assert!(accumulator.relog_selected_event_indices.is_empty()); + assert!(accumulator.stop_requested); + assert!(accumulator + .decode_error + .as_deref() + .is_some_and(|error| error.contains("manifest unavailable"))); + } + + #[test] + fn capability_decode_error_prefers_payload_pid_and_fails_closed_without_scope() { + assert_eq!( + decode_error_effective_pid(Some("42"), 9000, false), + Some(42) + ); + assert_eq!( + decode_error_effective_pid(Some("\"broker\""), 42, true), + Some(42) + ); + assert_eq!( + decode_error_effective_pid(Some("\"broker\""), 9000, false), + None + ); + assert_eq!(decode_error_effective_pid(None, 42, true), Some(42)); + assert_eq!(decode_error_effective_pid(None, 9000, false), None); + } + #[test] fn raw_visitor_panic_is_captured_inside_callback_state() { let mut visitor = @@ -794,7 +1313,12 @@ mod tests { accumulator.record_event_decode_error( windows::core::GUID::from_u128(1), 14, - tdh_decode::DecodeError::Event("malformed property".to_string()), + 1, + tdh_decode::DecodeError::event( + tdh_decode::EventDecodeKind::PayloadMalformed, + "malformed property".to_string(), + None, + ), ); assert!(accumulator.into_analysis().is_ok()); @@ -807,7 +1331,12 @@ mod tests { accumulator.record_event_decode_error( windows::core::GUID::from_u128(1), 14, - tdh_decode::DecodeError::Event("malformed property".to_string()), + 1, + tdh_decode::DecodeError::event( + tdh_decode::EventDecodeKind::PayloadMalformed, + "malformed property".to_string(), + None, + ), ); let error = accumulator.decode_error.as_deref().unwrap(); @@ -821,6 +1350,7 @@ mod tests { accumulator.record_event_decode_error( windows::core::GUID::from_u128(1), 14, + 1, tdh_decode::DecodeError::Schema("manifest unavailable".to_string()), ); @@ -836,6 +1366,9 @@ mod tests { access_type: access, filetime: 1, event_id: 4907, + provider: + learning_mode_core::VerboseLoggingProvider::PrivacyAuditingPermissiveLearningMode, + verbose_logging_properties: Vec::new(), } } @@ -888,10 +1421,30 @@ mod tests { ), ]; - let out = dedup_to_resources(denials).denials; + let analysis = dedup_to_resources(denials); - assert_eq!(out.len(), 1); - assert_eq!(out[0].resource, r"\\server\share\file.txt"); + assert_eq!( + analysis + .denials + .first() + .map(|denial| denial.resource.as_str()), + Some(r"\\server\share\file.txt") + ); + let excluded = analysis + .verbose_logging + .signatures + .iter() + .filter(|group| { + group.signature.reason == VerboseLoggingExclusionReason::UnusableResourcePath + }) + .collect::>(); + assert_eq!(excluded.len(), 1); + assert!(excluded.iter().all(|group| { + group.signature.access_type == Some(AccessType::Read) + && group.signature.resource_type == Some(ResourceType::File) + && group.count == 4 + })); + assert_eq!(property(&excluded[0].signature, "resource"), ""); } #[test] @@ -920,7 +1473,25 @@ mod tests { } #[test] - fn unique_denial_bound_requests_trace_stop() { + fn unique_denial_bound_marks_truncated_without_stopping() { + fn exclusion_count( + summary: &learning_mode_core::VerboseLoggingSummary, + provider: learning_mode_core::VerboseLoggingProvider, + event_id: u16, + reason: VerboseLoggingExclusionReason, + ) -> u64 { + summary + .signatures + .iter() + .filter(|group| { + group.signature.provider == provider + && group.signature.event_id == event_id + && group.signature.reason == reason + }) + .map(|group| group.count) + .sum() + } + let mut accumulator = Accumulator::analyze(); accumulator.denials = (0..MAX_UNIQUE_DENIALS) .map(|index| DeniedResource { @@ -931,6 +1502,9 @@ mod tests { filetime: 1, }) .collect(); + accumulator.seen = (0..MAX_UNIQUE_DENIALS) + .map(|index| (format!(r"c:\data\{index}.txt"), AccessType::Read)) + .collect(); accumulator.add_raw_denial(raw( r"C:\data\overflow.txt", @@ -938,8 +1512,42 @@ mod tests { ResourceType::File, )); - assert!(accumulator.stop_requested); + assert!( + !accumulator.stop_requested, + "hitting the unique-denial cap must not halt the trace early" + ); assert!(accumulator.truncated); + assert!(accumulator.verbose_logging.canonical_denial_limit_reached); + assert_eq!( + exclusion_count( + &accumulator.verbose_logging, + learning_mode_core::VerboseLoggingProvider::PrivacyAuditingPermissiveLearningMode, + 4907, + VerboseLoggingExclusionReason::CanonicalDenial + ), + 1 + ); + + // Processing continues past the cap: a further overflow candidate is + // still aggregated (not silently discarded), and a duplicate of an + // already-canonical denial retains the same canonical classification. + accumulator.add_raw_denial(raw( + r"C:\data\overflow-2.txt", + AccessType::Read, + ResourceType::File, + )); + accumulator.add_raw_denial(raw(r"C:\data\0.txt", AccessType::Read, ResourceType::File)); + + assert!(!accumulator.stop_requested); + assert_eq!( + exclusion_count( + &accumulator.verbose_logging, + learning_mode_core::VerboseLoggingProvider::PrivacyAuditingPermissiveLearningMode, + 4907, + VerboseLoggingExclusionReason::CanonicalDenial + ), + 3 + ); } #[test] @@ -959,23 +1567,45 @@ mod tests { #[test] fn out_of_scope_events_are_excluded_before_consuming_the_budget() { - // Lifetime scoping gates the shared processing budget: an event whose - // PID/time falls outside the attested sandbox lifetimes is not in - // scope, so `process_event_record` skips it before ever calling - // `begin_event`. This asserts the scope predicate that drives that - // early return; legacy (no-lifetime) analysis treats everything as in - // scope. - let scoped = Accumulator::analyze_for_process_lifetimes(&[ProcessLifetime { + let lifetimes = [ProcessLifetime { pid: 7, start_filetime: 100, end_filetime: 200, - }]); - assert!(scoped.in_analysis_scope(7, 150)); - assert!(!scoped.in_analysis_scope(7, 250), "outside the time range"); - assert!(!scoped.in_analysis_scope(9, 150), "unrelated PID"); + }]; + let events = [ + kernel_event( + 14, + 9, + 150, + &[ + ("ObjectType", "\"File\""), + ("ObjectName", "\"C:\\unrelated.txt\""), + ("AccessMask", "0x1"), + ], + ), + kernel_event( + 14, + 7, + 150, + &[ + ("ObjectType", "\"File\""), + ("ObjectName", "\"C:\\owned.txt\""), + ("AccessMask", "0x1"), + ], + ), + ]; + let mut accumulator = Accumulator { + processed_event_count: MAX_PROCESSED_EVENTS - 1, + ..Accumulator::analyze_for_process_lifetimes(&lifetimes) + }; - let legacy = Accumulator::analyze(); - assert!(legacy.in_analysis_scope(9, 150), "no lifetime filter"); + accumulate_collected_events(&events, &mut accumulator); + + assert_eq!(accumulator.processed_event_count, MAX_PROCESSED_EVENTS); + assert!(!accumulator.processing_limit_reached); + assert!(!accumulator.stop_requested); + assert_eq!(accumulator.denials.len(), 1); + assert_eq!(accumulator.denials[0].resource, r"C:\owned.txt"); } #[test] @@ -1123,7 +1753,8 @@ mod tests { /// empty-`ObjectType` event 14 (there is no event 28 in this mode). #[test] fn allow_shape_recovers_capability_from_dacl() { - // DWORD-padded allow ACE carrying S-1-15-3-1 (internetClient). + // DWORD-padded allow ACE containing the decimal SID S-1-15-3-1 + // (`internetClient`). let dacl = "hex:000000000000000001000000010200000000000F0300000001000000"; let events = vec![ permissive_event( @@ -1182,7 +1813,38 @@ mod tests { kernel_event(28, 0, 2, &[("ProcessId", "0x10"), ("Denied", "true")]), kernel_event(28, 0, 3, &[("ProcessId", "0x20"), ("Denied", "true")]), ]; - assert!(resources_from_events(&events).denials.is_empty()); + let out = resources_from_events(&events); + assert!(out.denials.is_empty()); + + // Every dropped candidate is still aggregated by closed reason, never + // by raw payload: one unresolved access-check event (14) plus two + // unresolved capability denials (28). The two event-28 signatures stay + // distinct because their retained ProcessId properties differ. + let groups = &out.verbose_logging.signatures; + assert_eq!(groups.len(), 3); + let event_14_group = groups + .iter() + .find(|group| group.signature.event_id == 14) + .expect("event 14 exclusion group present"); + assert_eq!( + event_14_group.signature.provider, + VerboseLoggingProvider::KernelGeneral + ); + assert_eq!( + event_14_group.signature.reason, + VerboseLoggingExclusionReason::UnresolvedCapability + ); + assert_eq!(event_14_group.count, 1); + let event_28_groups = groups + .iter() + .filter(|group| group.signature.event_id == 28) + .collect::>(); + assert_eq!(event_28_groups.len(), 2); + assert!(event_28_groups.iter().all(|group| { + group.signature.provider == VerboseLoggingProvider::KernelGeneral + && group.signature.reason == VerboseLoggingExclusionReason::UnresolvedCapability + && group.count == 1 + })); } #[test] @@ -1198,6 +1860,8 @@ mod tests { ("AccessMask", "0x1"), ], ), + kernel_event(9999, 43, 150, &[("Marker", "\"host\"")]), + kernel_event(9999, 42, 151, &[("Marker", "\"owned\"")]), kernel_event( 14, 42, @@ -1239,6 +1903,58 @@ mod tests { assert_eq!(analysis.denials.len(), 1); assert_eq!(analysis.denials[0].resource, r"C:\owned.txt"); + assert_eq!(analysis.verbose_logging.signatures.len(), 2); + assert!(analysis + .verbose_logging + .signatures + .iter() + .all(|group| group.signature.pid == 42)); + let unsupported = analysis + .verbose_logging + .signatures + .iter() + .find(|group| { + group.signature.reason == VerboseLoggingExclusionReason::UnsupportedEventSchema + }) + .expect("owned unknown event retained"); + assert_eq!(property(&unsupported.signature, "Marker"), "owned"); + } + + #[test] + fn brokered_capability_uses_payload_pid_for_process_scope() { + let events = vec![kernel_event( + 28, + 900, + 150, + &[ + ("Denied", "\"true\""), + ("ProcessId", "0x2a"), + ("CapabilityName", "\"internetClient\""), + ], + )]; + let lifetimes = [ProcessLifetime { + pid: 42, + start_filetime: 100, + end_filetime: 200, + }]; + + let analysis = resources_from_events_for_process_lifetimes(&events, Some(&lifetimes)); + + assert_eq!(analysis.denials.len(), 1); + assert_eq!(analysis.denials[0].pid, 42); + assert_eq!(analysis.denials[0].resource, "internetClient"); + let group = analysis + .verbose_logging + .signatures + .iter() + .find(|group| group.signature.reason == VerboseLoggingExclusionReason::CanonicalDenial) + .expect("canonical capability event retained"); + assert_eq!(group.signature.pid, 42); + assert_eq!(group.signature.access_type, Some(AccessType::Unknown)); + assert_eq!( + group.signature.resource_type, + Some(ResourceType::Capability) + ); } #[test] @@ -1257,18 +1973,227 @@ mod tests { let analysis = resources_from_events_for_process_lifetimes(&events, Some(&[])); assert!(analysis.denials.is_empty()); + assert!(analysis.verbose_logging.is_empty()); } /// Non-actionable object types and not-denied capability records are - /// dropped by the pipeline; unknown event IDs are ignored. + /// dropped by the pipeline as closed extraction reasons; an unknown event + /// ID from a known provider is classified `UnsupportedEventSchema` + /// without ever reaching TDH-decoded extraction logic. #[test] fn non_actionable_events_are_dropped() { let events = vec![ - kernel_event(14, 1, 1, &[("ObjectType", "\"Section\"")]), + kernel_event(14, 1, 1, &[("ObjectType", "\"Process\"")]), kernel_event(28, 0, 2, &[("ProcessId", "0x10"), ("Denied", "false")]), kernel_event(9999, 1, 3, &[("Foo", "\"bar\"")]), ]; - assert!(resources_from_events(&events).denials.is_empty()); + let out = resources_from_events(&events); + assert!(out.denials.is_empty()); + + let reason_for = |event_id: u16| { + out.verbose_logging + .signatures + .iter() + .find(|group| group.signature.event_id == event_id) + .map(|group| group.signature.reason) + }; + assert_eq!( + reason_for(14), + Some(VerboseLoggingExclusionReason::UnsupportedObjectType) + ); + assert_eq!( + reason_for(28), + Some(VerboseLoggingExclusionReason::NotActionable) + ); + assert_eq!( + reason_for(9999), + Some(VerboseLoggingExclusionReason::UnsupportedEventSchema) + ); + } + + #[test] + fn device_namespace_file_is_retained_as_unusable_resource_path() { + let events = vec![kernel_event( + 14, + 1996, + 134_309_021_955_593_414, + &[ + ("Mode", "\"Permissive\""), + ("ObjectType", "\"File\""), + ("ObjectName", "\"\\Device\\MountPointManager\""), + ("AccessMask", "0x100080"), + ], + )]; + + let out = resources_from_events(&events); + + assert!(out.denials.is_empty()); + assert_eq!(out.verbose_logging.signatures.len(), 1); + let group = &out.verbose_logging.signatures[0]; + assert_eq!(group.count, 1); + assert_eq!( + group.signature.provider, + VerboseLoggingProvider::KernelGeneral + ); + assert_eq!( + group.signature.provider_guid, + "{A68CA8B7-004F-D7B6-A698-07E2DE0F1F5D}" + ); + assert_eq!(group.signature.event_id, 14); + assert_eq!( + group.signature.reason, + VerboseLoggingExclusionReason::UnusableResourcePath + ); + assert_eq!(group.signature.pid, 1996); + assert_eq!(group.signature.access_type, Some(AccessType::Read)); + assert_eq!(group.signature.resource_type, Some(ResourceType::File)); + assert_eq!(property(&group.signature, "ObjectName"), ""); + } + + #[test] + fn output_gap_object_types_are_individually_retained() { + let cases = [ + ("Directory", r"\BaseNamedObjects"), + ( + "ALPC Port", + r"\Sessions\1\AppContainerNamedObjects\S-1-15-2-1\RPC Control\ubpmtaskhostchannel", + ), + ("RPC Interface", "f6beaff7-1e19-4fbb-9f8f-b89e2018337c"), + ]; + let events = cases + .iter() + .enumerate() + .map(|(index, (object_type, object_name))| CollectedEvent { + pid: 42, + filetime: index as u64 + 1, + parts: DecodedEventParts { + provider: crate::extractors::KERNEL_GENERAL_PROVIDER, + event_id: 14, + props: vec![ + ("Mode".to_string(), "\"Permissive\"".to_string()), + ("ObjectType".to_string(), format!("\"{object_type}\"")), + ("ObjectName".to_string(), format!("\"{object_name}\"")), + ("AccessMask".to_string(), "0x1".to_string()), + ], + }, + }) + .collect::>(); + + let out = resources_from_events(&events); + + assert!(out.denials.is_empty()); + assert_eq!(out.verbose_logging.signatures.len(), cases.len()); + for (object_type, object_name) in cases { + let group = out + .verbose_logging + .signatures + .iter() + .find(|group| property(&group.signature, "ObjectType") == object_type) + .unwrap_or_else(|| panic!("missing verbose logging signature for {object_type}")); + assert_eq!( + group.signature.reason, + VerboseLoggingExclusionReason::UnsupportedObjectType + ); + assert_eq!(property(&group.signature, "ObjectName"), object_name); + assert_eq!(group.count, 1); + } + } + + #[test] + fn long_section_names_with_shared_prefix_remain_distinct() { + let prefix = format!( + r"\Sessions\1\AppContainerNamedObjects\S-1-15-2-{}\C:*ProgramData*Microsoft*Windows*Caches*", + "1-".repeat(100) + ); + let names = [ + format!("{prefix}{{6AF0698E-D558-4F6E-9B3C-3716689AF493}}.db"), + format!("{prefix}{{DDF571F2-BE98-426D-8288-1A9A39C3FDA2}}.db"), + format!("{prefix}cversions.2.ro"), + ]; + let events = names + .iter() + .enumerate() + .map(|(index, object_name)| CollectedEvent { + pid: 42, + filetime: index as u64 + 1, + parts: DecodedEventParts { + provider: crate::extractors::KERNEL_GENERAL_PROVIDER, + event_id: 14, + props: vec![ + ("ObjectType".to_string(), "\"Section\"".to_string()), + ("ObjectName".to_string(), format!("\"{object_name}\"")), + ("AccessMask".to_string(), "0x6".to_string()), + ], + }, + }) + .collect::>(); + + let out = resources_from_events(&events); + + assert_eq!(out.denials.len(), names.len()); + assert!(out.denials.iter().all(|denial| { + denial.resource_type == ResourceType::Other + && denial.access_type == AccessType::Write + && names.contains(&denial.resource) + })); + assert_eq!(out.verbose_logging.signatures.len(), names.len()); + assert!(out.verbose_logging.signatures.iter().all(|group| { + group.signature.reason == VerboseLoggingExclusionReason::CanonicalDenial + && group.count == 1 + && property(&group.signature, "ObjectName").contains("" + ); + assert_eq!( + property(&canonical_group.signature, "UserName"), + "" + ); + } + + #[test] + fn processing_continues_past_the_unique_denial_cap_through_the_full_pipeline() { + let overflow_candidates = 5usize; + let events: Vec = (0..MAX_UNIQUE_DENIALS + overflow_candidates) + .map(|index| { + kernel_event( + 14, + 1, + index as u64, + &[ + ("ObjectType", "\"File\""), + ("ObjectName", &format!("\"C:\\data\\{index}.txt\"")), + ("AccessMask", "0x1"), + ], + ) + }) + .collect(); + + let out = resources_from_events(&events); + + assert_eq!(out.denials.len(), MAX_UNIQUE_DENIALS); + assert!(out.denied_resources_truncated); + assert!(out.verbose_logging.canonical_denial_limit_reached); + assert!(!out.verbose_logging.processed_events_truncated); + + // If the trace had stopped as soon as the cap was reached, only the + // The verbose logging accounts for every denial candidate, including those + // observed after the canonical unique-denial cap. + assert_eq!( + out.verbose_logging.total_occurrences, + (MAX_UNIQUE_DENIALS + overflow_candidates) as u64 + ); + } + + #[test] + fn capability_denial_recovered_from_dacl_records_no_exclusion() { + // Same shape as `allow_shape_recovers_capability_from_dacl`, but + // asserting the verbose logging side: a successfully DACL-recovered + // capability candidate must not also surface an `UnresolvedCapability` + // exclusion for the same event. + let dacl = "hex:000000000000000001000000010200000000000F0300000001000000"; + let events = vec![permissive_event( + 14, + 5900, + 21, + &[ + ("Mode", "\"Permissive\""), + ("ObjectType", "\"\""), + ("ObjectName", "\"\""), + ("AccessMask", "0x1"), + ("Dacl", dacl), + ], + )]; + + let out = resources_from_events(&events); + assert_eq!(out.denials.len(), 1); + assert_eq!(out.denials[0].resource, "internetClient"); + assert_eq!(out.verbose_logging.signatures.len(), 1); + let signature = &out.verbose_logging.signatures[0].signature; + assert_eq!( + signature.reason, + VerboseLoggingExclusionReason::CanonicalDenial + ); + assert_eq!(signature.access_type, Some(AccessType::Unknown)); + assert_eq!(signature.resource_type, Some(ResourceType::Capability)); + } + + fn find_signature( + summary: &learning_mode_core::VerboseLoggingSummary, + event_id: u16, + ) -> &learning_mode_core::VerboseLoggingAggregate { + summary + .signatures + .iter() + .find(|group| group.signature.event_id == event_id) + .unwrap_or_else(|| panic!("expected a verbose logging signature for event {event_id}")) + } + + fn property<'a>( + signature: &'a learning_mode_core::VerboseLoggingSignature, + name: &str, + ) -> &'a str { + signature + .properties + .iter() + .find(|(key, _)| key == name) + .unwrap_or_else(|| panic!("expected property {name:?} in signature {signature:?}")) + .1 + .as_str() + } + + #[test] + fn verbose_logging_byte_budget_preserves_guarded_protocol_headroom() { + let mut accumulator = Accumulator::analyze(); + let properties = (0..crate::extractors::MAX_SIGNATURE_PROPERTIES) + .map(|index| { + ( + format!("Property{index:02}"), + "x".repeat(crate::extractors::MAX_SIGNATURE_VALUE_LEN), + ) + }) + .collect::>(); + for pid in 0..learning_mode_core::MAX_VERBOSE_LOGGING_GROUPS as u32 { + accumulator.record_exclusion( + VerboseLoggingProvider::KernelGeneral, + 14, + VerboseLoggingExclusionReason::CanonicalDenial, + pid, + properties.clone(), + ); + } + + assert!(accumulator.verbose_logging.aggregate_groups_truncated); + assert!(accumulator.verbose_logging.overflow_occurrences > 0); + assert!(accumulator.verbose_logging_signature_bytes <= MAX_VERBOSE_LOGGING_SIGNATURE_BYTES); + } + + #[test] + fn unknown_event_id_signature_redacts_the_entire_file_path() { + let events = vec![kernel_event( + 9999, + 7, + 1, + &[("ObjectName", "\"C:\\Users\\jsmith\\secret.txt\"")], + )]; + + let out = resources_from_events(&events); + + let group = find_signature(&out.verbose_logging, 9999); + assert_eq!( + group.signature.reason, + VerboseLoggingExclusionReason::UnsupportedEventSchema + ); + assert_eq!( + property(&group.signature, "ObjectName"), + "", + "no part of the path may survive redaction" + ); + } + + #[test] + fn unresolved_capability_signature_retains_sid_pid_and_provider_guid() { + let events = vec![kernel_event( + 28, + 42, + 1, + &[ + ("ProcessId", "0x2A"), + ("Denied", "true"), + ("CandidateSid", "\"S-1-15-3-1\""), + ], + )]; + + let out = resources_from_events(&events); + + let group = find_signature(&out.verbose_logging, 28); + assert_eq!( + group.signature.reason, + VerboseLoggingExclusionReason::UnresolvedCapability + ); + assert_eq!( + group.signature.provider, + VerboseLoggingProvider::KernelGeneral + ); + assert_eq!( + group.signature.provider_guid, + crate::extractors::verbose_logging_provider_guid(VerboseLoggingProvider::KernelGeneral) + ); + assert_eq!(group.signature.pid, 42, "process identifier retained"); + assert_eq!( + property(&group.signature, "CandidateSid"), + "S-1-15-3-1", + "capability SIDs are retained identifiers, never redacted" + ); + } + + #[test] + fn signatures_with_identical_properties_dedupe_across_differing_timestamps() { + // Same event id/pid/properties, only `filetime` differs: the + // signature must exclude the exact timestamp so both collapse into + // one group with an incremented count, rather than two singletons. + let events = vec![ + kernel_event(9999, 7, 10, &[("Foo", "\"bar\"")]), + kernel_event(9999, 7, 20_000_000, &[("Foo", "\"bar\"")]), + ]; + + let out = resources_from_events(&events); + + assert_eq!( + out.verbose_logging.signatures.len(), + 1, + "differing only by timestamp must dedupe to a single signature" + ); + assert_eq!(find_signature(&out.verbose_logging, 9999).count, 2); + } + + #[test] + fn timestamp_like_properties_are_excluded_from_the_signature() { + let events = vec![kernel_event( + 9999, + 7, + 1, + &[ + ("Foo", "\"bar\""), + ("LastWriteTime", "\"132847890123456789\""), + ], + )]; + + let out = resources_from_events(&events); + + let group = find_signature(&out.verbose_logging, 9999); + assert!( + group + .signature + .properties + .iter() + .all(|(name, _)| !name.to_ascii_lowercase().contains("time")), + "timestamp-like properties must never reach the signature: {:?}", + group.signature.properties + ); + } + + #[test] + fn event_decode_failures_use_closed_reasons_and_schema_names() { + let mut accumulator = Accumulator::analyze(); + accumulator.record_event_decode_error( + crate::extractors::KERNEL_GENERAL_PROVIDER, + 14, + 9, + tdh_decode::DecodeError::event( + tdh_decode::EventDecodeKind::PayloadMalformed, + "property payload is malformed".to_string(), + Some("AccessCheck".to_string()), + ), + ); + accumulator.record_event_decode_error( + crate::extractors::KERNEL_GENERAL_PROVIDER, + 27, + 10, + tdh_decode::DecodeError::event( + tdh_decode::EventDecodeKind::DecoderLimitReached, + "property decode work exceeds limit 100000".to_string(), + Some("LearningModeViolation".to_string()), + ), + ); + accumulator.record_event_decode_error( + crate::extractors::KERNEL_GENERAL_PROVIDER, + 28, + 11, + tdh_decode::DecodeError::event( + tdh_decode::EventDecodeKind::UnsupportedPropertyEncoding, + "property has unsupported variable length".to_string(), + Some("CapabilityDenial".to_string()), + ), + ); + let out = accumulator + .into_analysis() + .expect("per-event decode failures are non-fatal in Analyze mode"); + + let malformed = find_signature(&out.verbose_logging, 14); + assert_eq!( + malformed.signature.reason, + VerboseLoggingExclusionReason::EventPayloadMalformed + ); + assert_eq!(malformed.signature.pid, 9); + assert_eq!(property(&malformed.signature, "EventName"), "AccessCheck"); + assert_eq!( + find_signature(&out.verbose_logging, 27).signature.reason, + VerboseLoggingExclusionReason::DecoderLimitReached + ); + assert_eq!( + find_signature(&out.verbose_logging, 28).signature.reason, + VerboseLoggingExclusionReason::UnsupportedPropertyEncoding + ); + assert_eq!( + find_signature(&out.verbose_logging, 28) + .signature + .resource_type, + Some(ResourceType::Capability) + ); + assert!(out.verbose_logging.signatures.iter().all(|aggregate| { + aggregate + .signature + .properties + .iter() + .all(|(name, _)| name == "EventName") + })); + } + + #[test] + fn event_28_decode_failure_classification_requires_a_known_schema_name() { + let analyze = |event_name: Option<&str>| { + let mut accumulator = Accumulator::analyze(); + accumulator.record_event_decode_error( + crate::extractors::KERNEL_GENERAL_PROVIDER, + 28, + 11, + tdh_decode::DecodeError::event( + tdh_decode::EventDecodeKind::PayloadMalformed, + "property payload is malformed".to_string(), + event_name.map(str::to_string), + ), + ); + accumulator.into_analysis().unwrap() + }; + + assert_eq!( + find_signature(&analyze(Some("CapabilityDenial")).verbose_logging, 28) + .signature + .resource_type, + Some(ResourceType::Capability) + ); + assert_eq!( + find_signature(&analyze(Some("LearningModeViolation")).verbose_logging, 28) + .signature + .resource_type, + Some(ResourceType::Ui) + ); + assert_eq!( + find_signature(&analyze(Some("UnknownEvent28")).verbose_logging, 28) + .signature + .resource_type, + None + ); + assert_eq!( + find_signature(&analyze(None).verbose_logging, 28) + .signature + .resource_type, + None + ); } } diff --git a/src/backends/learning_mode/windows/src/etl_filter.rs b/src/backends/learning_mode/windows/src/etl_filter.rs index bba17b9f2..1c61e2b90 100644 --- a/src/backends/learning_mode/windows/src/etl_filter.rs +++ b/src/backends/learning_mode/windows/src/etl_filter.rs @@ -7,7 +7,7 @@ use std::collections::HashSet; use std::os::windows::ffi::OsStrExt; use std::path::Path; use std::sync::atomic::{AtomicUsize, Ordering}; -use std::sync::Arc; +use std::sync::{Arc, Mutex}; use learning_mode_core::{AnalyzeError, ProcessLifetime}; use windows::core::{implement, Ref, BSTR}; @@ -19,8 +19,9 @@ use windows::Win32::System::Diagnostics::Etw::{ }; use crate::etl_decode::select_learning_mode_events_for_relogging; -use crate::extractors::is_learning_mode_event; +use crate::extractors::{is_learning_mode_event, verbose_logging_provider_for_guid}; use crate::process_lifetime::{attested_process_lifetimes, JobMembershipSnapshot}; +use crate::tdh_decode; const RPC_E_CHANGED_MODE: u32 = 0x8001_0106; @@ -56,20 +57,28 @@ impl Drop for ComApartment { #[implement(ITraceEventCallback)] struct ProcessScopedTraceFilter { selection: RelogSelectionState, + schema_cache: Mutex, } #[derive(Clone)] struct RelogSelectionState { selected_event_indices: Arc<[usize]>, + selected_event_pids: Arc<[u32]>, attested_pids: Arc>, event_cursor: Arc, selected_event_cursor: Arc, } impl RelogSelectionState { - fn new(selected_event_indices: Vec, process_lifetimes: &[ProcessLifetime]) -> Self { + fn new( + selected_event_indices: Vec, + selected_event_pids: Vec, + process_lifetimes: &[ProcessLifetime], + ) -> Self { + debug_assert_eq!(selected_event_indices.len(), selected_event_pids.len()); Self { selected_event_indices: selected_event_indices.into(), + selected_event_pids: selected_event_pids.into(), attested_pids: Arc::new( process_lifetimes .iter() @@ -81,7 +90,7 @@ impl RelogSelectionState { } } - fn observe_supported_event(&self, pid: u32) -> bool { + fn observe_known_provider_event(&self, pid: u32) -> bool { let event_index = self.event_cursor.fetch_add(1, Ordering::Relaxed); let selected_index = self.selected_event_cursor.load(Ordering::Relaxed); if self.selected_event_indices.get(selected_index) != Some(&event_index) { @@ -92,9 +101,11 @@ impl RelogSelectionState { // lifetime bounds. Revalidate the second pass's current PID before // injection so a different equal-timestamp ordering cannot substitute // a foreign process's event at the same ordinal. Do not advance the - // selected cursor on mismatch: the final count reconciliation then + // selected-event index on mismatch: the final count reconciliation then // fails closed and the partial destination is deleted. - if !self.attested_pids.contains(&pid) { + if self.selected_event_pids.get(selected_index) != Some(&pid) + || !self.attested_pids.contains(&pid) + { return false; } @@ -145,10 +156,34 @@ impl ITraceEventCallback_Impl for ProcessScopedTraceFilter_Impl { )); }; let header = &record.EventHeader; - if !is_learning_mode_event(header.ProviderId, header.EventDescriptor.Id) { + if verbose_logging_provider_for_guid(header.ProviderId).is_none() { return Ok(()); } - if self.selection.observe_supported_event(header.ProcessId) { + let is_supported_capability_event = header.EventDescriptor.Id + == crate::extractors::CAPABILITY_DENIAL_EVENT_ID + && is_learning_mode_event(header.ProviderId, header.EventDescriptor.Id); + let effective_pid = if is_supported_capability_event { + let payload_pid = self + .schema_cache + .lock() + .ok() + .and_then(|mut cache| unsafe { + tdh_decode::decode_event_property( + std::ptr::from_ref(record).cast_mut(), + &mut cache, + "ProcessId", + ) + .ok() + .flatten() + }) + .and_then(|pid| { + crate::extractors::effective_capability_event_pid(Some(pid.as_str())) + }); + payload_pid.unwrap_or(header.ProcessId) + } else { + header.ProcessId + }; + if self.selection.observe_known_provider_event(effective_pid) { // SAFETY: both interfaces are valid for this synchronous callback, // and Inject clones the event into the output trace. unsafe { relogger.Inject(event)? }; @@ -195,7 +230,11 @@ impl TraceRelogger for WindowsTraceRelogger { .map_err(|error| windows_error("ITraceRelogger::SetOutputFilename", error))?; } - let callback: ITraceEventCallback = ProcessScopedTraceFilter { selection }.into(); + let callback: ITraceEventCallback = ProcessScopedTraceFilter { + selection, + schema_cache: Mutex::new(tdh_decode::EventSchemaCache::default()), + } + .into(); // SAFETY: callback and relogger stay alive until ProcessTrace returns. unsafe { relogger @@ -272,13 +311,17 @@ fn relog_trace_with( let selection = select_learning_mode_events_for_relogging(source, process_lifetimes)?; let expected_event_count = selection.total_event_count; let expected_selected_event_count = selection.selected_event_indices.len(); - let selection = RelogSelectionState::new(selection.selected_event_indices, process_lifetimes); + let selection = RelogSelectionState::new( + selection.selected_event_indices, + selection.selected_event_pids, + process_lifetimes, + ); relogger.process(source, destination, selection.clone())?; let consumed_event_count = selection.consumed_event_count(); if consumed_event_count != expected_event_count { return Err(AnalyzeError::Decode(format!( - "Trace Relogger observed {consumed_event_count} supported Learning Mode events, but ProcessTrace selected {expected_event_count}" + "Trace Relogger observed {consumed_event_count} known-provider Learning Mode events, but ProcessTrace selected {expected_event_count}" ))); } let consumed_selected_event_count = selection.consumed_selected_event_count(); @@ -335,9 +378,9 @@ mod tests { #[test] fn selected_ordinal_with_foreign_pid_is_not_injected() { - let selection = RelogSelectionState::new(vec![0], &[lifetime(42)]); + let selection = RelogSelectionState::new(vec![0], vec![42], &[lifetime(42)]); - assert!(!selection.observe_supported_event(99)); + assert!(!selection.observe_known_provider_event(99)); assert_eq!(selection.consumed_event_count(), 1); assert_eq!( selection.consumed_selected_event_count(), @@ -348,9 +391,9 @@ mod tests { #[test] fn selected_ordinal_with_attested_pid_is_injected() { - let selection = RelogSelectionState::new(vec![0], &[lifetime(42)]); + let selection = RelogSelectionState::new(vec![0], vec![42], &[lifetime(42)]); - assert!(selection.observe_supported_event(42)); + assert!(selection.observe_known_provider_event(42)); assert_eq!(selection.consumed_event_count(), 1); assert_eq!(selection.consumed_selected_event_count(), 1); } diff --git a/src/backends/learning_mode/windows/src/extractors.rs b/src/backends/learning_mode/windows/src/extractors.rs index e61da0c23..5941a526c 100644 --- a/src/backends/learning_mode/windows/src/extractors.rs +++ b/src/backends/learning_mode/windows/src/extractors.rs @@ -20,31 +20,37 @@ //! //! The learning-mode ETL carries a set of event IDs that map onto the //! resource types we surface. This list grows as more denial sources are -//! decoded; unknown event IDs are discarded. The IDs handled today: +//! decoded; event IDs outside this vocabulary are excluded rather than +//! extracted, and (for the known providers below) that exclusion is +//! aggregated into [`learning_mode_core::VerboseLoggingSummary`] rather than +//! silently dropped. The IDs handled today: //! //! - **14 / 4907 — access check** — the primary denial event //! (`ObjectType` / `ObjectName` / `AccessMask`). `ObjectType` selects the //! resource type: `File` → [`ResourceType::File`], `Key` → //! [`ResourceType::Other`] (registry), and an **empty** `ObjectType` is a -//! brokered-capability check → [`ResourceType::Capability`]. Any other -//! object type (Section, Process, Thread, ...) is dropped (not actionable -//! via sandbox policy). The [`AccessType`] is derived from the +//! brokered-capability check → [`ResourceType::Capability`]. Named Section, +//! SymbolicLink, and Timer objects also map to [`ResourceType::Other`]. +//! Other object types are dropped until their access-mask vocabulary is +//! understood. The [`AccessType`] is derived from the //! `AccessMask` field (see [`access_type_from_mask`]). Emitted under both //! learning modes (`block` → `Mode="Normal"`, `allow` → //! `Mode="Permissive"`). //! - **27 — `LearningModeViolation`** — UI-surface denials → //! [`ResourceType::Ui`]. Carries no usable access mask, so the access type //! stays [`AccessType::Unknown`]. -//! - **28 — capability denial** — a compact capability-access-manager -//! record (`Denied` / `PackageSid` / `ProcessId`), emitted under -//! `block`; `allow` folds the same information into the -//! empty-`ObjectType` event 14 above. Mapped to [`ResourceType::Capability`]. -//! The capability *name* is resolved from the `PackageSid` capability SID -//! via [`crate::capability_names`] (well-known SID → friendly name; custom -//! hashed capabilities fall back to the SID string). Records without a -//! decoded identifier are omitted. - -use learning_mode_core::{AccessType, ResourceType}; +//! - **28 — schema-dependent denial** — either a UI violation carrying +//! `Category` / `Detail` / `Denied`, or a compact capability-access-manager +//! record (`Denied` / `PackageSid` / `ProcessId`). UI violations map to +//! [`ResourceType::Ui`]. Capability records map to +//! [`ResourceType::Capability`], with the capability name resolved from the +//! capability SID via [`crate::capability_names`] (well-known SID → friendly +//! name; custom hashed capabilities fall back to the SID string). + +use learning_mode_core::{ + AccessType, ResourceType, VerboseLoggingExclusionReason, VerboseLoggingProvider, +}; +use sha2::{Digest, Sha256}; use windows::core::GUID; /// Microsoft-Windows-Kernel-General provider. @@ -103,23 +109,101 @@ pub struct RawDenial { pub filetime: u64, /// Originating ETW event ID (kept for diagnostics). pub event_id: u16, + /// Symbolic category of the originating provider, for verbose logging + /// aggregation. Never a raw provider GUID. + pub provider: VerboseLoggingProvider, + /// Bounded sensitive-value-redacted properties retained for verbose logging signatures. + pub verbose_logging_properties: Vec<(String, String)>, } /// Routes a decoded event to the matching extractor by its event ID. /// -/// Returns `None` for events that are not learning-mode denials or that -/// carry an object type we don't surface. -pub fn extract_denial(parts: &DecodedEventParts, pid: u32, filetime: u64) -> Option { +/// Returns `Err` with a closed [`VerboseLoggingExclusionReason`] for events that +/// are not learning-mode denials, that carry an object type we don't +/// surface, or that otherwise fail extraction. Callers aggregate the +/// returned reason into [`learning_mode_core::VerboseLoggingSummary`] rather than +/// discarding it, except when a fallback extractor (e.g. +/// [`crate::capability_dacl`]) recovers an equivalent denial from the same +/// event. +pub fn extract_denial( + parts: &DecodedEventParts, + pid: u32, + filetime: u64, +) -> Result { + // Callers on the real trace path gate on `is_learning_mode_event` before + // decoding via TDH at all, so this branch only matters for direct/test + // callers that skip that gate. + let provider = verbose_logging_provider_for_guid(parts.provider) + .ok_or(VerboseLoggingExclusionReason::UnsupportedEventSchema)?; if !is_learning_mode_event(parts.provider, parts.event_id) { - return None; + return Err(VerboseLoggingExclusionReason::UnsupportedEventSchema); } + match parts.event_id { ACCESS_CHECK_EVENT_ID | PRIVACY_ACCESS_CHECK_EVENT_ID => { - build_denial_from_access_check(parts, pid, filetime) + build_denial_from_access_check(parts, pid, filetime, provider) } - LEARNING_MODE_VIOLATION_EVENT_ID => build_denial_from_learning_mode(parts, pid, filetime), - CAPABILITY_DENIAL_EVENT_ID => build_denial_from_capability(parts, pid, filetime), - _ => None, + LEARNING_MODE_VIOLATION_EVENT_ID => { + build_denial_from_learning_mode(parts, pid, filetime, provider) + } + CAPABILITY_DENIAL_EVENT_ID if is_ui_violation_schema(parts) => { + build_denial_from_learning_mode(parts, pid, filetime, provider) + } + CAPABILITY_DENIAL_EVENT_ID => build_denial_from_capability(parts, pid, filetime, provider), + _ => Err(VerboseLoggingExclusionReason::UnsupportedEventSchema), + } +} + +/// Returns typed denial classifications that can be determined independently +/// of whether the event contains every property required for canonical output. +pub(crate) fn verbose_logging_classification( + parts: &DecodedEventParts, +) -> (Option, Option) { + match parts.event_id { + ACCESS_CHECK_EVENT_ID | PRIVACY_ACCESS_CHECK_EVENT_ID => { + let Some(object_type) = find_prop(&parts.props, "ObjectType") else { + return (None, None); + }; + match object_type.trim_matches('"') { + "File" => ( + Some( + find_prop(&parts.props, "AccessMask") + .and_then(|value| parse_u32(value)) + .map(|mask| access_type_from_mask(mask, false)) + .unwrap_or(AccessType::Unknown), + ), + Some(ResourceType::File), + ), + "Key" => ( + Some( + find_prop(&parts.props, "AccessMask") + .and_then(|value| parse_u32(value)) + .map(|mask| access_type_from_mask(mask, true)) + .unwrap_or(AccessType::Unknown), + ), + Some(ResourceType::Other), + ), + "Section" | "SymbolicLink" | "Timer" => ( + Some( + find_prop(&parts.props, "AccessMask") + .and_then(|value| parse_u32(value)) + .map(|mask| { + named_object_access_type(object_type.trim_matches('"'), mask) + }) + .unwrap_or(AccessType::Unknown), + ), + Some(ResourceType::Other), + ), + "" => (Some(AccessType::Unknown), Some(ResourceType::Capability)), + _ => (None, None), + } + } + LEARNING_MODE_VIOLATION_EVENT_ID => (Some(AccessType::Unknown), Some(ResourceType::Ui)), + CAPABILITY_DENIAL_EVENT_ID if is_ui_violation_schema(parts) => { + (Some(AccessType::Unknown), Some(ResourceType::Ui)) + } + CAPABILITY_DENIAL_EVENT_ID => (Some(AccessType::Unknown), Some(ResourceType::Capability)), + _ => (None, None), } } @@ -142,13 +226,390 @@ pub(crate) fn is_learning_mode_event(provider: GUID, event_id: u16) -> bool { } } -/// Builds a [`RawDenial`] from an access-check (event 14 / 4907) payload. +pub(crate) fn effective_event_pid(parts: &DecodedEventParts, header_pid: u32) -> Option { + if parts.event_id == CAPABILITY_DENIAL_EVENT_ID { + effective_capability_event_pid( + find_prop(&parts.props, "ProcessId").map(std::string::String::as_str), + ) + } else { + Some(header_pid) + } +} + +fn is_ui_violation_schema(parts: &DecodedEventParts) -> bool { + parts.event_id == CAPABILITY_DENIAL_EVENT_ID + && find_prop(&parts.props, "Detail").is_some() + && find_prop(&parts.props, "Category").is_some() +} + +pub(crate) fn effective_capability_event_pid(process_id: Option<&str>) -> Option { + process_id.and_then(parse_u32) +} + +/// Maps a raw ETW provider GUID to its symbolic verbose logging category. +/// +/// Returns `None` for providers outside the Learning Mode vocabulary; those +/// events are ignored entirely (not aggregated), since they are unrelated +/// host traffic rather than an excluded Learning Mode outcome. +pub(crate) fn verbose_logging_provider_for_guid(provider: GUID) -> Option { + if provider == KERNEL_GENERAL_PROVIDER { + Some(VerboseLoggingProvider::KernelGeneral) + } else if provider == PRIVACY_LEARNING_MODE_PROVIDER { + Some(VerboseLoggingProvider::PrivacyAuditingPermissiveLearningMode) + } else { + None + } +} + +/// Renders a symbolic verbose logging provider category as its raw ETW +/// provider GUID, in stable uppercase braced form, for retention in a verbose +/// logging signature. Provider GUIDs are stable component identifiers, not +/// personal data, so unlike account/user values they are never redacted. +pub(crate) fn verbose_logging_provider_guid(provider: VerboseLoggingProvider) -> String { + match provider { + VerboseLoggingProvider::KernelGeneral => { + format_guid_braced_uppercase(KERNEL_GENERAL_PROVIDER) + } + VerboseLoggingProvider::PrivacyAuditingPermissiveLearningMode => { + format_guid_braced_uppercase(PRIVACY_LEARNING_MODE_PROVIDER) + } + } +} + +// Keep the serialized spelling independent of formatting changes in the +// `windows` crate: verbose signatures require braces and uppercase hex. +fn format_guid_braced_uppercase(guid: GUID) -> String { + format!( + "{{{:08X}-{:04X}-{:04X}-{:02X}{:02X}-{:02X}{:02X}{:02X}{:02X}{:02X}{:02X}}}", + guid.data1, + guid.data2, + guid.data3, + guid.data4[0], + guid.data4[1], + guid.data4[2], + guid.data4[3], + guid.data4[4], + guid.data4[5], + guid.data4[6], + guid.data4[7], + ) +} + +// ---- verbose logging signature sanitization ------------------------------------- +// +// A verbose logging signature retains identifiers useful for triage (SIDs, +// capability names, PIDs, provider/object GUIDs) but must never leak a +// human account/user name, a file path, an exact timestamp, or a free-form +// decoder error message. These bounds apply uniformly to every decoded +// property, in a fixed order: drop timestamp-like properties outright, +// redact sensitive content, *then* bound the surviving property count and +// value length — sanitizing always happens before truncation so a redaction +// is never chopped in half by a length cap. + +/// Fixed replacement for any redacted username/account-name value. +pub(crate) const REDACTED_USER: &str = ""; +/// Fixed replacement for a complete file path. +pub(crate) const REDACTED_PATH: &str = ""; +/// Maximum number of `(name, value)` properties retained in one verbose logging +/// signature. Bounds pathological/huge TDH property lists; sanitization +/// (never raw decoding) determines which survive, via deterministic +/// (sorted-by-name) truncation. +pub(crate) const MAX_SIGNATURE_PROPERTIES: usize = 24; +/// Maximum retained length (in `char`s) of one sanitized property value. +pub(crate) const MAX_SIGNATURE_VALUE_LEN: usize = 256; +const SHA256_HEX_LEN: usize = 64; +const BOUNDED_VALUE_MARKER_LEN: usize = "......".len(); +const _: () = assert!(MAX_SIGNATURE_VALUE_LEN > BOUNDED_VALUE_MARKER_LEN); +const TIMESTAMP_PROPERTY_NAMES: &[&str] = &[ + "time", + "timestamp", + "filetime", + "systemtime", + "eventtime", + "timecreated", + "creationtime", + "createtime", + "starttime", + "endtime", + "exittime", + "lastwritetime", +]; +const RETAINED_IDENTIFIER_SUFFIXES: &[&str] = &["sid", "guid", "identifier", "id"]; +const IDENTITY_PROPERTY_NAMES: &[&str] = &["user", "account", "owner", "upn"]; +const IDENTITY_PROPERTY_SUFFIXES: &[&str] = &[ + "username", + "accountname", + "ownername", + "principalname", + "account", + "upn", +]; + +#[derive(Clone, Copy)] +struct NormalizedPropertyName<'a>(&'a str); + +impl<'a> NormalizedPropertyName<'a> { + fn bytes(self) -> impl DoubleEndedIterator + Clone + 'a { + self.0 + .bytes() + .filter(|byte| !matches!(byte, b'_' | b'-')) + .map(|byte| byte.to_ascii_lowercase()) + } + + fn equals(self, expected: &str) -> bool { + self.bytes().eq(expected.bytes()) + } + + fn ends_with(self, suffix: &str) -> bool { + let mut bytes = self.bytes().rev(); + suffix + .bytes() + .rev() + .all(|expected| bytes.next() == Some(expected)) + } +} + +/// Returns whether `name` looks like it carries a timestamp, so it is +/// dropped from a verbose logging signature entirely (never redacted or +/// truncated) — exact timestamps must not prevent otherwise-identical +/// events from deduplicating. These are trusted ETW schema property names, so +/// matching is deliberately limited to known names and suffixes rather than +/// fuzzy spellings that could discard unrelated properties. +fn is_timestamp_like_property(name: &str) -> bool { + let normalized = NormalizedPropertyName(name); + TIMESTAMP_PROPERTY_NAMES + .iter() + .copied() + .any(|expected| normalized.equals(expected)) + || normalized.ends_with("timestamp") + || normalized.ends_with("filetime") +} + +/// Returns whether `name` is itself a standalone user/account-identity +/// property (as opposed to a path that merely *contains* a username), so +/// its value is replaced outright with [`REDACTED_USER`] regardless of +/// content. +fn is_identity_property(name: &str) -> bool { + let normalized = NormalizedPropertyName(name); + if RETAINED_IDENTIFIER_SUFFIXES + .iter() + .copied() + .any(|suffix| normalized.equals(suffix) || normalized.ends_with(suffix)) + { + return false; + } + IDENTITY_PROPERTY_NAMES + .iter() + .copied() + .any(|expected| normalized.equals(expected)) + || IDENTITY_PROPERTY_SUFFIXES + .iter() + .copied() + .any(|suffix| normalized.ends_with(suffix)) +} + +fn looks_like_file_path_property(name: &str, value: &str, object_type: Option<&str>) -> bool { + let normalized = NormalizedPropertyName(name); + if normalized.ends_with("path") || normalized.ends_with("filename") { + return true; + } + + if !normalized.equals("objectname") && !normalized.equals("resource") { + return false; + } + if object_type.is_some_and(|object_type| object_type.eq_ignore_ascii_case("File")) { + return true; + } + + crate::path_norm::is_user_visible_absolute(value) + || looks_like_dos_device_filesystem_path(value) + || looks_like_nt_filesystem_path(value) +} + +fn looks_like_dos_device_filesystem_path(value: &str) -> bool { + let rest = [r"\??\", r"\\?\", r"\\.\"] + .into_iter() + .find_map(|prefix| strip_prefix_ignore_ascii_case(value, prefix)); + let Some(rest) = rest else { + return false; + }; + if looks_like_drive_absolute_path(rest) + || strip_prefix_ignore_ascii_case(rest, r"UNC\").is_some() + { + return true; + } + + let Some(volume) = strip_prefix_ignore_ascii_case(rest, "Volume{") else { + return false; + }; + volume.contains(r"}\") +} + +fn looks_like_drive_absolute_path(value: &str) -> bool { + let bytes = value.as_bytes(); + bytes.len() >= 3 + && bytes[0].is_ascii_alphabetic() + && bytes[1] == b':' + && matches!(bytes[2], b'\\' | b'/') +} + +fn looks_like_nt_filesystem_path(value: &str) -> bool { + let Some(rest) = strip_prefix_ignore_ascii_case(value, r"\Device\") else { + return false; + }; + let Some((device, _path)) = rest.split_once('\\') else { + return false; + }; + if device.eq_ignore_ascii_case("Mup") || ends_with_ignore_ascii_case(device, "Redirector") { + return true; + } + + let Some(volume_number) = strip_prefix_ignore_ascii_case(device, "HarddiskVolume") else { + return false; + }; + !volume_number.is_empty() && volume_number.bytes().all(|byte| byte.is_ascii_digit()) +} + +fn strip_prefix_ignore_ascii_case<'a>(value: &'a str, prefix: &str) -> Option<&'a str> { + value + .get(..prefix.len()) + .is_some_and(|candidate| candidate.eq_ignore_ascii_case(prefix)) + .then(|| &value[prefix.len()..]) +} + +fn ends_with_ignore_ascii_case(value: &str, suffix: &str) -> bool { + value + .get(value.len().saturating_sub(suffix.len())..) + .is_some_and(|candidate| candidate.eq_ignore_ascii_case(suffix)) +} + +/// Deterministically discards sorted properties after +/// [`MAX_SIGNATURE_PROPERTIES`] and bounds retained values to +/// [`MAX_SIGNATURE_VALUE_LEN`] characters. +/// +/// Overlong values retain prefix and suffix context plus a digest of the full +/// sanitized value. The digest prevents distinct values with a long shared +/// prefix from collapsing into one verbose logging signature. +/// +/// Callers must sanitize (redact) *before* calling this so neither the retained +/// context nor the digest is derived from sensitive identity content. +pub(crate) fn bound_properties(mut properties: Vec<(String, String)>) -> Vec<(String, String)> { + properties.truncate(MAX_SIGNATURE_PROPERTIES); + for (_, value) in &mut properties { + let char_count = value.chars().count(); + if char_count > MAX_SIGNATURE_VALUE_LEN { + *value = bound_property_value(value, char_count); + } + } + properties +} + +fn bound_property_value(value: &str, char_count: usize) -> String { + let digest = Sha256::digest(value.as_bytes()); + let marker = format!("......"); + debug_assert_eq!(marker.len(), BOUNDED_VALUE_MARKER_LEN); + let context_len = MAX_SIGNATURE_VALUE_LEN - BOUNDED_VALUE_MARKER_LEN; + let prefix_len = context_len.div_ceil(2); + let suffix_len = context_len / 2; + let prefix = value.chars().take(prefix_len).collect::(); + let suffix = value + .chars() + .skip(char_count - suffix_len) + .collect::(); + format!("{prefix}{marker}{suffix}") +} + +/// Produces the deterministic, sanitized, bounded property list for a verbose +/// logging signature from one decoded event's raw TDH properties. +/// +/// Never includes a free-form decoder error message (decode failures are +/// recorded with an empty property list by the caller, before this +/// function would ever run) and never includes a timestamp-like property, +/// so exact-timestamp differences between otherwise-identical events don't +/// prevent their signatures from deduplicating. SIDs, capability names, +/// PIDs carried as properties, and GUID-shaped values are retained +/// verbatim; account/user-identity content and complete file paths are +/// redacted. Classification is schema-independent: newly decoded properties +/// automatically pass through these name/value checks without requiring a new +/// extractor branch. +pub(crate) fn sanitize_properties(props: &[(String, String)]) -> Vec<(String, String)> { + let usernames = props + .iter() + .filter(|(name, _)| is_identity_property(name)) + .flat_map(|(_, value)| username_match_candidates(value.trim_matches('"'))) + .collect::>(); + let object_type = props + .iter() + .find(|(name, _)| name.eq_ignore_ascii_case("ObjectType")) + .map(|(_, value)| value.trim_matches('"')); + let mut sanitized = std::collections::BTreeMap::new(); + for (name, raw_value) in props { + if is_timestamp_like_property(name) { + continue; + } + let value = raw_value.trim_matches('"'); + let sanitized_value = if is_identity_property(name) { + REDACTED_USER.to_string() + } else if looks_like_file_path_property(name, value, object_type) { + REDACTED_PATH.to_string() + } else { + redact_known_username_components(value, &usernames) + }; + sanitized.insert(name.clone(), sanitized_value); + } + + fn username_match_candidates(identity: &str) -> Vec { + let mut candidates = Vec::new(); + let account = identity + .rsplit_once('\\') + .map_or(identity, |(_, account)| account); + for candidate in [ + identity, + account, + account.split_once('@').map_or(account, |(name, _)| name), + ] { + if !candidate.is_empty() + && !candidates + .iter() + .any(|existing: &String| windows_paths_equal_ignore_case(existing, candidate)) + { + candidates.push(candidate.to_string()); + } + } + candidates + } + + fn redact_known_username_components(value: &str, usernames: &[String]) -> String { + value + .split_inclusive(['\\', '/']) + .map(|component| { + let (segment, separator) = if component.ends_with('\\') || component.ends_with('/') + { + component.split_at(component.len() - 1) + } else { + (component, "") + }; + if usernames + .iter() + .any(|username| windows_paths_equal_ignore_case(segment, username)) + { + format!("{REDACTED_USER}{separator}") + } else { + component.to_string() + } + }) + .collect() + } + bound_properties(sanitized.into_iter().collect()) +} + /// /// The `ObjectType` field selects the resource type: `File` and `Key` /// (registry) map to concrete resources, an **empty** `ObjectType` is a -/// brokered-capability check, and any other object type (Section, Process, -/// Thread, ...) is dropped as not actionable via sandbox policy. An absent -/// `ObjectType` field drops the event. +/// brokered-capability check, and the observed named-object types `Section`, +/// `SymbolicLink`, and `Timer` map to [`ResourceType::Other`]. Other object +/// types are dropped until their access-mask vocabulary is understood. An +/// absent `ObjectType` field drops the event. /// /// For file/registry resources the [`AccessType`] is derived from the /// event's `AccessMask` field (the desired access the caller was denied; @@ -156,32 +617,57 @@ pub(crate) fn is_learning_mode_event(provider: GUID, event_id: u16) -> bool { /// the type falls back to [`AccessType::Unknown`] so a decode gap never /// drops the denial itself. Capability checks carry a mask that is not a /// read/write/execute verb, so their access type is left `Unknown`. +/// +/// # Errors +/// +/// Returns the closed [`VerboseLoggingExclusionReason`] describing why no denial +/// could be built: a missing `ObjectType` ([`VerboseLoggingExclusionReason::MissingObjectType`]), +/// an object type this model can't represent +/// ([`VerboseLoggingExclusionReason::UnsupportedObjectType`]), a missing/empty +/// object name (registry/file: +/// [`VerboseLoggingExclusionReason::MissingObjectName`]; capability: an +/// unidentified brokered check, +/// [`VerboseLoggingExclusionReason::UnresolvedCapability`] — [`crate::capability_dacl`] +/// may still recover it from the event's DACL payload), or a self-access +/// check that isn't actionable ([`VerboseLoggingExclusionReason::NotActionable`]). pub fn build_denial_from_access_check( parts: &DecodedEventParts, pid: u32, filetime: u64, -) -> Option { - let object_type = find_prop(&parts.props, "ObjectType")?; + provider: VerboseLoggingProvider, +) -> Result { + let object_type = find_prop(&parts.props, "ObjectType") + .ok_or(VerboseLoggingExclusionReason::MissingObjectType)?; let object_type_str = object_type.trim_matches('"'); let resource_type = match object_type_str { "File" => ResourceType::File, "Key" => ResourceType::Other, + "Section" | "SymbolicLink" | "Timer" => ResourceType::Other, // A present-but-empty object type is a brokered-capability check. "" => ResourceType::Capability, - _ => return None, + _ => return Err(VerboseLoggingExclusionReason::UnsupportedObjectType), }; let object_name = find_prop(&parts.props, "ObjectName") .map(|v| v.trim_matches('"').to_string()) - .filter(|name| !name.is_empty())?; + .filter(|name| !name.is_empty()); + let object_name = match (resource_type, object_name) { + // An unidentified brokered-capability check: the identifier may + // still be recoverable from the event's DACL payload. + (ResourceType::Capability, None) => { + return Err(VerboseLoggingExclusionReason::UnresolvedCapability) + } + (_, None) => return Err(VerboseLoggingExclusionReason::MissingObjectName), + (_, Some(name)) => name, + }; if resource_type == ResourceType::File { let app_path = find_prop(&parts.props, "AppPath") .or_else(|| find_prop(&parts.props, "ApplicationPath")) .map(|value| value.trim_matches('"')); if app_path.is_some_and(|app_path| is_self_access(&object_name, app_path)) { - return None; + return Err(VerboseLoggingExclusionReason::NotActionable); } } @@ -191,23 +677,25 @@ pub fn build_denial_from_access_check( // classifier over it. AccessType::Unknown } else { - // Registry keys and files share the standard/generic mask bits but - // assign different meanings to the object-specific low bits, so the - // classifier needs to know which vocabulary applies. - let is_registry = object_type_str == "Key"; find_prop(&parts.props, "AccessMask") .and_then(|v| parse_u32(v)) - .map(|mask| access_type_from_mask(mask, is_registry)) + .map(|mask| match object_type_str { + "Key" => access_type_from_mask(mask, true), + "File" => access_type_from_mask(mask, false), + _ => named_object_access_type(object_type_str, mask), + }) .unwrap_or(AccessType::Unknown) }; - Some(RawDenial { + Ok(RawDenial { pid, resource_type, object_name, access_type, filetime, event_id: parts.event_id, + provider, + verbose_logging_properties: sanitize_properties(&parts.props), }) } @@ -264,26 +752,40 @@ fn strip_dos_namespace_prefix(path: &str) -> &str { /// These represent UI-surface denials. `Category` identifies the class and /// `Detail` identifies the concrete UI operation; `ProcessName` is the caller /// and must not be emitted as the denied resource. +/// +/// # Errors +/// +/// Returns [`VerboseLoggingExclusionReason::MissingObjectType`] when `Category` is +/// absent or unparseable, [`VerboseLoggingExclusionReason::MissingObjectName`] +/// when the required `Detail` is absent or unparseable, and +/// [`VerboseLoggingExclusionReason::NotActionable`] when the category/detail pair +/// describes no violation (`Category == 0`). pub fn build_denial_from_learning_mode( parts: &DecodedEventParts, pid: u32, filetime: u64, -) -> Option { - let category = find_prop(&parts.props, "Category").and_then(|value| parse_u32(value))?; + provider: VerboseLoggingProvider, +) -> Result { + let category = find_prop(&parts.props, "Category") + .and_then(|value| parse_u32(value)) + .ok_or(VerboseLoggingExclusionReason::MissingObjectType)?; let detail = match find_prop(&parts.props, "Detail") { - Some(value) => parse_u32(value)?, + Some(value) => parse_u32(value).ok_or(VerboseLoggingExclusionReason::MissingObjectName)?, None if category == crate::ui::CONVERT_TO_GUI => 0, - None => return None, + None => return Err(VerboseLoggingExclusionReason::MissingObjectName), }; - let object_name = crate::ui::resource_name(category, detail)?; + let object_name = crate::ui::resource_name(category, detail) + .ok_or(VerboseLoggingExclusionReason::NotActionable)?; - Some(RawDenial { + Ok(RawDenial { pid, resource_type: ResourceType::Ui, object_name, access_type: AccessType::Unknown, filetime, event_id: parts.event_id, + provider, + verbose_logging_properties: sanitize_properties(&parts.props), }) } @@ -295,19 +797,24 @@ pub fn build_denial_from_learning_mode( /// brokered checks) when present, else the header pid. The capability name /// comes from the `PackageSid` capability SID, resolved to its friendly /// policy name via [`crate::capability_names`] (custom hashed capabilities -/// fall back to the SID string). Records without a decoded identifier are -/// omitted. +/// fall back to the SID string). +/// +/// # Errors +/// +/// Returns [`VerboseLoggingExclusionReason::NotActionable`] when `Denied` is +/// absent or not `true`, and [`VerboseLoggingExclusionReason::UnresolvedCapability`] +/// when no usable capability identifier could be decoded. pub fn build_denial_from_capability( parts: &DecodedEventParts, pid: u32, filetime: u64, -) -> Option { + provider: VerboseLoggingProvider, +) -> Result { // A partially decoded event must not become a policy recommendation. - if !find_prop(&parts.props, "Denied")? - .trim_matches('"') - .eq_ignore_ascii_case("true") - { - return None; + let denied = find_prop(&parts.props, "Denied") + .is_some_and(|value| value.trim_matches('"').eq_ignore_ascii_case("true")); + if !denied { + return Err(VerboseLoggingExclusionReason::NotActionable); } let pid = find_prop(&parts.props, "ProcessId") @@ -332,15 +839,18 @@ pub fn build_denial_from_capability( && name != "" && name != "" && name != "" - })?; + }) + .ok_or(VerboseLoggingExclusionReason::UnresolvedCapability)?; - Some(RawDenial { + Ok(RawDenial { pid, resource_type: ResourceType::Capability, object_name, access_type: AccessType::Unknown, filetime, event_id: parts.event_id, + provider, + verbose_logging_properties: sanitize_properties(&parts.props), }) } @@ -445,6 +955,37 @@ fn access_type_from_mask(mask: u32, is_registry: bool) -> AccessType { } } +fn named_object_access_type(object_type: &str, mask: u32) -> AccessType { + let (read_bits, write_bits, execute_bits) = match object_type { + // ntifs.h SECTION_* rights. + "Section" => (0x0001 | 0x0004, 0x0002 | 0x0010, 0x0008 | 0x0020), + // ntifs.h SYMBOLIC_LINK_* rights. + "SymbolicLink" => (0x0001, 0x0002, 0), + // winnt.h TIMER_* rights. + "Timer" => (0x0001, 0x0002, 0), + _ => return AccessType::Unknown, + }; + + // Standard and generic rights are object-type independent. + const DELETE: u32 = 0x0001_0000; + const WRITE_DAC: u32 = 0x0004_0000; + const WRITE_OWNER: u32 = 0x0008_0000; + const GENERIC_READ: u32 = 0x8000_0000; + const GENERIC_WRITE: u32 = 0x4000_0000; + const GENERIC_EXECUTE: u32 = 0x2000_0000; + const GENERIC_ALL: u32 = 0x1000_0000; + + if mask & (write_bits | DELETE | WRITE_DAC | WRITE_OWNER | GENERIC_WRITE | GENERIC_ALL) != 0 { + AccessType::Write + } else if mask & (execute_bits | GENERIC_EXECUTE) != 0 { + AccessType::Execute + } else if mask & (read_bits | GENERIC_READ) != 0 { + AccessType::Read + } else { + AccessType::Unknown + } +} + fn find_prop<'a>(props: &'a [(String, String)], name: &str) -> Option<&'a String> { props.iter().find(|(k, _)| k == name).map(|(_, v)| v) } @@ -555,7 +1096,10 @@ mod tests { ("AccessMask", "0x1"), ], ); - assert!(extract_denial(&p, 1, FIXED_FILETIME).is_none()); + assert_eq!( + extract_denial(&p, 1, FIXED_FILETIME).unwrap_err(), + VerboseLoggingExclusionReason::NotActionable + ); } } @@ -581,7 +1125,7 @@ mod tests { ("AccessMask", "0x1"), ], ); - assert!(extract_denial(&p, 1, FIXED_FILETIME).is_some()); + assert!(extract_denial(&p, 1, FIXED_FILETIME).is_ok()); } #[test] @@ -598,7 +1142,7 @@ mod tests { ("AccessMask", "0x1"), ], ); - assert!(extract_denial(&p, 1, FIXED_FILETIME).is_some()); + assert!(extract_denial(&p, 1, FIXED_FILETIME).is_ok()); } #[test] @@ -620,7 +1164,7 @@ mod tests { ("AccessMask", "0x1"), ], ); - assert!(extract_denial(&p, 1, FIXED_FILETIME).is_some()); + assert!(extract_denial(&p, 1, FIXED_FILETIME).is_ok()); } #[test] @@ -634,7 +1178,7 @@ mod tests { ("AccessMask", "0x1"), ], ); - assert!(extract_denial(&p, 1, FIXED_FILETIME).is_some()); + assert!(extract_denial(&p, 1, FIXED_FILETIME).is_ok()); } #[test] @@ -648,7 +1192,7 @@ mod tests { ("AccessMask", "0x1"), ], ); - assert!(extract_denial(&p, 1, FIXED_FILETIME).is_some()); + assert!(extract_denial(&p, 1, FIXED_FILETIME).is_ok()); } #[test] @@ -681,7 +1225,10 @@ mod tests { ("AccessMask", "0x1"), ], ); - assert!(extract_denial(&p, 5900, FIXED_FILETIME).is_none()); + assert_eq!( + extract_denial(&p, 5900, FIXED_FILETIME).unwrap_err(), + VerboseLoggingExclusionReason::UnresolvedCapability + ); } #[test] @@ -695,7 +1242,10 @@ mod tests { ("AccessMask", "0x1"), ], ); - assert!(extract_denial(&p, 5900, FIXED_FILETIME).is_none()); + assert_eq!( + extract_denial(&p, 5900, FIXED_FILETIME).unwrap_err(), + VerboseLoggingExclusionReason::MissingObjectName + ); } } @@ -710,15 +1260,56 @@ mod tests { } #[test] - fn access_check_unknown_object_type_dropped() { - let p = parts(14, &[("ObjectType", "\"Section\"")]); - assert!(extract_denial(&p, 1, FIXED_FILETIME).is_none()); + fn access_check_observed_named_object_types_are_retained() { + for (object_type, object_name, mask, expected_access) in [ + ( + "Section", + r"\Sessions\1\BaseNamedObjects\shared-section", + "0x6", + AccessType::Write, + ), + ("SymbolicLink", r"\??\C:", "0x1", AccessType::Read), + ( + "Timer", + r"\Sessions\1\BaseNamedObjects\deadline", + "0x1", + AccessType::Read, + ), + ] { + let p = parts( + 14, + &[ + ("ObjectType", object_type), + ("ObjectName", object_name), + ("AccessMask", mask), + ], + ); + let denial = extract_denial(&p, 1, FIXED_FILETIME).unwrap(); + assert_eq!(denial.resource_type, ResourceType::Other); + assert_eq!(denial.object_name, object_name); + assert_eq!(denial.access_type, expected_access); + } + } + + #[test] + fn access_check_unrecognized_object_type_is_dropped() { + let p = parts( + 14, + &[("ObjectType", "\"Process\""), ("ObjectName", "\"target\"")], + ); + assert_eq!( + extract_denial(&p, 1, FIXED_FILETIME).unwrap_err(), + VerboseLoggingExclusionReason::UnsupportedObjectType + ); } #[test] fn access_check_absent_object_type_dropped() { let p = parts(14, &[("ObjectName", "\"x\"")]); - assert!(extract_denial(&p, 1, FIXED_FILETIME).is_none()); + assert_eq!( + extract_denial(&p, 1, FIXED_FILETIME).unwrap_err(), + VerboseLoggingExclusionReason::MissingObjectType + ); } // ---- event 27 UI ------------------------------------------------------ @@ -798,16 +1389,25 @@ mod tests { #[test] fn learning_mode_violation_rejects_invalid_required_numbers() { let invalid_category = parts(27, &[("Category", "not-a-number"), ("Detail", "4")]); - assert!(extract_denial(&invalid_category, 9999, FIXED_FILETIME).is_none()); + assert_eq!( + extract_denial(&invalid_category, 9999, FIXED_FILETIME).unwrap_err(), + VerboseLoggingExclusionReason::MissingObjectType + ); let invalid_detail = parts(27, &[("Category", "2"), ("Detail", "not-a-number")]); - assert!(extract_denial(&invalid_detail, 9999, FIXED_FILETIME).is_none()); + assert_eq!( + extract_denial(&invalid_detail, 9999, FIXED_FILETIME).unwrap_err(), + VerboseLoggingExclusionReason::MissingObjectName + ); } #[test] fn learning_mode_category_none_is_dropped() { let p = parts(27, &[("Category", "0"), ("Detail", "0")]); - assert!(extract_denial(&p, 9999, FIXED_FILETIME).is_none()); + assert_eq!( + extract_denial(&p, 9999, FIXED_FILETIME).unwrap_err(), + VerboseLoggingExclusionReason::NotActionable + ); } // ---- event 28 capability denial --------------------------------------- @@ -831,6 +1431,33 @@ mod tests { // pid comes from the payload ProcessId (0x1acc), not the header. assert_eq!(ev.pid, 0x1acc); assert_eq!(ev.object_name, "internetClient"); + assert_eq!(ev.provider, VerboseLoggingProvider::KernelGeneral); + } + + #[test] + fn event_28_ui_violation_is_not_misclassified_as_capability() { + let p = parts( + 28, + &[ + ("ProcessName", "\"powershell.exe\""), + ("ProcessId", "0x1594"), + ("SequenceNumber", "302"), + ("Category", "2"), + ("Detail", "1"), + ("Denied", "false"), + ("UserSid", "S-1-5-21-1-2-3-1000"), + ("PackageSid", "S-1-15-2-1-2-3-4-5-6-7"), + ], + ); + + let denial = extract_denial(&p, 0x1594, FIXED_FILETIME).unwrap(); + assert_eq!(denial.resource_type, ResourceType::Ui); + assert_eq!(denial.object_name, "Handles"); + assert_eq!(denial.pid, 0x1594); + assert_eq!( + verbose_logging_classification(&p), + (Some(AccessType::Unknown), Some(ResourceType::Ui)) + ); } #[test] @@ -871,13 +1498,28 @@ mod tests { #[test] fn capability_denial_not_denied_is_dropped() { let p = parts(28, &[("ProcessId", "0x10"), ("Denied", "false")]); - assert!(extract_denial(&p, 1, FIXED_FILETIME).is_none()); + assert_eq!( + extract_denial(&p, 1, FIXED_FILETIME).unwrap_err(), + VerboseLoggingExclusionReason::NotActionable + ); } #[test] fn capability_denial_without_denied_field_is_dropped() { let p = parts(28, &[("PackageSid", "S-1-15-3-1")]); - assert!(extract_denial(&p, 1, FIXED_FILETIME).is_none()); + assert_eq!( + extract_denial(&p, 1, FIXED_FILETIME).unwrap_err(), + VerboseLoggingExclusionReason::NotActionable + ); + } + + #[test] + fn capability_denial_without_identifier_is_unresolved() { + let p = parts(28, &[("ProcessId", "0x10"), ("Denied", "true")]); + assert_eq!( + extract_denial(&p, 1, FIXED_FILETIME).unwrap_err(), + VerboseLoggingExclusionReason::UnresolvedCapability + ); } #[test] @@ -887,20 +1529,485 @@ mod tests { 27, &[("Category", "2"), ("Detail", "4")], ); - assert!(extract_denial(&p, 1, FIXED_FILETIME).is_none()); + assert_eq!( + extract_denial(&p, 1, FIXED_FILETIME).unwrap_err(), + VerboseLoggingExclusionReason::UnsupportedEventSchema + ); + assert!(verbose_logging_provider_for_guid(GUID::from_u128( + 0x12345678_1234_1234_1234_1234567890ab + )) + .is_none()); } #[test] - fn capability_denial_falls_back_to_header_pid() { + fn capability_denial_uses_supplied_effective_pid() { let p = parts(28, &[("Denied", "true"), ("PackageSid", "S-1-15-3-1")]); let ev = extract_denial(&p, 555, FIXED_FILETIME).unwrap(); assert_eq!(ev.pid, 555); } + #[test] + fn capability_event_requires_payload_pid_for_scoping() { + let missing = parts(28, &[("Denied", "true")]); + let malformed = parts(28, &[("ProcessId", "\"broker\"")]); + let valid = parts(28, &[("ProcessId", "42")]); + + assert_eq!(effective_event_pid(&missing, 555), None); + assert_eq!(effective_event_pid(&malformed, 555), None); + assert_eq!(effective_event_pid(&valid, 555), Some(42)); + } + #[test] fn unrelated_event_ignored() { let p = parts(9999, &[("Foo", "\"bar\"")]); - assert!(extract_denial(&p, 1, FIXED_FILETIME).is_none()); + assert_eq!( + extract_denial(&p, 1, FIXED_FILETIME).unwrap_err(), + VerboseLoggingExclusionReason::UnsupportedEventSchema + ); + } + + #[test] + fn known_provider_guid_maps_to_symbolic_pii_free_category() { + assert_eq!( + verbose_logging_provider_for_guid(KERNEL_GENERAL_PROVIDER), + Some(VerboseLoggingProvider::KernelGeneral) + ); + assert_eq!( + verbose_logging_provider_for_guid(PRIVACY_LEARNING_MODE_PROVIDER), + Some(VerboseLoggingProvider::PrivacyAuditingPermissiveLearningMode) + ); + assert_eq!(verbose_logging_provider_for_guid(GUID::from_u128(0)), None); + } + + #[test] + fn verbose_logging_provider_guid_has_stable_spelling() { + let kernel_guid = verbose_logging_provider_guid(VerboseLoggingProvider::KernelGeneral); + let privacy_guid = verbose_logging_provider_guid( + VerboseLoggingProvider::PrivacyAuditingPermissiveLearningMode, + ); + assert_ne!(kernel_guid, privacy_guid); + assert_eq!( + kernel_guid, + format_guid_braced_uppercase(KERNEL_GENERAL_PROVIDER) + ); + assert_eq!( + privacy_guid, + format_guid_braced_uppercase(PRIVACY_LEARNING_MODE_PROVIDER) + ); + assert!(kernel_guid.starts_with('{') && kernel_guid.ends_with('}')); + } + + // ---- verbose logging signature sanitization ---------------------------------- + + #[test] + fn file_path_detection_preserves_non_file_identifiers() { + assert!(looks_like_file_path_property( + "ObjectName", + r"C:\Users\jsmith\secret.txt", + None + )); + assert!(looks_like_file_path_property( + "FilePath", + r"\Device\HarddiskVolume3\secret.txt", + Some("Section") + )); + assert!(looks_like_file_path_property( + "ObjectName", + r"C:\Users\alice\secret.txt", + Some("Section") + )); + for path in [ + r"\Device\HarddiskVolume3\Users\alice\secret.txt", + r"\device\mup\server\share\Users\alice\secret.txt", + r"\Device\LanmanRedirector\;Z:0000000000001234\server\share\secret.txt", + r"\??\C:\Users\alice\secret.txt", + r"\??\UNC\server\share\Users\alice\secret.txt", + ] { + assert!(looks_like_file_path_property( + "ObjectName", + path, + Some("Section") + )); + } + assert!(!looks_like_file_path_property( + "ObjectName", + r"\BaseNamedObjects\shared-cache", + Some("Section") + )); + assert!(!looks_like_file_path_property( + "ObjectName", + r"\REGISTRY\USER\S-1-5-21-1-2-3-1000\Software\Test", + Some("Key") + )); + assert!(!looks_like_file_path_property( + "resource", + "internetClient", + None + )); + assert!(!looks_like_file_path_property( + "ObjectName", + r"\Device\MountPointManager", + Some("Section") + )); + for identifier in [r"\??\FDC#GENERIC_FLOPPY_DRIVE", r"\\.\PhysicalDrive0"] { + assert!(!looks_like_file_path_property( + "ObjectName", + identifier, + Some("SymbolicLink") + )); + } + } + + #[test] + fn sanitize_properties_drops_timestamp_like_properties() { + let props = vec![ + ("ObjectName".to_string(), "\"C:\\a.txt\"".to_string()), + ("Timestamp".to_string(), "132847890123456789".to_string()), + ( + "LastWriteTime".to_string(), + "132847890123456789".to_string(), + ), + ("RuntimePolicy".to_string(), "\"retain\"".to_string()), + ("Timeout".to_string(), "\"30\"".to_string()), + ]; + let out = sanitize_properties(&props); + assert!(out + .iter() + .all(|(name, _)| name != "Timestamp" && name != "LastWriteTime")); + assert!(out.iter().any(|(name, _)| name == "ObjectName")); + assert!(out.iter().any(|(name, _)| name == "RuntimePolicy")); + assert!(out.iter().any(|(name, _)| name == "Timeout")); + } + + #[test] + fn sanitize_properties_redacts_standalone_identity_properties() { + let props = vec![ + ("UserName".to_string(), "\"jsmith\"".to_string()), + ( + "AccountName".to_string(), + "\"DOMAIN\\\\jsmith\"".to_string(), + ), + ("PackageSid".to_string(), "\"S-1-15-3-1\"".to_string()), + ("UserSid".to_string(), "\"S-1-5-21-123\"".to_string()), + ("AccountId".to_string(), "\"42\"".to_string()), + ]; + let out = sanitize_properties(&props); + let value_for = |name: &str| out.iter().find(|(k, _)| k == name).map(|(_, v)| v.as_str()); + assert_eq!(value_for("UserName"), Some(REDACTED_USER)); + assert_eq!(value_for("AccountName"), Some(REDACTED_USER)); + // SIDs are retained identifiers, never redacted. + assert_eq!(value_for("PackageSid"), Some("S-1-15-3-1")); + assert_eq!(value_for("UserSid"), Some("S-1-5-21-123")); + assert_eq!(value_for("AccountId"), Some("42")); + } + + #[test] + fn sanitize_properties_redacts_the_entire_file_path() { + let props = vec![ + ( + "ObjectName".to_string(), + "\"C:\\Users\\jsmith\\secret.txt\"".to_string(), + ), + ( + "AppPath".to_string(), + "\"C:\\Users\\jsmith\\app.exe\"".to_string(), + ), + ( + "ApplicationPath".to_string(), + "\"D:\\Profiles\\alice\\tool.exe\"".to_string(), + ), + ]; + let out = sanitize_properties(&props); + assert_eq!( + out, + vec![ + ("AppPath".to_string(), REDACTED_PATH.to_string()), + ("ApplicationPath".to_string(), REDACTED_PATH.to_string()), + ("ObjectName".to_string(), REDACTED_PATH.to_string()), + ] + ); + } + + #[test] + fn sanitize_properties_redacts_arbitrary_file_path() { + let props = vec![ + ("UserName".to_string(), "\"jsmith\"".to_string()), + ( + "ObjectName".to_string(), + "\"D:\\profiles\\jsmith\\secret.txt\"".to_string(), + ), + ]; + let out = sanitize_properties(&props); + let value_for = |name: &str| out.iter().find(|(k, _)| k == name).map(|(_, v)| v.as_str()); + assert_eq!(value_for("UserName"), Some(REDACTED_USER)); + assert_eq!(value_for("ObjectName"), Some(REDACTED_PATH)); + } + + #[test] + fn sanitize_properties_redacts_absolute_path_despite_non_file_object_type() { + for path in [ + r"C:\Users\alice\secret.txt", + r"\Device\HarddiskVolume3\Users\alice\secret.txt", + r"\Device\Mup\server\share\Users\alice\secret.txt", + ] { + let props = vec![ + ("ObjectType".to_string(), "\"Section\"".to_string()), + ("ObjectName".to_string(), format!("\"{path}\"")), + ]; + + let out = sanitize_properties(&props); + let value_for = + |name: &str| out.iter().find(|(k, _)| k == name).map(|(_, v)| v.as_str()); + assert_eq!(value_for("ObjectName"), Some(REDACTED_PATH)); + assert_eq!(value_for("ObjectType"), Some("Section")); + } + } + + #[test] + fn sanitize_properties_still_redacts_username_in_non_file_identifier() { + let props = vec![ + ("ObjectType".to_string(), "\"Section\"".to_string()), + ("UserName".to_string(), "\"jsmith\"".to_string()), + ( + "ObjectName".to_string(), + "\"\\BaseNamedObjects\\jsmith\\cache\"".to_string(), + ), + ]; + let out = sanitize_properties(&props); + let value_for = |name: &str| out.iter().find(|(k, _)| k == name).map(|(_, v)| v.as_str()); + assert_eq!( + value_for("ObjectName"), + Some(r"\BaseNamedObjects\\cache") + ); + } + + #[test] + fn sanitize_properties_redacts_path_with_qualified_username() { + for (property_name, identity) in [ + ("UserName", r"CONTOSO\jsmith"), + ("UserPrincipalName", "jsmith@example.com"), + ] { + let props = vec![ + (property_name.to_string(), format!("\"{identity}\"")), + ( + "ObjectName".to_string(), + "\"D:\\profiles\\jsmith\\secret.txt\"".to_string(), + ), + ]; + let out = sanitize_properties(&props); + let value_for = |name: &str| { + out.iter() + .find(|(key, _)| key == name) + .map(|(_, value)| value) + }; + assert_eq!( + value_for("ObjectName").map(String::as_str), + Some(REDACTED_PATH) + ); + assert_eq!( + value_for(property_name).map(String::as_str), + Some(REDACTED_USER) + ); + } + } + + #[test] + fn sanitize_properties_redacts_standard_account_identity_fields() { + for (property_name, identity) in [ + ("PrincipalName", "jsmith@example.com"), + ("TargetAccount", r"CONTOSO\jsmith"), + ("SubjectAccount", "jsmith"), + ] { + let props = vec![ + (property_name.to_string(), format!("\"{identity}\"")), + ( + "ObjectName".to_string(), + "\"D:\\profiles\\jsmith\\secret.txt\"".to_string(), + ), + ]; + let out = sanitize_properties(&props); + let value_for = |name: &str| { + out.iter() + .find(|(key, _)| key == name) + .map(|(_, value)| value) + }; + assert_eq!( + value_for(property_name).map(String::as_str), + Some(REDACTED_USER) + ); + assert_eq!( + value_for("ObjectName").map(String::as_str), + Some(REDACTED_PATH) + ); + } + } + + #[test] + fn identity_detection_does_not_match_embedded_name_fragments() { + let props = vec![ + ( + "AccountNamePolicy".to_string(), + "\"retain-this-value\"".to_string(), + ), + ( + "ConsiderationUserName".to_string(), + "\"redact-this-value\"".to_string(), + ), + ]; + + let out = sanitize_properties(&props); + let value_for = |name: &str| { + out.iter() + .find(|(key, _)| key == name) + .map(|(_, value)| value.as_str()) + }; + assert_eq!(value_for("AccountNamePolicy"), Some("retain-this-value")); + assert_eq!(value_for("ConsiderationUserName"), Some(REDACTED_USER)); + } + + #[test] + fn sanitize_properties_redacts_unicode_username_case_variants() { + let props = vec![ + ("UserName".to_string(), "\"JÖRG\"".to_string()), + ( + "ObjectName".to_string(), + "\"D:\\profiles\\jörg\\secret.txt\"".to_string(), + ), + ]; + let out = sanitize_properties(&props); + assert_eq!( + out.iter() + .find(|(name, _)| name == "ObjectName") + .map(|(_, value)| value.as_str()), + Some(REDACTED_PATH) + ); + } + + #[test] + fn sanitize_properties_is_deterministically_sorted_by_name() { + let props = vec![ + ("Zeta".to_string(), "\"z\"".to_string()), + ("Alpha".to_string(), "\"a\"".to_string()), + ]; + let out = sanitize_properties(&props); + assert_eq!( + out, + vec![ + ("Alpha".to_string(), "a".to_string()), + ("Zeta".to_string(), "z".to_string()), + ] + ); + } + + #[test] + fn sanitize_properties_never_carries_a_decoder_error_message() { + // Decode-failure signatures are built by the caller with an empty + // property list (there is no decoded payload to sanitize), so a + // free-form TDH error string can never reach `sanitize_properties` + // in the first place. + let props: Vec<(String, String)> = Vec::new(); + assert!(sanitize_properties(&props).is_empty()); + } + + #[test] + fn bound_properties_preserves_redaction_within_count_and_value_limits() { + let long_value = format!( + r"C:\Users\{}\{}", + "jsmith", + "x".repeat(MAX_SIGNATURE_VALUE_LEN * 2) + ); + let mut props = vec![("ObjectName".to_string(), long_value)]; + for i in 0..(MAX_SIGNATURE_PROPERTIES + 10) { + // `bound_properties` truncates in the given order (callers are + // expected to have already sorted deterministically); appending + // these after `ObjectName` keeps it within the retained prefix. + props.push((format!("Extra{i:03}"), "v".to_string())); + } + let sanitized: Vec<(String, String)> = props + .into_iter() + .map(|(name, value)| { + let value = if looks_like_file_path_property(&name, &value, None) { + REDACTED_PATH.to_string() + } else { + value + }; + (name, value) + }) + .collect(); + + let out = bound_properties(sanitized); + + assert_eq!(out.len(), MAX_SIGNATURE_PROPERTIES); + let object_name = out + .iter() + .find(|(name, _)| name == "ObjectName") + .expect("ObjectName retained (sorted first)"); + assert!( + object_name.1.contains(REDACTED_PATH), + "redaction must survive bounding: {}", + object_name.1 + ); + assert!(!object_name.1.contains(", + message: String, + }, +} + +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +pub(crate) enum EventDecodeKind { + PayloadMalformed, + DecoderLimitReached, + UnsupportedPropertyEncoding, } impl DecodeError { pub(crate) fn is_schema_error(&self) -> bool { matches!(self, Self::Schema(_)) } + + pub(crate) fn event_kind(&self) -> Option { + match self { + Self::Event { kind, .. } => Some(*kind), + Self::Schema(_) => None, + } + } + + pub(crate) fn event_name(&self) -> Option<&str> { + match self { + Self::Event { event_name, .. } => event_name.as_deref(), + Self::Schema(_) => None, + } + } + + pub(crate) fn event( + kind: EventDecodeKind, + message: String, + event_name: Option, + ) -> Self { + Self::Event { + kind, + event_name, + message, + } + } } impl std::fmt::Display for DecodeError { fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { match self { - Self::Schema(message) | Self::Event(message) => f.write_str(message), + Self::Schema(message) | Self::Event { message, .. } => f.write_str(message), } } } @@ -164,36 +201,16 @@ pub unsafe fn decode_event_parts( schema_cache: &mut EventSchemaCache, ) -> Result { let event = unsafe { &*event_record }; - let key = EventSchemaKey::from_record(event); let mut uncached_schema = None; - let cacheable = !unsafe { has_trace_logging_schema(event) }; - if !cacheable { - uncached_schema = Some(unsafe { load_event_schema(event_record) }?); - } else if !schema_cache.schemas.contains_key(&key) { - let schema = unsafe { load_event_schema(event_record) }?; - if schema_cache.schemas.len() < MAX_SCHEMA_CACHE_ENTRIES { - schema_cache.schemas.insert(key, schema); - } else { - uncached_schema = Some(schema); - } - } - let buffer = if cacheable { - schema_cache - .schemas - .get(&key) - .ok_or_else(|| DecodeError::Schema("event schema cache lookup failed".to_string()))? - } else { - uncached_schema - .as_ref() - .ok_or_else(|| DecodeError::Schema("uncached event schema missing".to_string()))? - }; + let buffer = unsafe { event_schema(event_record, event, schema_cache, &mut uncached_schema) }?; let info = unsafe { &*buffer.as_ptr() }; let header = event.EventHeader; let event_id = header.EventDescriptor.Id; let pointer_size = pointer_size_from_header_flags(header.Flags); + let event_name = schema_event_name(buffer.as_bytes(), info); let props = decode_properties(buffer.as_bytes(), info, event_record, pointer_size) - .map_err(DecodeError::Event)?; + .map_err(|error| map_property_decode_error(error, event_name))?; Ok(DecodedEventParts { provider: header.ProviderId, @@ -202,6 +219,103 @@ pub unsafe fn decode_event_parts( }) } +/// Decodes one named property without decoding properties that follow it. +/// +/// # Safety +/// `event_record` must satisfy the same requirements as [`decode_event_parts`]. +pub unsafe fn decode_event_property( + event_record: *mut EVENT_RECORD, + schema_cache: &mut EventSchemaCache, + property_name: &str, +) -> Result, DecodeError> { + let event = unsafe { &*event_record }; + let mut uncached_schema = None; + let buffer = unsafe { event_schema(event_record, event, schema_cache, &mut uncached_schema) }?; + let info = unsafe { &*buffer.as_ptr() }; + let event_name = schema_event_name(buffer.as_bytes(), info); + decode_named_property( + buffer.as_bytes(), + info, + event_record, + pointer_size_from_header_flags(event.EventHeader.Flags), + property_name, + ) + .map_err(|error| map_property_decode_error(error, event_name)) +} + +unsafe fn event_schema<'a>( + event_record: *mut EVENT_RECORD, + event: &EVENT_RECORD, + schema_cache: &'a mut EventSchemaCache, + uncached_schema: &'a mut Option, +) -> Result<&'a TdhInfoBuffer, DecodeError> { + let key = EventSchemaKey::from_record(event); + let cacheable = !unsafe { has_trace_logging_schema(event) }; + if !cacheable { + *uncached_schema = Some(unsafe { load_event_schema(event_record) }?); + } else if !schema_cache.schemas.contains_key(&key) { + let schema = unsafe { load_event_schema(event_record) }?; + cache_or_retain_schema(schema_cache, key, schema, uncached_schema); + } + schema_buffer(schema_cache, &key, uncached_schema) +} + +fn cache_or_retain_schema( + schema_cache: &mut EventSchemaCache, + key: EventSchemaKey, + schema: TdhInfoBuffer, + uncached_schema: &mut Option, +) { + if schema_cache.schemas.len() < MAX_SCHEMA_CACHE_ENTRIES { + schema_cache.schemas.insert(key, schema); + } else { + *uncached_schema = Some(schema); + } +} + +fn schema_buffer<'a>( + schema_cache: &'a EventSchemaCache, + key: &EventSchemaKey, + uncached_schema: &'a Option, +) -> Result<&'a TdhInfoBuffer, DecodeError> { + if let Some(buffer) = uncached_schema { + return Ok(buffer); + } + schema_cache + .schemas + .get(key) + .ok_or_else(|| DecodeError::Schema("event schema cache lookup failed".to_string())) +} + +fn map_property_decode_error( + error: PropertyDecodeError, + event_name: Option, +) -> DecodeError { + match error.kind { + PropertyDecodeErrorKind::Schema => DecodeError::Schema(error.message), + PropertyDecodeErrorKind::PayloadMalformed => { + DecodeError::event(EventDecodeKind::PayloadMalformed, error.message, event_name) + } + PropertyDecodeErrorKind::DecoderLimitReached => DecodeError::event( + EventDecodeKind::DecoderLimitReached, + error.message, + event_name, + ), + PropertyDecodeErrorKind::UnsupportedPropertyEncoding => DecodeError::event( + EventDecodeKind::UnsupportedPropertyEncoding, + error.message, + event_name, + ), + } +} + +fn schema_event_name(info_buf: &[u8], info: &TRACE_EVENT_INFO) -> Option { + // SAFETY: `info` points into the TDH buffer and this union member is the + // event-name offset for the decoding sources used by these providers. + let event_name_offset = unsafe { info.Anonymous1.EventNameOffset }; + wide_str_at(info_buf, event_name_offset).or_else(|| wide_str_at(info_buf, info.TaskNameOffset)) +} + unsafe fn load_event_schema(event_record: *mut EVENT_RECORD) -> Result { let mut buf_size: u32 = 0; // First call: discover required buffer size. ERROR_INSUFFICIENT_BUFFER = 122. @@ -242,14 +356,59 @@ unsafe fn has_trace_logging_schema(event_record: &EVENT_RECORD) -> bool { .any(|item| u32::from(item.ExtType) == EVENT_HEADER_EXT_TYPE_EVENT_SCHEMA_TL) } +#[derive(Debug, Clone, Copy, PartialEq, Eq)] +enum PropertyDecodeErrorKind { + Schema, + PayloadMalformed, + DecoderLimitReached, + UnsupportedPropertyEncoding, +} + +#[derive(Debug)] +struct PropertyDecodeError { + kind: PropertyDecodeErrorKind, + message: String, +} + +impl PropertyDecodeError { + fn schema(message: String) -> Self { + Self { + kind: PropertyDecodeErrorKind::Schema, + message, + } + } + + fn payload(message: String) -> Self { + Self { + kind: PropertyDecodeErrorKind::PayloadMalformed, + message, + } + } + + fn limit(message: String) -> Self { + Self { + kind: PropertyDecodeErrorKind::DecoderLimitReached, + message, + } + } + + fn unsupported(message: String) -> Self { + Self { + kind: PropertyDecodeErrorKind::UnsupportedPropertyEncoding, + message, + } + } +} + fn decode_properties( info_buf: &[u8], info: &TRACE_EVENT_INFO, event_record: *mut EVENT_RECORD, pointer_size: usize, -) -> Result, String> { - // SAFETY: caller passes a valid EVENT_RECORD; the field accesses - // are reads of POD fields. +) -> Result, PropertyDecodeError> { + // SAFETY: `decode_event_property` and the ETW callback supply a non-null + // `EVENT_RECORD` that remains valid for this synchronous decode. This + // borrow reads only its fixed-size header fields. let event = unsafe { &*event_record }; let user_data = event.UserData as *const u8; let user_data_len = event.UserDataLength as usize; @@ -261,10 +420,11 @@ fn decode_properties( let property_count = info.PropertyCount as usize; let prop_count = info.TopLevelPropertyCount as usize; if prop_count > property_count { - return Err(format!( + return Err(PropertyDecodeError::schema(format!( "top-level property count {prop_count} exceeds property count {property_count}" - )); + ))); } + let mut results = Vec::with_capacity(prop_count); let mut numeric_values = vec![None; property_count]; let mut offset: usize = 0; @@ -292,6 +452,62 @@ fn decode_properties( Ok(results) } +fn decode_named_property( + info_buf: &[u8], + info: &TRACE_EVENT_INFO, + event_record: *mut EVENT_RECORD, + pointer_size: usize, + property_name: &str, +) -> Result, PropertyDecodeError> { + // SAFETY: caller passes a valid EVENT_RECORD; the field accesses + // are reads of POD fields. + let event = unsafe { &*event_record }; + let user_data = event.UserData as *const u8; + let user_data_len = event.UserDataLength as usize; + if user_data.is_null() || user_data_len == 0 { + return Ok(None); + } + + let property_count = info.PropertyCount as usize; + let prop_count = info.TopLevelPropertyCount as usize; + if prop_count > property_count { + return Err(PropertyDecodeError::schema(format!( + "top-level property count {prop_count} exceeds property count {property_count}" + ))); + } + + let mut numeric_values = vec![None; property_count]; + let mut offset = 0; + let mut work_remaining = MAX_DECODE_WORK; + let mut decoded = Vec::new(); + let context = PropertyDecodeContext { + info_buf, + info, + user_data, + user_data_len, + pointer_size, + }; + for index in 0..prop_count { + decode_property( + index, + &context, + &mut offset, + &mut numeric_values, + 0, + &mut work_remaining, + &mut decoded, + )?; + if let Some((_, value)) = decoded + .iter() + .find(|(name, _)| name.eq_ignore_ascii_case(property_name)) + { + return Ok(Some(value.clone())); + } + decoded.clear(); + } + Ok(None) +} + struct PropertyDecodeContext<'a> { info_buf: &'a [u8], info: &'a TRACE_EVENT_INFO, @@ -308,15 +524,21 @@ fn decode_property( depth: usize, work_remaining: &mut usize, results: &mut Vec<(String, String)>, -) -> Result<(), String> { - *work_remaining = work_remaining - .checked_sub(1) - .ok_or_else(|| format!("property decode work exceeds limit {MAX_DECODE_WORK}"))?; +) -> Result<(), PropertyDecodeError> { + *work_remaining = work_remaining.checked_sub(1).ok_or_else(|| { + PropertyDecodeError::limit(format!( + "property decode work exceeds limit {MAX_DECODE_WORK}" + )) + })?; if depth > MAX_STRUCT_DEPTH { - return Err(format!("property nesting exceeds limit {MAX_STRUCT_DEPTH}")); + return Err(PropertyDecodeError::limit(format!( + "property nesting exceeds limit {MAX_STRUCT_DEPTH}" + ))); } if index >= context.info.PropertyCount as usize { - return Err(format!("property index {index} is out of range")); + return Err(PropertyDecodeError::schema(format!( + "property index {index} is out of range" + ))); } let prop_info = event_property_info(context.info, index); let prop_name = wide_str_at(context.info_buf, prop_info.NameOffset) @@ -324,25 +546,29 @@ fn decode_property( let flags = prop_info.Flags.0; let count = resolve_property_count(prop_info, flags, numeric_values, index)?; if count > MAX_PROPERTY_ELEMENTS { - return Err(format!( + return Err(PropertyDecodeError::limit(format!( "property '{prop_name}' count {count} exceeds limit {MAX_PROPERTY_ELEMENTS}" - )); + ))); } if flags & PROPERTY_STRUCT != 0 { let start_index = unsafe { prop_info.Anonymous1.structType.StructStartIndex } as usize; let member_count = unsafe { prop_info.Anonymous1.structType.NumOfStructMembers } as usize; - let end_index = start_index - .checked_add(member_count) - .ok_or_else(|| format!("property '{prop_name}' struct member range overflows"))?; + let end_index = start_index.checked_add(member_count).ok_or_else(|| { + PropertyDecodeError::schema(format!( + "property '{prop_name}' struct member range overflows" + )) + })?; if end_index > context.info.PropertyCount as usize { - return Err(format!( + return Err(PropertyDecodeError::schema(format!( "property '{prop_name}' struct member range {start_index}..{end_index} exceeds property count {}", context.info.PropertyCount - )); + ))); } if member_count == 0 { - return Err(format!("property '{prop_name}' has no struct members")); + return Err(PropertyDecodeError::schema(format!( + "property '{prop_name}' has no struct members" + ))); } results.push((prop_name, "".to_string())); for _ in 0..count { @@ -378,7 +604,9 @@ fn decode_property( for _ in 0..count { let remaining = context.user_data_len.saturating_sub(*offset); if remaining == 0 { - return Err(format!("property '{prop_name}' exceeds the event payload")); + return Err(PropertyDecodeError::payload(format!( + "property '{prop_name}' exceeds the event payload" + ))); } let data_ptr = if remaining > 0 { unsafe { context.user_data.add(*offset) } @@ -393,15 +621,17 @@ fn decode_property( context.pointer_size, ); if consumed == 0 && remaining > 0 { - return Err(format!( - "property '{prop_name}' has unsupported variable length" - )); + return Err(zero_consumption_error(&prop_name, in_type)); } *offset = offset .checked_add(consumed) .filter(|next| *next <= context.user_data_len) - .ok_or_else(|| format!("property '{prop_name}' exceeds the event payload"))?; + .ok_or_else(|| { + PropertyDecodeError::payload(format!( + "property '{prop_name}' exceeds the event payload" + )) + })?; if count == 1 { numeric_value = parse_numeric_metadata(&value); } @@ -423,7 +653,7 @@ fn resolve_property_count( flags: i32, numeric_values: &[Option], property_index: usize, -) -> Result { +) -> Result { if flags & PROPERTY_PARAM_COUNT != 0 { let count_index = unsafe { prop_info.Anonymous2.countPropertyIndex } as usize; resolved_metadata(numeric_values, count_index, "count", property_index) @@ -465,15 +695,56 @@ fn resolved_metadata( metadata_index: usize, kind: &str, property_index: usize, -) -> Result { - numeric_values - .get(metadata_index) - .and_then(|value| *value) - .ok_or_else(|| { - format!( - "property {property_index} references unresolved {kind} property {metadata_index}" - ) - }) +) -> Result { + let Some(value) = numeric_values.get(metadata_index) else { + return Err(PropertyDecodeError::schema(format!( + "property {property_index} references out-of-range {kind} property {metadata_index}" + ))); + }; + value.ok_or_else(|| { + PropertyDecodeError::schema(format!( + "property {property_index} references unresolved {kind} property {metadata_index}" + )) + }) +} + +fn is_known_property_type(in_type: u16) -> bool { + matches!( + in_type, + TDH_INTYPE_UNICODESTRING + | TDH_INTYPE_ANSISTRING + | TDH_INTYPE_INT8 + | TDH_INTYPE_UINT8 + | TDH_INTYPE_INT16 + | TDH_INTYPE_UINT16 + | TDH_INTYPE_INT32 + | TDH_INTYPE_UINT32 + | TDH_INTYPE_INT64 + | TDH_INTYPE_UINT64 + | TDH_INTYPE_FLOAT + | TDH_INTYPE_DOUBLE + | TDH_INTYPE_BOOLEAN + | TDH_INTYPE_BINARY + | TDH_INTYPE_GUID + | TDH_INTYPE_POINTER + | TDH_INTYPE_FILETIME + | TDH_INTYPE_SYSTEMTIME + | TDH_INTYPE_SID + | TDH_INTYPE_HEXINT32 + | TDH_INTYPE_HEXINT64 + | TDH_INTYPE_UNICODECHAR + | TDH_INTYPE_ANSICHAR + | TDH_INTYPE_SIZET + ) +} + +fn zero_consumption_error(property_name: &str, in_type: u16) -> PropertyDecodeError { + let message = format!("property '{property_name}' could not be decoded"); + if is_known_property_type(in_type) { + PropertyDecodeError::payload(message) + } else { + PropertyDecodeError::unsupported(message) + } } fn parse_numeric_metadata(value: &str) -> Option { @@ -663,12 +934,12 @@ fn format_property_value( fn format_sid(data: *const u8, available: usize) -> (String, usize) { let header = unsafe { std::slice::from_raw_parts(data, available.min(8)) }; if header.len() < 8 { - return ("".to_string(), available); + return ("".to_string(), 0); } let sub_authority_count = header[1] as usize; let length = 8usize.saturating_add(sub_authority_count.saturating_mul(4)); if length > available { - return ("".to_string(), available); + return ("".to_string(), 0); } let bytes = unsafe { std::slice::from_raw_parts(data, length) }; let authority = bytes[2..8] @@ -734,6 +1005,47 @@ mod tests { .collect() } + fn uint32_property_buffer(names: &[&str]) -> TdhInfoBuffer { + assert!(!names.is_empty()); + let encoded_names = names + .iter() + .map(|name| utf16_bytes(name)) + .collect::>(); + let metadata_len = std::mem::size_of::() + + (names.len() - 1) * std::mem::size_of::(); + let mut offsets = Vec::with_capacity(names.len()); + let mut next_offset = metadata_len; + for name in &encoded_names { + offsets.push(next_offset); + next_offset += name.len(); + } + + let mut buffer = TdhInfoBuffer::new(next_offset); + for (name, offset) in encoded_names.iter().zip(&offsets) { + buffer.as_bytes_mut()[*offset..*offset + name.len()].copy_from_slice(name); + } + let info = unsafe { &mut *buffer.as_mut_ptr() }; + info.PropertyCount = names.len() as u32; + info.TopLevelPropertyCount = names.len() as u32; + let properties = + std::ptr::addr_of_mut!(info.EventPropertyInfoArray) as *mut EVENT_PROPERTY_INFO; + for (index, offset) in offsets.into_iter().enumerate() { + let property = unsafe { &mut *properties.add(index) }; + property.NameOffset = offset as u32; + property.Anonymous1.nonStructType.InType = TDH_INTYPE_UINT32; + property.Anonymous2.count = 1; + property.Anonymous3.length = 4; + } + buffer + } + + fn event_record_for_payload(payload: &[u8]) -> EVENT_RECORD { + let mut record: EVENT_RECORD = unsafe { core::mem::zeroed() }; + record.UserData = payload.as_ptr().cast_mut().cast(); + record.UserDataLength = payload.len() as u16; + record + } + #[test] fn tdh_info_buffer_is_aligned_and_initialized() { let mut buffer = TdhInfoBuffer::new(std::mem::size_of::() + 7); @@ -747,6 +1059,37 @@ mod tests { assert!(buffer.as_bytes().iter().all(|byte| *byte == 0)); } + #[test] + fn schema_is_retained_uncached_at_cache_capacity() { + let mut cache = EventSchemaCache::default(); + for id in 0..MAX_SCHEMA_CACHE_ENTRIES { + let mut record: EVENT_RECORD = unsafe { core::mem::zeroed() }; + record.EventHeader.EventDescriptor.Id = id as u16; + let mut uncached = None; + cache_or_retain_schema( + &mut cache, + EventSchemaKey::from_record(&record), + TdhInfoBuffer::new(1), + &mut uncached, + ); + assert!(uncached.is_none()); + } + + let mut overflow_record: EVENT_RECORD = unsafe { core::mem::zeroed() }; + overflow_record.EventHeader.EventDescriptor.Id = MAX_SCHEMA_CACHE_ENTRIES as u16; + let overflow_key = EventSchemaKey::from_record(&overflow_record); + let mut uncached = None; + cache_or_retain_schema( + &mut cache, + overflow_key, + TdhInfoBuffer::new(std::mem::size_of::()), + &mut uncached, + ); + + assert_eq!(cache.schemas.len(), MAX_SCHEMA_CACHE_ENTRIES); + assert!(schema_buffer(&cache, &overflow_key, &uncached).is_ok()); + } + #[test] fn decode_property_surfaces_struct_children() { let struct_name = utf16_bytes("AccessCheck"); @@ -812,10 +1155,54 @@ mod tests { assert_eq!(offset, payload.len()); } + #[test] + fn decode_named_property_stops_after_requested_property() { + let buffer = uint32_property_buffer(&["Count", "ProcessId", "Trailing"]); + let payload = [7u32, 42] + .into_iter() + .flat_map(u32::to_le_bytes) + .collect::>(); + let mut record = event_record_for_payload(&payload); + let info = unsafe { &*buffer.as_ptr() }; + + let process_id = + decode_named_property(buffer.as_bytes(), info, &mut record, 8, "processid").unwrap(); + + assert_eq!(process_id.as_deref(), Some("42")); + } + + #[test] + fn decode_named_property_reports_missing_and_truncated_properties() { + let buffer = uint32_property_buffer(&["Count", "ProcessId"]); + let payload = [7u32, 42] + .into_iter() + .flat_map(u32::to_le_bytes) + .collect::>(); + let mut record = event_record_for_payload(&payload); + let info = unsafe { &*buffer.as_ptr() }; + + assert_eq!( + decode_named_property(buffer.as_bytes(), info, &mut record, 8, "Missing").unwrap(), + None + ); + + let truncated_payload = 7u32.to_le_bytes(); + let mut truncated_record = event_record_for_payload(&truncated_payload); + let error = decode_named_property( + buffer.as_bytes(), + info, + &mut truncated_record, + 8, + "ProcessId", + ) + .unwrap_err(); + assert_eq!(error.kind, PropertyDecodeErrorKind::PayloadMalformed); + } + fn decode_single_property( buffer: &TdhInfoBuffer, payload: &[u8], - ) -> Result, String> { + ) -> Result, PropertyDecodeError> { let info = unsafe { &*buffer.as_ptr() }; let context = PropertyDecodeContext { info_buf: buffer.as_bytes(), @@ -860,7 +1247,8 @@ mod tests { let error = decode_single_property(&buffer, &[1]).unwrap_err(); - assert!(error.contains("struct member range")); + assert_eq!(error.kind, PropertyDecodeErrorKind::Schema); + assert!(error.message.contains("struct member range")); } #[test] @@ -883,7 +1271,8 @@ mod tests { let error = decode_single_property(&buffer, &[1]).unwrap_err(); - assert!(error.contains("has no struct members")); + assert_eq!(error.kind, PropertyDecodeErrorKind::Schema); + assert!(error.message.contains("has no struct members")); } #[test] @@ -906,17 +1295,29 @@ mod tests { let error = decode_single_property(&buffer, &[1]).unwrap_err(); - assert!(error.contains("nesting exceeds limit")); + assert_eq!(error.kind, PropertyDecodeErrorKind::DecoderLimitReached); + assert!(error.message.contains("nesting exceeds limit")); } #[test] fn invalid_metadata_references_are_rejected() { - assert!(resolved_metadata(&[None], 3, "count", 0) - .unwrap_err() - .contains("unresolved count property 3")); - assert!(resolved_metadata(&[None], 2, "length", 0) - .unwrap_err() - .contains("unresolved length property 2")); + let count_error = resolved_metadata(&[None], 3, "count", 0).unwrap_err(); + assert_eq!(count_error.kind, PropertyDecodeErrorKind::Schema); + assert!(count_error + .message + .contains("out-of-range count property 3")); + + let length_error = resolved_metadata(&[None], 2, "length", 0).unwrap_err(); + assert_eq!(length_error.kind, PropertyDecodeErrorKind::Schema); + assert!(length_error + .message + .contains("out-of-range length property 2")); + + let unresolved_error = resolved_metadata(&[None], 0, "count", 1).unwrap_err(); + assert_eq!(unresolved_error.kind, PropertyDecodeErrorKind::Schema); + assert!(unresolved_error + .message + .contains("unresolved count property 0")); } #[test] @@ -960,7 +1361,8 @@ mod tests { ) .unwrap_err(); - assert!(error.contains("decode work exceeds limit")); + assert_eq!(error.kind, PropertyDecodeErrorKind::DecoderLimitReached); + assert!(error.message.contains("decode work exceeds limit")); } #[test] @@ -980,6 +1382,18 @@ mod tests { assert!(wide_str_at(&buf, 0).is_none()); } + #[test] + fn property_decode_errors_use_typed_categories() { + assert_eq!( + zero_consumption_error("Name", TDH_INTYPE_UNICODESTRING).kind, + PropertyDecodeErrorKind::PayloadMalformed + ); + assert_eq!( + zero_consumption_error("Value", u16::MAX).kind, + PropertyDecodeErrorKind::UnsupportedPropertyEncoding + ); + } + #[test] fn format_property_value_unicode_string_extracts_content() { let s = "hello"; @@ -1207,7 +1621,7 @@ mod tests { let bytes = [1u8, 3, 0, 0, 0, 0, 0, 15]; let (val, consumed) = format_property_value(TDH_INTYPE_SID, 0, bytes.as_ptr(), bytes.len()); assert_eq!(val, ""); - assert_eq!(consumed, bytes.len()); + assert_eq!(consumed, 0); } #[test] diff --git a/src/core/learning_mode_core/Cargo.toml b/src/core/learning_mode_core/Cargo.toml index 0f9288641..5ec4c520c 100644 --- a/src/core/learning_mode_core/Cargo.toml +++ b/src/core/learning_mode_core/Cargo.toml @@ -7,4 +7,7 @@ license.workspace = true [dependencies] serde = { workspace = true } serde_json = { workspace = true } +same-file = { workspace = true } +sha2 = { workspace = true } +tempfile = { workspace = true } thiserror = { workspace = true } diff --git a/src/core/learning_mode_core/src/analyze.rs b/src/core/learning_mode_core/src/analyze.rs index 534f0f46f..644db4b83 100644 --- a/src/core/learning_mode_core/src/analyze.rs +++ b/src/core/learning_mode_core/src/analyze.rs @@ -17,6 +17,7 @@ use serde::{Deserialize, Serialize}; use thiserror::Error; use crate::model::DeniedResource; +use crate::verbose_logging::{VerboseLoggingAggregate, VerboseLoggingSummary}; /// Result of decoding a capture source into bounded, de-duplicated denials. #[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize)] @@ -27,6 +28,9 @@ pub struct AnalysisResult { /// Whether additional unique denials were observed after the result bound /// was reached. pub denied_resources_truncated: bool, + /// Username-redacted signatures for outcomes omitted from canonical denials. + #[serde(default)] + pub verbose_logging: VerboseLoggingSummary, } /// Inclusive process-lifetime window used to scope a host-wide capture. @@ -61,8 +65,132 @@ impl AnalysisResult { Self { denials, denied_resources_truncated: false, + verbose_logging: VerboseLoggingSummary::default(), } } + + /// Trims verbose logging signatures so the complete compact JSON + /// serialization is no larger than `max_bytes`. + /// + /// Returns `false` when the canonical denials and empty verbose logging envelope + /// alone exceed `max_bytes`; canonical denials are never discarded. + pub fn fit_verbose_logging_within_serialized_bytes( + &mut self, + max_bytes: usize, + ) -> Result { + if serde_json::to_vec(self)?.len() <= max_bytes { + return Ok(true); + } + + let base_len = + serialized_analysis_len(self, &[], self.verbose_logging.signatures.as_slice())?; + if base_len > max_bytes { + return Ok(false); + } + + let original = std::mem::take(&mut self.verbose_logging.signatures); + let mut retained_bytes = 0usize; + const ENVELOPE_HEADROOM: usize = 4 * 1024; + let signature_budget = max_bytes + .saturating_sub(base_len) + .saturating_sub(ENVELOPE_HEADROOM); + let mut original = original; + original.sort_by_key(|aggregate| !aggregate.signature.reason.is_canonical_denial()); + for aggregate in original { + let aggregate_len = serde_json::to_vec(&aggregate)?.len().saturating_add(1); + if retained_bytes.saturating_add(aggregate_len) <= signature_budget { + retained_bytes += aggregate_len; + self.verbose_logging.signatures.push(aggregate); + } else { + self.verbose_logging.move_to_overflow(aggregate); + } + } + + let mut retained = std::mem::take(&mut self.verbose_logging.signatures); + let serialized_len = |retained_count: usize| { + serialized_analysis_len( + self, + &retained[..retained_count], + &retained[retained_count..], + ) + }; + let mut low = 0usize; + let mut high = retained.len(); + while low < high { + let middle = low + (high - low).div_ceil(2); + if serialized_len(middle)? <= max_bytes { + low = middle; + } else { + high = middle - 1; + } + } + let removed = retained.split_off(low); + self.verbose_logging.signatures = retained; + for aggregate in removed { + self.verbose_logging.move_to_overflow(aggregate); + } + self.verbose_logging + .signatures + .sort_by(|left, right| left.signature.cmp(&right.signature)); + Ok(serde_json::to_vec(self)?.len() <= max_bytes) + } +} + +fn serialized_analysis_len( + analysis: &AnalysisResult, + retained: &[VerboseLoggingAggregate], + removed: &[VerboseLoggingAggregate], +) -> Result { + #[derive(Serialize)] + #[serde(rename_all = "camelCase")] + struct AnalysisView<'a> { + denials: &'a [DeniedResource], + denied_resources_truncated: bool, + verbose_logging: VerboseLoggingView<'a>, + } + + #[derive(Serialize)] + #[serde(rename_all = "camelCase")] + struct VerboseLoggingView<'a> { + signatures: &'a [VerboseLoggingAggregate], + total_occurrences: u64, + overflow_occurrences: u64, + canonical_overflow_occurrences: u64, + aggregate_groups_truncated: bool, + processed_events_truncated: bool, + canonical_denial_limit_reached: bool, + } + + let removed_occurrences = removed.iter().fold(0u64, |total, aggregate| { + total.saturating_add(aggregate.count) + }); + let removed_canonical_occurrences = removed + .iter() + .filter(|aggregate| aggregate.signature.reason.is_canonical_denial()) + .fold(0u64, |total, aggregate| { + total.saturating_add(aggregate.count) + }); + let view = AnalysisView { + denials: &analysis.denials, + denied_resources_truncated: analysis.denied_resources_truncated, + verbose_logging: VerboseLoggingView { + signatures: retained, + total_occurrences: analysis.verbose_logging.total_occurrences, + overflow_occurrences: analysis + .verbose_logging + .overflow_occurrences + .saturating_add(removed_occurrences), + canonical_overflow_occurrences: analysis + .verbose_logging + .canonical_overflow_occurrences + .saturating_add(removed_canonical_occurrences), + aggregate_groups_truncated: analysis.verbose_logging.aggregate_groups_truncated + || !removed.is_empty(), + processed_events_truncated: analysis.verbose_logging.processed_events_truncated, + canonical_denial_limit_reached: analysis.verbose_logging.canonical_denial_limit_reached, + }, + }; + serde_json::to_vec(&view).map(|bytes| bytes.len()) } /// Failure modes when analysing a capture source into denials. @@ -108,6 +236,10 @@ pub trait DenialAnalyzer { mod tests { use super::*; use crate::model::{AccessType, ResourceType}; + use crate::verbose_logging::{ + VerboseLoggingAggregate, VerboseLoggingExclusionReason, VerboseLoggingProvider, + VerboseLoggingSignature, + }; /// A trivial analyzer returning a fixed set, proving the trait is /// object-safe and usable behind a `dyn` reference. @@ -132,6 +264,14 @@ mod tests { let got = analyzer.analyze(Path::new("ignored.etl")).unwrap(); assert_eq!(got.denials, denials); assert!(!got.denied_resources_truncated); + assert!(got.verbose_logging.is_empty()); + } + + #[test] + fn analysis_payload_without_verbose_logging_defaults_summary() { + let payload = br#"{"denials":[],"deniedResourcesTruncated":false}"#; + let result: AnalysisResult = serde_json::from_slice(payload).unwrap(); + assert!(result.verbose_logging.is_empty()); } #[test] @@ -160,4 +300,164 @@ mod tests { assert!(!lifetime.contains(42, 201)); assert!(!lifetime.contains(43, 150)); } + + #[test] + fn serialized_size_limit_moves_verbose_logging_groups_to_overflow() { + let signature = |pid| VerboseLoggingAggregate { + signature: VerboseLoggingSignature { + provider: VerboseLoggingProvider::KernelGeneral, + provider_guid: "provider".to_string(), + event_id: 14, + reason: VerboseLoggingExclusionReason::CanonicalDenial, + pid, + access_type: Some(AccessType::Read), + resource_type: Some(ResourceType::File), + properties: vec![("ObjectName".to_string(), "x".repeat(4_096))], + }, + count: 3, + }; + let mut result = AnalysisResult { + denials: vec![DeniedResource { + resource: "canonical".repeat(512), + resource_type: ResourceType::File, + access_type: AccessType::Read, + pid: 1, + filetime: 2, + }], + denied_resources_truncated: false, + verbose_logging: VerboseLoggingSummary { + signatures: vec![signature(1), signature(2)], + total_occurrences: 6, + ..Default::default() + }, + }; + let original_len = serde_json::to_vec(&result).unwrap().len(); + + assert!(result + .fit_verbose_logging_within_serialized_bytes(original_len - 1) + .unwrap()); + assert!(serde_json::to_vec(&result).unwrap().len() < original_len); + assert!(result.verbose_logging.aggregate_groups_truncated); + assert_eq!(result.verbose_logging.total_occurrences, 6); + assert!(result.verbose_logging.overflow_occurrences > 0); + } + + #[test] + fn serialized_size_limit_saturates_overflow_counters() { + let mut result = AnalysisResult { + denials: Vec::new(), + denied_resources_truncated: false, + verbose_logging: VerboseLoggingSummary { + signatures: vec![VerboseLoggingAggregate { + signature: VerboseLoggingSignature { + provider: VerboseLoggingProvider::KernelGeneral, + provider_guid: "provider".to_string(), + event_id: 14, + reason: VerboseLoggingExclusionReason::CanonicalDenial, + pid: 1, + access_type: Some(AccessType::Read), + resource_type: Some(ResourceType::File), + properties: vec![("ObjectName".to_string(), "x".repeat(4_096))], + }, + count: 3, + }], + total_occurrences: u64::MAX, + overflow_occurrences: u64::MAX - 1, + canonical_overflow_occurrences: u64::MAX - 1, + ..Default::default() + }, + }; + let original_len = serde_json::to_vec(&result).unwrap().len(); + + assert!(result + .fit_verbose_logging_within_serialized_bytes(original_len - 1) + .unwrap()); + assert_eq!(result.verbose_logging.overflow_occurrences, u64::MAX); + assert_eq!( + result.verbose_logging.canonical_overflow_occurrences, + u64::MAX + ); + } + + #[test] + fn serialized_size_limit_never_discards_canonical_denials() { + let mut result = AnalysisResult { + denials: vec![DeniedResource { + resource: "canonical".repeat(512), + resource_type: ResourceType::File, + access_type: AccessType::Read, + pid: 1, + filetime: 2, + }], + denied_resources_truncated: false, + verbose_logging: VerboseLoggingSummary { + signatures: vec![VerboseLoggingAggregate { + signature: VerboseLoggingSignature { + provider: VerboseLoggingProvider::KernelGeneral, + provider_guid: "provider".to_string(), + event_id: 14, + reason: VerboseLoggingExclusionReason::CanonicalDenial, + pid: 1, + access_type: Some(AccessType::Read), + resource_type: Some(ResourceType::File), + properties: vec![("ObjectName".to_string(), "value".to_string())], + }, + count: 1, + }], + total_occurrences: 1, + ..Default::default() + }, + }; + let original = result.clone(); + + assert!(!result + .fit_verbose_logging_within_serialized_bytes(1) + .unwrap()); + assert_eq!(result, original); + assert!(result + .fit_verbose_logging_within_serialized_bytes( + serde_json::to_vec(&original).unwrap().len() + ) + .unwrap()); + assert_eq!(result, original); + } + + #[test] + fn serialized_size_limit_handles_maximum_signature_count() { + let signatures = (0..crate::verbose_logging::MAX_VERBOSE_LOGGING_GROUPS) + .map(|pid| VerboseLoggingAggregate { + signature: VerboseLoggingSignature { + provider: VerboseLoggingProvider::KernelGeneral, + provider_guid: "provider".to_string(), + event_id: 14, + reason: VerboseLoggingExclusionReason::MissingObjectName, + pid: u32::try_from(pid).unwrap(), + access_type: Some(AccessType::Read), + resource_type: Some(ResourceType::File), + properties: vec![("ObjectName".to_string(), "x".repeat(256))], + }, + count: 1, + }) + .collect(); + let mut result = AnalysisResult { + denials: Vec::new(), + denied_resources_truncated: false, + verbose_logging: VerboseLoggingSummary { + signatures, + total_occurrences: crate::verbose_logging::MAX_VERBOSE_LOGGING_GROUPS as u64, + ..Default::default() + }, + }; + + assert!(result + .fit_verbose_logging_within_serialized_bytes(64 * 1024) + .unwrap()); + assert!(serde_json::to_vec(&result).unwrap().len() <= 64 * 1024); + assert!(!result.verbose_logging.signatures.is_empty()); + assert_eq!( + result.verbose_logging.signatures.len() as u64 + + result.verbose_logging.overflow_occurrences, + crate::verbose_logging::MAX_VERBOSE_LOGGING_GROUPS as u64 + ); + } } diff --git a/src/core/learning_mode_core/src/lib.rs b/src/core/learning_mode_core/src/lib.rs index b6d79508b..a505b767e 100644 --- a/src/core/learning_mode_core/src/lib.rs +++ b/src/core/learning_mode_core/src/lib.rs @@ -12,14 +12,15 @@ //! [`DeniedResource`] records. The per-OS decoder implements //! [`DenialAnalyzer`]; this crate owns the trait and the model. //! 3. **Emit** — the records plus a terminating [`DenialSummary`] are -//! written to a single JSON output file that host applications read to -//! regenerate their sandbox policy. See [`emit`]. +//! written to the canonical JSON output that host applications read to +//! regenerate policy. A deterministic verbose logging sibling contains bounded, +//! sensitive-value-redacted signatures for excluded decoder outcomes. //! //! This crate is the cross-platform hinge between stages 2 and 3: it //! defines the public [`DeniedResource`] model, the [`DenialSummary`] -//! terminator, the [`DenialsDocument`] output shape plus its [`emit`]ter, -//! and the [`DenialAnalyzer`] decode trait. It carries no OS-specific code -//! so the wire format never encodes a platform assumption. +//! terminator, the [`DenialsDocument`] and [`VerboseLoggingDocument`] output shapes, +//! and the [`DenialAnalyzer`] decode trait. It carries no OS-specific code so +//! the wire format never encodes a platform assumption. //! //! ## Mode caveat //! @@ -34,9 +35,21 @@ pub mod analyze; pub mod emit; pub mod model; +pub mod paired_output; pub mod summary; +pub mod verbose_logging; pub use analyze::{AnalysisResult, AnalyzeError, DenialAnalyzer, ProcessLifetime}; pub use emit::{write_document, DenialsDocument, DenialsOutputPointer}; pub use model::{AccessType, DedupKey, DeniedResource, ResourceType}; +pub use paired_output::{ + relocate_output_file, relocate_paired_output_files, write_paired_output_files, + ExistingOutputPolicy, RelocationOutcome, +}; pub use summary::DenialSummary; +pub use verbose_logging::{ + verbose_logging_sibling_path, write_verbose_logging_document, VerboseLoggingAggregate, + VerboseLoggingDocument, VerboseLoggingDocumentSummary, VerboseLoggingExclusionReason, + VerboseLoggingProvider, VerboseLoggingSignature, VerboseLoggingSummary, + MAX_VERBOSE_LOGGING_GROUPS, MAX_VERBOSE_LOGGING_SIGNATURE_BYTES, +}; diff --git a/src/core/learning_mode_core/src/model.rs b/src/core/learning_mode_core/src/model.rs index 26110b275..1354d6735 100644 --- a/src/core/learning_mode_core/src/model.rs +++ b/src/core/learning_mode_core/src/model.rs @@ -43,7 +43,7 @@ mod decimal_u64 { /// The variant set is deliberately closed and cross-platform. The /// Windows decoder classifies ETW events into these buckets; other /// backends map their native sources onto the same vocabulary. -#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash, Serialize, Deserialize)] +#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash, Serialize, Deserialize)] #[serde(rename_all = "lowercase")] pub enum ResourceType { /// Filesystem path (file or directory). @@ -62,7 +62,7 @@ pub enum ResourceType { } /// The kind of access that was attempted and denied. -#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash, Serialize, Deserialize)] +#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash, Serialize, Deserialize)] #[serde(rename_all = "lowercase")] pub enum AccessType { /// Read / query access. diff --git a/src/core/learning_mode_core/src/paired_output.rs b/src/core/learning_mode_core/src/paired_output.rs new file mode 100644 index 000000000..19bc8927e --- /dev/null +++ b/src/core/learning_mode_core/src/paired_output.rs @@ -0,0 +1,1068 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +//! Transactional staging for the canonical and verbose logging output pair. + +use sha2::{Digest, Sha256}; +use std::io::{Read, Seek, Write}; +use std::path::{Path, PathBuf}; + +#[derive(Debug)] +struct OutputPairLock { + file: std::fs::File, +} + +impl OutputPairLock { + fn acquire(operation: &str, canonical_path: &Path) -> std::io::Result { + let file_name = canonical_path + .file_name() + .and_then(|name| name.to_str()) + .ok_or_else(|| { + std::io::Error::other(format!( + "{operation} canonical output path has no usable file name: {}", + canonical_path.display() + )) + })?; + let lock_name = format!(".{file_name}.pair.lock"); + let lock_path = canonical_path + .parent() + .unwrap_or_else(|| Path::new(".")) + .join(lock_name); + let file = std::fs::OpenOptions::new() + .read(true) + .write(true) + .create(true) + .truncate(false) + .open(&lock_path) + .map_err(|error| { + std::io::Error::other(format!( + "{operation} failed to open output-pair lock {}: {error}", + lock_path.display() + )) + })?; + file.try_lock().map_err(|error| { + std::io::Error::other(format!( + "{operation} output pair is being written by another process (lock {}): {error}", + lock_path.display() + )) + })?; + Ok(Self { file }) + } +} + +impl Drop for OutputPairLock { + fn drop(&mut self) { + let _ = std::fs::File::unlock(&self.file); + } +} + +#[derive(Debug)] +struct PromotedOutput { + handle: same_file::Handle, + digest: [u8; 32], +} + +impl PromotedOutput { + fn from_file(mut file: std::fs::File) -> std::io::Result { + let handle = same_file::Handle::from_file(file.try_clone()?)?; + let digest = file_digest(&mut file)?; + Ok(Self { handle, digest }) + } + + fn matches_path(&self, path: &Path) -> std::io::Result { + let mut file = std::fs::File::open(path)?; + let path_handle = same_file::Handle::from_file(file.try_clone()?)?; + if self.handle != path_handle { + return Ok(false); + } + Ok(self.digest == file_digest(&mut file)?) + } +} + +fn file_digest(reader: &mut (impl Read + Seek)) -> std::io::Result<[u8; 32]> { + reader.rewind()?; + let mut digest = Sha256::new(); + let mut buffer = [0u8; 16 * 1024]; + loop { + let read = reader.read(&mut buffer)?; + if read == 0 { + break; + } + digest.update(&buffer[..read]); + } + Ok(digest.finalize().into()) +} + +/// Controls how an existing output pair is handled during promotion. +#[derive(Debug, Clone, Copy, Eq, PartialEq)] +pub enum ExistingOutputPolicy { + /// Fail rather than overwrite either output. + CreateNew, + /// Atomically replace each individual output. + Replace, +} + +/// Result of a successfully committed output relocation. +/// +/// Source cleanup happens after the destination is committed. Cleanup failures +/// are warnings rather than relocation failures so callers can publish the +/// authoritative destination path. +#[derive(Debug, Default)] +pub struct RelocationOutcome { + cleanup_warnings: Vec, +} + +impl RelocationOutcome { + /// Returns warnings produced while removing verified source artifacts. + pub fn cleanup_warnings(&self) -> &[String] { + &self.cleanup_warnings + } + + /// Consumes the outcome and returns its source-cleanup warnings. + pub fn into_cleanup_warnings(self) -> Vec { + self.cleanup_warnings + } + + fn record_cleanup_error(&mut self, kind: &str, path: &Path, error: std::io::Error) { + self.cleanup_warnings.push(format!( + "relocation committed, but failed to remove {kind} source {}: {error}", + path.display() + )); + } +} + +/// Stages, flushes, and promotes a canonical output and its verbose logging sibling. +/// +/// Both documents are serialized before either final path is changed. Replace +/// mode retains the previous files until both new files are promoted, allowing +/// a failed promotion to restore the complete previous pair. +pub fn write_paired_output_files( + operation: &str, + canonical_path: &Path, + verbose_logging_path: &Path, + policy: ExistingOutputPolicy, + write_canonical: impl FnOnce(&mut std::io::BufWriter) -> std::io::Result<()>, + write_verbose_logging: impl FnOnce(&mut std::io::BufWriter) -> std::io::Result<()>, +) -> std::io::Result<()> { + let _pair_lock = match policy { + ExistingOutputPolicy::CreateNew => None, + ExistingOutputPolicy::Replace => Some(OutputPairLock::acquire(operation, canonical_path)?), + }; + match policy { + ExistingOutputPolicy::CreateNew => { + ensure_output_absent(operation, canonical_path, "canonical")?; + ensure_output_absent(operation, verbose_logging_path, "verbose logging")?; + } + ExistingOutputPolicy::Replace => { + ensure_output_replaceable(operation, canonical_path, "canonical")?; + ensure_output_replaceable(operation, verbose_logging_path, "verbose logging")?; + } + } + + let canonical_temp = + stage_output_file(operation, canonical_path, "canonical", write_canonical)?; + let verbose_logging_temp = stage_output_file( + operation, + verbose_logging_path, + "verbose logging", + write_verbose_logging, + )?; + + let canonical_backup = if policy == ExistingOutputPolicy::Replace { + backup_existing_output(operation, canonical_path, "canonical")? + } else { + None + }; + let verbose_logging_backup = if policy == ExistingOutputPolicy::Replace { + match backup_existing_output(operation, verbose_logging_path, "verbose logging") { + Ok(backup) => backup, + Err(error) => { + return Err(combine_error_with_rollback( + error, + restore_output(canonical_path, canonical_backup.as_deref(), None), + )) + } + } + } else { + None + }; + + let verbose_logging_promoted = match promote_output_file( + operation, + verbose_logging_temp, + verbose_logging_path, + "verbose logging", + ) { + Ok(promoted) => promoted, + Err(error) => { + return Err(combine_error_with_rollback( + error, + restore_output_pair( + canonical_path, + canonical_backup.as_deref(), + None, + verbose_logging_path, + verbose_logging_backup.as_deref(), + None, + ), + )) + } + }; + let canonical_promoted = + match promote_output_file(operation, canonical_temp, canonical_path, "canonical") { + Ok(promoted) => promoted, + Err(error) => { + return Err(combine_error_with_rollback( + error, + restore_output_pair( + canonical_path, + canonical_backup.as_deref(), + None, + verbose_logging_path, + verbose_logging_backup.as_deref(), + Some(verbose_logging_promoted), + ), + )) + } + }; + + drop((canonical_promoted, verbose_logging_promoted)); + remove_backups( + canonical_backup.as_deref(), + verbose_logging_backup.as_deref(), + ) +} + +/// Copies an existing canonical/verbose logging pair to new no-clobber destinations, +/// then removes only source files whose identity and contents still match the +/// files that were copied. +/// +/// The destination pair uses the same transactional promotion and rollback as +/// [`write_paired_output_files`]. Source cleanup quarantines and verifies each +/// file before deletion, so a concurrent replacement is restored rather than +/// removed. +/// +/// # Errors +/// +/// Returns an error when the source pair cannot be read or the destination pair +/// cannot be committed atomically. Source-cleanup failures are returned as +/// warnings in [`RelocationOutcome`] after destination commit. +pub fn relocate_paired_output_files( + operation: &str, + canonical_source_path: &Path, + verbose_logging_source_path: &Path, + canonical_destination_path: &Path, + verbose_logging_destination_path: &Path, +) -> std::io::Result { + if canonical_source_path == canonical_destination_path + && verbose_logging_source_path == verbose_logging_destination_path + { + return Ok(RelocationOutcome::default()); + } + if canonical_source_path == canonical_destination_path + || verbose_logging_source_path == verbose_logging_destination_path + { + return Err(std::io::Error::other(format!( + "{operation} cannot relocate only one member of an output pair" + ))); + } + + let mut canonical_source = std::fs::File::open(canonical_source_path)?; + let canonical_identity = PromotedOutput::from_file(canonical_source.try_clone()?)?; + let mut verbose_logging_source = std::fs::File::open(verbose_logging_source_path)?; + let verbose_logging_identity = PromotedOutput::from_file(verbose_logging_source.try_clone()?)?; + + write_paired_output_files( + operation, + canonical_destination_path, + verbose_logging_destination_path, + ExistingOutputPolicy::CreateNew, + |writer| { + canonical_source.rewind()?; + std::io::copy(&mut canonical_source, writer).map(|_| ()) + }, + |writer| { + verbose_logging_source.rewind()?; + std::io::copy(&mut verbose_logging_source, writer).map(|_| ()) + }, + )?; + + drop((canonical_source, verbose_logging_source)); + let verbose_logging_cleanup = remove_promoted_output_if_owned( + verbose_logging_source_path, + verbose_logging_identity, + None, + ) + .and_then(cleanup_result); + let canonical_cleanup = + remove_promoted_output_if_owned(canonical_source_path, canonical_identity, None) + .and_then(cleanup_result); + let mut outcome = RelocationOutcome::default(); + if let Err(error) = verbose_logging_cleanup { + outcome.record_cleanup_error("verbose logging", verbose_logging_source_path, error); + } + if let Err(error) = canonical_cleanup { + outcome.record_cleanup_error("canonical", canonical_source_path, error); + } + Ok(outcome) +} + +/// Copies one existing output to a new no-clobber destination, then removes +/// the source only if its identity and contents still match the copied file. +/// +/// # Errors +/// +/// Returns an error when the source cannot be read or the destination cannot be +/// committed without clobbering. Source-cleanup failures are returned as +/// warnings in [`RelocationOutcome`] after destination commit. +pub fn relocate_output_file( + operation: &str, + kind: &str, + source_path: &Path, + destination_path: &Path, +) -> std::io::Result { + if source_path == destination_path { + return Ok(RelocationOutcome::default()); + } + + let mut source = std::fs::File::open(source_path)?; + let source_identity = PromotedOutput::from_file(source.try_clone()?)?; + ensure_output_absent(operation, destination_path, kind)?; + let temp = stage_output_file(operation, destination_path, kind, |writer| { + source.rewind()?; + std::io::copy(&mut source, writer).map(|_| ()) + })?; + let promoted = promote_output_file(operation, temp, destination_path, kind)?; + drop((source, promoted)); + let mut outcome = RelocationOutcome::default(); + if let Err(error) = + remove_promoted_output_if_owned(source_path, source_identity, None).and_then(cleanup_result) + { + outcome.record_cleanup_error(kind, source_path, error); + } + Ok(outcome) +} + +fn cleanup_result(error: Option) -> std::io::Result<()> { + error.map_or(Ok(()), Err) +} + +fn ensure_output_absent(operation: &str, path: &Path, kind: &str) -> std::io::Result<()> { + match std::fs::symlink_metadata(path) { + Ok(_) => Err(std::io::Error::new( + std::io::ErrorKind::AlreadyExists, + format!( + "{operation} {kind} output file already exists: {}", + path.display() + ), + )), + Err(error) if error.kind() == std::io::ErrorKind::NotFound => Ok(()), + Err(error) => Err(std::io::Error::other(format!( + "{operation} failed to inspect {kind} output file {}: {error}", + path.display() + ))), + } +} + +fn ensure_output_replaceable(operation: &str, path: &Path, kind: &str) -> std::io::Result<()> { + match std::fs::symlink_metadata(path) { + Ok(metadata) if metadata.file_type().is_file() => Ok(()), + Ok(_) => Err(std::io::Error::other(format!( + "{operation} cannot replace non-file {kind} output path {}", + path.display() + ))), + Err(error) if error.kind() == std::io::ErrorKind::NotFound => Ok(()), + Err(error) => Err(std::io::Error::other(format!( + "{operation} failed to inspect {kind} output file {}: {error}", + path.display() + ))), + } +} + +fn stage_output_file( + operation: &str, + final_path: &Path, + kind: &str, + write: impl FnOnce(&mut std::io::BufWriter) -> std::io::Result<()>, +) -> std::io::Result { + let parent = final_path.parent().unwrap_or_else(|| Path::new(".")); + let temp = tempfile::NamedTempFile::new_in(parent).map_err(|error| { + std::io::Error::other(format!( + "{operation} failed to create temporary {kind} output file in {}: {error}", + parent.display() + )) + })?; + let file = temp.as_file().try_clone().map_err(|error| { + std::io::Error::other(format!( + "{operation} failed to open temporary {kind} output file for {}: {error}", + final_path.display() + )) + })?; + let mut writer = std::io::BufWriter::new(file); + write(&mut writer) + .and_then(|()| writer.flush()) + .and_then(|()| writer.get_ref().sync_all()) + .map_err(|error| { + std::io::Error::other(format!( + "{operation} failed to write temporary {kind} output file for {}: {error}", + final_path.display() + )) + })?; + Ok(temp) +} + +fn promote_output_file( + operation: &str, + temp: tempfile::NamedTempFile, + final_path: &Path, + kind: &str, +) -> std::io::Result { + let identity_file = temp.reopen().map_err(|error| { + std::io::Error::other(format!( + "{operation} failed to identify temporary {kind} output file for {}: {error}", + final_path.display() + )) + })?; + let promoted = PromotedOutput::from_file(identity_file).map_err(|error| { + std::io::Error::other(format!( + "{operation} failed to identify temporary {kind} output file for {}: {error}", + final_path.display() + )) + })?; + temp.persist_noclobber(final_path) + .map(|_| promoted) + .map_err(|error| { + std::io::Error::other(format!( + "{operation} failed to promote {kind} output file {}: {}", + final_path.display(), + error.error + )) + }) +} + +fn backup_existing_output( + operation: &str, + final_path: &Path, + kind: &str, +) -> std::io::Result> { + backup_existing_output_with(operation, final_path, kind, persist_existing_file_noclobber) +} + +fn backup_existing_output_with( + operation: &str, + final_path: &Path, + kind: &str, + persist: impl FnOnce(&Path, &Path) -> std::io::Result<()>, +) -> std::io::Result> { + let file = match std::fs::File::open(final_path) { + Ok(file) => file, + Err(error) if error.kind() == std::io::ErrorKind::NotFound => return Ok(None), + Err(error) => { + return Err(std::io::Error::other(format!( + "{operation} failed to inspect {kind} output file {}: {error}", + final_path.display() + ))) + } + }; + let expected = PromotedOutput::from_file(file).map_err(|error| { + std::io::Error::other(format!( + "{operation} failed to identify existing {kind} output file {}: {error}", + final_path.display() + )) + })?; + let backup_path = vacant_sibling_path(operation, final_path, kind)?; + persist(final_path, &backup_path).map_err(|error| { + std::io::Error::other(format!( + "{operation} failed to back up {kind} output file {}: {error}", + final_path.display() + )) + })?; + let matches = expected.matches_path(&backup_path).map_err(|error| { + std::io::Error::other(format!( + "{operation} failed to verify backed-up {kind} output file {}: {error}", + backup_path.display() + )) + }); + drop(expected); + + match matches { + Ok(true) => Ok(Some(backup_path)), + Ok(false) => { + let error = std::io::Error::other(format!( + "{operation} detected that {kind} output {} was replaced while it was being backed up", + final_path.display() + )); + match persist_existing_file_noclobber(&backup_path, final_path) { + Ok(()) => Err(error), + Err(restore_error) => Err(std::io::Error::other(format!( + "{error}; additionally failed to restore unowned file {} to {}: {restore_error}", + backup_path.display(), + final_path.display() + ))), + } + } + Err(error) => match persist_existing_file_noclobber(&backup_path, final_path) { + Ok(()) => Err(error), + Err(restore_error) => Err(std::io::Error::other(format!( + "{error}; additionally failed to restore unverifiable file {} to {}: {restore_error}", + backup_path.display(), + final_path.display() + ))), + }, + } +} + +fn vacant_sibling_path(operation: &str, final_path: &Path, kind: &str) -> std::io::Result { + let parent = final_path.parent().unwrap_or_else(|| Path::new(".")); + let backup = tempfile::NamedTempFile::new_in(parent).map_err(|error| { + std::io::Error::other(format!( + "{operation} failed to reserve temporary path for {kind} output file {}: {error}", + final_path.display() + )) + })?; + let backup_path = backup.path().to_path_buf(); + backup.close().map_err(|error| { + std::io::Error::other(format!( + "{operation} failed to prepare temporary path for {kind} output file {}: {error}", + final_path.display() + )) + })?; + Ok(backup_path) +} + +fn restore_output_pair( + canonical_path: &Path, + canonical_backup: Option<&Path>, + canonical_promoted: Option, + verbose_logging_path: &Path, + verbose_logging_backup: Option<&Path>, + verbose_logging_promoted: Option, +) -> std::io::Result<()> { + let verbose_logging_result = restore_output( + verbose_logging_path, + verbose_logging_backup, + verbose_logging_promoted, + ); + let canonical_result = restore_output(canonical_path, canonical_backup, canonical_promoted); + match (verbose_logging_result, canonical_result) { + (Ok(()), Ok(())) => Ok(()), + (Err(error), Ok(())) | (Ok(()), Err(error)) => Err(error), + (Err(first), Err(second)) => Err(std::io::Error::other(format!( + "{first}; additionally failed to restore {}: {second}", + canonical_path.display() + ))), + } +} + +fn restore_output( + final_path: &Path, + backup_path: Option<&Path>, + promoted: Option, +) -> std::io::Result<()> { + let cleanup_error = if let Some(promoted) = promoted { + remove_promoted_output_if_owned(final_path, promoted, backup_path)? + } else if backup_path.is_some() && final_path.try_exists()? { + return Err(std::io::Error::new( + std::io::ErrorKind::AlreadyExists, + format!( + "cannot restore {} because another writer created it; backup retained at {}", + final_path.display(), + backup_path.map_or_else(|| "".into(), |path| path.display().to_string()) + ), + )); + } else { + None + }; + let restore_result = backup_path.map_or(Ok(()), |backup_path| { + restore_backup_noclobber(backup_path, final_path) + }); + finish_restore(final_path, cleanup_error, restore_result) +} + +fn remove_promoted_output_if_owned( + final_path: &Path, + promoted: PromotedOutput, + backup_path: Option<&Path>, +) -> std::io::Result> { + let quarantine_path = vacant_sibling_path("paired output rollback", final_path, "promoted")?; + match persist_existing_file_noclobber(final_path, &quarantine_path) { + Ok(()) => {} + Err(error) if error.kind() == std::io::ErrorKind::NotFound => return Ok(None), + Err(error) => { + return Err(std::io::Error::other(format!( + "failed to quarantine promoted output {} at {}: {error}", + final_path.display(), + quarantine_path.display() + ))) + } + } + let matches = promoted.matches_path(&quarantine_path).map_err(|error| { + std::io::Error::other(format!( + "failed to verify ownership of quarantined output {}: {error}", + quarantine_path.display() + )) + }); + drop(promoted); + match matches { + Ok(true) => remove_quarantine_or_restore(final_path, &quarantine_path, remove_if_present), + Ok(false) => { + let restore_result = persist_existing_file_noclobber(&quarantine_path, final_path); + if let Err(restore_error) = restore_result { + return Err(std::io::Error::other(format!( + "cannot restore {} because another writer replaced the promoted output; \ + unowned file retained at {} and backup retained at {}: {restore_error}", + final_path.display(), + quarantine_path.display(), + backup_path.map_or_else(|| "".into(), |path| path.display().to_string()) + ))); + } + Err(std::io::Error::other(format!( + "cannot restore {} because another writer replaced the promoted output; backup retained at {}", + final_path.display(), + backup_path.map_or_else(|| "".into(), |path| path.display().to_string()) + ))) + } + Err(error) => combine_error_with_restore( + error, + persist_existing_file_noclobber(&quarantine_path, final_path), + &quarantine_path, + final_path, + ), + } +} + +fn remove_quarantine_or_restore( + final_path: &Path, + quarantine_path: &Path, + remove: impl FnOnce(&Path) -> std::io::Result<()>, +) -> std::io::Result> { + match remove(quarantine_path) { + Ok(()) => Ok(None), + Err(error) => combine_error_with_restore( + std::io::Error::other(format!( + "failed to remove quarantined promoted output {}: {error}", + quarantine_path.display() + )), + persist_existing_file_noclobber(quarantine_path, final_path), + quarantine_path, + final_path, + ), + } +} + +fn combine_error_with_restore( + error: std::io::Error, + restore: std::io::Result<()>, + source_path: &Path, + final_path: &Path, +) -> std::io::Result> { + match restore { + Ok(()) => Err(error), + Err(restore_error) => Err(std::io::Error::other(format!( + "{error}; additionally failed to restore {} to {}: {restore_error}", + source_path.display(), + final_path.display() + ))), + } +} + +fn finish_restore( + final_path: &Path, + cleanup_error: Option, + restore_result: std::io::Result<()>, +) -> std::io::Result<()> { + match (cleanup_error, restore_result) { + (None, Ok(())) => Ok(()), + (None, Err(error)) | (Some(error), Ok(())) => Err(error), + (Some(cleanup_error), Err(restore_error)) => Err(std::io::Error::other(format!( + "{cleanup_error}; additionally failed to restore {}: {restore_error}", + final_path.display() + ))), + } +} + +fn restore_backup_noclobber(backup_path: &Path, final_path: &Path) -> std::io::Result<()> { + persist_existing_file_noclobber(backup_path, final_path).map_err(|error| { + std::io::Error::other(format!( + "failed to restore backup {} to {}: {error}", + backup_path.display(), + final_path.display() + )) + }) +} + +fn persist_existing_file_noclobber(source_path: &Path, final_path: &Path) -> std::io::Result<()> { + let file = std::fs::OpenOptions::new().read(true).open(source_path)?; + let temp_path = tempfile::TempPath::try_from_path(source_path.to_path_buf())?; + let mut source = tempfile::NamedTempFile::from_parts(file, temp_path); + // On a failed no-clobber promotion the original file is the recovery + // artifact, so it must outlive the temporary wrapper. + source.disable_cleanup(true); + source + .persist_noclobber(final_path) + .map(|_| ()) + .map_err(|error| error.error) +} + +fn remove_backups( + canonical_backup: Option<&Path>, + verbose_logging_backup: Option<&Path>, +) -> std::io::Result<()> { + let canonical_result = canonical_backup.map_or(Ok(()), |path| { + remove_if_present(path).map_err(|error| { + std::io::Error::other(format!( + "failed to remove canonical backup {}: {error}", + path.display() + )) + }) + }); + let verbose_logging_result = verbose_logging_backup.map_or(Ok(()), |path| { + remove_if_present(path).map_err(|error| { + std::io::Error::other(format!( + "failed to remove verbose logging backup {}: {error}", + path.display() + )) + }) + }); + match (canonical_result, verbose_logging_result) { + (Ok(()), Ok(())) => Ok(()), + (Err(error), Ok(())) | (Ok(()), Err(error)) => Err(error), + (Err(first), Err(second)) => Err(std::io::Error::other(format!( + "{first}; additionally failed to remove verbose logging backup: {second}" + ))), + } +} + +fn remove_if_present(path: &Path) -> std::io::Result<()> { + match std::fs::remove_file(path) { + Ok(()) => Ok(()), + Err(error) if error.kind() == std::io::ErrorKind::NotFound => Ok(()), + Err(error) => Err(error), + } +} + +fn combine_error_with_rollback( + error: std::io::Error, + rollback: std::io::Result<()>, +) -> std::io::Error { + match rollback { + Ok(()) => error, + Err(rollback_error) => std::io::Error::other(format!( + "{error}; additionally failed to roll back output pair: {rollback_error}" + )), + } +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn replace_rejects_non_file_output_before_promoting_sibling() { + let directory = tempfile::tempdir().unwrap(); + let canonical_path = directory.path().join("denials.json"); + let verbose_logging_path = directory.path().join("denials.verbose.json"); + std::fs::create_dir(&canonical_path).unwrap(); + + let error = write_paired_output_files( + "test", + &canonical_path, + &verbose_logging_path, + ExistingOutputPolicy::Replace, + |writer| writer.write_all(b"canonical"), + |writer| writer.write_all(b"verbose"), + ) + .unwrap_err(); + + assert!(error + .to_string() + .contains("cannot replace non-file canonical")); + assert!(!verbose_logging_path.exists()); + } + + #[test] + fn failed_second_promotion_restores_previous_output() { + let directory = tempfile::tempdir().unwrap(); + let shared_path = directory.path().join("denials.json"); + std::fs::write(&shared_path, b"previous").unwrap(); + + let error = write_paired_output_files( + "test", + &shared_path, + &shared_path, + ExistingOutputPolicy::Replace, + |writer| writer.write_all(b"canonical"), + |writer| writer.write_all(b"verbose"), + ) + .unwrap_err(); + + assert!(error.to_string().contains("failed to promote canonical")); + assert_eq!(std::fs::read(shared_path).unwrap(), b"previous"); + } + + #[test] + fn relocation_rolls_back_failed_second_promotion_and_keeps_sources() { + let directory = tempfile::tempdir().unwrap(); + let canonical_source = directory.path().join("source-denials.json"); + let verbose_logging_source = directory.path().join("source-denials.verbose.json"); + let shared_destination = directory.path().join("denials.json"); + std::fs::write(&canonical_source, b"canonical").unwrap(); + std::fs::write(&verbose_logging_source, b"verbose").unwrap(); + + let error = relocate_paired_output_files( + "test relocation", + &canonical_source, + &verbose_logging_source, + &shared_destination, + &shared_destination, + ) + .unwrap_err(); + + assert!(error.to_string().contains("failed to promote canonical")); + assert!(!shared_destination.exists()); + assert_eq!(std::fs::read(canonical_source).unwrap(), b"canonical"); + assert_eq!(std::fs::read(verbose_logging_source).unwrap(), b"verbose"); + } + + #[test] + fn rollback_does_not_delete_unpromoted_collision() { + let directory = tempfile::tempdir().unwrap(); + let final_path = directory.path().join("denials.json"); + let backup_path = directory.path().join("backup.json"); + std::fs::write(&final_path, b"concurrent").unwrap(); + std::fs::write(&backup_path, b"previous").unwrap(); + + let error = restore_output(&final_path, Some(&backup_path), None).unwrap_err(); + + assert!(error.to_string().contains("cannot restore")); + assert_eq!(std::fs::read(final_path).unwrap(), b"concurrent"); + assert_eq!(std::fs::read(backup_path).unwrap(), b"previous"); + } + + #[test] + fn rollback_does_not_delete_replacement_of_promoted_output() { + let directory = tempfile::tempdir().unwrap(); + let final_path = directory.path().join("denials.json"); + let displaced_path = directory.path().join("displaced.json"); + let backup_path = directory.path().join("backup.json"); + std::fs::write(&final_path, b"promoted").unwrap(); + let promoted = + PromotedOutput::from_file(std::fs::File::open(&final_path).unwrap()).unwrap(); + std::fs::rename(&final_path, &displaced_path).unwrap(); + std::fs::write(&final_path, b"concurrent").unwrap(); + std::fs::write(&backup_path, b"previous").unwrap(); + + let error = restore_output(&final_path, Some(&backup_path), Some(promoted)).unwrap_err(); + + assert!(error.to_string().contains("another writer replaced")); + assert_eq!(std::fs::read(final_path).unwrap(), b"concurrent"); + assert_eq!(std::fs::read(backup_path).unwrap(), b"previous"); + } + + #[test] + fn rollback_does_not_delete_in_place_overwrite_of_promoted_output() { + let directory = tempfile::tempdir().unwrap(); + let final_path = directory.path().join("denials.json"); + let backup_path = directory.path().join("backup.json"); + std::fs::write(&final_path, b"promoted").unwrap(); + let promoted = + PromotedOutput::from_file(std::fs::File::open(&final_path).unwrap()).unwrap(); + std::fs::write(&final_path, b"replaced").unwrap(); + std::fs::write(&backup_path, b"previous").unwrap(); + + let error = restore_output(&final_path, Some(&backup_path), Some(promoted)).unwrap_err(); + + assert!(error.to_string().contains("another writer replaced")); + assert_eq!(std::fs::read(final_path).unwrap(), b"replaced"); + assert_eq!(std::fs::read(backup_path).unwrap(), b"previous"); + } + + #[test] + fn rollback_restores_backup_when_promoted_output_was_deleted() { + let directory = tempfile::tempdir().unwrap(); + let final_path = directory.path().join("denials.json"); + let backup_path = directory.path().join("backup.json"); + std::fs::write(&final_path, b"promoted").unwrap(); + let promoted = + PromotedOutput::from_file(std::fs::File::open(&final_path).unwrap()).unwrap(); + std::fs::remove_file(&final_path).unwrap(); + std::fs::write(&backup_path, b"previous").unwrap(); + + restore_output(&final_path, Some(&backup_path), Some(promoted)).unwrap(); + + assert_eq!(std::fs::read(final_path).unwrap(), b"previous"); + assert!(!backup_path.exists()); + } + + #[test] + fn rollback_reports_cleanup_failure_after_attempting_restore() { + let cleanup_error = std::io::Error::other("quarantine cleanup failed"); + let restore_error = std::io::Error::other("backup restore failed"); + + let error = finish_restore( + Path::new("denials.json"), + Some(cleanup_error), + Err(restore_error), + ) + .unwrap_err(); + + assert!(error.to_string().contains("quarantine cleanup failed")); + assert!(error.to_string().contains("backup restore failed")); + } + + #[test] + fn rollback_reports_failed_quarantine_restore() { + let error = combine_error_with_restore( + std::io::Error::other("identity check failed"), + Err(std::io::Error::other("restore failed")), + Path::new("quarantine.tmp"), + Path::new("denials.json"), + ) + .unwrap_err(); + + assert!(error.to_string().contains("identity check failed")); + assert!(error.to_string().contains("quarantine.tmp")); + assert!(error.to_string().contains("restore failed")); + } + + #[test] + fn backup_restores_concurrent_replacement_instead_of_claiming_it() { + let directory = tempfile::tempdir().unwrap(); + let final_path = directory.path().join("denials.json"); + std::fs::write(&final_path, b"original").unwrap(); + + let error = backup_existing_output_with( + "test", + &final_path, + "canonical", + |source_path, backup_path| { + std::fs::remove_file(source_path)?; + std::fs::write(source_path, b"concurrent")?; + persist_existing_file_noclobber(source_path, backup_path) + }, + ) + .unwrap_err(); + + assert!(error.to_string().contains("was replaced")); + assert_eq!(std::fs::read(&final_path).unwrap(), b"concurrent"); + } + + #[test] + fn promotion_error_describes_rollback_failure() { + let error = combine_error_with_rollback( + std::io::Error::other("promotion failed"), + Err(std::io::Error::other("restore failed")), + ); + + assert!(error.to_string().contains("promotion failed")); + assert!(error + .to_string() + .contains("failed to roll back output pair")); + assert!(error.to_string().contains("restore failed")); + } + + #[test] + fn backup_restore_error_names_source_and_destination() { + let directory = tempfile::tempdir().unwrap(); + let backup_path = directory.path().join("backup.json"); + let final_path = directory.path().join("denials.json"); + std::fs::write(&backup_path, b"previous").unwrap(); + std::fs::write(&final_path, b"concurrent").unwrap(); + + let error = restore_backup_noclobber(&backup_path, &final_path).unwrap_err(); + + assert!(error + .to_string() + .contains(&backup_path.display().to_string())); + assert!(error + .to_string() + .contains(&final_path.display().to_string())); + } + + #[test] + fn backup_cleanup_error_names_the_failed_path() { + let directory = tempfile::tempdir().unwrap(); + let canonical_backup = directory.path().join("canonical-backup"); + std::fs::create_dir(&canonical_backup).unwrap(); + + let error = remove_backups(Some(&canonical_backup), None).unwrap_err(); + + assert!(error + .to_string() + .contains(&canonical_backup.display().to_string())); + } + + #[test] + #[allow(clippy::permissions_set_readonly_false)] + fn rollback_restores_read_only_backup() { + let directory = tempfile::tempdir().unwrap(); + let backup_path = directory.path().join("backup.json"); + let final_path = directory.path().join("denials.json"); + std::fs::write(&backup_path, b"previous").unwrap(); + let mut permissions = std::fs::metadata(&backup_path).unwrap().permissions(); + permissions.set_readonly(true); + std::fs::set_permissions(&backup_path, permissions).unwrap(); + + persist_existing_file_noclobber(&backup_path, &final_path).unwrap(); + + assert_eq!(std::fs::read(&final_path).unwrap(), b"previous"); + #[cfg(windows)] + { + let mut permissions = std::fs::metadata(&final_path).unwrap().permissions(); + permissions.set_readonly(false); + std::fs::set_permissions(final_path, permissions).unwrap(); + } + } + + #[test] + fn output_pair_lock_rejects_concurrent_writer() { + let directory = tempfile::tempdir().unwrap(); + let canonical_path = directory.path().join("denials.json"); + let first = OutputPairLock::acquire("test", &canonical_path).unwrap(); + + let error = OutputPairLock::acquire("test", &canonical_path).unwrap_err(); + + assert!(error.to_string().contains("another process")); + drop(first); + OutputPairLock::acquire("test", &canonical_path).unwrap(); + } + + #[test] + fn create_new_pair_does_not_leave_a_lock_artifact() { + let directory = tempfile::tempdir().unwrap(); + let canonical_path = directory.path().join("denials.json"); + let verbose_logging_path = directory.path().join("denials.verbose.json"); + + write_paired_output_files( + "test", + &canonical_path, + &verbose_logging_path, + ExistingOutputPolicy::CreateNew, + |writer| writer.write_all(b"canonical"), + |writer| writer.write_all(b"verbose"), + ) + .unwrap(); + + assert!(!directory.path().join(".denials.json.pair.lock").exists()); + } + + #[test] + fn quarantine_cleanup_failure_restores_the_original_path() { + let directory = tempfile::tempdir().unwrap(); + let final_path = directory.path().join("source.json"); + let quarantine_path = directory.path().join("source.quarantine"); + std::fs::write(&quarantine_path, b"source").unwrap(); + + let error = remove_quarantine_or_restore(&final_path, &quarantine_path, |_| { + Err(std::io::Error::new( + std::io::ErrorKind::PermissionDenied, + "injected cleanup failure", + )) + }) + .unwrap_err(); + + assert!(error.to_string().contains("injected cleanup failure")); + assert_eq!(std::fs::read(final_path).unwrap(), b"source"); + assert!(!quarantine_path.exists()); + } +} diff --git a/src/core/learning_mode_core/src/verbose_logging.rs b/src/core/learning_mode_core/src/verbose_logging.rs new file mode 100644 index 000000000..1716ad3e1 --- /dev/null +++ b/src/core/learning_mode_core/src/verbose_logging.rs @@ -0,0 +1,529 @@ +// Copyright (c) Microsoft Corporation. +// Licensed under the MIT License. + +//! Sensitive-value-redacted, deduplicated diagnostics for Learning Mode events, +//! including every canonical denial occurrence. + +use std::io::{self, Write}; +use std::path::{Path, PathBuf}; + +use serde::{Deserialize, Serialize}; + +/// Maximum number of distinct aggregate groups retained in one analysis. +pub const MAX_VERBOSE_LOGGING_GROUPS: usize = 4_096; +/// Maximum compact-JSON bytes retained across distinct serialized signatures. +/// +/// This leaves substantial headroom under the guarded WPR analysis protocol's +/// 64 MiB frame limit for canonical denials and envelope overhead. +pub const MAX_VERBOSE_LOGGING_SIGNATURE_BYTES: usize = 16 * 1024 * 1024; + +/// Stable category for a known Learning Mode ETW provider. +#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash, Serialize, Deserialize)] +#[serde(rename_all = "camelCase")] +pub enum VerboseLoggingProvider { + /// Microsoft-Windows-Kernel-General. + KernelGeneral, + /// Microsoft-Windows-Privacy-Auditing-PermissiveLearningMode. + PrivacyAuditingPermissiveLearningMode, +} + +/// Closed reason why a decoder outcome was omitted from canonical denials. +#[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash, Serialize, Deserialize)] +#[serde(rename_all = "camelCase")] +pub enum VerboseLoggingExclusionReason { + /// The event produced a valid canonical denial candidate. + CanonicalDenial, + /// The provider is known, but the event ID is not a supported denial schema. + UnsupportedEventSchema, + /// The event payload conflicted with its declared TDH schema. + EventPayloadMalformed, + /// A decoder safety bound prevented full payload processing. + DecoderLimitReached, + /// The payload uses a property encoding the decoder cannot consume. + UnsupportedPropertyEncoding, + /// A required object-type property was absent or empty. + MissingObjectType, + /// A required object/resource-name property was absent or empty. + MissingObjectName, + /// The event described an object category the canonical model cannot represent. + UnsupportedObjectType, + /// A resource value could not be converted to a safe user-visible resource. + UnusableResourcePath, + /// A capability event did not contain a usable capability denial. + UnresolvedCapability, + /// The event was valid but did not describe an actionable denial. + NotActionable, +} + +impl VerboseLoggingExclusionReason { + /// Returns whether this outcome represents a valid denial candidate. + #[must_use] + pub fn is_canonical_denial(self) -> bool { + self == Self::CanonicalDenial + } +} + +/// One sanitized event signature used as a verbose logging deduplication key. +#[derive(Debug, Clone, PartialEq, Eq, PartialOrd, Ord, Serialize, Deserialize)] +#[serde(rename_all = "camelCase")] +pub struct VerboseLoggingSignature { + /// Symbolic provider category. + pub provider: VerboseLoggingProvider, + /// Stable ETW provider GUID. + pub provider_guid: String, + /// Provider-scoped ETW schema identifier. + pub event_id: u16, + /// Closed exclusion category. + pub reason: VerboseLoggingExclusionReason, + /// Process identifier from the event header. + pub pid: u32, + /// Classified access type when the event produced a denial candidate. + #[serde(default, skip_serializing_if = "Option::is_none")] + pub access_type: Option, + /// Classified resource type when the event produced a denial candidate. + #[serde(default, skip_serializing_if = "Option::is_none")] + pub resource_type: Option, + /// Sorted, bounded, sensitive-value-redacted event properties. + pub properties: Vec<(String, String)>, +} + +/// One deduplicated verbose logging signature and its occurrence count. +#[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize)] +#[serde(rename_all = "camelCase")] +pub struct VerboseLoggingAggregate { + /// Sanitized signature shared by all counted occurrences. + pub signature: VerboseLoggingSignature, + /// Number of matching exclusion outcomes. + pub count: u64, +} + +/// Bounded aggregate state produced by one decoder pass. +#[derive(Debug, Clone, Default, PartialEq, Eq, Serialize, Deserialize)] +#[serde(rename_all = "camelCase")] +pub struct VerboseLoggingSummary { + /// Sorted sanitized signatures retained within [`MAX_VERBOSE_LOGGING_GROUPS`]. + pub signatures: Vec, + /// Total recorded event outcomes, including groups collapsed into overflow. + pub total_occurrences: u64, + /// Outcomes whose new aggregate key could not be retained at the group bound. + pub overflow_occurrences: u64, + /// Canonical-denial occurrences whose signatures could not be retained. + pub canonical_overflow_occurrences: u64, + /// Whether aggregate keys were omitted at the group bound. + pub aggregate_groups_truncated: bool, + /// Whether the ETL processed-event bound prevented complete accounting. + pub processed_events_truncated: bool, + /// Whether the canonical unique-denial bound was reached. + pub canonical_denial_limit_reached: bool, +} + +impl VerboseLoggingSummary { + /// Records one event outcome while preserving deterministic group order. + pub fn record(&mut self, signature: VerboseLoggingSignature) { + self.total_occurrences = self.total_occurrences.saturating_add(1); + match self + .signatures + .binary_search_by(|group| group.signature.cmp(&signature)) + { + Ok(index) => { + self.signatures[index].count = self.signatures[index].count.saturating_add(1); + } + Err(index) if self.signatures.len() < MAX_VERBOSE_LOGGING_GROUPS => { + self.signatures.insert( + index, + VerboseLoggingAggregate { + signature, + count: 1, + }, + ); + } + Err(_) => { + if signature.reason.is_canonical_denial() && self.evict_one_noncanonical_group(None) + { + let index = self + .signatures + .binary_search_by(|group| group.signature.cmp(&signature)) + .unwrap_err(); + self.signatures.insert( + index, + VerboseLoggingAggregate { + signature, + count: 1, + }, + ); + } else { + self.record_overflow(signature.reason.is_canonical_denial()); + self.total_occurrences = self.total_occurrences.saturating_sub(1); + } + } + } + } + + /// Records an outcome while bounding compact serialized signature bytes. + pub fn record_with_byte_budget( + &mut self, + signature: VerboseLoggingSignature, + retained_bytes: &mut usize, + max_bytes: usize, + ) { + if let Ok(index) = self + .signatures + .binary_search_by(|group| group.signature.cmp(&signature)) + { + self.total_occurrences = self.total_occurrences.saturating_add(1); + self.signatures[index].count = self.signatures[index].count.saturating_add(1); + return; + } + + let serialized_len = Self::serialized_signature_len(&signature); + while self.signatures.len() >= MAX_VERBOSE_LOGGING_GROUPS + || retained_bytes.saturating_add(serialized_len) > max_bytes + { + if !signature.reason.is_canonical_denial() + || !self.evict_one_noncanonical_group(Some(retained_bytes)) + { + self.record_overflow(signature.reason.is_canonical_denial()); + return; + } + } + + let index = self + .signatures + .binary_search_by(|group| group.signature.cmp(&signature)) + .unwrap_err(); + self.signatures.insert( + index, + VerboseLoggingAggregate { + signature, + count: 1, + }, + ); + self.total_occurrences = self.total_occurrences.saturating_add(1); + *retained_bytes = retained_bytes.saturating_add(serialized_len); + } + + /// Counts an outcome whose new signature could not be retained at a bound. + pub fn record_overflow(&mut self, canonical: bool) { + self.total_occurrences = self.total_occurrences.saturating_add(1); + self.overflow_occurrences = self.overflow_occurrences.saturating_add(1); + if canonical { + self.canonical_overflow_occurrences = + self.canonical_overflow_occurrences.saturating_add(1); + } + self.aggregate_groups_truncated = true; + } + + /// Moves a retained aggregate into overflow accounting. + pub(crate) fn move_to_overflow(&mut self, aggregate: VerboseLoggingAggregate) { + self.overflow_occurrences = self.overflow_occurrences.saturating_add(aggregate.count); + if aggregate.signature.reason.is_canonical_denial() { + self.canonical_overflow_occurrences = self + .canonical_overflow_occurrences + .saturating_add(aggregate.count); + } + self.aggregate_groups_truncated = true; + } + + fn evict_one_noncanonical_group(&mut self, retained_bytes: Option<&mut usize>) -> bool { + let Some(index) = self + .signatures + .iter() + .rposition(|group| !group.signature.reason.is_canonical_denial()) + else { + return false; + }; + let aggregate = self.signatures.remove(index); + if let Some(retained_bytes) = retained_bytes { + *retained_bytes = + retained_bytes.saturating_sub(Self::serialized_signature_len(&aggregate.signature)); + } + self.move_to_overflow(aggregate); + true + } + + /// Marks accounting incomplete because the processed-event bound was reached. + pub fn mark_processed_events_truncated(&mut self) { + self.processed_events_truncated = true; + } + + /// Marks that otherwise-valid candidates exceeded the canonical result bound. + pub fn mark_canonical_denial_limit_reached(&mut self) { + self.canonical_denial_limit_reached = true; + } + + /// Returns whether this analysis observed no excluded outcomes or truncation. + #[must_use] + pub fn is_empty(&self) -> bool { + self.signatures.is_empty() + && self.total_occurrences == 0 + && self.overflow_occurrences == 0 + && self.canonical_overflow_occurrences == 0 + && !self.aggregate_groups_truncated + && !self.processed_events_truncated + && !self.canonical_denial_limit_reached + } + + fn serialized_signature_len(signature: &VerboseLoggingSignature) -> usize { + serde_json::to_vec(&VerboseLoggingAggregate { + signature: signature.clone(), + count: 1, + }) + .map_or(usize::MAX, |bytes| bytes.len()) + } +} + +/// Versioned on-disk verbose logging document. +#[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize)] +#[serde(rename_all = "camelCase")] +pub struct VerboseLoggingDocument { + /// Verbose logging schema version. + pub version: u32, + /// Sorted deduplicated sanitized signatures. + pub signatures: Vec, + /// Aggregate summary and bounds state. + pub summary: VerboseLoggingDocumentSummary, +} + +/// Bounds and count summary for a [`VerboseLoggingDocument`]. +#[derive(Debug, Clone, PartialEq, Eq, Serialize, Deserialize)] +#[serde(rename_all = "camelCase")] +pub struct VerboseLoggingDocumentSummary { + /// Total recorded event outcomes, including overflow. + pub total_occurrences: u64, + /// Outcomes collapsed because the group bound was reached. + pub overflow_occurrences: u64, + /// Canonical-denial occurrences collapsed into overflow. + pub canonical_overflow_occurrences: u64, + /// Whether aggregate keys were omitted. + pub aggregate_groups_truncated: bool, + /// Whether the processed-event limit prevented complete accounting. + pub processed_events_truncated: bool, + /// Whether the canonical unique-denial limit was reached. + pub canonical_denial_limit_reached: bool, +} + +impl VerboseLoggingDocument { + /// Current verbose logging document schema version. + pub const VERSION: u32 = 1; + + /// Builds an on-disk document from decoder aggregate state. + #[must_use] + pub fn new(summary: &VerboseLoggingSummary) -> Self { + Self { + version: Self::VERSION, + signatures: summary.signatures.clone(), + summary: VerboseLoggingDocumentSummary { + total_occurrences: summary.total_occurrences, + overflow_occurrences: summary.overflow_occurrences, + canonical_overflow_occurrences: summary.canonical_overflow_occurrences, + aggregate_groups_truncated: summary.aggregate_groups_truncated, + processed_events_truncated: summary.processed_events_truncated, + canonical_denial_limit_reached: summary.canonical_denial_limit_reached, + }, + } + } +} + +/// Derives the deterministic verbose logging sibling for a canonical denials path. +/// +/// # Errors +/// +/// Returns an error when `output_path` has no usable file name. +pub fn verbose_logging_sibling_path(output_path: &Path) -> io::Result { + let file_name = output_path + .file_name() + .and_then(|value| value.to_str()) + .ok_or_else(|| { + io::Error::other(format!( + "denials output path has no usable file name: {}", + output_path.display() + )) + })?; + let stem = output_path + .file_stem() + .and_then(|value| value.to_str()) + .unwrap_or(file_name); + let sibling = format!("{stem}.verbose.json"); + Ok(match output_path.parent() { + Some(parent) if !parent.as_os_str().is_empty() => parent.join(sibling), + _ => PathBuf::from(sibling), + }) +} + +/// Writes a pretty-printed verbose logging JSON document and trailing newline. +/// +/// # Errors +/// +/// Returns serialization or underlying writer failures. +pub fn write_verbose_logging_document( + writer: &mut W, + document: &VerboseLoggingDocument, +) -> io::Result<()> { + serde_json::to_writer_pretty(&mut *writer, document).map_err(io::Error::other)?; + writer.write_all(b"\n")?; + writer.flush() +} + +#[cfg(test)] +mod tests { + use super::*; + + #[test] + fn aggregates_and_sorts_sanitized_signatures() { + let mut summary = VerboseLoggingSummary::default(); + let signature = VerboseLoggingSignature { + provider: VerboseLoggingProvider::KernelGeneral, + provider_guid: "{A68CA8B7-004F-D7B6-A698-07E2DE0F1F5D}".to_string(), + event_id: 14, + reason: VerboseLoggingExclusionReason::MissingObjectName, + pid: 42, + access_type: None, + resource_type: None, + properties: vec![ + ("ObjectName".to_string(), "".to_string()), + ("Sid".to_string(), "S-1-15-3-1".to_string()), + ], + }; + summary.record(signature.clone()); + summary.record(signature); + + assert_eq!(summary.total_occurrences, 2); + assert_eq!(summary.signatures.len(), 1); + assert_eq!(summary.signatures[0].count, 2); + + let mut bytes = Vec::new(); + write_verbose_logging_document(&mut bytes, &VerboseLoggingDocument::new(&summary)).unwrap(); + let text = String::from_utf8(bytes).unwrap(); + assert!(text.contains("S-1-15-3-1")); + assert!(text.contains("")); + assert!(text.contains("providerGuid")); + assert!(text.contains("\"pid\": 42")); + assert!(!text.contains("accessType")); + assert!(!text.contains("resourceType")); + } + + #[test] + fn group_bound_collapses_new_keys_into_overflow() { + let mut summary = VerboseLoggingSummary::default(); + for event_id in 0..MAX_VERBOSE_LOGGING_GROUPS as u16 { + summary.record(VerboseLoggingSignature { + provider: VerboseLoggingProvider::KernelGeneral, + provider_guid: "kernel".to_string(), + event_id, + reason: VerboseLoggingExclusionReason::UnsupportedEventSchema, + pid: 1, + access_type: None, + resource_type: None, + properties: Vec::new(), + }); + } + summary.record(VerboseLoggingSignature { + provider: VerboseLoggingProvider::PrivacyAuditingPermissiveLearningMode, + provider_guid: "privacy".to_string(), + event_id: u16::MAX, + reason: VerboseLoggingExclusionReason::UnsupportedEventSchema, + pid: 1, + access_type: None, + resource_type: None, + properties: Vec::new(), + }); + + assert_eq!(summary.signatures.len(), MAX_VERBOSE_LOGGING_GROUPS); + assert_eq!(summary.overflow_occurrences, 1); + assert!(summary.aggregate_groups_truncated); + } + + #[test] + fn canonical_signature_evicts_noncanonical_signature_at_group_bound() { + let mut summary = VerboseLoggingSummary::default(); + for event_id in 0..MAX_VERBOSE_LOGGING_GROUPS as u16 { + summary.record(VerboseLoggingSignature { + provider: VerboseLoggingProvider::KernelGeneral, + provider_guid: "kernel".to_string(), + event_id, + reason: VerboseLoggingExclusionReason::UnsupportedEventSchema, + pid: 1, + access_type: None, + resource_type: None, + properties: Vec::new(), + }); + } + summary.record(VerboseLoggingSignature { + provider: VerboseLoggingProvider::KernelGeneral, + provider_guid: "kernel".to_string(), + event_id: u16::MAX, + reason: VerboseLoggingExclusionReason::CanonicalDenial, + pid: 1, + access_type: Some(crate::AccessType::Read), + resource_type: Some(crate::ResourceType::File), + properties: Vec::new(), + }); + + assert!(summary + .signatures + .iter() + .any(|group| group.signature.reason == VerboseLoggingExclusionReason::CanonicalDenial)); + assert_eq!(summary.overflow_occurrences, 1); + assert_eq!(summary.canonical_overflow_occurrences, 0); + } + + #[test] + fn byte_budget_leaves_guarded_analysis_protocol_headroom() { + let mut summary = VerboseLoggingSummary::default(); + let mut retained_bytes = 0; + let properties = (0..24) + .map(|index| (format!("Property{index:02}"), "x".repeat(256))) + .collect::>(); + for pid in 0..MAX_VERBOSE_LOGGING_GROUPS as u32 { + summary.record_with_byte_budget( + VerboseLoggingSignature { + provider: VerboseLoggingProvider::KernelGeneral, + provider_guid: "{A68CA8B7-004F-D7B6-A698-07E2DE0F1F5D}".to_string(), + event_id: 14, + reason: VerboseLoggingExclusionReason::CanonicalDenial, + pid, + access_type: Some(crate::AccessType::Read), + resource_type: Some(crate::ResourceType::File), + properties: properties.clone(), + }, + &mut retained_bytes, + MAX_VERBOSE_LOGGING_SIGNATURE_BYTES, + ); + } + + assert!(summary.aggregate_groups_truncated); + assert!(summary.overflow_occurrences > 0); + assert!(retained_bytes <= MAX_VERBOSE_LOGGING_SIGNATURE_BYTES); + let payload = serde_json::to_vec(&crate::AnalysisResult { + denials: Vec::new(), + denied_resources_truncated: false, + verbose_logging: summary, + }) + .unwrap(); + assert!(payload.len() < 64 * 1024 * 1024); + } + + #[test] + fn document_round_trips() { + let mut summary = VerboseLoggingSummary::default(); + summary.mark_canonical_denial_limit_reached(); + summary.mark_processed_events_truncated(); + let document = VerboseLoggingDocument::new(&summary); + let mut bytes = Vec::new(); + write_verbose_logging_document(&mut bytes, &document).unwrap(); + let parsed: VerboseLoggingDocument = serde_json::from_slice(&bytes).unwrap(); + assert_eq!(parsed, document); + } + + #[test] + fn sibling_path_replaces_the_canonical_extension() { + assert_eq!( + verbose_logging_sibling_path(Path::new(r"C:\out\denials.123.json")).unwrap(), + PathBuf::from(r"C:\out\denials.123.verbose.json") + ); + assert_eq!( + verbose_logging_sibling_path(Path::new("denials")).unwrap(), + PathBuf::from("denials.verbose.json") + ); + } +} diff --git a/src/core/mxc_engine/src/lib.rs b/src/core/mxc_engine/src/lib.rs index e5fe40fb0..401d8a347 100644 --- a/src/core/mxc_engine/src/lib.rs +++ b/src/core/mxc_engine/src/lib.rs @@ -50,6 +50,8 @@ pub use policy::{ WslcSection, }; pub use probe::{available_backends, AvailableBackend, BackendCapability}; +#[cfg(target_os = "windows")] +pub use run::resolve_runner_for_audit; #[cfg(any(target_os = "windows", target_os = "linux", target_os = "macos"))] pub use run::{resolve_runner, run, ResolvedRunner}; pub use state_aware::{exec_state_aware_json, run_state_aware, run_state_aware_json}; diff --git a/src/core/mxc_engine/src/run.rs b/src/core/mxc_engine/src/run.rs index b17ea9f2f..aa958ebe5 100644 --- a/src/core/mxc_engine/src/run.rs +++ b/src/core/mxc_engine/src/run.rs @@ -93,6 +93,15 @@ pub fn resolve_runner( resolve_runner_inner(request, logger).map_err(Error::from) } +/// Resolve a runner for the `wxc-exec --audit` compatibility workflow. +#[cfg(target_os = "windows")] +pub fn resolve_runner_for_audit( + request: &ExecutionRequest, + logger: &mut Logger, +) -> Result { + resolve_runner_inner_windows(request, logger).map_err(Error::from) +} + /// Resolve `request`'s backend and run it to completion. /// /// Convenience over [`resolve_runner`] for callers without external guard / diff --git a/src/core/wxc/src/audit.rs b/src/core/wxc/src/audit.rs index 7b024f391..e3290a9e8 100644 --- a/src/core/wxc/src/audit.rs +++ b/src/core/wxc/src/audit.rs @@ -45,7 +45,7 @@ pub fn finalize( context: &AuditContext, exe_dir: &Path, verbose: bool, -) -> Result<(), String> { +) -> Result, String> { let metadata = response .output_metadata .as_mut() @@ -61,6 +61,13 @@ pub fn finalize( .as_mut() .ok_or_else(|| "captureDenials returned no successful output metadata".to_string())?; let source_denials = PathBuf::from(&capture.output_path); + let source_verbose_logging = learning_mode_core::verbose_logging_sibling_path(&source_denials) + .map_err(|error| { + format!( + "failed to derive verbose logging path from {}: {error}", + source_denials.display() + ) + })?; let source_etl = capture .etl_path .as_deref() @@ -78,6 +85,12 @@ pub fn finalize( source_etl.display() )); } + if !source_verbose_logging.is_file() { + return Err(format!( + "captureDenials verbose logging output file is missing: {}", + source_verbose_logging.display() + )); + } let document: learning_mode_core::DenialsDocument = serde_json::from_slice(&std::fs::read(&source_denials).map_err(|error| { @@ -93,15 +106,35 @@ pub fn finalize( ) })?; validate_metadata(capture, &document)?; + let _: learning_mode_core::VerboseLoggingDocument = + serde_json::from_slice(&std::fs::read(&source_verbose_logging).map_err(|error| { + format!( + "failed to read captureDenials verbose logging output {}: {error}", + source_verbose_logging.display() + ) + })?) + .map_err(|error| { + format!( + "captureDenials verbose logging output {} is not valid JSON: {error}", + source_verbose_logging.display() + ) + })?; let final_denials = context.log_dir.join("denials.json"); + let final_verbose_logging = learning_mode_core::verbose_logging_sibling_path(&final_denials) + .map_err(|error| format!("failed to derive audit verbose logging output path: {error}"))?; let final_etl = context.log_dir.join("trace.etl"); - relocate_artifacts( + let cleanup_warnings = relocate_artifacts( capture, - &source_denials, - &final_denials, - &source_etl, - &final_etl, + &ArtifactRelocation { + source_denials: &source_denials, + final_denials: &final_denials, + source_verbose_logging: &source_verbose_logging, + final_verbose_logging: &final_verbose_logging, + source_etl: &source_etl, + final_etl: &final_etl, + }, + learning_mode_core::relocate_paired_output_files, move_new_file, )?; remove_empty_managed_directory(source_etl.parent(), &context.log_dir)?; @@ -120,7 +153,7 @@ pub fn finalize( ) .map_err(|error| format!("failed to generate audit compatibility artifacts: {error:#}"))?; - Ok(()) + Ok(cleanup_warnings) } fn validate_metadata( @@ -143,67 +176,73 @@ fn validate_metadata( /// on-disk state and the metadata paths mutually truthful even on partial /// failure. /// -/// Both destinations are preflighted (no-clobber) before anything moves. The -/// primary denials JSON moves first and its final path is published to the -/// metadata immediately; the retained ETL moves second and its final path is -/// published immediately on success. If the ETL move fails, the JSON is -/// truthfully recorded at its final location while the ETL — never touched — -/// stays at its source with `etl_path` still pointing there. Nothing is -/// stranded and no metadata is left referencing a file that has moved. +/// The JSON pair is relocated transactionally and its final canonical path is +/// published only after both siblings commit. The retained ETL moves last and +/// its final path is published immediately on success. A later move failure +/// therefore leaves every metadata path truthful. /// /// `move_file` is injected so tests can force a second-move failure /// deterministically; production passes [`move_new_file`]. +struct ArtifactRelocation<'a> { + source_denials: &'a Path, + final_denials: &'a Path, + source_verbose_logging: &'a Path, + final_verbose_logging: &'a Path, + source_etl: &'a Path, + final_etl: &'a Path, +} + fn relocate_artifacts( capture: &mut wxc_common::models::CaptureDenialsOutput, - source_denials: &Path, - final_denials: &Path, - source_etl: &Path, - final_etl: &Path, - mut move_file: impl FnMut(&Path, &Path) -> Result<(), String>, -) -> Result<(), String> { - ensure_destination_available(source_denials, final_denials)?; - ensure_destination_available(source_etl, final_etl)?; - - // Primary denials JSON first: publish its final path the instant it moves so - // a later ETL failure can never leave `output_path` referencing a file that - // has already been renamed away. - move_file(source_denials, final_denials)?; - capture.output_path = final_denials.to_string_lossy().into_owned(); + paths: &ArtifactRelocation<'_>, + relocate_pair: impl FnOnce( + &str, + &Path, + &Path, + &Path, + &Path, + ) -> std::io::Result, + mut move_file: impl FnMut(&Path, &Path) -> Result, +) -> Result, String> { + ensure_destination_available(paths.source_etl, paths.final_etl)?; + + let pair_outcome = relocate_pair( + "audit output relocation", + paths.source_denials, + paths.source_verbose_logging, + paths.final_denials, + paths.final_verbose_logging, + ) + .map_err(|error| format!("failed to relocate audit output pair: {error}"))?; + capture.output_path = paths.final_denials.to_string_lossy().into_owned(); + let mut cleanup_warnings = pair_outcome.into_cleanup_warnings(); - // Retained ETL second: on failure it stays at its source and `etl_path` + // Retained ETL last: on failure it stays at its source and `etl_path` // still points there (unchanged), so each artifact remains individually // truthful even though the relocation as a whole failed. - move_file(source_etl, final_etl)?; - capture.etl_path = Some(final_etl.to_string_lossy().into_owned()); - Ok(()) + let etl_outcome = move_file(paths.source_etl, paths.final_etl)?; + capture.etl_path = Some(paths.final_etl.to_string_lossy().into_owned()); + cleanup_warnings.extend(etl_outcome.into_cleanup_warnings()); + Ok(cleanup_warnings) } -fn move_new_file(source: &Path, destination: &Path) -> Result<(), String> { - if source == destination { - return Ok(()); - } - ensure_destination_available(source, destination)?; - match std::fs::rename(source, destination) { - Ok(()) => Ok(()), - Err(rename_error) => { - std::fs::copy(source, destination).map_err(|copy_error| { - format!( - "failed to move audit artifact {} to {}: {rename_error}; \ - copy fallback failed: {copy_error}", - source.display(), - destination.display() - ) - })?; - std::fs::remove_file(source).map_err(|remove_error| { - let _ = std::fs::remove_file(destination); - format!( - "copied audit artifact to {}, but failed to remove source {}: {remove_error}", - destination.display(), - source.display() - ) - }) - } - } +fn move_new_file( + source: &Path, + destination: &Path, +) -> Result { + learning_mode_core::relocate_output_file( + "audit artifact relocation", + "retained ETL", + source, + destination, + ) + .map_err(|error| { + format!( + "failed to move audit artifact {} to {}: {error}", + source.display(), + destination.display() + ) + }) } fn ensure_destination_available(source: &Path, destination: &Path) -> Result<(), String> { @@ -251,7 +290,9 @@ fn remove_empty_managed_directory( #[cfg(test)] mod tests { use super::*; - use learning_mode_core::{DenialSummary, DenialsDocument}; + use learning_mode_core::{ + DenialSummary, DenialsDocument, VerboseLoggingDocument, VerboseLoggingSummary, + }; use wxc_common::models::{ CaptureDenialsErrorOutput, CaptureDenialsOutput, SandboxOutputMetadata, }; @@ -298,9 +339,15 @@ mod tests { finalize(&mut response, &context, directory.path(), false).unwrap(); assert!(!source_denials.exists()); + assert!( + !learning_mode_core::verbose_logging_sibling_path(&source_denials) + .unwrap() + .exists() + ); assert!(!source_etl.exists()); assert!(!retained_dir.exists()); assert_eq!(std::fs::read(log_dir.join("trace.etl")).unwrap(), b"etl"); + assert!(log_dir.join("denials.verbose.json").is_file()); let capture = response .output_metadata .as_ref() @@ -353,6 +400,7 @@ mod tests { Some(log_dir.join("trace.etl").as_path()) ); assert!(log_dir.join("denials.json").is_file()); + assert!(log_dir.join("denials.verbose.json").is_file()); assert!(log_dir.join("trace.etl").is_file()); } @@ -402,9 +450,45 @@ mod tests { assert!(error.contains("canonical denials JSON")); assert!(source_denials.exists()); + assert!( + learning_mode_core::verbose_logging_sibling_path(&source_denials) + .unwrap() + .exists() + ); assert!(source_etl.exists()); } + #[test] + fn finalize_rejects_malformed_verbose_logging_without_moving_artifacts() { + let directory = tempfile::tempdir().unwrap(); + let log_dir = directory.path().join("audit"); + std::fs::create_dir_all(&log_dir).unwrap(); + let source_denials = log_dir.join("denials.unique.json"); + let source_verbose_logging = + learning_mode_core::verbose_logging_sibling_path(&source_denials).unwrap(); + let source_etl = log_dir.join("denials.unique.etl"); + let document = DenialsDocument::new(Vec::new(), DenialSummary::new(0, 0, false)); + std::fs::write(&source_denials, serde_json::to_vec(&document).unwrap()).unwrap(); + std::fs::write(&source_etl, b"etl").unwrap(); + let mut response = response_with_capture(&source_denials, &source_etl, 0); + std::fs::write(&source_verbose_logging, b"{").unwrap(); + let context = AuditContext { + log_dir: log_dir.clone(), + config_path: None, + }; + + let error = finalize(&mut response, &context, directory.path(), false).unwrap_err(); + + assert!(error.contains("verbose logging output")); + assert!(error.contains("not valid JSON")); + assert!(source_denials.is_file()); + assert!(source_verbose_logging.is_file()); + assert!(source_etl.is_file()); + assert!(!log_dir.join("denials.json").exists()); + assert!(!log_dir.join("denials.verbose.json").exists()); + assert!(!log_dir.join("trace.etl").exists()); + } + #[test] fn finalize_preflights_both_destinations_before_moving_artifacts() { let directory = tempfile::tempdir().unwrap(); @@ -424,26 +508,72 @@ mod tests { let error = finalize(&mut response, &context, directory.path(), false).unwrap_err(); - assert!(error.contains("destination already exists")); + assert!(error.contains("canonical output file already exists")); assert!(source_denials.exists()); + assert!( + learning_mode_core::verbose_logging_sibling_path(&source_denials) + .unwrap() + .exists() + ); assert!(source_etl.exists()); assert!(!log_dir.join("trace.etl").exists()); } #[test] - fn relocate_keeps_metadata_truthful_when_second_move_fails() { - // Primary JSON moves; the ETL (second) move is forced to fail. The JSON - // must be truthfully recorded at its final path, and the ETL — never - // touched — must remain at its source with `etl_path` still pointing - // there. Nothing is stranded and no metadata is left stale. + fn etl_relocation_never_clobbers_an_existing_destination() { + let directory = tempfile::tempdir().unwrap(); + let source = directory.path().join("source.json"); + let destination = directory.path().join("destination.json"); + std::fs::write(&source, b"new").unwrap(); + std::fs::write(&destination, b"existing").unwrap(); + + let error = move_new_file(&source, &destination).unwrap_err(); + + assert!(error.contains("already exists")); + assert_eq!(std::fs::read(&source).unwrap(), b"new"); + assert_eq!(std::fs::read(&destination).unwrap(), b"existing"); + } + + #[test] + fn finalize_rejects_missing_verbose_logging_output() { + let directory = tempfile::tempdir().unwrap(); + let log_dir = directory.path().join("audit"); + std::fs::create_dir_all(&log_dir).unwrap(); + let source_denials = log_dir.join("denials.unique.json"); + let source_etl = log_dir.join("denials.unique.etl"); + let document = DenialsDocument::new(Vec::new(), DenialSummary::new(0, 0, false)); + std::fs::write(&source_denials, serde_json::to_vec(&document).unwrap()).unwrap(); + std::fs::write(&source_etl, b"etl").unwrap(); + let mut response = response_with_capture(&source_denials, &source_etl, 0); + std::fs::remove_file( + learning_mode_core::verbose_logging_sibling_path(&source_denials).unwrap(), + ) + .unwrap(); + let context = AuditContext { + log_dir, + config_path: None, + }; + + let error = finalize(&mut response, &context, directory.path(), false).unwrap_err(); + + assert!(error.contains("verbose logging output file is missing")); + assert!(source_denials.exists()); + assert!(source_etl.exists()); + } + + #[test] + fn relocate_keeps_metadata_truthful_when_etl_move_fails() { let directory = tempfile::tempdir().unwrap(); let log_dir = directory.path().join("audit"); std::fs::create_dir_all(&log_dir).unwrap(); let source_denials = log_dir.join("denials.unique.json"); + let source_verbose_logging = log_dir.join("denials.unique.verbose.json"); let source_etl = log_dir.join("denials.unique.etl"); let final_denials = log_dir.join("denials.json"); + let final_verbose_logging = log_dir.join("denials.verbose.json"); let final_etl = log_dir.join("trace.etl"); std::fs::write(&source_denials, b"denials").unwrap(); + std::fs::write(&source_verbose_logging, b"verbose").unwrap(); std::fs::write(&source_etl, b"etl").unwrap(); let mut capture = CaptureDenialsOutput { kind: CaptureDenialsOutput::KIND.to_string(), @@ -457,16 +587,23 @@ mod tests { let mut calls = 0; let error = relocate_artifacts( &mut capture, - &source_denials, - &final_denials, - &source_etl, - &final_etl, + &ArtifactRelocation { + source_denials: &source_denials, + final_denials: &final_denials, + source_verbose_logging: &source_verbose_logging, + final_verbose_logging: &final_verbose_logging, + source_etl: &source_etl, + final_etl: &final_etl, + }, + learning_mode_core::relocate_paired_output_files, |source, destination| { calls += 1; if calls == 1 { - std::fs::rename(source, destination).map_err(|error| error.to_string()) - } else { Err("injected ETL move failure".to_string()) + } else { + std::fs::rename(source, destination) + .map(|_| learning_mode_core::RelocationOutcome::default()) + .map_err(|error| error.to_string()) } }, ) @@ -477,6 +614,8 @@ mod tests { assert!(final_denials.is_file()); assert!(!source_denials.exists()); assert_eq!(Path::new(&capture.output_path), final_denials); + assert!(final_verbose_logging.is_file()); + assert!(!source_verbose_logging.exists()); // ETL untouched; metadata still truthfully points at the source. assert!(source_etl.is_file()); assert!(!final_etl.exists()); @@ -486,11 +625,63 @@ mod tests { ); } + #[test] + fn relocate_rolls_back_json_pair_before_publishing_metadata() { + let directory = tempfile::tempdir().unwrap(); + let source_denials = directory.path().join("denials.unique.json"); + let source_verbose_logging = directory.path().join("denials.unique.verbose.json"); + let source_etl = directory.path().join("denials.unique.etl"); + let shared_destination = directory.path().join("denials.json"); + let final_etl = directory.path().join("trace.etl"); + std::fs::write(&source_denials, b"denials").unwrap(); + std::fs::write(&source_verbose_logging, b"verbose").unwrap(); + std::fs::write(&source_etl, b"etl").unwrap(); + let mut capture = CaptureDenialsOutput { + kind: CaptureDenialsOutput::KIND.to_string(), + output_path: source_denials.to_string_lossy().into_owned(), + exit_code: 0, + total_denials: 0, + denied_resources_truncated: false, + etl_path: Some(source_etl.to_string_lossy().into_owned()), + }; + + let error = relocate_artifacts( + &mut capture, + &ArtifactRelocation { + source_denials: &source_denials, + final_denials: &shared_destination, + source_verbose_logging: &source_verbose_logging, + final_verbose_logging: &shared_destination, + source_etl: &source_etl, + final_etl: &final_etl, + }, + learning_mode_core::relocate_paired_output_files, + |_, _| panic!("ETL relocation must not run after JSON-pair failure"), + ) + .unwrap_err(); + + assert!(error.contains("failed to promote canonical")); + assert_eq!(Path::new(&capture.output_path), source_denials); + assert!(source_denials.is_file()); + assert!(source_verbose_logging.is_file()); + assert!(!shared_destination.exists()); + assert!(source_etl.is_file()); + assert!(!final_etl.exists()); + } + fn response_with_capture( denials_path: &Path, etl_path: &Path, exit_code: i32, ) -> ScriptResponse { + let verbose_logging_path = + learning_mode_core::verbose_logging_sibling_path(denials_path).unwrap(); + let verbose_logging = VerboseLoggingDocument::new(&VerboseLoggingSummary::default()); + std::fs::write( + verbose_logging_path, + serde_json::to_vec(&verbose_logging).unwrap(), + ) + .unwrap(); ScriptResponse { exit_code, output_metadata: Some(Box::new(SandboxOutputMetadata { diff --git a/src/core/wxc/src/main.rs b/src/core/wxc/src/main.rs index 52ef9e01a..4a08e6dcb 100644 --- a/src/core/wxc/src/main.rs +++ b/src/core/wxc/src/main.rs @@ -1225,18 +1225,25 @@ fn main() { #[cfg(target_os = "windows")] if let Some(context) = audit_context.as_ref() { if !cli.dry_run { - if let Err(error) = audit::finalize(&mut response, context, &exe_dir, cli.audit_verbose) - { - let message = format!("audit finalization failed: {error}"); - let _ = writeln!(logger, "[audit] {message}"); - eprintln!("error: {message}"); - response.exit_code = -1; - response.error_message = match response.error_message.is_empty() { - true => message, - false => format!("{}; {message}", response.error_message), - }; - } else { - eprintln!("[audit] artifacts written to {}", context.log_dir.display()); + match audit::finalize(&mut response, context, &exe_dir, cli.audit_verbose) { + Ok(cleanup_warnings) => { + for warning in cleanup_warnings { + let message = format!("[audit] warning: {warning}"); + let _ = writeln!(logger, "{message}"); + eprintln!("{message}"); + } + eprintln!("[audit] artifacts written to {}", context.log_dir.display()); + } + Err(error) => { + let message = format!("audit finalization failed: {error}"); + let _ = writeln!(logger, "[audit] {message}"); + eprintln!("error: {message}"); + response.exit_code = -1; + response.error_message = match response.error_message.is_empty() { + true => message, + false => format!("{}; {message}", response.error_message), + }; + } } } } diff --git a/src/host/plm/readme.md b/src/host/plm/readme.md index 04d20c04c..ae4937f15 100644 --- a/src/host/plm/readme.md +++ b/src/host/plm/readme.md @@ -195,6 +195,78 @@ consumer's local Cargo output directory. A locally built or user-writable adjacent `plm.exe` is intentionally rejected, which means native PSEC capture may remain available but the guarded-WPR legacy fallback is unavailable. +For an isolated developer validation loop, a locally built `plm.exe` can be +Authenticode-signed with a short-lived development code-signing certificate +whose signer Organization is `Microsoft Corporation`. Trust that certificate +only on the validation machine, deploy the signed binary in an +administrator-protected directory, and remove the certificate after testing. +This exercises the production trust gate without adding an unsigned-build +bypass; production packages still require the normal Microsoft-signed binary. + +`signtool.exe` is included with the Windows SDK. If it is not available on the +development machine, install the SDK from the +[official Windows SDK downloads](https://learn.microsoft.com/windows/apps/windows-sdk/downloads) +before running the example. The following PowerShell creates a one-day, +non-exportable local certificate, signs a development build, and exports only +its public certificate: + +```powershell +$cert = New-SelfSignedCertificate ` + -Type CodeSigningCert ` + -Subject 'CN=MXC Local Validation TEST ONLY,O=Microsoft Corporation' ` + -CertStoreLocation 'Cert:\CurrentUser\My' ` + -KeyExportPolicy NonExportable ` + -NotAfter (Get-Date).AddDays(1) ` + -HashAlgorithm SHA256 + +$signTool = Get-ChildItem ` + "${env:ProgramFiles(x86)}\Windows Kits\10\bin" ` + -Filter signtool.exe -Recurse | + Where-Object FullName -Like '*\x64\signtool.exe' | + Sort-Object FullName -Descending | + Select-Object -First 1 + +& $signTool.FullName sign ` + /sha1 $cert.Thumbprint /s My /fd SHA256 .\plm.exe + +Export-Certificate -Cert $cert -FilePath .\mxc-dev-validation.cer +$cert.Thumbprint | Set-Content .\mxc-dev-validation.thumbprint +``` + +On an isolated validation machine, an administrator can trust the public +certificate locally and verify the signed binary: + +```powershell +$certificate = Import-Certificate ` + -FilePath .\mxc-dev-validation.cer ` + -CertStoreLocation 'Cert:\LocalMachine\Root' +Import-Certificate ` + -FilePath .\mxc-dev-validation.cer ` + -CertStoreLocation 'Cert:\LocalMachine\TrustedPublisher' + +Get-AuthenticodeSignature .\plm.exe +``` + +Deploy `plm.exe` in an administrator-protected directory such as +`C:\Program Files\MXC-Dev\`; the directory-integrity gate still rejects a +signed binary from a user-writable location. After validation, remove the +certificate from the validation machine and remove the private-key certificate +from the development machine: + +```powershell +$thumbprint = Get-Content .\mxc-dev-validation.thumbprint + +# Run elevated on the validation machine. +Remove-Item "Cert:\LocalMachine\Root\$thumbprint" +Remove-Item "Cert:\LocalMachine\TrustedPublisher\$thumbprint" + +# Run on the development machine. +Remove-Item "Cert:\CurrentUser\My\$thumbprint" +``` + +The certificate and signed binary are test artifacts: do not publish, +redistribute, or use them outside the isolated validation environment. + ### Bounded discard-confirmation If discarding a guarded session fails, MXC confirms that the elevated guardian diff --git a/src/host/plm/src/analysis.rs b/src/host/plm/src/analysis.rs index 17c70c907..133036438 100644 --- a/src/host/plm/src/analysis.rs +++ b/src/host/plm/src/analysis.rs @@ -4,13 +4,13 @@ //! Canonical Learning Mode analysis and compatibility views for `plm.exe`. use std::collections::{HashMap, HashSet}; -use std::io::Write; use std::path::Path; use anyhow::{Context, Result}; use learning_mode_core::{ - write_document, AccessType, AnalysisResult, DenialAnalyzer, DenialSummary, DenialsDocument, - DeniedResource, ResourceType, + verbose_logging_sibling_path, write_document, write_paired_output_files, + write_verbose_logging_document, AccessType, AnalysisResult, DenialAnalyzer, DenialSummary, + DenialsDocument, DeniedResource, ExistingOutputPolicy, ResourceType, VerboseLoggingDocument, }; use learning_mode_windows::EtlDenialAnalyzer; @@ -24,7 +24,8 @@ pub fn analyze_trace(trace_file: &Path) -> Result { .with_context(|| format!("failed to analyze {}", trace_file.display())) } -/// Write canonical denials JSON atomically and return the document that was written. +/// Write canonical denials JSON and its verbose logging sibling, then return the +/// canonical document. pub fn write_denials( output_path: &Path, analysis: &AnalysisResult, @@ -40,16 +41,17 @@ pub fn write_denials( analysis.denied_resources_truncated, ); let document = DenialsDocument::new(analysis.denials.clone(), summary); - let mut temp = tempfile::NamedTempFile::new_in(parent) - .with_context(|| format!("failed to create denials temp file in {}", parent.display()))?; - write_document(&mut temp, &document) - .with_context(|| format!("failed to write {}", output_path.display()))?; - temp.flush() - .and_then(|_| temp.as_file().sync_all()) - .with_context(|| format!("failed to flush {}", output_path.display()))?; - temp.persist(output_path) - .map_err(|error| error.error) - .with_context(|| format!("failed to replace {}", output_path.display()))?; + let verbose_logging_document = VerboseLoggingDocument::new(&analysis.verbose_logging); + let verbose_logging_path = verbose_logging_sibling_path(output_path) + .with_context(|| format!("failed to derive sibling for {}", output_path.display()))?; + write_paired_output_files( + "plm stop", + output_path, + &verbose_logging_path, + ExistingOutputPolicy::Replace, + |writer| write_document(writer, &document), + |writer| write_verbose_logging_document(writer, &verbose_logging_document), + )?; Ok(document) } @@ -292,13 +294,38 @@ mod tests { let analysis = AnalysisResult { denials: vec![denial(r"C:\read.txt", ResourceType::File, AccessType::Read)], denied_resources_truncated: true, + verbose_logging: Default::default(), }; write_denials(&path, &analysis, 7).unwrap(); let document: DenialsDocument = - serde_json::from_slice(&std::fs::read(path).unwrap()).unwrap(); + serde_json::from_slice(&std::fs::read(&path).unwrap()).unwrap(); + let verbose_logging_path = learning_mode_core::verbose_logging_sibling_path(&path).unwrap(); + let verbose_logging_document: learning_mode_core::VerboseLoggingDocument = + serde_json::from_slice(&std::fs::read(verbose_logging_path).unwrap()).unwrap(); assert_eq!(document.denials, analysis.denials); assert_eq!(document.summary.exit_code, 7); assert!(document.summary.denied_resources_truncated); + assert_eq!(verbose_logging_document.summary.total_occurrences, 0); + } + + #[test] + fn canonical_promotion_failure_removes_verbose_logging_sibling() { + let dir = tempfile::tempdir().unwrap(); + let path = dir.path().join("denials.json"); + std::fs::create_dir(&path).unwrap(); + let verbose_logging_path = learning_mode_core::verbose_logging_sibling_path(&path).unwrap(); + let analysis = AnalysisResult { + denials: Vec::new(), + denied_resources_truncated: false, + verbose_logging: Default::default(), + }; + + let error = write_denials(&path, &analysis, 0).unwrap_err(); + + assert!(error + .to_string() + .contains("cannot replace non-file canonical")); + assert!(!verbose_logging_path.exists()); } } diff --git a/src/host/plm/src/log.rs b/src/host/plm/src/log.rs index b818d97d0..559370144 100644 --- a/src/host/plm/src/log.rs +++ b/src/host/plm/src/log.rs @@ -98,6 +98,7 @@ mod tests { assert!(!can_generate_policy_preview(&AnalysisResult { denials: Vec::new(), denied_resources_truncated: true, + verbose_logging: Default::default(), })); } } diff --git a/src/host/plm/src/stop.rs b/src/host/plm/src/stop.rs index ab4cfefd0..41a426b22 100644 --- a/src/host/plm/src/stop.rs +++ b/src/host/plm/src/stop.rs @@ -89,9 +89,13 @@ fn prepare_config_output_paths( trace_path: &Path, denials_path: &Path, ) -> Result> { - if same_config_target(trace_path, denials_path) { + let verbose_logging_path = learning_mode_core::verbose_logging_sibling_path(denials_path) + .context("failed to derive verbose logging output path")?; + if same_config_target(trace_path, denials_path) + || same_config_target(trace_path, &verbose_logging_path) + { anyhow::bail!( - "trace output {} would be overwritten by denials output {}", + "trace output {} would be overwritten by a denials output derived from {}", trace_path.display(), denials_path.display() ); @@ -112,7 +116,10 @@ fn prepare_config_output_paths( ("config snapshot", snapshot.as_path()), ("adjusted config", adjusted.as_path()), ] { - if same_config_target(path, trace_path) || same_config_target(path, denials_path) { + if same_config_target(path, trace_path) + || same_config_target(path, denials_path) + || same_config_target(path, &verbose_logging_path) + { anyhow::bail!( "{label} path {} collides with a capture output", path.display() @@ -659,6 +666,35 @@ mod tests { assert!(error.to_string().contains("would be overwritten")); } + #[test] + fn rejects_user_selected_trace_path_that_matches_derived_verbose_output() { + // `--trace-file` is caller-controlled, while this sibling path is + // derived from denials.json. Without this check, publishing the verbose + // output would overwrite the retained ETL before post-processing ends. + let trace = Path::new(r"C:\captures\denials.verbose.json"); + let error = prepare_config_output_paths( + None, + Path::new(r"C:\captures"), + trace, + Path::new(r"C:\captures\denials.json"), + ) + .unwrap_err(); + assert!(error.to_string().contains("would be overwritten")); + } + + #[test] + fn config_snapshot_cannot_collide_with_verbose_logging_output() { + let source = Path::new(r"C:\source\denials.verbose.json"); + let error = prepare_config_output_paths( + Some(source), + Path::new(r"C:\captures"), + Path::new(r"C:\captures\trace.etl"), + Path::new(r"C:\captures\denials.json"), + ) + .unwrap_err(); + assert!(error.to_string().contains("config snapshot")); + } + #[test] fn trailing_dot_trace_alias_cannot_collide_with_denials_output() { let dir = std::env::temp_dir().join(format!("plm_alias_target_{}", std::process::id()));