From 7a965955a82a134fbf337ba9193a57ed0e460b59 Mon Sep 17 00:00:00 2001 From: Jacob Dereje Date: Mon, 5 Oct 2026 14:01:24 -0700 Subject: [PATCH 01/10] Retain unrecognized Learning Mode events Copilot-Session: 7758b99e-b7a0-4060-baf9-268db306b58b --- docs/learning-mode/capabilities.md | 80 ++- src/Cargo.lock | 2 + .../common/src/capture_output.rs | 1 + src/core/learning_mode_core/src/analyze.rs | 4 + .../learning_mode_core/src/verbose_logging.rs | 48 +- .../windows/Cargo.toml | 2 + .../windows/src/capability_dacl.rs | 2 + .../windows/src/etl_decode.rs | 641 ++++++++++++++---- .../windows/src/etl_filter.rs | 200 +++++- .../windows/src/extractors.rs | 142 +++- .../windows/src/tdh_decode.rs | 19 +- src/core/mxc_engine/src/verbose_telemetry.rs | 41 +- src/host/plm/src/elevated.rs | 2 +- src/host/plm/src/stop.rs | 11 +- .../wxc_e2e_tests/tests/e2e_telemetry_etw.rs | 10 +- 15 files changed, 995 insertions(+), 210 deletions(-) diff --git a/docs/learning-mode/capabilities.md b/docs/learning-mode/capabilities.md index 1c406d233..0163fc8f1 100644 --- a/docs/learning-mode/capabilities.md +++ b/docs/learning-mode/capabilities.md @@ -207,7 +207,9 @@ sandbox policy: - Analysis retains at most 10,000 unique denials and processes at most 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`. + sets `summary.deniedResourcesTruncated` to `true`. Missing schemas for + supported denial events also set this flag. Incomplete results do not produce + policy previews or adjusted configurations. - `resource` is the user-visible identifier for the denied resource, interpreted by `resourceType`: an absolute `C:\…` path for `file`, the AppContainer **capability name** (e.g. `internetClient`) for `capability`, @@ -220,9 +222,9 @@ sandbox policy: 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 - checks as empty-`ObjectType` access events that are omitted because they do - not carry a stable capability identifier. + denials are recorded under `block`; `allow` traces can expose capability + checks as empty-`ObjectType` access events. Known capabilities can be recovered + from their DACL payload; unresolved checks remain verbose diagnostics. - `filetime` is a decimal string containing the Windows `FILETIME` value, so JavaScript consumers retain all 64 bits without numeric precision loss. @@ -235,7 +237,7 @@ policy denial occurrences plus diagnostic outcomes omitted from the policy file: ```json { - "version": 2, + "version": 3, "signatures": [ { "signature": { @@ -266,18 +268,24 @@ policy denial occurrences plus diagnostic outcomes omitted from the policy file: ``` Signatures are keyed by symbolic provider category, provider GUID, -provider-scoped event ID, closed outcome reason, PID, and sorted sanitized -properties. SIDs, capability names, GUIDs, PIDs/process identifiers, and +provider-scoped event ID, optional schema `eventName`, closed outcome reason, +PID, and sorted sanitized properties. The schema name distinguishes TraceLogging +events that share ID 0 and is separate from any payload field named `EventName`. +It is sanitized and bounded like other values, and is omitted when unavailable. +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 -``. +``; a path inside a command line or rendered array causes that entire +property value to be redacted. Standalone user/account names remain replaced +with ``. Properties whose names contain file paths are omitted. Exact header timestamps and timestamp-like properties are omitted so otherwise identical events deduplicate, and free-form decoder errors are never serialized. +This is an outcome summary, not an ordered event ledger: repeats become a count, +and one source event can produce several capability-denial outcomes. -Every valid actionable denial is classified as `actionable` in the verbose -file, including its first occurrence, later duplicates, and candidates observed -after the actionable file's unique-denial bound. Those occurrences deduplicate -under the same signature and increment its count. `accessType` and +Every valid policy denial is classified as `actionable` in the verbose file. +Its first occurrence, later duplicates, and candidates observed after the +actionable file's unique-denial bound are all retained. 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. @@ -305,26 +313,45 @@ 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. +Unknown providers and event IDs receive best-effort TDH decoding. Events with no +actionable extractor use `unsupportedEventSchema` and retain their sanitized +properties. Unknown providers use `provider: "other"` with their actual GUID +in the local file. Different provider GUIDs remain separate deduplication keys. +They do not create new actionable policy grants. 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. +in the optional `eventName` metadata field, with no partial payload properties. +Free-form decoder errors are +never serialized. Failure to obtain the event schema is retained as +`schemaUnavailable` rather than aborting the analysis, and marks actionable +results incomplete when the event belongs to a supported denial schema. +For brokered Event 28, scoped analysis marks the result incomplete even when +the missing schema prevents reading its workload PID; unattributed event +contents are not retained. 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 +signatures and 16 MiB of compact signature data, with 24 sorted properties per +signature and 256 characters per property value. +`overflowOccurrences` and `aggregateGroupsTruncated` indicate that additional diagnostic groups were omitted. `actionableOverflowOccurrences` counts omitted actionable-denial occurrences, while `processedEventsTruncated` indicates that the 1,000,000-event limit prevented complete accounting. The actionable file itself is never reduced to make room for verbose logging. +The existing 64 MiB guarded analysis frame can also move verbose groups into +overflow accounting. These bounds are retained; the file does not claim complete +event-by-event coverage. + +Guarded WPR keeps only events from the exact job-attested process lifetimes, +including brokered capability attribution, regardless of provider. Its generated +relogging header is excluded from analysis so it does not add a diagnostic that +was absent from the source. A schema lookup failure while scoping brokered +Event 28 fails the capture, because its workload PID cannot be established. +Neither the unattributed event nor a potentially incomplete filtered trace is +returned. The host-wide source ETL is not transferred. The actionable and verbose logging files fail together: MXC stages both and reports capture failure unless both final artifacts are committed. The verbose logging path @@ -336,7 +363,9 @@ When stable telemetry is enabled and authorized, MXC may validate, compact, and send this redacted verbose document through `Microsoft.MXC/MXC.VerboseDenials`. Each event contains a valid JSON array of complete signatures and document reconstruction metadata. Before emission, MXC derives provider GUIDs from the -closed provider enum and drops every verbose property name and value. MXC does +closed provider enum and drops every verbose property name and value. For `other`, +the telemetry GUID is empty. Matching groups are combined again after these +values and the schema `eventName` are removed. MXC does not send the actionable denials file, workload-derived properties, or raw ETL through telemetry. See [MXC telemetry](../telemetry/telemetry.md). @@ -372,9 +401,10 @@ WPR's source ETL is host-wide, so the elevated guarded-WPR helper never transfers that file across the privilege boundary for `captureDenials` or `--audit`. After the sandbox process tree terminates, the helper uses the retained, job-attested process handles and their exact PID/creation/exit -`FILETIME` ranges to relog a second ETL. The -retained ETL contains only supported Learning Mode events whose event header -falls inside one of those attested process generations. Guarded analysis and +`FILETIME` ranges to relog a second ETL. The retained ETL contains events from +any provider attributed to those process generations, plus required ETL metadata. +Brokered capability events use their payload `ProcessId` rather than the +broker's header PID. Guarded analysis and retention both consume that same filtered ETL; filtering failure transfers no trace. The host-wide source remains in protected elevated scratch and is deleted with that scratch. The unelevated caller writes the filtered retained diff --git a/src/Cargo.lock b/src/Cargo.lock index fc6a0c59a..9d8cac8c5 100644 --- a/src/Cargo.lock +++ b/src/Cargo.lock @@ -1375,7 +1375,9 @@ dependencies = [ "flatbuffers", "learning_mode_core", "process_security_environment_spec", + "tempfile", "thiserror", + "tracelogging", "windows", "windows-core", "wxc_common", diff --git a/src/backends/process_container/common/src/capture_output.rs b/src/backends/process_container/common/src/capture_output.rs index d575f5dbd..6c5bb9368 100644 --- a/src/backends/process_container/common/src/capture_output.rs +++ b/src/backends/process_container/common/src/capture_output.rs @@ -336,6 +336,7 @@ mod tests { let output_path = directory.path().join("denials.json"); let mut analysis = AnalysisResult::complete(Vec::new()); analysis.verbose_logging.record(VerboseLoggingSignature { + event_name: None, provider: VerboseLoggingProvider::KernelGeneral, provider_guid: "{A68CA8B7-004F-D7B6-A698-07E2DE0F1F5D}".to_string(), event_id: 14, diff --git a/src/core/learning_mode_core/src/analyze.rs b/src/core/learning_mode_core/src/analyze.rs index c924fc04b..9fcfdff5c 100644 --- a/src/core/learning_mode_core/src/analyze.rs +++ b/src/core/learning_mode_core/src/analyze.rs @@ -306,6 +306,7 @@ mod tests { let signature = |pid| VerboseLoggingAggregate { signature: VerboseLoggingSignature { provider: VerboseLoggingProvider::KernelGeneral, + event_name: None, provider_guid: "provider".to_string(), event_id: 14, reason: VerboseLoggingOutcomeReason::Actionable, @@ -351,6 +352,7 @@ mod tests { signatures: vec![VerboseLoggingAggregate { signature: VerboseLoggingSignature { provider: VerboseLoggingProvider::KernelGeneral, + event_name: None, provider_guid: "provider".to_string(), event_id: 14, reason: VerboseLoggingOutcomeReason::Actionable, @@ -395,6 +397,7 @@ mod tests { signature: VerboseLoggingSignature { provider: VerboseLoggingProvider::KernelGeneral, provider_guid: "provider".to_string(), + event_name: None, event_id: 14, reason: VerboseLoggingOutcomeReason::Actionable, pid: 1, @@ -428,6 +431,7 @@ mod tests { .map(|pid| VerboseLoggingAggregate { signature: VerboseLoggingSignature { provider: VerboseLoggingProvider::KernelGeneral, + event_name: None, provider_guid: "provider".to_string(), event_id: 14, reason: VerboseLoggingOutcomeReason::MissingObjectName, diff --git a/src/core/learning_mode_core/src/verbose_logging.rs b/src/core/learning_mode_core/src/verbose_logging.rs index a3870eac0..f24eec783 100644 --- a/src/core/learning_mode_core/src/verbose_logging.rs +++ b/src/core/learning_mode_core/src/verbose_logging.rs @@ -17,10 +17,12 @@ pub const MAX_VERBOSE_LOGGING_GROUPS: usize = 4_096; /// 64 MiB frame limit for actionable denials and envelope overhead. pub const MAX_VERBOSE_LOGGING_SIGNATURE_BYTES: usize = 16 * 1024 * 1024; -/// Stable category for a known Learning Mode ETW provider. +/// Stable category for a Learning Mode ETW provider. #[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash, Serialize, Deserialize)] #[serde(rename_all = "camelCase")] pub enum VerboseLoggingProvider { + /// Any other provider, identified by its GUID in the local output. + Other, /// Microsoft-Windows-Kernel-General. KernelGeneral, /// Microsoft-Windows-Privacy-Auditing-PermissiveLearningMode. @@ -33,8 +35,10 @@ pub enum VerboseLoggingProvider { pub enum VerboseLoggingOutcomeReason { /// The event produced a valid actionable denial. Actionable, - /// The provider is known, but the event ID is not a supported denial schema. + /// No actionable extractor supports this provider/event pair. UnsupportedEventSchema, + /// TDH could not resolve the event schema. + SchemaUnavailable, /// The event payload conflicted with its declared TDH schema. EventPayloadMalformed, /// A decoder safety bound prevented full payload processing. @@ -73,6 +77,9 @@ pub struct VerboseLoggingSignature { pub provider_guid: String, /// Provider-scoped ETW schema identifier. pub event_id: u16, + /// Sanitized schema name, separate from payload properties. + #[serde(default, skip_serializing_if = "Option::is_none")] + pub event_name: Option, /// Closed exclusion category. pub reason: VerboseLoggingOutcomeReason, /// Process identifier from the event header. @@ -303,7 +310,7 @@ pub struct VerboseLoggingDocumentSummary { impl VerboseLoggingDocument { /// Current verbose logging document schema version. - pub const VERSION: u32 = 2; + pub const VERSION: u32 = 3; /// Builds an on-disk document from decoder aggregate state. #[must_use] @@ -371,6 +378,7 @@ mod tests { fn aggregates_and_sorts_sanitized_signatures() { let mut summary = VerboseLoggingSummary::default(); let signature = VerboseLoggingSignature { + event_name: None, provider: VerboseLoggingProvider::KernelGeneral, provider_guid: "{A68CA8B7-004F-D7B6-A698-07E2DE0F1F5D}".to_string(), event_id: 14, @@ -407,6 +415,7 @@ mod tests { for event_id in 0..MAX_VERBOSE_LOGGING_GROUPS as u16 { summary.record(VerboseLoggingSignature { provider: VerboseLoggingProvider::KernelGeneral, + event_name: None, provider_guid: "kernel".to_string(), event_id, reason: VerboseLoggingOutcomeReason::UnsupportedEventSchema, @@ -418,6 +427,7 @@ mod tests { } summary.record(VerboseLoggingSignature { provider: VerboseLoggingProvider::PrivacyAuditingPermissiveLearningMode, + event_name: None, provider_guid: "privacy".to_string(), event_id: u16::MAX, reason: VerboseLoggingOutcomeReason::UnsupportedEventSchema, @@ -439,6 +449,7 @@ mod tests { summary.record(VerboseLoggingSignature { provider: VerboseLoggingProvider::KernelGeneral, provider_guid: "kernel".to_string(), + event_name: None, event_id, reason: VerboseLoggingOutcomeReason::UnsupportedEventSchema, pid: 1, @@ -452,6 +463,7 @@ mod tests { provider_guid: "kernel".to_string(), event_id: u16::MAX, reason: VerboseLoggingOutcomeReason::Actionable, + event_name: None, pid: 1, access_type: Some(crate::AccessType::Read), resource_type: Some(crate::ResourceType::File), @@ -476,6 +488,7 @@ mod tests { for pid in 0..MAX_VERBOSE_LOGGING_GROUPS as u32 { summary.record_with_byte_budget( VerboseLoggingSignature { + event_name: None, provider: VerboseLoggingProvider::KernelGeneral, provider_guid: "{A68CA8B7-004F-D7B6-A698-07E2DE0F1F5D}".to_string(), event_id: 14, @@ -514,6 +527,32 @@ mod tests { assert_eq!(parsed, document); } + #[test] + fn schema_name_is_optional_and_separate_from_payload() { + let old = serde_json::json!({ + "provider": "other", + "providerGuid": "provider", + "eventId": 0, + "reason": "unsupportedEventSchema", + "pid": 42, + "properties": [["EventName", "payload-name"]] + }); + let mut signature: VerboseLoggingSignature = serde_json::from_value(old).unwrap(); + assert!(signature.event_name.is_none()); + assert!(serde_json::to_value(&signature) + .unwrap() + .get("eventName") + .is_none()); + signature.event_name = Some("schema-name".into()); + let json = serde_json::to_value(&signature).unwrap(); + assert_eq!(json["eventName"], "schema-name"); + assert_eq!(json["properties"][0][1], "payload-name"); + assert_eq!( + serde_json::from_value::(json).unwrap(), + signature + ); + } + #[test] fn document_uses_actionable_vocabulary() { let mut summary = VerboseLoggingSummary::default(); @@ -521,6 +560,7 @@ mod tests { provider: VerboseLoggingProvider::KernelGeneral, provider_guid: "kernel".to_string(), event_id: 14, + event_name: None, reason: VerboseLoggingOutcomeReason::Actionable, pid: 1, access_type: Some(crate::AccessType::Read), @@ -531,7 +571,7 @@ mod tests { summary.mark_actionable_limit_reached(); let value = serde_json::to_value(VerboseLoggingDocument::new(&summary)).unwrap(); - assert_eq!(value["version"], 2); + assert_eq!(value["version"], 3); assert_eq!(value["signatures"][0]["signature"]["reason"], "actionable"); assert_eq!(value["summary"]["actionableOverflowOccurrences"], 2); assert_eq!(value["summary"]["actionableLimitReached"], true); diff --git a/src/core/learning_mode_platforms/windows/Cargo.toml b/src/core/learning_mode_platforms/windows/Cargo.toml index 457ef2975..3dc53179c 100644 --- a/src/core/learning_mode_platforms/windows/Cargo.toml +++ b/src/core/learning_mode_platforms/windows/Cargo.toml @@ -17,5 +17,7 @@ windows = { workspace = true } windows-core = { workspace = true } [target.'cfg(target_os = "windows")'.dev-dependencies] +tempfile = { workspace = true } +tracelogging = { workspace = true } flatbuffers = { workspace = true } process_security_environment_spec = { workspace = true } diff --git a/src/core/learning_mode_platforms/windows/src/capability_dacl.rs b/src/core/learning_mode_platforms/windows/src/capability_dacl.rs index bee880627..0a8a90676 100644 --- a/src/core/learning_mode_platforms/windows/src/capability_dacl.rs +++ b/src/core/learning_mode_platforms/windows/src/capability_dacl.rs @@ -674,6 +674,7 @@ mod tests { fn parts(name: &str, value: String) -> DecodedEventParts { DecodedEventParts { provider: PRIVACY_LEARNING_MODE_PROVIDER, + event_name: None, event_id: ACCESS_CHECK_EVENT_ID, props: vec![ ("ObjectType".to_string(), "\"\"".to_string()), @@ -852,6 +853,7 @@ mod tests { #[test] fn ignores_non_permissive_provider() { let event = DecodedEventParts { + event_name: None, provider: GUID::zeroed(), event_id: ACCESS_CHECK_EVENT_ID, props: Vec::new(), diff --git a/src/core/learning_mode_platforms/windows/src/etl_decode.rs b/src/core/learning_mode_platforms/windows/src/etl_decode.rs index b3eb07d4b..852d4c623 100644 --- a/src/core/learning_mode_platforms/windows/src/etl_decode.rs +++ b/src/core/learning_mode_platforms/windows/src/etl_decode.rs @@ -2,7 +2,7 @@ // Licensed under the MIT License. //! Sealed-ETL decoder: turns the `.etl` delivered by the Learning Mode trace API -//! produces into cross-platform [`DeniedResource`]s. +//! into cross-platform [`DeniedResource`]s. //! //! The trace is opened in **file mode** (`EVENT_TRACE_LOGFILEW.LogFileName`, //! without `PROCESS_TRACE_MODE_REAL_TIME`). `ProcessTrace` walks every @@ -18,11 +18,11 @@ //! The diagnostic console has a separate real-time, display-oriented ETW //! consumer in `tools/mxc_diagnostic_console`. It is a binary-private module //! that owns trace sessions and channels arbitrary provider events to a UI. -//! This backend instead reads sealed files synchronously, filters a fixed -//! provider/event vocabulary, bounds results, and skips malformed individual -//! events without invalidating the rest of the capture. Depending on the tool would invert the workspace dependency -//! direction; shared generic TDH primitives can be extracted later if another -//! runtime consumer needs them. +//! This backend reads sealed files synchronously and keeps bounded, deduplicated +//! diagnostics even for unfamiliar or malformed events. Only known schemas +//! produce actionable denials. Depending on the tool would invert the workspace +//! dependency direction; shared generic TDH primitives can be extracted later +//! if another runtime consumer needs them. use std::collections::{HashMap, HashSet}; use std::os::windows::ffi::OsStrExt; @@ -144,6 +144,7 @@ struct Accumulator<'visitor> { schema_cache: tdh_decode::EventSchemaCache, verbose_logging: VerboseLoggingSummary, verbose_logging_signature_bytes: usize, + skip_relog_header: bool, } impl<'visitor> Accumulator<'visitor> { @@ -167,6 +168,7 @@ impl<'visitor> Accumulator<'visitor> { schema_cache: tdh_decode::EventSchemaCache::default(), verbose_logging: VerboseLoggingSummary::default(), verbose_logging_signature_bytes: 0, + skip_relog_header: false, } } @@ -197,6 +199,7 @@ impl<'visitor> Accumulator<'visitor> { schema_cache: tdh_decode::EventSchemaCache::default(), verbose_logging: VerboseLoggingSummary::default(), verbose_logging_signature_bytes: 0, + skip_relog_header: false, } } @@ -220,10 +223,11 @@ impl<'visitor> Accumulator<'visitor> { schema_cache: tdh_decode::EventSchemaCache::default(), verbose_logging: VerboseLoggingSummary::default(), verbose_logging_signature_bytes: 0, + skip_relog_header: false, } } - fn add_raw_denial(&mut self, raw: RawDenial) { + fn add_raw_denial(&mut self, raw: RawDenial, event_name: Option<&str>) { if !self.event_in_scope(raw.pid, raw.filetime) { return; } @@ -235,6 +239,7 @@ impl<'visitor> Accumulator<'visitor> { &raw, &candidate, VerboseLoggingOutcomeReason::UnusableResourcePath, + event_name, ); return; } @@ -247,6 +252,7 @@ impl<'visitor> Accumulator<'visitor> { &raw, &candidate, VerboseLoggingOutcomeReason::UnusableResourcePath, + event_name, ); return; } @@ -254,7 +260,12 @@ impl<'visitor> Accumulator<'visitor> { } else { path_norm::to_user_visible(&raw.object_name).unwrap_or_else(|| raw.object_name.clone()) }; - self.record_raw_denial_outcome(&raw, &resource, VerboseLoggingOutcomeReason::Actionable); + self.record_raw_denial_outcome( + &raw, + &resource, + VerboseLoggingOutcomeReason::Actionable, + event_name, + ); let dedup_resource = match raw.resource_type { learning_mode_core::ResourceType::File | learning_mode_core::ResourceType::Other => { resource.to_ascii_lowercase() @@ -295,6 +306,7 @@ impl<'visitor> Accumulator<'visitor> { raw: &RawDenial, resource: &str, reason: VerboseLoggingOutcomeReason, + event_name: Option<&str>, ) { let mut properties = raw .verbose_logging_properties @@ -332,7 +344,7 @@ impl<'visitor> Accumulator<'visitor> { crate::extractors::bound_properties(properties.into_iter().collect::>()); self.record_outcome( raw.provider, - raw.event_id, + (raw.event_id, event_name), reason, raw.pid, (Some(raw.access_type), Some(raw.resource_type)), @@ -347,18 +359,18 @@ impl<'visitor> Accumulator<'visitor> { fn record_exclusion( &mut self, provider: VerboseLoggingProvider, - event_id: u16, + event: (u16, Option<&str>), reason: VerboseLoggingOutcomeReason, pid: u32, properties: Vec<(String, String)>, ) { - self.record_outcome(provider, event_id, reason, pid, (None, None), properties); + self.record_outcome(provider, event, reason, pid, (None, None), properties); } fn record_outcome( &mut self, provider: VerboseLoggingProvider, - event_id: u16, + event: (u16, Option<&str>), reason: VerboseLoggingOutcomeReason, pid: u32, classification: ( @@ -371,13 +383,39 @@ impl<'visitor> Accumulator<'visitor> { let signature = VerboseLoggingSignature { provider, provider_guid: crate::extractors::verbose_logging_provider_guid(provider), - event_id, + event_id: event.0, + event_name: crate::extractors::sanitize_event_name(event.1), reason, pid, access_type, resource_type, properties, }; + self.record_signature(signature); + } + + fn record_unknown_provider_outcome( + &mut self, + provider: windows::core::GUID, + event: (u16, Option<&str>), + reason: VerboseLoggingOutcomeReason, + pid: u32, + properties: Vec<(String, String)>, + ) { + self.record_signature(VerboseLoggingSignature { + provider: VerboseLoggingProvider::Other, + provider_guid: crate::extractors::format_guid_braced_uppercase(provider), + event_id: event.0, + event_name: crate::extractors::sanitize_event_name(event.1), + reason, + pid, + access_type: None, + resource_type: None, + properties, + }); + } + + fn record_signature(&mut self, signature: VerboseLoggingSignature) { self.verbose_logging.record_with_byte_budget( signature, &mut self.verbose_logging_signature_bytes, @@ -418,13 +456,8 @@ 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. + /// Analysis records a closed diagnostic reason and continues. Raw diagnostic + /// visitors require every event to decode successfully and fail instead. fn record_event_decode_error( &mut self, provider: windows::core::GUID, @@ -432,7 +465,7 @@ impl<'visitor> Accumulator<'visitor> { pid: u32, error: tdh_decode::DecodeError, ) { - let fatal = matches!(self.mode, CollectionMode::Raw) || error.is_schema_error(); + let fatal = matches!(self.mode, CollectionMode::Raw); if fatal { if self.decode_error.is_none() { self.decode_error = @@ -440,26 +473,25 @@ impl<'visitor> Accumulator<'visitor> { } return; } + let reason = match error.event_kind() { + Some(tdh_decode::EventDecodeKind::PayloadMalformed) => { + VerboseLoggingOutcomeReason::EventPayloadMalformed + } + Some(tdh_decode::EventDecodeKind::DecoderLimitReached) => { + VerboseLoggingOutcomeReason::DecoderLimitReached + } + Some(tdh_decode::EventDecodeKind::UnsupportedPropertyEncoding) => { + VerboseLoggingOutcomeReason::UnsupportedPropertyEncoding + } + None => VerboseLoggingOutcomeReason::SchemaUnavailable, + }; + if reason == VerboseLoggingOutcomeReason::SchemaUnavailable + && is_learning_mode_event(provider, event_id) + { + self.truncated = true; + } + let event = (event_id, error.event_name()); if let Some(category) = crate::extractors::verbose_logging_provider_for_guid(provider) { - let reason = match error.event_kind() { - Some(tdh_decode::EventDecodeKind::PayloadMalformed) => { - VerboseLoggingOutcomeReason::EventPayloadMalformed - } - Some(tdh_decode::EventDecodeKind::DecoderLimitReached) => { - VerboseLoggingOutcomeReason::DecoderLimitReached - } - Some(tdh_decode::EventDecodeKind::UnsupportedPropertyEncoding) => { - VerboseLoggingOutcomeReason::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), @@ -478,7 +510,9 @@ impl<'visitor> Accumulator<'visitor> { }, _ => (None, None), }; - self.record_outcome(category, event_id, reason, pid, classification, properties); + self.record_outcome(category, event, reason, pid, classification, Vec::new()); + } else { + self.record_unknown_provider_outcome(provider, event, reason, pid, Vec::new()); } } @@ -544,6 +578,39 @@ impl EtlDenialAnalyzer { let process_lifetimes = attested_process_lifetimes(membership)?; self.analyze_for_process_lifetimes(source_path, &process_lifetimes) } + + /// Analyzes a relogged trace for exact job-attested process generations. + /// + /// The relogger's generated transport header is not a source observation. + /// + /// # Errors + /// + /// Returns [`AnalyzeError`] when job evidence is invalid or the trace cannot + /// be decoded. + pub fn analyze_relogged_for_job_membership( + &self, + source_path: &Path, + membership: &JobMembershipSnapshot, + ) -> Result { + let lifetimes = attested_process_lifetimes(membership)?; + self.analyze_relogged_for_process_lifetimes(source_path, &lifetimes) + } + + pub(crate) fn analyze_relogged_for_process_lifetimes( + &self, + source_path: &Path, + lifetimes: &[ProcessLifetime], + ) -> Result { + let mut accumulator = Accumulator::analyze_for_process_lifetimes(lifetimes); + accumulator.skip_relog_header = true; + process_trace_file(source_path, &mut accumulator)?; + if accumulator.skip_relog_header { + return Err(AnalyzeError::Decode( + "relogged trace has no transport header".into(), + )); + } + accumulator.into_analysis() + } } impl DenialAnalyzer for EtlDenialAnalyzer { @@ -616,7 +683,7 @@ pub fn visit_raw_events( Ok(accumulator.raw_event_count) } -/// Builds a bounded decision vector for known-provider Learning Mode events in +/// Builds a bounded decision vector for all in-scope 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. @@ -643,7 +710,7 @@ pub(crate) fn select_learning_mode_events_for_relogging( fn dedup_to_resources>(raws: I) -> AnalysisResult { let mut accumulator = Accumulator::analyze(); for raw in raws { - accumulator.add_raw_denial(raw); + accumulator.add_raw_denial(raw, None); } accumulator .into_analysis() @@ -705,7 +772,9 @@ fn process_trace_file( // ERROR_SUCCESS (0) is end-of-file. ERROR_CANCELLED (1223) is expected // when our buffer callback stops after a processing bound or fatal error. - if status.0 != 0 && status.0 != 1223 { + if status.0 != 0 + && !(status.0 == 1223 && (accumulator.stop_requested || accumulator.decode_error.is_some())) + { return Err(AnalyzeError::Decode(format!( "ProcessTrace failed for '{}': Win32 error {}", source_path.display(), @@ -781,10 +850,18 @@ unsafe fn process_event_record(event_record: *mut EVENT_RECORD, acc: &mut Accumu let provider = header.ProviderId; let event_id = header.EventDescriptor.Id; - if matches!(acc.mode, CollectionMode::SelectForRelogging) { - if crate::extractors::verbose_logging_provider_for_guid(provider).is_none() { - return; + if acc.skip_relog_header { + acc.skip_relog_header = false; + if provider != windows::core::GUID::from_u128(0x68fdd900_4a3e_11d1_84f4_0000f80464e3) + || event_id != 0 + || header.EventDescriptor.Opcode != 0 + { + acc.decode_error = Some("relogged trace has an invalid transport header".into()); } + return; + } + + if matches!(acc.mode, CollectionMode::SelectForRelogging) { let event_index = acc.relog_event_count; let Some(next_event_count) = acc.relog_event_count.checked_add(1) else { acc.decode_error = @@ -822,29 +899,13 @@ unsafe fn process_event_record(event_record: *mut EVENT_RECORD, acc: &mut Accumu let mut analyze_filetime = None; if matches!(acc.mode, CollectionMode::Analyze) { - 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; }; 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, - VerboseLoggingOutcomeReason::UnsupportedEventSchema, - header.ProcessId, - Vec::new(), - ); + let brokered = event_id == crate::extractors::CAPABILITY_DENIAL_EVENT_ID + && is_learning_mode_event(provider, event_id); + if !brokered && !acc.event_in_scope(header.ProcessId, filetime) { return; } } @@ -864,12 +925,16 @@ unsafe fn process_event_record(event_record: *mut EVENT_RECORD, acc: &mut Accumu }, 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 { + if matches!(&error, tdh_decode::DecodeError::Schema(_)) + && event_id == crate::extractors::CAPABILITY_DENIAL_EVENT_ID + && is_learning_mode_event(provider, event_id) + { + acc.truncated = true; + } + let pid = 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, @@ -927,10 +992,9 @@ fn select_capability_decode_result_for_relogging( 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}" - )); + Err(tdh_decode::DecodeError::Schema(_)) => { + acc.decode_error = + Some("could not scope brokered capability event: schema unavailable".into()); acc.stop_requested = true; } Err(_) => { @@ -977,27 +1041,32 @@ fn select_event_for_relogging( acc.relog_selected_event_pids.push(pid); } -/// Extracts denials from one decoded, in-vocabulary event and feeds them -/// (or their closed outcome 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. +/// Extracts known denials and retains other scoped events as diagnostics. fn handle_decoded_event( parts: &DecodedEventParts, header_pid: u32, filetime: u64, acc: &mut Accumulator<'_>, ) { + let event = (parts.event_id, parts.event_name.as_deref()); let Some(category) = crate::extractors::verbose_logging_provider_for_guid(parts.provider) else { + if acc.event_in_scope(header_pid, filetime) && acc.begin_event() { + acc.record_unknown_provider_outcome( + parts.provider, + event, + VerboseLoggingOutcomeReason::UnsupportedEventSchema, + header_pid, + crate::extractors::sanitize_properties(&parts.props), + ); + } 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, + event, VerboseLoggingOutcomeReason::UnsupportedEventSchema, header_pid, crate::extractors::sanitize_properties(&parts.props), @@ -1009,7 +1078,7 @@ fn handle_decoded_event( if acc.event_in_scope(header_pid, filetime) && acc.begin_event() { acc.record_outcome( category, - parts.event_id, + event, VerboseLoggingOutcomeReason::EventPayloadMalformed, header_pid, crate::extractors::verbose_logging_classification(parts), @@ -1030,18 +1099,18 @@ fn handle_decoded_event( // `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); + acc.add_raw_denial(raw, event.1); } match primary { - Ok(raw) => acc.add_raw_denial(raw), + Ok(raw) => acc.add_raw_denial(raw, event.1), Err(reason) => { let recovered_by_dacl = reason == VerboseLoggingOutcomeReason::UnresolvedCapability && !capability_candidates.is_empty(); if !recovered_by_dacl { acc.record_outcome( category, - parts.event_id, + event, reason, pid, crate::extractors::verbose_logging_classification(parts), @@ -1076,6 +1145,133 @@ mod tests { const SCOPED_END_FILETIME: u64 = 200; const SCOPED_EVENT_FILETIME: u64 = 150; + #[test] + fn callback_decodes_unknown_events_and_deduplicates_decode_failures() { + let mut accumulator = Accumulator::analyze(); + let payload = 42u32.to_le_bytes(); + for (provider, names) in [ + (windows::core::GUID::from_u128(1), Some(vec!["FutureValue"])), + ( + crate::extractors::KERNEL_GENERAL_PROVIDER, + Some(vec!["FutureValue"]), + ), + ( + windows::core::GUID::from_u128(2), + Some(vec!["First", "Missing"]), + ), + (windows::core::GUID::from_u128(3), None), + ] { + for time in [100, 200] { + // SAFETY: the initialized record and payload remain live + // throughout the synchronous callback. + let mut record: EVENT_RECORD = unsafe { core::mem::zeroed() }; + record.EventHeader.ProviderId = provider; + record.EventHeader.EventDescriptor.Id = 999; + record.EventHeader.ProcessId = 42; + record.EventHeader.TimeStamp = time; + record.UserData = payload.as_ptr().cast_mut().cast(); + record.UserDataLength = payload.len() as u16; + if let Some(names) = &names { + accumulator.schema_cache.insert_test_schema(&record, names); + } + unsafe { process_event_record(&mut record, &mut accumulator) }; + } + } + let analysis = accumulator.into_analysis().unwrap(); + let groups = &analysis.verbose_logging.signatures; + assert_eq!(analysis.verbose_logging.total_occurrences, 8); + assert_eq!(groups.len(), 4); + assert!(groups.iter().all(|group| group.count == 2)); + let decoded = groups + .iter() + .filter(|group| { + group.signature.reason == VerboseLoggingOutcomeReason::UnsupportedEventSchema + }) + .collect::>(); + assert_eq!(decoded.len(), 2); + assert!(decoded + .iter() + .all(|group| property(&group.signature, "FutureValue") == "42")); + for reason in [ + VerboseLoggingOutcomeReason::EventPayloadMalformed, + VerboseLoggingOutcomeReason::SchemaUnavailable, + ] { + let group = groups + .iter() + .find(|group| group.signature.reason == reason) + .unwrap(); + assert!(group.signature.properties.is_empty()); + assert_eq!(group.signature.provider, VerboseLoggingProvider::Other); + } + assert!(analysis.denials.is_empty()); + } + + #[test] + fn unknown_event_dedup_preserves_provider_identity_and_process_scope() { + let properties = [("ProcessId", "99"), ("FutureValue", "42")]; + let first = windows::core::GUID::from_u128(1); + let second = windows::core::GUID::from_u128(2); + let events = [ + event_with_provider(first, 28, 42, 150, &properties), + event_with_provider(first, 28, 42, 151, &properties), + event_with_provider(second, 28, 42, 152, &properties), + event_with_provider(first, 29, 42, 153, &properties), + event_with_provider(first, 28, 99, 150, &[("ProcessId", "42")]), + event_with_provider(first, 28, 42, 201, &properties), + kernel_event( + 14, + 42, + 160, + &[ + ("ObjectType", "File"), + ("ObjectName", r"C:\kept.txt"), + ("AccessMask", "1"), + ], + ), + ]; + let analysis = resources_from_events_for_process_lifetimes( + &events, + Some(&[ProcessLifetime { + pid: 42, + start_filetime: 100, + end_filetime: 200, + }]), + ); + let groups = &analysis.verbose_logging.signatures; + assert_eq!(groups.len(), 4); + assert_eq!(analysis.verbose_logging.total_occurrences, 5); + let repeated = groups + .iter() + .find(|group| { + group.signature.provider_guid + == crate::extractors::format_guid_braced_uppercase(first) + && group.signature.event_id == 28 + }) + .unwrap(); + assert_eq!(repeated.count, 2); + assert_eq!(repeated.signature.pid, 42); + let expected = vec![DeniedResource { + resource: r"C:\kept.txt".into(), + resource_type: ResourceType::File, + access_type: AccessType::Read, + pid: 42, + filetime: 160, + }]; + let serialize = |denials| { + let mut bytes = Vec::new(); + learning_mode_core::write_document( + &mut bytes, + &learning_mode_core::DenialsDocument::new( + denials, + learning_mode_core::DenialSummary::new(0, 1, false), + ), + ) + .unwrap(); + bytes + }; + assert_eq!(serialize(analysis.denials), serialize(expected)); + } + #[test] fn process_lifetime_index_matches_pid_and_merged_time_ranges() { let index = ProcessLifetimeIndex::new(&[ @@ -1118,7 +1314,7 @@ mod tests { } #[test] - fn relog_selection_tracks_known_provider_ordinals_and_exact_lifetimes() { + fn relog_selection_tracks_all_provider_ordinals_and_exact_lifetimes() { let mut accumulator = Accumulator::select_for_relogging(&[ProcessLifetime { pid: 42, start_filetime: 100, @@ -1143,8 +1339,8 @@ mod tests { 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); - assert_eq!(accumulator.relog_selected_event_indices, [0, 2]); + assert_eq!(accumulator.relog_event_count, 5); + assert_eq!(accumulator.relog_selected_event_indices, [0, 1, 3]); assert!(accumulator.decode_error.is_none()); } @@ -1195,6 +1391,7 @@ mod tests { }]); let parts = DecodedEventParts { provider: crate::extractors::KERNEL_GENERAL_PROVIDER, + event_name: None, event_id: crate::extractors::CAPABILITY_DENIAL_EVENT_ID, props: Vec::new(), }; @@ -1234,29 +1431,80 @@ mod tests { } #[test] - fn relog_selection_stops_on_capability_schema_failure() { + fn brokered_schema_failure_marks_incomplete_before_pid_resolution() { + for (provider, event_id, incomplete) in [ + (crate::extractors::KERNEL_GENERAL_PROVIDER, 28, true), + (crate::extractors::KERNEL_GENERAL_PROVIDER, 14, false), + (crate::extractors::PRIVACY_LEARNING_MODE_PROVIDER, 28, false), + (windows::core::GUID::from_u128(1), 28, false), + ] { + let mut accumulator = Accumulator::analyze_for_process_lifetimes(&[ProcessLifetime { + pid: 42, + start_filetime: 100, + end_filetime: 200, + }]); + let mut record = EVENT_RECORD::default(); + record.EventHeader.ProviderId = provider; + record.EventHeader.EventDescriptor.Id = event_id; + record.EventHeader.EventDescriptor.Version = u8::MAX; + record.EventHeader.ProcessId = 9000; + record.EventHeader.TimeStamp = 150; + if incomplete { + assert!(matches!( + unsafe { + tdh_decode::decode_event_parts(&mut record, &mut accumulator.schema_cache) + }, + Err(tdh_decode::DecodeError::Schema(_)) + )); + } + unsafe { process_event_record(&mut record, &mut accumulator) }; + assert_eq!(accumulator.truncated, incomplete); + assert!(accumulator.verbose_logging.is_empty()); + assert!(!accumulator.stop_requested); + assert!(accumulator.decode_error.is_none()); + + let valid = kernel_event( + 14, + 42, + 160, + &[ + ("ObjectType", "File"), + ("ObjectName", r"C:\kept.txt"), + ("AccessMask", "1"), + ], + ); + handle_decoded_event(&valid.parts, valid.pid, valid.filetime, &mut accumulator); + let analysis = accumulator.into_analysis().unwrap(); + assert_eq!(analysis.denied_resources_truncated, incomplete); + assert_eq!(analysis.denials.len(), 1); + assert_eq!(analysis.denials[0].resource, r"C:\kept.txt"); + assert_eq!(analysis.verbose_logging.total_occurrences, 1); + } + } + + #[test] + fn relog_selection_rejects_unattributable_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, - ); + let mut record = EVENT_RECORD::default(); + record.EventHeader.ProviderId = crate::extractors::KERNEL_GENERAL_PROVIDER; + record.EventHeader.EventDescriptor.Id = crate::extractors::CAPABILITY_DENIAL_EVENT_ID; + record.EventHeader.EventDescriptor.Version = u8::MAX; + record.EventHeader.ProcessId = 9000; + record.EventHeader.TimeStamp = 150; + unsafe { process_event_record(&mut record, &mut accumulator) }; assert!(accumulator.relog_selected_event_indices.is_empty()); + assert!(accumulator.relog_selected_event_pids.is_empty()); + assert!(accumulator.verbose_logging.is_empty()); assert!(accumulator.stop_requested); - assert!(accumulator - .decode_error - .as_deref() - .is_some_and(|error| error.contains("manifest unavailable"))); + assert_eq!( + accumulator.decode_error.as_deref(), + Some("could not scope brokered capability event: schema unavailable") + ); } #[test] @@ -1284,6 +1532,7 @@ mod tests { let mut accumulator = Accumulator::raw(&mut visitor); let parts = DecodedEventParts { provider: windows::core::GUID::from_u128(0), + event_name: None, event_id: 1, props: Vec::new(), }; @@ -1341,7 +1590,7 @@ mod tests { } #[test] - fn analyze_mode_reports_schema_lookup_failure() { + fn analyze_mode_records_schema_lookup_failure_without_aborting() { let mut accumulator = Accumulator::analyze(); accumulator.record_event_decode_error( windows::core::GUID::from_u128(1), @@ -1350,8 +1599,84 @@ mod tests { tdh_decode::DecodeError::Schema("manifest unavailable".to_string()), ); - let error = accumulator.into_analysis().unwrap_err(); - assert!(error.to_string().contains("manifest unavailable")); + let analysis = accumulator.into_analysis().unwrap(); + let group = &analysis.verbose_logging.signatures[0]; + assert_eq!( + group.signature.reason, + VerboseLoggingOutcomeReason::SchemaUnavailable + ); + assert!(group.signature.properties.is_empty()); + assert_eq!(group.count, 1); + let mut bytes = Vec::new(); + learning_mode_core::write_verbose_logging_document( + &mut bytes, + &learning_mode_core::VerboseLoggingDocument::new(&analysis.verbose_logging), + ) + .unwrap(); + assert!(!String::from_utf8(bytes) + .unwrap() + .contains("manifest unavailable")); + } + + #[test] + fn schema_failure_completeness_follows_the_supported_event_vocabulary() { + let kernel = crate::extractors::KERNEL_GENERAL_PROVIDER; + let privacy = crate::extractors::PRIVACY_LEARNING_MODE_PROVIDER; + for (provider, event_id, incomplete) in [ + (kernel, 14, true), + (kernel, 27, true), + (kernel, 28, true), + (privacy, 14, true), + (privacy, 27, true), + (privacy, 4907, true), + (kernel, 999, false), + (privacy, 28, false), + (windows::core::GUID::from_u128(1), 14, false), + ] { + let mut accumulator = Accumulator::analyze(); + accumulator.record_event_decode_error( + provider, + event_id, + 42, + tdh_decode::DecodeError::Schema("manifest unavailable".into()), + ); + let event = kernel_event( + 14, + 42, + 150, + &[ + ("ObjectType", "File"), + ("ObjectName", r"C:\kept.txt"), + ("AccessMask", "1"), + ], + ); + handle_decoded_event(&event.parts, event.pid, event.filetime, &mut accumulator); + let analysis = accumulator.into_analysis().unwrap(); + assert_eq!( + analysis.denied_resources_truncated, incomplete, + "{provider:?} {event_id}" + ); + assert_eq!(analysis.denials.len(), 1); + assert_eq!(analysis.denials[0].resource, r"C:\kept.txt"); + assert_eq!(analysis.verbose_logging.total_occurrences, 2); + assert!(analysis.verbose_logging.signatures.iter().any(|group| { + group.signature.reason == VerboseLoggingOutcomeReason::SchemaUnavailable + })); + let mut bytes = Vec::new(); + let summary = learning_mode_core::DenialSummary::new( + 0, + analysis.denials.len(), + analysis.denied_resources_truncated, + ); + learning_mode_core::write_document( + &mut bytes, + &learning_mode_core::DenialsDocument::new(analysis.denials, summary), + ) + .unwrap(); + assert!(String::from_utf8(bytes) + .unwrap() + .contains(&format!("\"deniedResourcesTruncated\": {incomplete}"))); + } } fn raw(path: &str, access: AccessType, rt: ResourceType) -> RawDenial { @@ -1502,11 +1827,14 @@ mod tests { .map(|index| (format!(r"c:\data\{index}.txt"), AccessType::Read)) .collect(); - accumulator.add_raw_denial(raw( - r"C:\data\overflow.txt", - AccessType::Read, - ResourceType::File, - )); + accumulator.add_raw_denial( + raw( + r"C:\data\overflow.txt", + AccessType::Read, + ResourceType::File, + ), + None, + ); assert!( !accumulator.stop_requested, @@ -1527,12 +1855,18 @@ mod tests { // Processing continues past the cap: a further overflow candidate is // still aggregated (not silently discarded), and a duplicate of an // already-actionable denial retains the same actionable 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)); + accumulator.add_raw_denial( + raw( + r"C:\data\overflow-2.txt", + AccessType::Read, + ResourceType::File, + ), + None, + ); + accumulator.add_raw_denial( + raw(r"C:\data\0.txt", AccessType::Read, ResourceType::File), + None, + ); assert!(!accumulator.stop_requested); assert_eq!( @@ -1645,6 +1979,7 @@ mod tests { parts: DecodedEventParts { provider, event_id, + event_name: None, props: kv .iter() .map(|(k, v)| ((*k).to_string(), (*v).to_string())) @@ -2076,6 +2411,7 @@ mod tests { parts: DecodedEventParts { provider: crate::extractors::KERNEL_GENERAL_PROVIDER, event_id: 14, + event_name: None, props: vec![ ("Mode".to_string(), "\"Permissive\"".to_string()), ("ObjectType".to_string(), format!("\"{object_type}\"")), @@ -2126,6 +2462,7 @@ mod tests { parts: DecodedEventParts { provider: crate::extractors::KERNEL_GENERAL_PROVIDER, event_id: 14, + event_name: None, props: vec![ ("ObjectType".to_string(), "\"Section\"".to_string()), ("ObjectName".to_string(), format!("\"{object_name}\"")), @@ -2263,10 +2600,7 @@ mod tests { } #[test] - fn unrelated_provider_is_ignored_without_accounting() { - // A provider outside the known Learning Mode vocabulary must not - // contribute any verbose logging accounting at all, even though its event - // ID happens to collide with a known access-check ID. + fn unknown_provider_is_retained_without_creating_actionable_denials() { let events = vec![event_with_provider( windows::core::GUID::from_u128(0xdead_beef), 14, @@ -2281,16 +2615,21 @@ mod tests { let out = resources_from_events(&events); assert!(out.denials.is_empty()); - assert!( - out.verbose_logging.is_empty(), - "unrelated providers are ignored, not aggregated" + assert_eq!(out.verbose_logging.signatures.len(), 1); + let group = &out.verbose_logging.signatures[0]; + assert_eq!(group.signature.provider, VerboseLoggingProvider::Other); + assert_eq!( + group.signature.provider_guid, + "{00000000-0000-0000-0000-0000DEADBEEF}" ); + assert_eq!(property(&group.signature, "ObjectName"), ""); + assert_eq!(group.count, 1); } #[test] fn actionable_candidates_and_duplicates_share_one_verbose_logging_signature() { let make_event = |sequence_no: u64| { - kernel_event( + let mut event = kernel_event( 14, 7, sequence_no, @@ -2300,7 +2639,9 @@ mod tests { ("AccessMask", "0x1"), ("UserName", "\"jsmith\""), ], - ) + ); + event.parts.event_name = Some("AccessCheck".into()); + event }; let events = vec![make_event(1), make_event(2), make_event(3)]; @@ -2322,6 +2663,10 @@ mod tests { VerboseLoggingProvider::KernelGeneral ); assert_eq!(actionable_group.signature.event_id, 14); + assert_eq!( + actionable_group.signature.event_name.as_deref(), + Some("AccessCheck") + ); assert_eq!( actionable_group.count, 3, "all three occurrences are retained" @@ -2385,7 +2730,7 @@ mod tests { // capability candidate must not also surface an `UnresolvedCapability` // exclusion for the same event. let dacl = "hex:000000000000000001000000010200000000000F0300000001000000"; - let events = vec![permissive_event( + let mut events = vec![permissive_event( 14, 5900, 21, @@ -2397,6 +2742,7 @@ mod tests { ("Dacl", dacl), ], )]; + events[0].parts.event_name = Some("CapabilityCheck".into()); let out = resources_from_events(&events); assert_eq!(out.denials.len(), 1); @@ -2406,6 +2752,7 @@ mod tests { assert_eq!(signature.reason, VerboseLoggingOutcomeReason::Actionable); assert_eq!(signature.access_type, Some(AccessType::Unknown)); assert_eq!(signature.resource_type, Some(ResourceType::Capability)); + assert_eq!(signature.event_name.as_deref(), Some("CapabilityCheck")); } fn find_signature( @@ -2446,7 +2793,7 @@ mod tests { for pid in 0..learning_mode_core::MAX_VERBOSE_LOGGING_GROUPS as u32 { accumulator.record_exclusion( VerboseLoggingProvider::KernelGeneral, - 14, + (14, None), VerboseLoggingOutcomeReason::Actionable, pid, properties.clone(), @@ -2606,7 +2953,10 @@ mod tests { VerboseLoggingOutcomeReason::EventPayloadMalformed ); assert_eq!(malformed.signature.pid, 9); - assert_eq!(property(&malformed.signature, "EventName"), "AccessCheck"); + assert_eq!( + malformed.signature.event_name.as_deref(), + Some("AccessCheck") + ); assert_eq!( find_signature(&out.verbose_logging, 27).signature.reason, VerboseLoggingOutcomeReason::DecoderLimitReached @@ -2622,11 +2972,7 @@ mod tests { Some(ResourceType::Capability) ); assert!(out.verbose_logging.signatures.iter().all(|aggregate| { - aggregate - .signature - .properties - .iter() - .all(|(name, _)| name == "EventName") + aggregate.signature.properties.is_empty() && aggregate.signature.event_name.is_some() })); } @@ -2672,4 +3018,29 @@ mod tests { None ); } + + #[test] + fn decode_failure_schema_names_are_sanitized_for_all_providers() { + for provider in [ + crate::extractors::KERNEL_GENERAL_PROVIDER, + windows::core::GUID::from_u128(1), + ] { + let mut accumulator = Accumulator::analyze(); + accumulator.record_event_decode_error( + provider, + 999, + 42, + tdh_decode::DecodeError::event( + tdh_decode::EventDecodeKind::PayloadMalformed, + "private decoder message".into(), + Some(r"C:\Users\private\schema".into()), + ), + ); + let analysis = accumulator.into_analysis().unwrap(); + let group = &analysis.verbose_logging.signatures[0]; + assert_eq!(group.signature.event_name.as_deref(), Some("")); + assert!(group.signature.properties.is_empty()); + assert_eq!(group.count, 1); + } + } } diff --git a/src/core/learning_mode_platforms/windows/src/etl_filter.rs b/src/core/learning_mode_platforms/windows/src/etl_filter.rs index 1c61e2b90..f9ae1ae46 100644 --- a/src/core/learning_mode_platforms/windows/src/etl_filter.rs +++ b/src/core/learning_mode_platforms/windows/src/etl_filter.rs @@ -1,8 +1,6 @@ // Copyright (c) Microsoft Corporation. // Licensed under the MIT License. -//! Process-scoped ETL rewriting for guarded WPR captures. - use std::collections::HashSet; use std::os::windows::ffi::OsStrExt; use std::path::Path; @@ -19,7 +17,7 @@ use windows::Win32::System::Diagnostics::Etw::{ }; use crate::etl_decode::select_learning_mode_events_for_relogging; -use crate::extractors::{is_learning_mode_event, verbose_logging_provider_for_guid}; +use crate::extractors::is_learning_mode_event; use crate::process_lifetime::{attested_process_lifetimes, JobMembershipSnapshot}; use crate::tdh_decode; @@ -90,19 +88,13 @@ impl RelogSelectionState { } } - fn observe_known_provider_event(&self, pid: u32) -> bool { + fn observe_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) { return false; } - // The first ProcessTrace pass selected this ordinal using exact PID and - // 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-event index on mismatch: the final count reconciliation then - // fails closed and the partial destination is deleted. if self.selected_event_pids.get(selected_index) != Some(&pid) || !self.attested_pids.contains(&pid) { @@ -130,8 +122,13 @@ impl ITraceEventCallback_Impl for ProcessScopedTraceFilter_Impl { ) -> windows::core::Result<()> { let header_event = header_event.ok()?; let relogger = relogger.ok()?; - // SAFETY: both interfaces are valid for this synchronous callback. - // The trace header is required for a standalone output ETL. + // SAFETY: Trace Relogger keeps the header and its interfaces valid + // throughout this synchronous callback. + let record = unsafe { header_event.GetEventRecord()? }; + let record = unsafe { record.as_ref() }.ok_or_else(|| { + windows::core::Error::from_hresult(windows::Win32::Foundation::E_POINTER) + })?; + self.selection.observe_event(record.EventHeader.ProcessId); unsafe { relogger.Inject(header_event)? }; Ok(()) } @@ -156,9 +153,6 @@ impl ITraceEventCallback_Impl for ProcessScopedTraceFilter_Impl { )); }; let header = &record.EventHeader; - if verbose_logging_provider_for_guid(header.ProviderId).is_none() { - return Ok(()); - } let is_supported_capability_event = header.EventDescriptor.Id == crate::extractors::CAPABILITY_DENIAL_EVENT_ID && is_learning_mode_event(header.ProviderId, header.EventDescriptor.Id); @@ -183,7 +177,7 @@ impl ITraceEventCallback_Impl for ProcessScopedTraceFilter_Impl { } else { header.ProcessId }; - if self.selection.observe_known_provider_event(effective_pid) { + if self.selection.observe_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)? }; @@ -321,7 +315,7 @@ fn relog_trace_with( 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} known-provider Learning Mode events, but ProcessTrace selected {expected_event_count}" + "Trace Relogger observed {consumed_event_count} events, but ProcessTrace selected {expected_event_count}" ))); } let consumed_selected_event_count = selection.consumed_selected_event_count(); @@ -365,6 +359,174 @@ fn windows_error(operation: &str, error: windows::core::Error) -> AnalyzeError { mod tests { use super::*; + #[test] + fn private_trace_relogging_preserves_unknown_events() { + use windows::core::PCWSTR; + use windows::Win32::System::Diagnostics::Etw::{ + ControlTraceW, EnableTraceEx2, StartTraceW, CONTROLTRACE_HANDLE, + EVENT_TRACE_CONTROL_STOP, EVENT_TRACE_PRIVATE_IN_PROC, EVENT_TRACE_PRIVATE_LOGGER_MODE, + EVENT_TRACE_PROPERTIES, WNODE_FLAG_TRACED_GUID, + }; + tracelogging::define_provider!( + TEST_PROVIDER, + "MxcTest.Redaction", + id("a93bc25e-f2de-485a-90e7-a2d8970b22a9") + ); + + let directory = tempfile::tempdir().unwrap(); + let source = directory.path().join("source.etl"); + let destination = directory.path().join("scoped.etl"); + let provider = windows::core::GUID::from_u128(0xa93bc25e_f2de_485a_90e7_a2d8970b22a9); + let name = format!("mxc-verbose-test-{}", std::process::id()) + .encode_utf16() + .chain([0]) + .collect::>(); + let path = source + .as_os_str() + .encode_wide() + .chain([0]) + .collect::>(); + let mut locations = 2u16.to_le_bytes().to_vec(); + for value in [r"C:\Users\alice\secret.txt", r"D:\private.txt"] { + locations.extend(value.encode_utf16().chain([0]).flat_map(u16::to_le_bytes)); + } + let mut storage = vec![0u64; 512]; + let properties = storage.as_mut_ptr().cast::(); + let mut session = CONTROLTRACE_HANDLE::default(); + // SAFETY: the aligned buffer holds both null-terminated strings and + // outlives the synchronous ETW calls. + unsafe { + (*properties).Wnode.BufferSize = (storage.len() * 8) as u32; + (*properties).Wnode.Guid = provider; + (*properties).Wnode.Flags = WNODE_FLAG_TRACED_GUID; + (*properties).Wnode.ClientContext = 1; + (*properties).BufferSize = 64; + (*properties).LogFileMode = + EVENT_TRACE_PRIVATE_LOGGER_MODE | EVENT_TRACE_PRIVATE_IN_PROC; + (*properties).LoggerNameOffset = std::mem::size_of::() as u32; + (*properties).LogFileNameOffset = + (*properties).LoggerNameOffset + (name.len() * 2) as u32; + assert!((*properties).LogFileNameOffset as usize + path.len() * 2 <= storage.len() * 8); + std::ptr::copy_nonoverlapping( + path.as_ptr(), + storage + .as_mut_ptr() + .cast::() + .add((*properties).LogFileNameOffset as usize) + .cast::(), + path.len(), + ); + assert_eq!(TEST_PROVIDER.register(), 0); + let started = StartTraceW(&mut session, PCWSTR(name.as_ptr()), properties); + if started.0 != 0 { + TEST_PROVIDER.unregister(); + panic!("private StartTraceW failed: {}", started.0); + } + let enabled = EnableTraceEx2(session, &provider, 1, 5, u64::MAX, 0, 0, None); + let emit = || { + [ + tracelogging::write_event!( + TEST_PROVIDER, + "CompositeProperties", + cstr8("CommandLine", r"cmd.exe /c type C:\Users\alice\secret.txt"), + raw_field_slice("FutureLocations", CStr16, &locations), + u32("SafeIdentifier", &42), + u32("C:\\Users\\alice\\secret.txt", &42), + cstr8("EventName", "payload-name"), + ), + tracelogging::write_event!( + TEST_PROVIDER, + "OtherCompositeProperties", + cstr8("CommandLine", r"cmd.exe /c type C:\Users\alice\secret.txt"), + raw_field_slice("FutureLocations", CStr16, &locations), + u32("SafeIdentifier", &42), + u32("C:\\Users\\alice\\secret.txt", &42), + cstr8("EventName", "payload-name"), + ), + ] + }; + let first = emit(); + let second = emit(); + let stopped = ControlTraceW( + session, + PCWSTR(name.as_ptr()), + properties, + EVENT_TRACE_CONTROL_STOP, + ); + let unregistered = TEST_PROVIDER.unregister(); + for status in [enabled.0, stopped.0, unregistered] + .into_iter() + .chain(first) + .chain(second) + { + assert_eq!(status, 0); + } + } + if let Some(path) = std::env::var_os("MXC_TEST_ETL_OUTPUT") { + std::fs::copy(&source, path).expect("failed to retain the test ETL for CLI replay"); + } + let lifetimes = [ProcessLifetime { + pid: std::process::id(), + start_filetime: 0, + end_filetime: u64::MAX, + }]; + let native = crate::EtlDenialAnalyzer + .analyze_for_process_lifetimes(&source, &lifetimes) + .unwrap(); + filter_trace_for_process_lifetimes(&source, &destination, &lifetimes).unwrap(); + let guarded = crate::EtlDenialAnalyzer + .analyze_relogged_for_process_lifetimes(&destination, &lifetimes) + .unwrap(); + let provider_guid = crate::extractors::format_guid_braced_uppercase(provider); + let groups = native + .verbose_logging + .signatures + .iter() + .filter(|group| group.signature.provider_guid == provider_guid) + .collect::>(); + assert_eq!(groups.len(), 2, "{groups:?}"); + assert_eq!( + groups + .iter() + .map(|group| group.signature.event_name.as_deref()) + .collect::>(), + [ + Some("CompositeProperties"), + Some("OtherCompositeProperties") + ] + ); + for group in groups { + assert_eq!(group.count, 2); + for name in ["CommandLine", "FutureLocations"] { + assert_eq!( + group + .signature + .properties + .iter() + .find(|(key, _)| key == name), + Some(&( + name.to_string(), + crate::extractors::REDACTED_PATH.to_string() + )), + ); + } + assert!(group + .signature + .properties + .contains(&("SafeIdentifier".into(), "42".into()))); + assert!(group + .signature + .properties + .contains(&("EventName".into(), "payload-name".into()))); + assert!(!group + .signature + .properties + .iter() + .any(|(name, _)| name.contains(r"C:\Users"))); + } + assert_eq!(native.verbose_logging, guarded.verbose_logging); + } + const START: u64 = 100; const END: u64 = 200; @@ -380,7 +542,7 @@ mod tests { fn selected_ordinal_with_foreign_pid_is_not_injected() { let selection = RelogSelectionState::new(vec![0], vec![42], &[lifetime(42)]); - assert!(!selection.observe_known_provider_event(99)); + assert!(!selection.observe_event(99)); assert_eq!(selection.consumed_event_count(), 1); assert_eq!( selection.consumed_selected_event_count(), @@ -393,7 +555,7 @@ mod tests { fn selected_ordinal_with_attested_pid_is_injected() { let selection = RelogSelectionState::new(vec![0], vec![42], &[lifetime(42)]); - assert!(selection.observe_known_provider_event(42)); + assert!(selection.observe_event(42)); assert_eq!(selection.consumed_event_count(), 1); assert_eq!(selection.consumed_selected_event_count(), 1); } diff --git a/src/core/learning_mode_platforms/windows/src/extractors.rs b/src/core/learning_mode_platforms/windows/src/extractors.rs index 8c7dbb5ef..3af59a674 100644 --- a/src/core/learning_mode_platforms/windows/src/extractors.rs +++ b/src/core/learning_mode_platforms/windows/src/extractors.rs @@ -88,6 +88,8 @@ pub struct DecodedEventParts { pub provider: GUID, /// Originating ETW event ID. pub event_id: u16, + /// Schema-declared event name. + pub event_name: Option, /// `(name, value)` pairs from the decoded payload. String values are /// often TDH-quoted; extractors trim the surrounding quotes. pub props: Vec<(String, String)>, @@ -251,9 +253,8 @@ pub(crate) fn effective_capability_event_pid(process_id: Option<&str>) -> Option /// 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. +/// Returns `None` outside the actionable vocabulary. Verbose logging retains +/// those events as `Other` after process scoping. pub(crate) fn verbose_logging_provider_for_guid(provider: GUID) -> Option { if provider == KERNEL_GENERAL_PROVIDER { Some(VerboseLoggingProvider::KernelGeneral) @@ -270,6 +271,7 @@ pub(crate) fn verbose_logging_provider_for_guid(provider: GUID) -> Option String { match provider { + VerboseLoggingProvider::Other => String::new(), VerboseLoggingProvider::KernelGeneral => { format_guid_braced_uppercase(KERNEL_GENERAL_PROVIDER) } @@ -281,7 +283,7 @@ pub(crate) fn verbose_logging_provider_guid(provider: VerboseLoggingProvider) -> // 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 { +pub(crate) fn format_guid_braced_uppercase(guid: GUID) -> String { format!( "{{{:08X}-{:04X}-{:04X}-{:02X}{:02X}-{:02X}{:02X}{:02X}{:02X}{:02X}{:02X}}}", guid.data1, @@ -413,20 +415,32 @@ fn is_identity_property(name: &str) -> bool { 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") { + if normalized.ends_with("path") + || normalized.ends_with("filename") + || normalized.ends_with("filenamestring") + { 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")) { + if (normalized.equals("objectname") || normalized.equals("resource")) + && 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) + value.char_indices().any(|(offset, _)| { + let candidate = &value[offset..]; + if offset > 0 + && candidate.get(1..4) == Some("://") + && (value.as_bytes()[offset - 1].is_ascii_alphanumeric() + || matches!(value.as_bytes()[offset - 1], b'+' | b'-' | b'.')) + { + return false; + } + crate::path_norm::is_user_visible_absolute(candidate) + || looks_like_dos_device_filesystem_path(candidate) + || looks_like_nt_filesystem_path(candidate) + }) } fn looks_like_dos_device_filesystem_path(value: &str) -> bool { @@ -547,7 +561,7 @@ pub(crate) fn sanitize_properties(props: &[(String, String)]) -> Vec<(String, St .map(|(_, value)| value.trim_matches('"')); let mut sanitized = std::collections::BTreeMap::new(); for (name, raw_value) in props { - if is_timestamp_like_property(name) { + if is_timestamp_like_property(name) || looks_like_file_path_property("", name, None) { continue; } let value = raw_value.trim_matches('"'); @@ -606,6 +620,14 @@ pub(crate) fn sanitize_properties(props: &[(String, String)]) -> Vec<(String, St bound_properties(sanitized.into_iter().collect()) } +pub(crate) fn sanitize_event_name(name: Option<&str>) -> Option { + let name = name?; + sanitize_properties(&[("EventName".into(), name.into())]) + .into_iter() + .next() + .map(|(_, value)| value) +} + /// /// The `ObjectType` field selects the resource type: `File` and `Key` /// (registry) map to concrete resources, an **empty** `ObjectType` is a @@ -1025,6 +1047,7 @@ mod tests { DecodedEventParts { provider, event_id, + event_name: None, props: kv .iter() .map(|(k, v)| ((*k).to_string(), (*v).to_string())) @@ -1708,7 +1731,13 @@ mod tests { r"\Device\MountPointManager", Some("Section") )); - for identifier in [r"\??\FDC#GENERIC_FLOPPY_DRIVE", r"\\.\PhysicalDrive0"] { + for identifier in [ + r"\??\FDC#GENERIC_FLOPPY_DRIVE", + r"\\.\PhysicalDrive0", + "https://example.com/resource", + "custom+a://example.com/resource", + r"\Device\NamedPipe\mxc", + ] { assert!(!looks_like_file_path_property( "ObjectName", identifier, @@ -1802,6 +1831,91 @@ mod tests { assert_eq!(value_for("ObjectName"), Some(REDACTED_PATH)); } + #[test] + fn future_property_names_do_not_bypass_path_redaction() { + let properties = sanitize_properties(&[ + ("FutureLocation".into(), r"C:\Users\private\file.txt".into()), + ("LogFileNameString".into(), "ReloggedFile.ETL".into()), + ( + "UnrecognizedField".into(), + r"\\server\share\private.txt".into(), + ), + ]); + assert!(properties.iter().all(|(_, value)| value == REDACTED_PATH)); + } + + #[test] + fn sanitize_properties_omits_sensitive_property_names() { + let props = [ + (r"C:\Users\alice\secret.txt".into(), "42".into()), + (r"lookup \\server\share\private.txt".into(), "43".into()), + (r"\Device\HarddiskVolume3\private.txt".into(), "44".into()), + ("SafeIdentifier".into(), "42".into()), + ]; + assert_eq!( + sanitize_properties(&props), + [("SafeIdentifier".into(), "42".into())] + ); + } + + #[test] + fn event_names_are_sanitized_and_bounded() { + assert_eq!(sanitize_event_name(None), None); + assert_eq!( + sanitize_event_name(Some("AccessCheck")).as_deref(), + Some("AccessCheck") + ); + assert_eq!( + sanitize_event_name(Some(r"C:\Users\alice\secret.txt")).as_deref(), + Some(REDACTED_PATH) + ); + let first = sanitize_event_name(Some(&format!("{}First", "a".repeat(400)))).unwrap(); + let second = sanitize_event_name(Some(&format!("{}Second", "a".repeat(400)))).unwrap(); + assert_ne!(first, second); + assert!(first.chars().count() <= MAX_SIGNATURE_VALUE_LEN); + assert!(second.chars().count() <= MAX_SIGNATURE_VALUE_LEN); + } + + #[test] + fn sanitize_properties_redacts_embedded_file_paths() { + let long_value = format!("{}C:\\Users\\alice\\secret.txt", "prefix ".repeat(100)); + for value in [ + r"cmd.exe /c type C:\Users\alice\secret.txt", + r#"--input="C:\Program Files\private\data.txt""#, + r"open \\server\share\private.txt", + r"open \??\C:\Users\alice\secret.txt", + r"open \\?\Volume{1234}\private.txt", + r"open \Device\HarddiskVolume3\Users\alice\secret.txt", + "message: C:/Users/alice/secret.txt", + "\u{03bb}: C:\\Users\\alice\\secret.txt", + ] + .into_iter() + .chain([long_value.as_str()]) + { + assert_eq!( + sanitize_properties(&[("CommandLine".into(), value.into())]), + [("CommandLine".into(), REDACTED_PATH.into())], + "{value}", + ); + } + } + + #[test] + fn sanitize_properties_redacts_paths_in_rendered_arrays() { + for value in [ + r#"["C:\Users\alice\secret.txt", "D:\private.txt"]"#, + r#"["safe", "\\server\share\private.txt"]"#, + r#"["safe", "\Device\HarddiskVolume3\private.txt"]"#, + r#"["C:\\Users\\alice\\secret.txt"]"#, + ] { + assert_eq!( + sanitize_properties(&[("FutureLocations".into(), value.into())]), + [("FutureLocations".into(), REDACTED_PATH.into())], + "{value}", + ); + } + } + #[test] fn sanitize_properties_redacts_absolute_path_despite_non_file_object_type() { for path in [ diff --git a/src/core/learning_mode_platforms/windows/src/tdh_decode.rs b/src/core/learning_mode_platforms/windows/src/tdh_decode.rs index 63ce8ebaa..77cf17628 100644 --- a/src/core/learning_mode_platforms/windows/src/tdh_decode.rs +++ b/src/core/learning_mode_platforms/windows/src/tdh_decode.rs @@ -88,6 +88,16 @@ pub(crate) struct EventSchemaCache { schemas: HashMap, } +#[cfg(test)] +impl EventSchemaCache { + pub(crate) fn insert_test_schema(&mut self, record: &EVENT_RECORD, names: &[&str]) { + self.schemas.insert( + EventSchemaKey::from_record(record), + tests::uint32_property_buffer(names), + ); + } +} + #[derive(Debug)] pub(crate) enum DecodeError { Schema(String), @@ -106,10 +116,6 @@ pub(crate) enum EventDecodeKind { } 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), @@ -210,11 +216,12 @@ pub unsafe fn decode_event_parts( 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(|error| map_property_decode_error(error, event_name))?; + .map_err(|error| map_property_decode_error(error, event_name.clone()))?; Ok(DecodedEventParts { provider: header.ProviderId, event_id, + event_name, props, }) } @@ -1005,7 +1012,7 @@ mod tests { .collect() } - fn uint32_property_buffer(names: &[&str]) -> TdhInfoBuffer { + pub(super) fn uint32_property_buffer(names: &[&str]) -> TdhInfoBuffer { assert!(!names.is_empty()); let encoded_names = names .iter() diff --git a/src/core/mxc_engine/src/verbose_telemetry.rs b/src/core/mxc_engine/src/verbose_telemetry.rs index 9f15efac5..39437829c 100644 --- a/src/core/mxc_engine/src/verbose_telemetry.rs +++ b/src/core/mxc_engine/src/verbose_telemetry.rs @@ -7,7 +7,8 @@ use std::io::Read; use std::path::Path; use learning_mode_core::{ - verbose_logging_sibling_path, VerboseLoggingDocument, VerboseLoggingProvider, + verbose_logging_sibling_path, VerboseLoggingAggregate, VerboseLoggingDocument, + VerboseLoggingProvider, }; use wxc_common::hashing::sha256_hex; use wxc_common::models::{ContainmentBackend, ScriptResponse}; @@ -145,16 +146,25 @@ fn prepare_document(path: &Path) -> Result { } fn project_for_telemetry(mut document: VerboseLoggingDocument) -> VerboseLoggingDocument { - for aggregate in &mut document.signatures { + let mut groups = std::collections::BTreeMap::new(); + for mut aggregate in document.signatures { aggregate.signature.provider_guid = canonical_provider_guid(aggregate.signature.provider).to_string(); + aggregate.signature.event_name = None; aggregate.signature.properties.clear(); + let count = groups.entry(aggregate.signature).or_insert(0u64); + *count = count.saturating_add(aggregate.count); } + document.signatures = groups + .into_iter() + .map(|(signature, count)| VerboseLoggingAggregate { signature, count }) + .collect(); document } fn canonical_provider_guid(provider: VerboseLoggingProvider) -> &'static str { match provider { + VerboseLoggingProvider::Other => "", VerboseLoggingProvider::KernelGeneral => "{A68CA8B7-004F-D7B6-A698-07E2DE0F1F5D}", VerboseLoggingProvider::PrivacyAuditingPermissiveLearningMode => { "{811A1DDB-2E69-5F25-ADC0-4B186170E760}" @@ -218,6 +228,7 @@ mod tests { fn aggregate(event_id: u16, value: &str) -> VerboseLoggingAggregate { VerboseLoggingAggregate { signature: VerboseLoggingSignature { + event_name: None, provider: VerboseLoggingProvider::KernelGeneral, provider_guid: "{a68ca8b7-004f-d7b6-a698-07e2de0f1f5d}".to_string(), event_id, @@ -355,6 +366,7 @@ mod tests { let injected = "customer-secret"; let mut doc = document(vec![aggregate(1, injected)]); doc.signatures[0].signature.provider_guid = injected.to_string(); + doc.signatures[0].signature.event_name = Some(injected.to_string()); doc.signatures[0].signature.properties = vec![(injected.to_string(), injected.to_string())]; let projected = project_for_telemetry(doc); @@ -367,4 +379,29 @@ mod tests { ); assert!(projected.signatures[0].signature.properties.is_empty()); } + + #[test] + fn telemetry_deduplicates_after_removing_unknown_provider_guids_and_properties() { + let mut first = aggregate(999, "first-secret"); + first.signature.provider = VerboseLoggingProvider::Other; + first.signature.provider_guid = "first-provider".into(); + first.signature.event_name = Some("first-event".into()); + first.count = 3; + let mut second = first.clone(); + second.signature.provider_guid = "second-provider".into(); + second.signature.event_name = Some("second-event".into()); + second.signature.properties[0].1 = "second-secret".into(); + second.count = 4; + let mut input = document(vec![first, second]); + input.summary.total_occurrences = 7; + + let projected = project_for_telemetry(input); + + assert_eq!(projected.signatures.len(), 1); + assert_eq!(projected.signatures[0].count, 7); + assert!(projected.signatures[0].signature.provider_guid.is_empty()); + assert!(projected.signatures[0].signature.event_name.is_none()); + assert!(projected.signatures[0].signature.properties.is_empty()); + assert_eq!(projected.summary.total_occurrences, 7); + } } diff --git a/src/host/plm/src/elevated.rs b/src/host/plm/src/elevated.rs index e9ac125b7..2ef4a4e60 100644 --- a/src/host/plm/src/elevated.rs +++ b/src/host/plm/src/elevated.rs @@ -2138,7 +2138,7 @@ fn write_analysis_response( membership: &JobMembershipSnapshot, ) -> Result<()> { let analysis = EtlDenialAnalyzer - .analyze_for_job_membership(trace_path, membership) + .analyze_relogged_for_job_membership(trace_path, membership) .context("failed to decode guarded WPR trace for the sandbox process tree")?; write_serialized_analysis_response(pipe, &analysis) } diff --git a/src/host/plm/src/stop.rs b/src/host/plm/src/stop.rs index e88890508..13b91d3ff 100644 --- a/src/host/plm/src/stop.rs +++ b/src/host/plm/src/stop.rs @@ -527,7 +527,16 @@ mod tests { #[test] fn truncated_actionable_denials_snapshot_but_skip_adjusted_config() { - let document = DenialsDocument::new(Vec::new(), DenialSummary::new(0, 0, true)); + let document = DenialsDocument::new( + vec![DeniedResource { + resource: "internetClient".to_string(), + resource_type: ResourceType::Capability, + access_type: AccessType::Unknown, + pid: 42, + filetime: 1, + }], + DenialSummary::new(0, 1, true), + ); let (_directory, log_dir, adjusted) = postprocess_fixture(&document); diff --git a/src/testing/wxc_e2e_tests/tests/e2e_telemetry_etw.rs b/src/testing/wxc_e2e_tests/tests/e2e_telemetry_etw.rs index c9d0f0f57..b4524a948 100644 --- a/src/testing/wxc_e2e_tests/tests/e2e_telemetry_etw.rs +++ b/src/testing/wxc_e2e_tests/tests/e2e_telemetry_etw.rs @@ -135,6 +135,8 @@ fn build_instrumented_wxc_exec() -> PathBuf { "build", "-p", "wxc", + "-p", + "plm", // `test-support` is what makes `MXC_TEST_LOCALAPPDATA_OVERRIDE` // observable to the child; without it the consent store is the real // per-user one and this test would mutate developer state. @@ -236,12 +238,14 @@ fn run_traced_execution(exe: &Path, local_app_data: &Path) -> std::process::Outp fn write_capture_config(workdir: &Path) -> PathBuf { let config_path = workdir.join("capture-config.json"); let output_path = workdir.join("denials.json"); + let denied_file = workdir.join("denied.txt"); + std::fs::write(&denied_file, "telemetry E2E fixture").expect("failed to write denied fixture"); let config = serde_json::json!({ "version": "0.9.0-alpha", "containerId": "TelemetryVerboseDenialsE2E", "containment": "processcontainer", "process": { - "commandLine": "cmd.exe /c type C:\\Windows\\System32\\config\\SAM >nul 2>&1 & exit /b 0" + "commandLine": format!("cmd.exe /d /c type \"{}\" & exit /b 0", denied_file.display()) }, "processContainer": { "captureDenials": { @@ -297,7 +301,7 @@ fn find_verbose_artifact(workdir: &Path) -> Option { /// Decodes an `.etl` to XML and returns the text, or `None` if it holds no /// decodable events (`tracerpt` reports failure on an empty trace). fn decode_trace(etl: &Path, workdir: &Path) -> Option { - let dump = workdir.join("dump.xml"); + let dump = workdir.join(etl.file_name()?).with_extension("xml"); let _ = std::fs::remove_file(&dump); Command::new("tracerpt") .arg(etl) @@ -474,7 +478,7 @@ fn test_verbose_denials_etw_payload_honors_consent() { &std::fs::read(&verbose_path).expect("failed to read verbose artifact"), ) .expect("verbose artifact was not valid JSON"); - assert_eq!(verbose["version"], 2); + assert_eq!(verbose["version"], 3); let granted_dump = decode_trace(&granted_etl, &workdir) .expect("tracerpt produced no output for the verbose telemetry run"); From 88434b55aa9879f349c9e25a85b49bd3fb84fd3c Mon Sep 17 00:00:00 2001 From: Jacob Dereje Date: Mon, 5 Oct 2026 15:59:38 -0700 Subject: [PATCH 02/10] Cache unavailable event schemas and use verbose format v4 Copilot-Session: 7758b99e-b7a0-4060-baf9-268db306b58b --- docs/learning-mode/capabilities.md | 4 +- .../learning_mode_core/src/verbose_logging.rs | 4 +- .../windows/src/etl_decode.rs | 41 +++-- .../windows/src/tdh_decode.rs | 141 ++++++++++++------ .../wxc_e2e_tests/tests/e2e_telemetry_etw.rs | 2 +- 5 files changed, 130 insertions(+), 62 deletions(-) diff --git a/docs/learning-mode/capabilities.md b/docs/learning-mode/capabilities.md index 0163fc8f1..f765628fa 100644 --- a/docs/learning-mode/capabilities.md +++ b/docs/learning-mode/capabilities.md @@ -237,7 +237,7 @@ policy denial occurrences plus diagnostic outcomes omitted from the policy file: ```json { - "version": 3, + "version": 4, "signatures": [ { "signature": { @@ -329,6 +329,8 @@ Free-form decoder errors are never serialized. Failure to obtain the event schema is retained as `schemaUnavailable` rather than aborting the analysis, and marks actionable results incomplete when the event belongs to a supported denial schema. +Missing manifest schemas share the 4,096-entry schema cache with successful +lookups; TraceLogging metadata is decoded per event. For brokered Event 28, scoped analysis marks the result incomplete even when the missing schema prevents reading its workload PID; unattributed event contents are not retained. diff --git a/src/core/learning_mode_core/src/verbose_logging.rs b/src/core/learning_mode_core/src/verbose_logging.rs index f24eec783..babb253c6 100644 --- a/src/core/learning_mode_core/src/verbose_logging.rs +++ b/src/core/learning_mode_core/src/verbose_logging.rs @@ -310,7 +310,7 @@ pub struct VerboseLoggingDocumentSummary { impl VerboseLoggingDocument { /// Current verbose logging document schema version. - pub const VERSION: u32 = 3; + pub const VERSION: u32 = 4; /// Builds an on-disk document from decoder aggregate state. #[must_use] @@ -571,7 +571,7 @@ mod tests { summary.mark_actionable_limit_reached(); let value = serde_json::to_value(VerboseLoggingDocument::new(&summary)).unwrap(); - assert_eq!(value["version"], 3); + assert_eq!(value["version"], 4); assert_eq!(value["signatures"][0]["signature"]["reason"], "actionable"); assert_eq!(value["summary"]["actionableOverflowOccurrences"], 2); assert_eq!(value["summary"]["actionableLimitReached"], true); diff --git a/src/core/learning_mode_platforms/windows/src/etl_decode.rs b/src/core/learning_mode_platforms/windows/src/etl_decode.rs index 852d4c623..187e169db 100644 --- a/src/core/learning_mode_platforms/windows/src/etl_decode.rs +++ b/src/core/learning_mode_platforms/windows/src/etl_decode.rs @@ -926,24 +926,23 @@ unsafe fn process_event_record(event_record: *mut EVENT_RECORD, acc: &mut Accumu Err(error) => { if matches!(acc.mode, CollectionMode::Analyze) { let filetime = analyze_filetime.expect("analyze mode has normalized FILETIME"); - if matches!(&error, tdh_decode::DecodeError::Schema(_)) - && event_id == crate::extractors::CAPABILITY_DENIAL_EVENT_ID - && is_learning_mode_event(provider, event_id) - { - acc.truncated = true; - } let pid = 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", - ) - } - .ok() - .flatten(); + let process_id = if matches!(&error, tdh_decode::DecodeError::Schema(_)) { + acc.truncated = true; + None + } else { + 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, @@ -1450,6 +1449,13 @@ mod tests { record.EventHeader.ProcessId = 9000; record.EventHeader.TimeStamp = 150; if incomplete { + for id in 0..4096 { + let mut cached = EVENT_RECORD::default(); + cached.EventHeader.EventDescriptor.Id = id; + accumulator + .schema_cache + .insert_test_schema(&cached, &["ProcessId"]); + } assert!(matches!( unsafe { tdh_decode::decode_event_parts(&mut record, &mut accumulator.schema_cache) @@ -1457,7 +1463,12 @@ mod tests { Err(tdh_decode::DecodeError::Schema(_)) )); } + let schema_loads = accumulator.schema_cache.schema_loads; unsafe { process_event_record(&mut record, &mut accumulator) }; + assert_eq!( + accumulator.schema_cache.schema_loads - schema_loads, + usize::from(incomplete) + ); assert_eq!(accumulator.truncated, incomplete); assert!(accumulator.verbose_logging.is_empty()); assert!(!accumulator.stop_requested); diff --git a/src/core/learning_mode_platforms/windows/src/tdh_decode.rs b/src/core/learning_mode_platforms/windows/src/tdh_decode.rs index 77cf17628..d596c0c2e 100644 --- a/src/core/learning_mode_platforms/windows/src/tdh_decode.rs +++ b/src/core/learning_mode_platforms/windows/src/tdh_decode.rs @@ -85,7 +85,9 @@ impl EventSchemaKey { #[derive(Default)] pub(crate) struct EventSchemaCache { - schemas: HashMap, + schemas: HashMap>, + #[cfg(test)] + pub(crate) schema_loads: usize, } #[cfg(test)] @@ -93,12 +95,12 @@ impl EventSchemaCache { pub(crate) fn insert_test_schema(&mut self, record: &EVENT_RECORD, names: &[&str]) { self.schemas.insert( EventSchemaKey::from_record(record), - tests::uint32_property_buffer(names), + Ok(tests::uint32_property_buffer(names)), ); } } -#[derive(Debug)] +#[derive(Debug, Clone)] pub(crate) enum DecodeError { Schema(String), Event { @@ -195,8 +197,7 @@ impl TdhInfoBuffer { /// Decodes an `EVENT_RECORD` into `DecodedEventParts`. /// -/// Returns `None` when TDH can't describe the event (rare — usually -/// indicates a corrupted or unknown event). +/// Returns a schema error when TDH cannot describe the event. /// /// # Safety /// `event_record` must point to a valid `EVENT_RECORD` provided by the @@ -254,15 +255,21 @@ unsafe fn event_schema<'a>( event_record: *mut EVENT_RECORD, event: &EVENT_RECORD, schema_cache: &'a mut EventSchemaCache, - uncached_schema: &'a mut Option, + 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); + if !cacheable || !schema_cache.schemas.contains_key(&key) { + #[cfg(test)] + { + schema_cache.schema_loads += 1; + } + let schema = unsafe { load_event_schema(event_record) }; + if cacheable { + cache_or_retain_schema(schema_cache, key, schema, uncached_schema); + } else { + *uncached_schema = Some(schema); + } } schema_buffer(schema_cache, &key, uncached_schema) } @@ -270,8 +277,8 @@ unsafe fn event_schema<'a>( fn cache_or_retain_schema( schema_cache: &mut EventSchemaCache, key: EventSchemaKey, - schema: TdhInfoBuffer, - uncached_schema: &mut Option, + schema: Result, + uncached_schema: &mut Option>, ) { if schema_cache.schemas.len() < MAX_SCHEMA_CACHE_ENTRIES { schema_cache.schemas.insert(key, schema); @@ -283,15 +290,14 @@ fn cache_or_retain_schema( fn schema_buffer<'a>( schema_cache: &'a EventSchemaCache, key: &EventSchemaKey, - uncached_schema: &'a Option, + 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())) + uncached_schema + .as_ref() + .or_else(|| schema_cache.schemas.get(key)) + .ok_or_else(|| DecodeError::Schema("event schema cache lookup failed".to_string()))? + .as_ref() + .map_err(Clone::clone) } fn map_property_decode_error( @@ -1067,34 +1073,62 @@ mod tests { } #[test] - fn schema_is_retained_uncached_at_cache_capacity() { + fn missing_manifest_schema_is_cached_for_full_and_property_decoding() { + let mut cache = EventSchemaCache::default(); + let mut record = EVENT_RECORD::default(); + record.EventHeader.ProviderId = GUID::from_u128(1); + + for _ in 0..3 { + assert!(matches!( + unsafe { decode_event_parts(&mut record, &mut cache) }, + Err(DecodeError::Schema(_)) + )); + assert!(matches!( + unsafe { decode_event_property(&mut record, &mut cache, "ProcessId") }, + Err(DecodeError::Schema(_)) + )); + } + + assert_eq!(cache.schema_loads, 1); + assert_eq!(cache.schemas.len(), 1); + } + + #[test] + fn successful_and_missing_schemas_share_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, - ); + let key = EventSchemaKey::from_record(&record); + let schema = if id % 2 == 0 { + Ok(TdhInfoBuffer::new(1)) + } else { + Err(DecodeError::Schema("missing schema".into())) + }; + cache_or_retain_schema(&mut cache, key, schema, &mut uncached); assert!(uncached.is_none()); + assert_eq!(schema_buffer(&cache, &key, &uncached).is_ok(), id % 2 == 0); } 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, - ); + for schema in [ + Ok(TdhInfoBuffer::new(std::mem::size_of::())), + Err(DecodeError::Schema("missing schema".into())), + ] { + let success = schema.is_ok(); + let mut uncached = None; + cache_or_retain_schema(&mut cache, overflow_key, schema, &mut uncached); - assert_eq!(cache.schemas.len(), MAX_SCHEMA_CACHE_ENTRIES); - assert!(schema_buffer(&cache, &overflow_key, &uncached).is_ok()); + assert_eq!(cache.schemas.len(), MAX_SCHEMA_CACHE_ENTRIES); + assert!(!cache.schemas.contains_key(&overflow_key)); + assert_eq!( + schema_buffer(&cache, &overflow_key, &uncached).is_ok(), + success + ); + } } #[test] @@ -1498,15 +1532,36 @@ mod tests { } #[test] - fn trace_logging_schema_events_are_not_cacheable_by_descriptor_alone() { - let mut item: windows::Win32::System::Diagnostics::Etw::EVENT_HEADER_EXTENDED_DATA_ITEM = - unsafe { std::mem::zeroed() }; - item.ExtType = EVENT_HEADER_EXT_TYPE_EVENT_SCHEMA_TL as u16; - let mut record: EVENT_RECORD = unsafe { std::mem::zeroed() }; + fn trace_logging_schema_failures_are_not_cached() { + let mut cache = EventSchemaCache::default(); + let mut record = EVENT_RECORD::default(); + record.EventHeader.ProviderId = GUID::from_u128(1); + record.EventHeader.EventDescriptor.Channel = 11; + assert!(matches!( + unsafe { decode_event_parts(&mut record, &mut cache) }, + Err(DecodeError::Schema(_)) + )); + + let metadata = [0_u8; 4]; + let mut item = windows::Win32::System::Diagnostics::Etw::EVENT_HEADER_EXTENDED_DATA_ITEM { + ExtType: EVENT_HEADER_EXT_TYPE_EVENT_SCHEMA_TL as u16, + DataSize: metadata.len() as u16, + DataPtr: metadata.as_ptr() as u64, + ..Default::default() + }; + record.EventHeader.Flags = 1; record.ExtendedDataCount = 1; record.ExtendedData = &mut item; - assert!(unsafe { has_trace_logging_schema(&record) }); + + for _ in 0..2 { + assert!(matches!( + unsafe { decode_event_parts(&mut record, &mut cache) }, + Err(DecodeError::Schema(_)) + )); + } + assert_eq!(cache.schema_loads, 3); + assert_eq!(cache.schemas.len(), 1); } #[test] diff --git a/src/testing/wxc_e2e_tests/tests/e2e_telemetry_etw.rs b/src/testing/wxc_e2e_tests/tests/e2e_telemetry_etw.rs index b4524a948..98173bfde 100644 --- a/src/testing/wxc_e2e_tests/tests/e2e_telemetry_etw.rs +++ b/src/testing/wxc_e2e_tests/tests/e2e_telemetry_etw.rs @@ -478,7 +478,7 @@ fn test_verbose_denials_etw_payload_honors_consent() { &std::fs::read(&verbose_path).expect("failed to read verbose artifact"), ) .expect("verbose artifact was not valid JSON"); - assert_eq!(verbose["version"], 3); + assert_eq!(verbose["version"], 4); let granted_dump = decode_trace(&granted_etl, &workdir) .expect("tracerpt produced no output for the verbose telemetry run"); From b4ecedde8525465d2815d10cdc8d1d71833d0421 Mon Sep 17 00:00:00 2001 From: Jacob Dereje Date: Tue, 6 Oct 2026 13:19:59 -0700 Subject: [PATCH 03/10] Keep verbose output scoped to Learning Mode events Copilot-Session: 7758b99e-b7a0-4060-baf9-268db306b58b --- docs/learning-mode/capabilities.md | 26 +- .../windows/src/etl_decode.rs | 387 +++++++++++------- .../windows/src/etl_filter.rs | 53 ++- .../windows/src/extractors.rs | 14 +- 4 files changed, 277 insertions(+), 203 deletions(-) diff --git a/docs/learning-mode/capabilities.md b/docs/learning-mode/capabilities.md index f765628fa..fd3e9fd11 100644 --- a/docs/learning-mode/capabilities.md +++ b/docs/learning-mode/capabilities.md @@ -313,11 +313,18 @@ 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 providers and event IDs receive best-effort TDH decoding. Events with no -actionable extractor use `unsupportedEventSchema` and retain their sanitized -properties. Unknown providers use `provider: "other"` with their actual GUID -in the local file. Different provider GUIDs remain separate deduplication keys. -They do not create new actionable policy grants. +Analysis selects known Learning Mode provider/event pairs: + +| Provider | Event IDs | +|---|---| +| Microsoft-Windows-Kernel-General | 14, 27, 28 | +| Microsoft-Windows-Privacy-Auditing-PermissiveLearningMode | 14, 27, 4907 | + +Other providers and event IDs are excluded before decoding. This selection +does not depend on resource type: unfamiliar object types within selected events +retain their sanitized properties as verbose diagnostics, without creating +new actionable policy grants. Raw schema-discovery visitors and the WPR capture +profile are unchanged. Per-event TDH failures use closed diagnostic reasons: `eventPayloadMalformed` means the payload conflicts with its declared schema, @@ -347,8 +354,9 @@ The existing 64 MiB guarded analysis frame can also move verbose groups into overflow accounting. These bounds are retained; the file does not claim complete event-by-event coverage. -Guarded WPR keeps only events from the exact job-attested process lifetimes, -including brokered capability attribution, regardless of provider. Its generated +Guarded WPR keeps the selected Learning Mode events from the exact job-attested +process lifetimes, including brokered capability attribution. +Required ETL headers remain in the retained trace. Its generated relogging header is excluded from analysis so it does not add a diagnostic that was absent from the source. A schema lookup failure while scoping brokered Event 28 fails the capture, because its workload PID cannot be established. @@ -403,8 +411,8 @@ WPR's source ETL is host-wide, so the elevated guarded-WPR helper never transfers that file across the privilege boundary for `captureDenials` or `--audit`. After the sandbox process tree terminates, the helper uses the retained, job-attested process handles and their exact PID/creation/exit -`FILETIME` ranges to relog a second ETL. The retained ETL contains events from -any provider attributed to those process generations, plus required ETL metadata. +`FILETIME` ranges to relog a second ETL. The retained ETL contains selected +Learning Mode events attributed to those process generations, plus required ETL headers. Brokered capability events use their payload `ProcessId` rather than the broker's header PID. Guarded analysis and retention both consume that same filtered ETL; filtering failure transfers no diff --git a/src/core/learning_mode_platforms/windows/src/etl_decode.rs b/src/core/learning_mode_platforms/windows/src/etl_decode.rs index 187e169db..46c073386 100644 --- a/src/core/learning_mode_platforms/windows/src/etl_decode.rs +++ b/src/core/learning_mode_platforms/windows/src/etl_decode.rs @@ -19,10 +19,10 @@ //! consumer in `tools/mxc_diagnostic_console`. It is a binary-private module //! that owns trace sessions and channels arbitrary provider events to a UI. //! This backend reads sealed files synchronously and keeps bounded, deduplicated -//! diagnostics even for unfamiliar or malformed events. Only known schemas -//! produce actionable denials. Depending on the tool would invert the workspace -//! dependency direction; shared generic TDH primitives can be extracted later -//! if another runtime consumer needs them. +//! diagnostics for every resource type in selected Learning Mode events. +//! Only known schemas produce actionable denials. Depending on the tool would +//! invert the workspace dependency direction; shared generic TDH primitives can +//! be extracted later if another runtime consumer needs them. use std::collections::{HashMap, HashSet}; use std::os::windows::ffi::OsStrExt; @@ -356,6 +356,7 @@ impl<'visitor> Accumulator<'visitor> { /// 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`. + #[cfg(test)] fn record_exclusion( &mut self, provider: VerboseLoggingProvider, @@ -394,27 +395,6 @@ impl<'visitor> Accumulator<'visitor> { self.record_signature(signature); } - fn record_unknown_provider_outcome( - &mut self, - provider: windows::core::GUID, - event: (u16, Option<&str>), - reason: VerboseLoggingOutcomeReason, - pid: u32, - properties: Vec<(String, String)>, - ) { - self.record_signature(VerboseLoggingSignature { - provider: VerboseLoggingProvider::Other, - provider_guid: crate::extractors::format_guid_braced_uppercase(provider), - event_id: event.0, - event_name: crate::extractors::sanitize_event_name(event.1), - reason, - pid, - access_type: None, - resource_type: None, - properties, - }); - } - fn record_signature(&mut self, signature: VerboseLoggingSignature) { self.verbose_logging.record_with_byte_budget( signature, @@ -473,6 +453,9 @@ impl<'visitor> Accumulator<'visitor> { } return; } + if !is_learning_mode_event(provider, event_id) { + return; + } let reason = match error.event_kind() { Some(tdh_decode::EventDecodeKind::PayloadMalformed) => { VerboseLoggingOutcomeReason::EventPayloadMalformed @@ -485,9 +468,7 @@ impl<'visitor> Accumulator<'visitor> { } None => VerboseLoggingOutcomeReason::SchemaUnavailable, }; - if reason == VerboseLoggingOutcomeReason::SchemaUnavailable - && is_learning_mode_event(provider, event_id) - { + if reason == VerboseLoggingOutcomeReason::SchemaUnavailable { self.truncated = true; } let event = (event_id, error.event_name()); @@ -511,8 +492,6 @@ impl<'visitor> Accumulator<'visitor> { _ => (None, None), }; self.record_outcome(category, event, reason, pid, classification, Vec::new()); - } else { - self.record_unknown_provider_outcome(provider, event, reason, pid, Vec::new()); } } @@ -683,7 +662,7 @@ pub fn visit_raw_events( Ok(accumulator.raw_event_count) } -/// Builds a bounded decision vector for all in-scope events in +/// Builds a bounded decision vector for selected in-scope 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. @@ -870,12 +849,13 @@ unsafe fn process_event_record(event_record: *mut EVENT_RECORD, acc: &mut Accumu return; }; acc.relog_event_count = next_event_count; + if !is_learning_mode_event(provider, event_id) { + return; + } let Some(filetime) = normalized_filetime(header.TimeStamp, acc) else { return; }; - if event_id == crate::extractors::CAPABILITY_DENIAL_EVENT_ID - && is_learning_mode_event(provider, event_id) - { + 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") }; @@ -899,12 +879,14 @@ unsafe fn process_event_record(event_record: *mut EVENT_RECORD, acc: &mut Accumu let mut analyze_filetime = None; if matches!(acc.mode, CollectionMode::Analyze) { + if !is_learning_mode_event(provider, event_id) { + return; + } let Some(filetime) = normalized_filetime(header.TimeStamp, acc) else { return; }; analyze_filetime = Some(filetime); - let brokered = event_id == crate::extractors::CAPABILITY_DENIAL_EVENT_ID - && is_learning_mode_event(provider, event_id); + let brokered = event_id == crate::extractors::CAPABILITY_DENIAL_EVENT_ID; if !brokered && !acc.event_in_scope(header.ProcessId, filetime) { return; } @@ -926,9 +908,7 @@ unsafe fn process_event_record(event_record: *mut EVENT_RECORD, acc: &mut Accumu Err(error) => { if matches!(acc.mode, CollectionMode::Analyze) { let filetime = analyze_filetime.expect("analyze mode has normalized FILETIME"); - let pid = if event_id == crate::extractors::CAPABILITY_DENIAL_EVENT_ID - && is_learning_mode_event(provider, event_id) - { + let pid = if event_id == crate::extractors::CAPABILITY_DENIAL_EVENT_ID { let process_id = if matches!(&error, tdh_decode::DecodeError::Schema(_)) { acc.truncated = true; None @@ -1040,39 +1020,21 @@ fn select_event_for_relogging( acc.relog_selected_event_pids.push(pid); } -/// Extracts known denials and retains other scoped events as diagnostics. +/// Extracts known denials and retains other resource types as diagnostics. fn handle_decoded_event( parts: &DecodedEventParts, header_pid: u32, filetime: u64, acc: &mut Accumulator<'_>, ) { + if !is_learning_mode_event(parts.provider, parts.event_id) { + return; + } let event = (parts.event_id, parts.event_name.as_deref()); let Some(category) = crate::extractors::verbose_logging_provider_for_guid(parts.provider) else { - if acc.event_in_scope(header_pid, filetime) && acc.begin_event() { - acc.record_unknown_provider_outcome( - parts.provider, - event, - VerboseLoggingOutcomeReason::UnsupportedEventSchema, - header_pid, - crate::extractors::sanitize_properties(&parts.props), - ); - } 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, - event, - VerboseLoggingOutcomeReason::UnsupportedEventSchema, - header_pid, - crate::extractors::sanitize_properties(&parts.props), - ); - } - return; - } 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( @@ -1145,27 +1107,140 @@ mod tests { const SCOPED_EVENT_FILETIME: u64 = 150; #[test] - fn callback_decodes_unknown_events_and_deduplicates_decode_failures() { + fn callback_selects_only_learning_mode_events_before_decoding() { + let kernel = crate::extractors::KERNEL_GENERAL_PROVIDER; + let privacy = crate::extractors::PRIVACY_LEARNING_MODE_PROVIDER; + for (provider, event_id, retained) in [ + (kernel, 14, true), + (kernel, 27, true), + (kernel, 28, true), + (privacy, 14, true), + (privacy, 27, true), + (privacy, 4907, true), + (kernel, 4907, false), + (privacy, 28, false), + (kernel, 999, false), + (windows::core::GUID::from_u128(1), 14, false), + ( + windows::core::GUID::from_u128(0x3d6fa8d0_fe05_11d0_9dda_00c04fd7ba7c), + 0, + false, + ), + ] { + let lifetime = ProcessLifetime { + pid: SCOPED_PID, + start_filetime: SCOPED_START_FILETIME, + end_filetime: SCOPED_END_FILETIME, + }; + for mut accumulator in [ + Accumulator::analyze(), + Accumulator::analyze_for_process_lifetimes(&[lifetime]), + ] { + let mut record = EVENT_RECORD::default(); + record.EventHeader.ProviderId = provider; + record.EventHeader.EventDescriptor.Id = event_id; + record.EventHeader.ProcessId = SCOPED_PID; + record.EventHeader.TimeStamp = SCOPED_EVENT_FILETIME as i64; + let payload = SCOPED_PID.to_le_bytes(); + record.UserData = payload.as_ptr().cast_mut().cast(); + record.UserDataLength = payload.len() as u16; + if retained { + accumulator + .schema_cache + .insert_test_schema(&record, &["ProcessId"]); + } + unsafe { process_event_record(&mut record, &mut accumulator) }; + assert_eq!( + accumulator.schema_cache.schema_loads, 0, + "{provider:?} {event_id}" + ); + assert_eq!(accumulator.processed_event_count, usize::from(retained)); + let analysis = accumulator.into_analysis().unwrap(); + assert_eq!( + analysis.verbose_logging.total_occurrences, + u64::from(retained) + ); + assert!(!analysis.denied_resources_truncated); + } + } + } + + #[test] + fn raw_visitor_preserves_runtime_metadata() { + let mut visitor = |_: &DecodedEventParts| Ok(()); + let mut accumulator = Accumulator::raw(&mut visitor); + let mut record = EVENT_RECORD::default(); + record.EventHeader.ProviderId = + windows::core::GUID::from_u128(0x2cb15d1d_5fc1_11d2_abe1_00a0c911f518); + accumulator + .schema_cache + .insert_test_schema(&record, &["FutureValue"]); + + unsafe { process_event_record(&mut record, &mut accumulator) }; + + assert_eq!(accumulator.raw_event_count, 1); + assert!(accumulator.decode_error.is_none()); + } + + #[test] + fn selected_access_checks_do_not_filter_object_types() { + for (provider, event_id) in [ + (crate::extractors::KERNEL_GENERAL_PROVIDER, 14), + (crate::extractors::PRIVACY_LEARNING_MODE_PROVIDER, 4907), + ] { + for object_type in ["Dll", "Thread", "Process", "FutureObject"] { + let event = event_with_provider( + provider, + event_id, + SCOPED_PID, + SCOPED_EVENT_FILETIME, + &[ + ("ObjectType", object_type), + ("ObjectName", "retained-identifier"), + ], + ); + let analysis = resources_from_events(&[event]); + assert!(analysis.denials.is_empty()); + let signature = &find_signature(&analysis.verbose_logging, event_id).signature; + assert_eq!( + signature.reason, + VerboseLoggingOutcomeReason::UnsupportedObjectType + ); + assert_eq!(property(signature, "ObjectType"), object_type); + assert_eq!(property(signature, "ObjectName"), "retained-identifier"); + } + } + } + + #[test] + fn callback_keeps_unknown_resources_and_deduplicates_decode_failures() { let mut accumulator = Accumulator::analyze(); let payload = 42u32.to_le_bytes(); - for (provider, names) in [ - (windows::core::GUID::from_u128(1), Some(vec!["FutureValue"])), + for (provider, event_id, names) in [ ( crate::extractors::KERNEL_GENERAL_PROVIDER, - Some(vec!["FutureValue"]), + 14, + Some(vec!["ObjectType"]), ), ( - windows::core::GUID::from_u128(2), + crate::extractors::PRIVACY_LEARNING_MODE_PROVIDER, + 4907, + Some(vec!["ObjectType"]), + ), + ( + crate::extractors::KERNEL_GENERAL_PROVIDER, + 27, Some(vec!["First", "Missing"]), ), - (windows::core::GUID::from_u128(3), None), + (crate::extractors::KERNEL_GENERAL_PROVIDER, 28, None), ] { for time in [100, 200] { // SAFETY: the initialized record and payload remain live // throughout the synchronous callback. let mut record: EVENT_RECORD = unsafe { core::mem::zeroed() }; record.EventHeader.ProviderId = provider; - record.EventHeader.EventDescriptor.Id = 999; + record.EventHeader.EventDescriptor.Id = event_id; + record.EventHeader.EventDescriptor.Version = u8::MAX; record.EventHeader.ProcessId = 42; record.EventHeader.TimeStamp = time; record.UserData = payload.as_ptr().cast_mut().cast(); @@ -1184,13 +1259,13 @@ mod tests { let decoded = groups .iter() .filter(|group| { - group.signature.reason == VerboseLoggingOutcomeReason::UnsupportedEventSchema + group.signature.reason == VerboseLoggingOutcomeReason::UnsupportedObjectType }) .collect::>(); assert_eq!(decoded.len(), 2); assert!(decoded .iter() - .all(|group| property(&group.signature, "FutureValue") == "42")); + .all(|group| property(&group.signature, "ObjectType") == "42")); for reason in [ VerboseLoggingOutcomeReason::EventPayloadMalformed, VerboseLoggingOutcomeReason::SchemaUnavailable, @@ -1200,23 +1275,30 @@ mod tests { .find(|group| group.signature.reason == reason) .unwrap(); assert!(group.signature.properties.is_empty()); - assert_eq!(group.signature.provider, VerboseLoggingProvider::Other); + assert_eq!( + group.signature.provider, + VerboseLoggingProvider::KernelGeneral + ); } assert!(analysis.denials.is_empty()); } #[test] - fn unknown_event_dedup_preserves_provider_identity_and_process_scope() { - let properties = [("ProcessId", "99"), ("FutureValue", "42")]; - let first = windows::core::GUID::from_u128(1); - let second = windows::core::GUID::from_u128(2); + fn unknown_resource_dedup_preserves_provider_identity_and_process_scope() { + let properties = [ + ("ObjectType", "FutureObject"), + ("ObjectName", "future-resource"), + ("ProcessId", "99"), + ]; + let first = crate::extractors::KERNEL_GENERAL_PROVIDER; + let second = crate::extractors::PRIVACY_LEARNING_MODE_PROVIDER; let events = [ - event_with_provider(first, 28, 42, 150, &properties), - event_with_provider(first, 28, 42, 151, &properties), - event_with_provider(second, 28, 42, 152, &properties), - event_with_provider(first, 29, 42, 153, &properties), - event_with_provider(first, 28, 99, 150, &[("ProcessId", "42")]), - event_with_provider(first, 28, 42, 201, &properties), + event_with_provider(first, 14, 42, 150, &properties), + event_with_provider(first, 14, 42, 151, &properties), + event_with_provider(second, 14, 42, 152, &properties), + event_with_provider(second, 4907, 42, 153, &properties), + event_with_provider(first, 14, 99, 150, &[("ProcessId", "42")]), + event_with_provider(first, 14, 42, 201, &properties), kernel_event( 14, 42, @@ -1244,7 +1326,7 @@ mod tests { .find(|group| { group.signature.provider_guid == crate::extractors::format_guid_braced_uppercase(first) - && group.signature.event_id == 28 + && group.signature.reason == VerboseLoggingOutcomeReason::UnsupportedObjectType }) .unwrap(); assert_eq!(repeated.count, 2); @@ -1337,9 +1419,40 @@ mod tests { visit(crate::extractors::KERNEL_GENERAL_PROVIDER, 27, 42, 201); visit(crate::extractors::KERNEL_GENERAL_PROVIDER, 999, 42, 200); visit(crate::extractors::KERNEL_GENERAL_PROVIDER, 14, 43, 150); + visit( + windows::core::GUID::from_u128(0x2cb15d1d_5fc1_11d2_abe1_00a0c911f518), + 0, + 42, + 150, + ); + visit( + windows::core::GUID::from_u128(0x68fdd900_4a3e_11d1_84f4_0000f80464e3), + 0, + 42, + 150, + ); + visit( + windows::core::GUID::from_u128(0x3d6fa8d0_fe05_11d0_9dda_00c04fd7ba7c), + 0, + 42, + 150, + ); + visit(windows::core::GUID::from_u128(1), 18, 42, 150); + visit( + windows::core::GUID::from_u128(0xb675ec37_bdb6_4648_bc92_f3fdc74d3ca2), + 18, + 42, + 150, + ); + visit( + windows::core::GUID::from_u128(0xb675ec37_bdb6_4648_bc92_f3fdc74d3ca2), + 19, + 42, + 150, + ); - assert_eq!(accumulator.relog_event_count, 5); - assert_eq!(accumulator.relog_selected_event_indices, [0, 1, 3]); + assert_eq!(accumulator.relog_event_count, 11); + assert_eq!(accumulator.relog_selected_event_indices, [0]); assert!(accumulator.decode_error.is_none()); } @@ -1567,7 +1680,7 @@ mod tests { fn analyze_mode_skips_malformed_event_without_failing_trace() { let mut accumulator = Accumulator::analyze(); accumulator.record_event_decode_error( - windows::core::GUID::from_u128(1), + crate::extractors::KERNEL_GENERAL_PROVIDER, 14, 1, tdh_decode::DecodeError::event( @@ -1604,7 +1717,7 @@ mod tests { fn analyze_mode_records_schema_lookup_failure_without_aborting() { let mut accumulator = Accumulator::analyze(); accumulator.record_event_decode_error( - windows::core::GUID::from_u128(1), + crate::extractors::KERNEL_GENERAL_PROVIDER, 14, 1, tdh_decode::DecodeError::Schema("manifest unavailable".to_string()), @@ -1669,10 +1782,16 @@ mod tests { ); assert_eq!(analysis.denials.len(), 1); assert_eq!(analysis.denials[0].resource, r"C:\kept.txt"); - assert_eq!(analysis.verbose_logging.total_occurrences, 2); - assert!(analysis.verbose_logging.signatures.iter().any(|group| { - group.signature.reason == VerboseLoggingOutcomeReason::SchemaUnavailable - })); + assert_eq!( + analysis.verbose_logging.total_occurrences, + 1 + u64::from(incomplete) + ); + assert_eq!( + analysis.verbose_logging.signatures.iter().any(|group| { + group.signature.reason == VerboseLoggingOutcomeReason::SchemaUnavailable + }), + incomplete + ); let mut bytes = Vec::new(); let summary = learning_mode_core::DenialSummary::new( 0, @@ -2256,21 +2375,12 @@ 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_eq!(analysis.verbose_logging.signatures.len(), 1); assert!(analysis .verbose_logging .signatures .iter() .all(|group| group.signature.pid == 42)); - let unsupported = analysis - .verbose_logging - .signatures - .iter() - .find(|group| { - group.signature.reason == VerboseLoggingOutcomeReason::UnsupportedEventSchema - }) - .expect("owned unknown event retained"); - assert_eq!(property(&unsupported.signature, "Marker"), "owned"); } #[test] @@ -2329,10 +2439,7 @@ mod tests { assert!(analysis.verbose_logging.is_empty()); } - /// Non-actionable object types and not-denied capability records are - /// 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. + /// Resource exclusions remain diagnostic; unrelated event IDs are ignored. #[test] fn non_actionable_events_are_dropped() { let events = vec![ @@ -2358,10 +2465,7 @@ mod tests { reason_for(28), Some(VerboseLoggingOutcomeReason::NotActionable) ); - assert_eq!( - reason_for(9999), - Some(VerboseLoggingOutcomeReason::UnsupportedEventSchema) - ); + assert_eq!(reason_for(9999), None); } #[test] @@ -2583,35 +2687,11 @@ mod tests { let out = resources_from_events(&events); assert!(out.denials.is_empty()); - // Each event ID is valid for the *other* known provider, so both are - // classified `UnsupportedEventSchema` for their own provider rather - // than silently ignored or misrouted. - assert_eq!(out.verbose_logging.signatures.len(), 2); - assert!(out - .verbose_logging - .signatures - .iter() - .all(|group| group.signature.reason - == VerboseLoggingOutcomeReason::UnsupportedEventSchema)); - assert!(out - .verbose_logging - .signatures - .iter() - .any(|group| group.signature.provider - == VerboseLoggingProvider::PrivacyAuditingPermissiveLearningMode - && group.signature.event_id == 28)); - assert!(out - .verbose_logging - .signatures - .iter() - .any( - |group| group.signature.provider == VerboseLoggingProvider::KernelGeneral - && group.signature.event_id == 4907 - )); + assert!(out.verbose_logging.is_empty()); } #[test] - fn unknown_provider_is_retained_without_creating_actionable_denials() { + fn unknown_provider_is_ignored_even_with_a_learning_mode_event_id() { let events = vec![event_with_provider( windows::core::GUID::from_u128(0xdead_beef), 14, @@ -2626,15 +2706,7 @@ mod tests { 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.signature.provider, VerboseLoggingProvider::Other); - assert_eq!( - group.signature.provider_guid, - "{00000000-0000-0000-0000-0000DEADBEEF}" - ); - assert_eq!(property(&group.signature, "ObjectName"), ""); - assert_eq!(group.count, 1); + assert!(out.verbose_logging.is_empty()); } #[test] @@ -2817,20 +2889,23 @@ mod tests { } #[test] - fn unknown_event_id_signature_redacts_the_entire_file_path() { + fn unknown_resource_signature_redacts_the_entire_file_path() { let events = vec![kernel_event( - 9999, + 14, 7, 1, - &[("ObjectName", "\"C:\\Users\\jsmith\\secret.txt\"")], + &[ + ("ObjectType", "FutureObject"), + ("ObjectName", "\"C:\\Users\\jsmith\\secret.txt\""), + ], )]; let out = resources_from_events(&events); - let group = find_signature(&out.verbose_logging, 9999); + let group = find_signature(&out.verbose_logging, 14); assert_eq!( group.signature.reason, - VerboseLoggingOutcomeReason::UnsupportedEventSchema + VerboseLoggingOutcomeReason::UnsupportedObjectType ); assert_eq!( property(&group.signature, "ObjectName"), @@ -2881,8 +2956,8 @@ mod tests { // 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\"")]), + kernel_event(14, 7, 10, &[("Foo", "\"bar\"")]), + kernel_event(14, 7, 20_000_000, &[("Foo", "\"bar\"")]), ]; let out = resources_from_events(&events); @@ -2892,13 +2967,13 @@ mod tests { 1, "differing only by timestamp must dedupe to a single signature" ); - assert_eq!(find_signature(&out.verbose_logging, 9999).count, 2); + assert_eq!(find_signature(&out.verbose_logging, 14).count, 2); } #[test] fn timestamp_like_properties_are_excluded_from_the_signature() { let events = vec![kernel_event( - 9999, + 14, 7, 1, &[ @@ -2909,7 +2984,7 @@ mod tests { let out = resources_from_events(&events); - let group = find_signature(&out.verbose_logging, 9999); + let group = find_signature(&out.verbose_logging, 14); assert!( group .signature @@ -3031,15 +3106,15 @@ mod tests { } #[test] - fn decode_failure_schema_names_are_sanitized_for_all_providers() { + fn decode_failure_schema_names_are_sanitized_for_learning_mode_providers() { for provider in [ crate::extractors::KERNEL_GENERAL_PROVIDER, - windows::core::GUID::from_u128(1), + crate::extractors::PRIVACY_LEARNING_MODE_PROVIDER, ] { let mut accumulator = Accumulator::analyze(); accumulator.record_event_decode_error( provider, - 999, + 14, 42, tdh_decode::DecodeError::event( tdh_decode::EventDecodeKind::PayloadMalformed, diff --git a/src/core/learning_mode_platforms/windows/src/etl_filter.rs b/src/core/learning_mode_platforms/windows/src/etl_filter.rs index f9ae1ae46..dd546cf3b 100644 --- a/src/core/learning_mode_platforms/windows/src/etl_filter.rs +++ b/src/core/learning_mode_platforms/windows/src/etl_filter.rs @@ -360,7 +360,7 @@ mod tests { use super::*; #[test] - fn private_trace_relogging_preserves_unknown_events() { + fn private_trace_relogging_excludes_unrelated_events_but_raw_decoding_preserves_them() { use windows::core::PCWSTR; use windows::Win32::System::Diagnostics::Etw::{ ControlTraceW, EnableTraceEx2, StartTraceW, CONTROLTRACE_HANDLE, @@ -477,54 +477,47 @@ mod tests { let guarded = crate::EtlDenialAnalyzer .analyze_relogged_for_process_lifetimes(&destination, &lifetimes) .unwrap(); - let provider_guid = crate::extractors::format_guid_braced_uppercase(provider); - let groups = native - .verbose_logging - .signatures - .iter() - .filter(|group| group.signature.provider_guid == provider_guid) - .collect::>(); - assert_eq!(groups.len(), 2, "{groups:?}"); + let mut decoded = Vec::new(); + crate::visit_raw_events(&source, &mut |parts| { + if parts.provider == provider { + decoded.push(parts.clone()); + } + Ok(()) + }) + .unwrap(); + assert_eq!(decoded.len(), 4); assert_eq!( - groups + decoded .iter() - .map(|group| group.signature.event_name.as_deref()) + .map(|parts| parts.event_name.as_deref()) .collect::>(), [ + Some("CompositeProperties"), + Some("OtherCompositeProperties"), Some("CompositeProperties"), Some("OtherCompositeProperties") ] ); - for group in groups { - assert_eq!(group.count, 2); + for parts in decoded { + let properties = crate::extractors::sanitize_properties(&parts.props); for name in ["CommandLine", "FutureLocations"] { assert_eq!( - group - .signature - .properties - .iter() - .find(|(key, _)| key == name), + properties.iter().find(|(key, _)| key == name), Some(&( name.to_string(), crate::extractors::REDACTED_PATH.to_string() )), ); } - assert!(group - .signature - .properties - .contains(&("SafeIdentifier".into(), "42".into()))); - assert!(group - .signature - .properties - .contains(&("EventName".into(), "payload-name".into()))); - assert!(!group - .signature - .properties + assert!(properties.contains(&("SafeIdentifier".into(), "42".into()))); + assert!(properties.contains(&("EventName".into(), "payload-name".into()))); + assert!(!properties .iter() .any(|(name, _)| name.contains(r"C:\Users"))); } - assert_eq!(native.verbose_logging, guarded.verbose_logging); + assert_eq!(native, guarded); + assert!(native.verbose_logging.is_empty()); + assert!(native.denials.is_empty()); } const START: u64 = 100; diff --git a/src/core/learning_mode_platforms/windows/src/extractors.rs b/src/core/learning_mode_platforms/windows/src/extractors.rs index 3af59a674..9aa08d420 100644 --- a/src/core/learning_mode_platforms/windows/src/extractors.rs +++ b/src/core/learning_mode_platforms/windows/src/extractors.rs @@ -20,10 +20,9 @@ //! //! 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; 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: +//! decoded; provider/event pairs outside this vocabulary are excluded. +//! Every resource type within these events remains eligible for verbose +//! diagnostics. The IDs handled today: //! //! - **14 / 4907 — access check** — the primary denial event //! (`ObjectType` / `ObjectName` / `AccessMask`). `ObjectType` selects the @@ -34,8 +33,8 @@ //! access are retained only as verbose diagnostics. Named Section, //! SymbolicLink, and Timer objects are likewise verbose-only because MXC has //! no corresponding policy grants. -//! Other object types are dropped until their access-mask vocabulary is -//! understood. The [`AccessType`] is derived from the +//! Other object types remain verbose diagnostics 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"`). @@ -253,8 +252,7 @@ pub(crate) fn effective_capability_event_pid(process_id: Option<&str>) -> Option /// Maps a raw ETW provider GUID to its symbolic verbose logging category. /// -/// Returns `None` outside the actionable vocabulary. Verbose logging retains -/// those events as `Other` after process scoping. +/// Returns `None` outside the Learning Mode provider vocabulary. pub(crate) fn verbose_logging_provider_for_guid(provider: GUID) -> Option { if provider == KERNEL_GENERAL_PROVIDER { Some(VerboseLoggingProvider::KernelGeneral) From 717fb745dac5ab0a916eda661a0d76383f1f313d Mon Sep 17 00:00:00 2001 From: Jacob Dereje Date: Tue, 6 Oct 2026 14:07:14 -0700 Subject: [PATCH 04/10] Include NetworkDecisionV1 in verbose diagnostics Copilot-Session: 7758b99e-b7a0-4060-baf9-268db306b58b --- docs/learning-mode/capabilities.md | 9 ++ .../learning_mode_core/src/verbose_logging.rs | 2 + .../windows/src/etl_decode.rs | 133 +++++++++++++++++- .../windows/src/extractors.rs | 19 ++- src/core/mxc_engine/src/verbose_telemetry.rs | 23 +++ 5 files changed, 179 insertions(+), 7 deletions(-) diff --git a/docs/learning-mode/capabilities.md b/docs/learning-mode/capabilities.md index fd3e9fd11..5df3fd88b 100644 --- a/docs/learning-mode/capabilities.md +++ b/docs/learning-mode/capabilities.md @@ -319,6 +319,7 @@ Analysis selects known Learning Mode provider/event pairs: |---|---| | Microsoft-Windows-Kernel-General | 14, 27, 28 | | Microsoft-Windows-Privacy-Auditing-PermissiveLearningMode | 14, 27, 4907 | +| Microsoft-Windows-LearningMode-NetworkDecision | 1 (`NetworkDecisionV1`) | Other providers and event IDs are excluded before decoding. This selection does not depend on resource type: unfamiliar object types within selected events @@ -326,6 +327,14 @@ retain their sanitized properties as verbose diagnostics, without creating new actionable policy grants. Raw schema-discovery visitors and the WPR capture profile are unchanged. +`NetworkDecisionV1` uses provider `{71237669-21C3-4101-BD2F-FF38945D725A}`. +Its sanitized payload is retained as a verbose diagnostic without creating +network policy grants. The event has no reliable workload PID, so its signature +uses `pid: 0` rather than the broker's header PID. Process-scoped analysis and +guarded WPR exclude this source because they cannot safely attribute it to a job. +Collection requires option-aware native broker capture; adding this allowlist +entry does not enable network collection through legacy capture or WPR. + 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 diff --git a/src/core/learning_mode_core/src/verbose_logging.rs b/src/core/learning_mode_core/src/verbose_logging.rs index babb253c6..185cfce55 100644 --- a/src/core/learning_mode_core/src/verbose_logging.rs +++ b/src/core/learning_mode_core/src/verbose_logging.rs @@ -27,6 +27,8 @@ pub enum VerboseLoggingProvider { KernelGeneral, /// Microsoft-Windows-Privacy-Auditing-PermissiveLearningMode. PrivacyAuditingPermissiveLearningMode, + /// Microsoft-Windows-LearningMode-NetworkDecision. + LearningModeNetworkDecision, } /// Closed reason describing how a decoder outcome was handled. diff --git a/src/core/learning_mode_platforms/windows/src/etl_decode.rs b/src/core/learning_mode_platforms/windows/src/etl_decode.rs index 46c073386..86523c870 100644 --- a/src/core/learning_mode_platforms/windows/src/etl_decode.rs +++ b/src/core/learning_mode_platforms/windows/src/etl_decode.rs @@ -39,7 +39,9 @@ use windows::Win32::System::Diagnostics::Etw::{ PROCESS_TRACE_MODE_EVENT_RECORD, }; -use crate::extractors::{extract_denial, is_learning_mode_event, DecodedEventParts, RawDenial}; +use crate::extractors::{ + extract_denial, is_learning_mode_event, DecodedEventParts, RawDenial, NETWORK_DECISION_PROVIDER, +}; use crate::process_lifetime::{attested_process_lifetimes, JobMembershipSnapshot}; use crate::{path_norm, tdh_decode}; @@ -456,6 +458,11 @@ impl<'visitor> Accumulator<'visitor> { if !is_learning_mode_event(provider, event_id) { return; } + let pid = if provider == NETWORK_DECISION_PROVIDER { + 0 + } else { + pid + }; let reason = match error.event_kind() { Some(tdh_decode::EventDecodeKind::PayloadMalformed) => { VerboseLoggingOutcomeReason::EventPayloadMalformed @@ -849,7 +856,7 @@ unsafe fn process_event_record(event_record: *mut EVENT_RECORD, acc: &mut Accumu return; }; acc.relog_event_count = next_event_count; - if !is_learning_mode_event(provider, event_id) { + if !is_learning_mode_event(provider, event_id) || provider == NETWORK_DECISION_PROVIDER { return; } let Some(filetime) = normalized_filetime(header.TimeStamp, acc) else { @@ -874,12 +881,14 @@ unsafe fn process_event_record(event_record: *mut EVENT_RECORD, acc: &mut Accumu // 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. + // effective workload PID below. Native-only network events are excluded + // from process scoping; other events use the header PID directly. let mut analyze_filetime = None; if matches!(acc.mode, CollectionMode::Analyze) { - if !is_learning_mode_event(provider, event_id) { + if !is_learning_mode_event(provider, event_id) + || (provider == NETWORK_DECISION_PROVIDER && acc.process_lifetimes.is_some()) + { return; } let Some(filetime) = normalized_filetime(header.TimeStamp, acc) else { @@ -1027,7 +1036,9 @@ fn handle_decoded_event( filetime: u64, acc: &mut Accumulator<'_>, ) { - if !is_learning_mode_event(parts.provider, parts.event_id) { + if !is_learning_mode_event(parts.provider, parts.event_id) + || (parts.provider == NETWORK_DECISION_PROVIDER && acc.process_lifetimes.is_some()) + { return; } let event = (parts.event_id, parts.event_name.as_deref()); @@ -1106,6 +1117,116 @@ mod tests { const SCOPED_END_FILETIME: u64 = 200; const SCOPED_EVENT_FILETIME: u64 = 150; + #[test] + fn network_decision_is_retained_only_in_unscoped_native_analysis() { + let provider = windows::core::GUID::from_u128(0x71237669_21c3_4101_bd2f_ff38945d725a); + assert!(is_learning_mode_event(provider, 1)); + for event_id in [0, 2, 14, 28] { + assert!(!is_learning_mode_event(provider, event_id)); + } + assert!(!is_learning_mode_event( + crate::extractors::KERNEL_GENERAL_PROVIDER, + 1 + )); + let event = event_with_provider( + provider, + 1, + SCOPED_PID, + SCOPED_EVENT_FILETIME, + &[ + ("SchemaVersion", "1"), + ("Reason", "100"), + ("ProcessId", "42"), + ("ApplicationId", r"C:\Users\private\app.exe"), + ("RemoteAddress", "203.0.113.10"), + ], + ); + let native = resources_from_events(std::slice::from_ref(&event)); + assert!(native.denials.is_empty()); + let signature = &native.verbose_logging.signatures[0].signature; + assert_eq!( + signature.provider, + VerboseLoggingProvider::LearningModeNetworkDecision + ); + assert_eq!( + signature.provider_guid, + "{71237669-21C3-4101-BD2F-FF38945D725A}" + ); + assert_eq!(signature.pid, 0); + assert_eq!( + signature.reason, + VerboseLoggingOutcomeReason::UnsupportedEventSchema + ); + assert_eq!(property(signature, "Reason"), "100"); + assert_eq!(property(signature, "ApplicationId"), ""); + assert_eq!(property(signature, "RemoteAddress"), "203.0.113.10"); + + let lifetimes = [ProcessLifetime { + pid: SCOPED_PID, + start_filetime: SCOPED_START_FILETIME, + end_filetime: SCOPED_END_FILETIME, + }]; + let scoped = resources_from_events_for_process_lifetimes(&[event], Some(&lifetimes)); + assert!(scoped.verbose_logging.is_empty()); + + for mut accumulator in [ + Accumulator::analyze(), + Accumulator::analyze_for_process_lifetimes(&lifetimes), + Accumulator::select_for_relogging(&lifetimes), + ] { + let native = accumulator.process_lifetimes.is_none(); + let mut record = EVENT_RECORD::default(); + record.EventHeader.ProviderId = provider; + record.EventHeader.EventDescriptor.Id = 1; + record.EventHeader.ProcessId = SCOPED_PID; + record.EventHeader.TimeStamp = SCOPED_EVENT_FILETIME as i64; + let payload = 100u32.to_le_bytes(); + record.UserData = payload.as_ptr().cast_mut().cast(); + record.UserDataLength = payload.len() as u16; + if native { + accumulator + .schema_cache + .insert_test_schema(&record, &["Reason"]); + } + unsafe { process_event_record(&mut record, &mut accumulator) }; + assert_eq!(accumulator.schema_cache.schema_loads, 0); + assert_eq!( + accumulator.verbose_logging.total_occurrences, + u64::from(native) + ); + if native { + assert_eq!(accumulator.verbose_logging.signatures[0].signature.pid, 0); + } + assert!(accumulator.relog_selected_event_indices.is_empty()); + assert!(!accumulator.truncated); + } + } + + #[test] + fn network_decode_failure_does_not_attribute_the_broker_pid() { + let mut accumulator = Accumulator::analyze(); + accumulator.record_event_decode_error( + windows::core::GUID::from_u128(0x71237669_21c3_4101_bd2f_ff38945d725a), + 1, + SCOPED_PID, + tdh_decode::DecodeError::event( + tdh_decode::EventDecodeKind::PayloadMalformed, + "malformed network event".into(), + Some("NetworkDecisionV1".into()), + ), + ); + let group = &accumulator.verbose_logging.signatures[0]; + assert_eq!(group.signature.pid, 0); + assert_eq!( + group.signature.event_name.as_deref(), + Some("NetworkDecisionV1") + ); + assert_eq!( + group.signature.reason, + VerboseLoggingOutcomeReason::EventPayloadMalformed + ); + } + #[test] fn callback_selects_only_learning_mode_events_before_decoding() { let kernel = crate::extractors::KERNEL_GENERAL_PROVIDER; diff --git a/src/core/learning_mode_platforms/windows/src/extractors.rs b/src/core/learning_mode_platforms/windows/src/extractors.rs index 9aa08d420..c35ff32b8 100644 --- a/src/core/learning_mode_platforms/windows/src/extractors.rs +++ b/src/core/learning_mode_platforms/windows/src/extractors.rs @@ -48,6 +48,8 @@ //! [`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). +//! - **1 — `NetworkDecisionV1`** — the dedicated network-decision provider's +//! native-capture event. Retained as verbose diagnostics without policy grants. use learning_mode_core::{ AccessType, ResourceType, VerboseLoggingOutcomeReason, VerboseLoggingProvider, @@ -71,6 +73,11 @@ pub(crate) const PRIVACY_LEARNING_MODE_PROVIDER: GUID = GUID { data4: [0xad, 0xc0, 0x4b, 0x18, 0x61, 0x70, 0xe7, 0x60], }; +/// Microsoft-Windows-LearningMode-NetworkDecision. +pub(crate) const NETWORK_DECISION_PROVIDER: GUID = + GUID::from_u128(0x71237669_21c3_4101_bd2f_ff38945d725a); +pub(crate) const NETWORK_DECISION_EVENT_ID: u16 = 1; + pub(crate) const ACCESS_CHECK_EVENT_ID: u16 = 14; pub(crate) const LEARNING_MODE_VIOLATION_EVENT_ID: u16 = 27; pub(crate) const CAPABILITY_DENIAL_EVENT_ID: u16 = 28; @@ -225,13 +232,18 @@ pub(crate) fn is_learning_mode_event(provider: GUID, event_id: u16) -> bool { | LEARNING_MODE_VIOLATION_EVENT_ID | PRIVACY_ACCESS_CHECK_EVENT_ID ) + } else if provider == NETWORK_DECISION_PROVIDER { + event_id == NETWORK_DECISION_EVENT_ID } else { false } } pub(crate) fn effective_event_pid(parts: &DecodedEventParts, header_pid: u32) -> Option { - if parts.event_id == CAPABILITY_DENIAL_EVENT_ID { + if parts.provider == NETWORK_DECISION_PROVIDER { + // Network decisions identify the broker, not a reliable workload PID. + Some(0) + } else if parts.event_id == CAPABILITY_DENIAL_EVENT_ID { effective_capability_event_pid( find_prop(&parts.props, "ProcessId").map(std::string::String::as_str), ) @@ -258,6 +270,8 @@ pub(crate) fn verbose_logging_provider_for_guid(provider: GUID) -> Option VerboseLoggingProvider::PrivacyAuditingPermissiveLearningMode => { format_guid_braced_uppercase(PRIVACY_LEARNING_MODE_PROVIDER) } + VerboseLoggingProvider::LearningModeNetworkDecision => { + format_guid_braced_uppercase(NETWORK_DECISION_PROVIDER) + } } } diff --git a/src/core/mxc_engine/src/verbose_telemetry.rs b/src/core/mxc_engine/src/verbose_telemetry.rs index 39437829c..47b130e1e 100644 --- a/src/core/mxc_engine/src/verbose_telemetry.rs +++ b/src/core/mxc_engine/src/verbose_telemetry.rs @@ -169,6 +169,9 @@ fn canonical_provider_guid(provider: VerboseLoggingProvider) -> &'static str { VerboseLoggingProvider::PrivacyAuditingPermissiveLearningMode => { "{811A1DDB-2E69-5F25-ADC0-4B186170E760}" } + VerboseLoggingProvider::LearningModeNetworkDecision => { + "{71237669-21C3-4101-BD2F-FF38945D725A}" + } } } @@ -380,6 +383,26 @@ mod tests { assert!(projected.signatures[0].signature.properties.is_empty()); } + #[test] + fn telemetry_projection_strips_network_payload_and_canonicalizes_provider() { + let mut doc = document(vec![aggregate(1, "private-network-data")]); + doc.signatures[0].signature.provider = VerboseLoggingProvider::LearningModeNetworkDecision; + doc.signatures[0].signature.provider_guid = "untrusted-provider".into(); + doc.signatures[0].signature.event_name = Some("NetworkDecisionV1".into()); + + let projected = project_for_telemetry(doc); + + assert_eq!( + projected.signatures[0].signature.provider_guid, + "{71237669-21C3-4101-BD2F-FF38945D725A}" + ); + assert!(projected.signatures[0].signature.properties.is_empty()); + assert!(projected.signatures[0].signature.event_name.is_none()); + let json = serde_json::to_string(&projected).unwrap(); + assert!(!json.contains("private-network-data")); + assert!(!json.contains("untrusted-provider")); + } + #[test] fn telemetry_deduplicates_after_removing_unknown_provider_guids_and_properties() { let mut first = aggregate(999, "first-secret"); From b38566cc3482b708694f9208c62289043816b3f2 Mon Sep 17 00:00:00 2001 From: Jacob Dereje Date: Tue, 6 Oct 2026 14:29:43 -0700 Subject: [PATCH 05/10] Share and streamline file path detection Copilot-Session: 7758b99e-b7a0-4060-baf9-268db306b58b --- .../windows/src/etl_decode.rs | 4 -- .../windows/src/extractors.rs | 43 +++++++++++++++++-- 2 files changed, 39 insertions(+), 8 deletions(-) diff --git a/src/core/learning_mode_platforms/windows/src/etl_decode.rs b/src/core/learning_mode_platforms/windows/src/etl_decode.rs index 86523c870..a14ec5bca 100644 --- a/src/core/learning_mode_platforms/windows/src/etl_decode.rs +++ b/src/core/learning_mode_platforms/windows/src/etl_decode.rs @@ -879,10 +879,6 @@ unsafe fn process_event_record(event_record: *mut EVENT_RECORD, acc: &mut Accumu return; } - // Establish scope before charging the event against the shared processing - // budget. Brokered capability events are scoped after decoding their - // effective workload PID below. Native-only network events are excluded - // from process scoping; other events use the header PID directly. let mut analyze_filetime = None; if matches!(acc.mode, CollectionMode::Analyze) { diff --git a/src/core/learning_mode_platforms/windows/src/extractors.rs b/src/core/learning_mode_platforms/windows/src/extractors.rs index c35ff32b8..f93433147 100644 --- a/src/core/learning_mode_platforms/windows/src/extractors.rs +++ b/src/core/learning_mode_platforms/windows/src/extractors.rs @@ -241,7 +241,6 @@ pub(crate) fn is_learning_mode_event(provider: GUID, event_id: u16) -> bool { pub(crate) fn effective_event_pid(parts: &DecodedEventParts, header_pid: u32) -> Option { if parts.provider == NETWORK_DECISION_PROVIDER { - // Network decisions identify the broker, not a reliable workload PID. Some(0) } else if parts.event_id == CAPABILITY_DENIAL_EVENT_ID { effective_capability_event_pid( @@ -443,8 +442,19 @@ fn looks_like_file_path_property(name: &str, value: &str, object_type: Option<&s return true; } - value.char_indices().any(|(offset, _)| { - let candidate = &value[offset..]; + contains_file_path(value) +} + +fn contains_file_path(value: &str) -> bool { + value.match_indices(['\\', ':']).any(|(offset, marker)| { + let offset = if marker == ":" { + offset.saturating_sub(1) + } else { + offset + }; + let Some(candidate) = value.get(offset..) else { + return false; + }; if offset > 0 && candidate.get(1..4) == Some("://") && (value.as_bytes()[offset - 1].is_ascii_alphanumeric() @@ -576,7 +586,7 @@ pub(crate) fn sanitize_properties(props: &[(String, String)]) -> Vec<(String, St .map(|(_, value)| value.trim_matches('"')); let mut sanitized = std::collections::BTreeMap::new(); for (name, raw_value) in props { - if is_timestamp_like_property(name) || looks_like_file_path_property("", name, None) { + if is_timestamp_like_property(name) || contains_file_path(name) { continue; } let value = raw_value.trim_matches('"'); @@ -1761,6 +1771,31 @@ mod tests { } } + #[test] + fn path_content_scan_handles_candidate_boundaries() { + for (value, expected) in [ + ("", false), + (":", false), + ("::", false), + ("\u{03bb}:/not-a-drive", false), + ("\u{03bb}:C:/private.txt", true), + ("https://example.com:443/resource", false), + ("custom+a://example.com/resource", false), + (r"\\server\pipe\mxc", false), + (r"\Device\NamedPipe\mxc", false), + (r"\BaseNamedObjects\cache", false), + (r"C:\", true), + ("C:/", true), + (r"prefix \\server\share\file.txt", true), + (r"prefix \\?\Volume{1234}\file.txt", true), + ] { + assert_eq!(contains_file_path(value), expected, "{value}"); + } + let prefix = "ordinary text ".repeat(4096); + assert!(!contains_file_path(&prefix)); + assert!(contains_file_path(&format!("{prefix}C:\\private.txt"))); + } + #[test] fn sanitize_properties_drops_timestamp_like_properties() { let props = vec![ From 8444782aa3c64a8c2667cf2ebcedb2c2bef429c4 Mon Sep 17 00:00:00 2001 From: Jacob Dereje Date: Tue, 6 Oct 2026 21:45:39 -0700 Subject: [PATCH 06/10] Address review feedback and drop doc and comment changes Require an allowlisted, process-scoped Learning Mode event at each selected relog ordinal, and keep a missing NetworkDecisionV1 schema from marking actionable results incomplete. Copilot-Session: ca558f28-d3df-4b85-9e44-b9fddef77c62 --- docs/learning-mode/capabilities.md | 99 +++++-------------- .../learning_mode_core/verbose_logging.rs | 8 +- .../core/learning_mode_windows/etl_decode.rs | 66 ++++++------- .../core/learning_mode_windows/etl_filter.rs | 45 +++++---- .../core/learning_mode_windows/extractors.rs | 17 ++-- .../core/learning_mode_windows/tdh_decode.rs | 2 - 6 files changed, 94 insertions(+), 143 deletions(-) diff --git a/docs/learning-mode/capabilities.md b/docs/learning-mode/capabilities.md index 06b62fad8..e5c5dbb69 100644 --- a/docs/learning-mode/capabilities.md +++ b/docs/learning-mode/capabilities.md @@ -209,9 +209,7 @@ sandbox policy: - Analysis retains at most 10,000 unique denials and processes at most 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`. Missing schemas for - supported denial events also set this flag. Incomplete results do not produce - policy previews or adjusted configurations. + sets `summary.deniedResourcesTruncated` to `true`. - `resource` is the user-visible identifier for the denied resource, interpreted by `resourceType`: an absolute `C:\…` path for `file`, the AppContainer **capability name** (e.g. `internetClient`) for `capability`, @@ -224,9 +222,9 @@ sandbox policy: 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`; `allow` traces can expose capability - checks as empty-`ObjectType` access events. Known capabilities can be recovered - from their DACL payload; unresolved checks remain verbose diagnostics. + denials are recorded under `block`; current `allow` traces expose capability + checks as empty-`ObjectType` access events that are omitted because they do + not carry a stable capability identifier. - `filetime` is a decimal string containing the Windows `FILETIME` value, so JavaScript consumers retain all 64 bits without numeric precision loss. @@ -239,7 +237,7 @@ policy denial occurrences plus diagnostic outcomes omitted from the policy file: ```json { - "version": 4, + "version": 2, "signatures": [ { "signature": { @@ -270,24 +268,18 @@ policy denial occurrences plus diagnostic outcomes omitted from the policy file: ``` Signatures are keyed by symbolic provider category, provider GUID, -provider-scoped event ID, optional schema `eventName`, closed outcome reason, -PID, and sorted sanitized properties. The schema name distinguishes TraceLogging -events that share ID 0 and is separate from any payload field named `EventName`. -It is sanitized and bounded like other values, and is omitted when unavailable. -SIDs, capability names, GUIDs, PIDs/process identifiers, and +provider-scoped event ID, closed outcome 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 -``; a path inside a command line or rendered array causes that entire -property value to be redacted. Standalone user/account names remain replaced -with ``. Properties whose names contain file paths are omitted. +``; 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. -This is an outcome summary, not an ordered event ledger: repeats become a count, -and one source event can produce several capability-denial outcomes. -Every valid policy denial is classified as `actionable` in the verbose file. -Its first occurrence, later duplicates, and candidates observed after the -actionable file's unique-denial bound are all retained. Those occurrences -deduplicate under the same signature and increment its count. `accessType` and +Every valid actionable denial is classified as `actionable` in the verbose +file, including its first occurrence, later duplicates, and candidates observed +after the actionable 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. @@ -315,64 +307,26 @@ 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. -Analysis selects known Learning Mode provider/event pairs: - -| Provider | Event IDs | -|---|---| -| Microsoft-Windows-Kernel-General | 14, 27, 28 | -| Microsoft-Windows-Privacy-Auditing-PermissiveLearningMode | 14, 27, 4907 | -| Microsoft-Windows-LearningMode-NetworkDecision | 1 (`NetworkDecisionV1`) | - -Other providers and event IDs are excluded before decoding. This selection -does not depend on resource type: unfamiliar object types within selected events -retain their sanitized properties as verbose diagnostics, without creating -new actionable policy grants. Raw schema-discovery visitors and the WPR capture -profile are unchanged. - -`NetworkDecisionV1` uses provider `{71237669-21C3-4101-BD2F-FF38945D725A}`. -Its sanitized payload is retained as a verbose diagnostic without creating -network policy grants. The event has no reliable workload PID, so its signature -uses `pid: 0` rather than the broker's header PID. Process-scoped analysis and -guarded WPR exclude this source because they cannot safely attribute it to a job. -Collection requires option-aware native broker capture; adding this allowlist -entry does not enable network collection through legacy capture or WPR. +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 -in the optional `eventName` metadata field, with no partial payload properties. -Free-form decoder errors are -never serialized. Failure to obtain the event schema is retained as -`schemaUnavailable` rather than aborting the analysis, and marks actionable -results incomplete when the event belongs to a supported denial schema. -Missing manifest schemas share the 4,096-entry schema cache with successful -lookups; TraceLogging metadata is decoded per event. -For brokered Event 28, scoped analysis marks the result incomplete even when -the missing schema prevents reading its workload PID; unattributed event -contents are not 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 and 16 MiB of compact signature data, with 24 sorted properties per -signature and 256 characters per property value. -`overflowOccurrences` and `aggregateGroupsTruncated` indicate that +signatures, 24 sorted properties per signature, and 256 characters per property +value. `overflowOccurrences` and `aggregateGroupsTruncated` indicate that additional diagnostic groups were omitted. `actionableOverflowOccurrences` counts omitted actionable-denial occurrences, while `processedEventsTruncated` indicates that the 1,000,000-event limit prevented complete accounting. The actionable file itself is never reduced to make room for verbose logging. -The existing 64 MiB guarded analysis frame can also move verbose groups into -overflow accounting. These bounds are retained; the file does not claim complete -event-by-event coverage. - -Guarded WPR keeps the selected Learning Mode events from the exact job-attested -process lifetimes, including brokered capability attribution. -Required ETL headers remain in the retained trace. Its generated -relogging header is excluded from analysis so it does not add a diagnostic that -was absent from the source. A schema lookup failure while scoping brokered -Event 28 fails the capture, because its workload PID cannot be established. -Neither the unattributed event nor a potentially incomplete filtered trace is -returned. The host-wide source ETL is not transferred. The actionable and verbose logging files fail together: MXC stages both and reports capture failure unless both final artifacts are committed. The verbose logging path @@ -384,9 +338,7 @@ When stable telemetry is enabled and authorized, MXC may validate, compact, and send this redacted verbose document through `Microsoft.MXC/MXC.VerboseDenials`. Each event contains a valid JSON array of complete signatures and document reconstruction metadata. Before emission, MXC derives provider GUIDs from the -closed provider enum and drops every verbose property name and value. For `other`, -the telemetry GUID is empty. Matching groups are combined again after these -values and the schema `eventName` are removed. MXC does +closed provider enum and drops every verbose property name and value. MXC does not send the actionable denials file, workload-derived properties, or raw ETL through telemetry. See [MXC telemetry](../telemetry/telemetry.md). @@ -422,10 +374,9 @@ WPR's source ETL is host-wide, so the elevated guarded-WPR helper never transfers that file across the privilege boundary for `captureDenials` or `--audit`. After the sandbox process tree terminates, the helper uses the retained, job-attested process handles and their exact PID/creation/exit -`FILETIME` ranges to relog a second ETL. The retained ETL contains selected -Learning Mode events attributed to those process generations, plus required ETL headers. -Brokered capability events use their payload `ProcessId` rather than the -broker's header PID. Guarded analysis and +`FILETIME` ranges to relog a second ETL. The +retained ETL contains only supported Learning Mode events whose event header +falls inside one of those attested process generations. Guarded analysis and retention both consume that same filtered ETL; filtering failure transfers no trace. The host-wide source remains in protected elevated scratch and is deleted with that scratch. The unelevated caller writes the filtered retained diff --git a/src/mxc-sdk/src/core/learning_mode_core/verbose_logging.rs b/src/mxc-sdk/src/core/learning_mode_core/verbose_logging.rs index ffe02f35d..2937e7262 100644 --- a/src/mxc-sdk/src/core/learning_mode_core/verbose_logging.rs +++ b/src/mxc-sdk/src/core/learning_mode_core/verbose_logging.rs @@ -17,11 +17,11 @@ pub const MAX_VERBOSE_LOGGING_GROUPS: usize = 4_096; /// 64 MiB frame limit for actionable denials and envelope overhead. pub const MAX_VERBOSE_LOGGING_SIGNATURE_BYTES: usize = 16 * 1024 * 1024; -/// Stable category for a Learning Mode ETW provider. +/// 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 { - /// Any other provider, identified by its GUID in the local output. + /// Any other provider. Other, /// Microsoft-Windows-Kernel-General. KernelGeneral, @@ -37,7 +37,7 @@ pub enum VerboseLoggingProvider { pub enum VerboseLoggingOutcomeReason { /// The event produced a valid actionable denial. Actionable, - /// No actionable extractor supports this provider/event pair. + /// The provider is known, but the event ID is not a supported denial schema. UnsupportedEventSchema, /// TDH could not resolve the event schema. SchemaUnavailable, @@ -79,7 +79,7 @@ pub struct VerboseLoggingSignature { pub provider_guid: String, /// Provider-scoped ETW schema identifier. pub event_id: u16, - /// Sanitized schema name, separate from payload properties. + /// Sanitized schema name. #[serde(default, skip_serializing_if = "Option::is_none")] pub event_name: Option, /// Closed exclusion category. diff --git a/src/mxc-sdk/src/core/learning_mode_windows/etl_decode.rs b/src/mxc-sdk/src/core/learning_mode_windows/etl_decode.rs index 26a8fa9a0..3d86f6f64 100644 --- a/src/mxc-sdk/src/core/learning_mode_windows/etl_decode.rs +++ b/src/mxc-sdk/src/core/learning_mode_windows/etl_decode.rs @@ -2,7 +2,7 @@ // Licensed under the MIT License. //! Sealed-ETL decoder: turns the `.etl` delivered by the Learning Mode trace API -//! into cross-platform [`DeniedResource`]s. +//! produces into cross-platform [`DeniedResource`]s. //! //! The trace is opened in **file mode** (`EVENT_TRACE_LOGFILEW.LogFileName`, //! without `PROCESS_TRACE_MODE_REAL_TIME`). `ProcessTrace` walks every @@ -18,11 +18,11 @@ //! The diagnostic console has a separate real-time, display-oriented ETW //! consumer in `tools/mxc_diagnostic_console`. It is a binary-private module //! that owns trace sessions and channels arbitrary provider events to a UI. -//! This backend reads sealed files synchronously and keeps bounded, deduplicated -//! diagnostics for every resource type in selected Learning Mode events. -//! Only known schemas produce actionable denials. Depending on the tool would -//! invert the workspace dependency direction; shared generic TDH primitives can -//! be extracted later if another runtime consumer needs them. +//! This backend instead reads sealed files synchronously, filters a fixed +//! provider/event vocabulary, bounds results, and skips malformed individual +//! events without invalidating the rest of the capture. Depending on the tool would invert the workspace dependency +//! direction; shared generic TDH primitives can be extracted later if another +//! runtime consumer needs them. use std::collections::{HashMap, HashSet}; use std::os::windows::ffi::OsStrExt; @@ -442,9 +442,6 @@ impl<'visitor> Accumulator<'visitor> { } /// Handles a TDH decode failure for one event. - /// - /// Analysis records a closed diagnostic reason and continues. Raw diagnostic - /// visitors require every event to decode successfully and fail instead. fn record_event_decode_error( &mut self, provider: windows::core::GUID, @@ -480,7 +477,9 @@ impl<'visitor> Accumulator<'visitor> { } None => VerboseLoggingOutcomeReason::SchemaUnavailable, }; - if reason == VerboseLoggingOutcomeReason::SchemaUnavailable { + if reason == VerboseLoggingOutcomeReason::SchemaUnavailable + && provider != NETWORK_DECISION_PROVIDER + { self.truncated = true; } let event = (event_id, error.event_name()); @@ -574,14 +573,6 @@ impl EtlDenialAnalyzer { self.analyze_for_process_lifetimes(source_path, &process_lifetimes) } - /// Analyzes a relogged trace for exact job-attested process generations. - /// - /// The relogger's generated transport header is not a source observation. - /// - /// # Errors - /// - /// Returns [`AnalyzeError`] when job evidence is invalid or the trace cannot - /// be decoded. pub fn analyze_relogged_for_job_membership( &self, source_path: &Path, @@ -678,7 +669,7 @@ pub fn visit_raw_events( Ok(accumulator.raw_event_count) } -/// Builds a bounded decision vector for selected in-scope 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. @@ -1039,7 +1030,12 @@ fn select_event_for_relogging( acc.relog_selected_event_pids.push(pid); } -/// Extracts known denials and retains other resource types as diagnostics. +/// Extracts denials from one decoded, in-vocabulary event and feeds them +/// (or their closed outcome 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, @@ -1380,9 +1376,7 @@ mod tests { ), ] { for time in [100, 200] { - // SAFETY: the initialized record and payload remain live - // throughout the synchronous callback. - let mut record: EVENT_RECORD = unsafe { core::mem::zeroed() }; + let mut record = EVENT_RECORD::default(); record.EventHeader.ProviderId = provider; record.EventHeader.EventDescriptor.Id = event_id; record.EventHeader.EventDescriptor.Version = u8::MAX; @@ -1925,16 +1919,17 @@ mod tests { fn schema_failure_completeness_follows_the_supported_event_vocabulary() { let kernel = crate::learning_mode_windows::extractors::KERNEL_GENERAL_PROVIDER; let privacy = crate::learning_mode_windows::extractors::PRIVACY_LEARNING_MODE_PROVIDER; - for (provider, event_id, incomplete) in [ - (kernel, 14, true), - (kernel, 27, true), - (kernel, 28, true), - (privacy, 14, true), - (privacy, 27, true), - (privacy, 4907, true), - (kernel, 999, false), - (privacy, 28, false), - (windows::core::GUID::from_u128(1), 14, false), + for (provider, event_id, retained, incomplete) in [ + (kernel, 14, true, true), + (kernel, 27, true, true), + (kernel, 28, true, true), + (privacy, 14, true, true), + (privacy, 27, true, true), + (privacy, 4907, true, true), + (NETWORK_DECISION_PROVIDER, 1, true, false), + (kernel, 999, false, false), + (privacy, 28, false, false), + (windows::core::GUID::from_u128(1), 14, false, false), ] { let mut accumulator = Accumulator::analyze(); accumulator.record_event_decode_error( @@ -1963,13 +1958,13 @@ mod tests { assert_eq!(analysis.denials[0].resource, r"C:\kept.txt"); assert_eq!( analysis.verbose_logging.total_occurrences, - 1 + u64::from(incomplete) + 1 + u64::from(retained) ); assert_eq!( analysis.verbose_logging.signatures.iter().any(|group| { group.signature.reason == VerboseLoggingOutcomeReason::SchemaUnavailable }), - incomplete + retained ); let mut bytes = Vec::new(); let summary = crate::learning_mode_core::DenialSummary::new( @@ -2618,7 +2613,6 @@ mod tests { assert!(analysis.verbose_logging.is_empty()); } - /// Resource exclusions remain diagnostic; unrelated event IDs are ignored. #[test] fn non_actionable_events_are_dropped() { let events = vec![ diff --git a/src/mxc-sdk/src/core/learning_mode_windows/etl_filter.rs b/src/mxc-sdk/src/core/learning_mode_windows/etl_filter.rs index fba5d27f4..aacff3753 100644 --- a/src/mxc-sdk/src/core/learning_mode_windows/etl_filter.rs +++ b/src/mxc-sdk/src/core/learning_mode_windows/etl_filter.rs @@ -17,7 +17,7 @@ use windows::Win32::System::Diagnostics::Etw::{ }; use crate::learning_mode_windows::etl_decode::select_learning_mode_events_for_relogging; -use crate::learning_mode_windows::extractors::is_learning_mode_event; +use crate::learning_mode_windows::extractors::{is_learning_mode_event, NETWORK_DECISION_PROVIDER}; use crate::learning_mode_windows::process_lifetime::{ attested_process_lifetimes, JobMembershipSnapshot, }; @@ -90,13 +90,16 @@ impl RelogSelectionState { } } - fn observe_event(&self, pid: u32) -> bool { + fn observe_event(&self, pid: Option) -> 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) { return false; } + let Some(pid) = pid else { + return false; + }; if self.selected_event_pids.get(selected_index) != Some(&pid) || !self.attested_pids.contains(&pid) { @@ -124,13 +127,9 @@ impl ITraceEventCallback_Impl for ProcessScopedTraceFilter_Impl { ) -> windows::core::Result<()> { let header_event = header_event.ok()?; let relogger = relogger.ok()?; - // SAFETY: Trace Relogger keeps the header and its interfaces valid - // throughout this synchronous callback. - let record = unsafe { header_event.GetEventRecord()? }; - let record = unsafe { record.as_ref() }.ok_or_else(|| { - windows::core::Error::from_hresult(windows::Win32::Foundation::E_POINTER) - })?; - self.selection.observe_event(record.EventHeader.ProcessId); + self.selection.observe_event(None); + // SAFETY: both interfaces are valid for this synchronous callback. + // The trace header is required for a standalone output ETL. unsafe { relogger.Inject(header_event)? }; Ok(()) } @@ -155,9 +154,11 @@ impl ITraceEventCallback_Impl for ProcessScopedTraceFilter_Impl { )); }; let header = &record.EventHeader; - let is_supported_capability_event = header.EventDescriptor.Id - == crate::learning_mode_windows::extractors::CAPABILITY_DENIAL_EVENT_ID - && is_learning_mode_event(header.ProviderId, header.EventDescriptor.Id); + let selectable = is_learning_mode_event(header.ProviderId, header.EventDescriptor.Id) + && header.ProviderId != NETWORK_DECISION_PROVIDER; + let is_supported_capability_event = selectable + && header.EventDescriptor.Id + == crate::learning_mode_windows::extractors::CAPABILITY_DENIAL_EVENT_ID; let effective_pid = if is_supported_capability_event { let payload_pid = self .schema_cache @@ -181,7 +182,10 @@ impl ITraceEventCallback_Impl for ProcessScopedTraceFilter_Impl { } else { header.ProcessId }; - if self.selection.observe_event(effective_pid) { + if self + .selection + .observe_event(selectable.then_some(effective_pid)) + { // SAFETY: both interfaces are valid for this synchronous callback, // and Inject clones the event into the output trace. unsafe { relogger.Inject(event)? }; @@ -397,8 +401,6 @@ mod tests { let mut storage = vec![0u64; 512]; let properties = storage.as_mut_ptr().cast::(); let mut session = CONTROLTRACE_HANDLE::default(); - // SAFETY: the aligned buffer holds both null-terminated strings and - // outlives the synchronous ETW calls. unsafe { (*properties).Wnode.BufferSize = (storage.len() * 8) as u32; (*properties).Wnode.Guid = provider; @@ -540,7 +542,7 @@ mod tests { fn selected_ordinal_with_foreign_pid_is_not_injected() { let selection = RelogSelectionState::new(vec![0], vec![42], &[lifetime(42)]); - assert!(!selection.observe_event(99)); + assert!(!selection.observe_event(Some(99))); assert_eq!(selection.consumed_event_count(), 1); assert_eq!( selection.consumed_selected_event_count(), @@ -549,11 +551,20 @@ mod tests { ); } + #[test] + fn selected_ordinal_with_unrelated_event_is_not_injected() { + let selection = RelogSelectionState::new(vec![0], vec![42], &[lifetime(42)]); + + assert!(!selection.observe_event(None)); + assert_eq!(selection.consumed_event_count(), 1); + assert_eq!(selection.consumed_selected_event_count(), 0); + } + #[test] fn selected_ordinal_with_attested_pid_is_injected() { let selection = RelogSelectionState::new(vec![0], vec![42], &[lifetime(42)]); - assert!(selection.observe_event(42)); + assert!(selection.observe_event(Some(42))); assert_eq!(selection.consumed_event_count(), 1); assert_eq!(selection.consumed_selected_event_count(), 1); } diff --git a/src/mxc-sdk/src/core/learning_mode_windows/extractors.rs b/src/mxc-sdk/src/core/learning_mode_windows/extractors.rs index a05cb2d1b..273451a27 100644 --- a/src/mxc-sdk/src/core/learning_mode_windows/extractors.rs +++ b/src/mxc-sdk/src/core/learning_mode_windows/extractors.rs @@ -20,9 +20,8 @@ //! //! 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; provider/event pairs outside this vocabulary are excluded. -//! Every resource type within these events remains eligible for verbose -//! diagnostics. The IDs handled today: +//! decoded; event IDs outside this vocabulary are excluded rather than +//! extracted. The IDs handled today: //! //! - **14 / 4907 — access check** — the primary denial event //! (`ObjectType` / `ObjectName` / `AccessMask`). `ObjectType` selects the @@ -33,8 +32,8 @@ //! access are retained only as verbose diagnostics. Named Section, //! SymbolicLink, and Timer objects are likewise verbose-only because MXC has //! no corresponding policy grants. -//! Other object types remain verbose diagnostics until their access-mask -//! vocabulary is understood. The [`AccessType`] is derived from the +//! 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"`). @@ -48,8 +47,6 @@ //! [`ResourceType::Capability`], with the capability name resolved from the //! capability SID via [`crate::learning_mode_windows::capability_names`] (well-known SID → friendly //! name; custom hashed capabilities fall back to the SID string). -//! - **1 — `NetworkDecisionV1`** — the dedicated network-decision provider's -//! native-capture event. Retained as verbose diagnostics without policy grants. use crate::learning_mode_core::{ AccessType, ResourceType, VerboseLoggingOutcomeReason, VerboseLoggingProvider, @@ -73,7 +70,6 @@ pub(crate) const PRIVACY_LEARNING_MODE_PROVIDER: GUID = GUID { data4: [0xad, 0xc0, 0x4b, 0x18, 0x61, 0x70, 0xe7, 0x60], }; -/// Microsoft-Windows-LearningMode-NetworkDecision. pub(crate) const NETWORK_DECISION_PROVIDER: GUID = GUID::from_u128(0x71237669_21c3_4101_bd2f_ff38945d725a); pub(crate) const NETWORK_DECISION_EVENT_ID: u16 = 1; @@ -94,7 +90,6 @@ pub struct DecodedEventParts { pub provider: GUID, /// Originating ETW event ID. pub event_id: u16, - /// Schema-declared event name. pub event_name: Option, /// `(name, value)` pairs from the decoded payload. String values are /// often TDH-quoted; extractors trim the surrounding quotes. @@ -263,7 +258,9 @@ pub(crate) fn effective_capability_event_pid(process_id: Option<&str>) -> Option /// Maps a raw ETW provider GUID to its symbolic verbose logging category. /// -/// Returns `None` outside the Learning Mode provider vocabulary. +/// 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) diff --git a/src/mxc-sdk/src/core/learning_mode_windows/tdh_decode.rs b/src/mxc-sdk/src/core/learning_mode_windows/tdh_decode.rs index 58829af24..1e26a94b5 100644 --- a/src/mxc-sdk/src/core/learning_mode_windows/tdh_decode.rs +++ b/src/mxc-sdk/src/core/learning_mode_windows/tdh_decode.rs @@ -197,8 +197,6 @@ impl TdhInfoBuffer { /// Decodes an `EVENT_RECORD` into `DecodedEventParts`. /// -/// Returns a schema error when TDH cannot describe the event. -/// /// # Safety /// `event_record` must point to a valid `EVENT_RECORD` provided by the /// ETW callback; the caller must not retain references to its fields From 94b6418b77f820b16b5d2ad29bfe3c0a5529beb0 Mon Sep 17 00:00:00 2001 From: Jacob Dereje Date: Wed, 7 Oct 2026 09:12:02 -0700 Subject: [PATCH 07/10] Remove unused verbose logging code Copilot-Session: ca558f28-d3df-4b85-9e44-b9fddef77c62 --- .../learning_mode_core/verbose_logging.rs | 4 +- .../core/learning_mode_windows/etl_decode.rs | 37 ++------- .../core/learning_mode_windows/extractors.rs | 78 ++++++++----------- .../src/core/mxc_engine/verbose_telemetry.rs | 7 +- 4 files changed, 44 insertions(+), 82 deletions(-) diff --git a/src/mxc-sdk/src/core/learning_mode_core/verbose_logging.rs b/src/mxc-sdk/src/core/learning_mode_core/verbose_logging.rs index 2937e7262..78c10bfec 100644 --- a/src/mxc-sdk/src/core/learning_mode_core/verbose_logging.rs +++ b/src/mxc-sdk/src/core/learning_mode_core/verbose_logging.rs @@ -21,8 +21,6 @@ pub const MAX_VERBOSE_LOGGING_SIGNATURE_BYTES: usize = 16 * 1024 * 1024; #[derive(Debug, Clone, Copy, PartialEq, Eq, PartialOrd, Ord, Hash, Serialize, Deserialize)] #[serde(rename_all = "camelCase")] pub enum VerboseLoggingProvider { - /// Any other provider. - Other, /// Microsoft-Windows-Kernel-General. KernelGeneral, /// Microsoft-Windows-Privacy-Auditing-PermissiveLearningMode. @@ -532,7 +530,7 @@ mod tests { #[test] fn schema_name_is_optional_and_separate_from_payload() { let old = serde_json::json!({ - "provider": "other", + "provider": "kernelGeneral", "providerGuid": "provider", "eventId": 0, "reason": "unsupportedEventSchema", diff --git a/src/mxc-sdk/src/core/learning_mode_windows/etl_decode.rs b/src/mxc-sdk/src/core/learning_mode_windows/etl_decode.rs index 3d86f6f64..de16b899f 100644 --- a/src/mxc-sdk/src/core/learning_mode_windows/etl_decode.rs +++ b/src/mxc-sdk/src/core/learning_mode_windows/etl_decode.rs @@ -35,7 +35,7 @@ use crate::learning_mode_core::{ }; use windows::core::PWSTR; use windows::Win32::System::Diagnostics::Etw::{ - CloseTrace, OpenTraceW, ProcessTrace, EVENT_RECORD, EVENT_TRACE_LOGFILEW, + CloseTrace, EventTraceGuid, OpenTraceW, ProcessTrace, EVENT_RECORD, EVENT_TRACE_LOGFILEW, PROCESS_TRACE_MODE_EVENT_RECORD, }; @@ -357,22 +357,6 @@ impl<'visitor> Accumulator<'visitor> { ); } - /// 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`. - #[cfg(test)] - fn record_exclusion( - &mut self, - provider: VerboseLoggingProvider, - event: (u16, Option<&str>), - reason: VerboseLoggingOutcomeReason, - pid: u32, - properties: Vec<(String, String)>, - ) { - self.record_outcome(provider, event, reason, pid, (None, None), properties); - } - fn record_outcome( &mut self, provider: VerboseLoggingProvider, @@ -399,10 +383,6 @@ impl<'visitor> Accumulator<'visitor> { resource_type, properties, }; - self.record_signature(signature); - } - - fn record_signature(&mut self, signature: VerboseLoggingSignature) { self.verbose_logging.record_with_byte_budget( signature, &mut self.verbose_logging_signature_bytes, @@ -838,10 +818,7 @@ unsafe fn process_event_record(event_record: *mut EVENT_RECORD, acc: &mut Accumu if acc.skip_relog_header { acc.skip_relog_header = false; - if provider != windows::core::GUID::from_u128(0x68fdd900_4a3e_11d1_84f4_0000f80464e3) - || event_id != 0 - || header.EventDescriptor.Opcode != 0 - { + if provider != EventTraceGuid || event_id != 0 || header.EventDescriptor.Opcode != 0 { acc.decode_error = Some("relogged trace has an invalid transport header".into()); } return; @@ -1584,12 +1561,7 @@ mod tests { 42, 150, ); - visit( - windows::core::GUID::from_u128(0x68fdd900_4a3e_11d1_84f4_0000f80464e3), - 0, - 42, - 150, - ); + visit(EventTraceGuid, 0, 42, 150); visit( windows::core::GUID::from_u128(0x3d6fa8d0_fe05_11d0_9dda_00c04fd7ba7c), 0, @@ -3047,11 +3019,12 @@ mod tests { }) .collect::>(); for pid in 0..crate::learning_mode_core::MAX_VERBOSE_LOGGING_GROUPS as u32 { - accumulator.record_exclusion( + accumulator.record_outcome( VerboseLoggingProvider::KernelGeneral, (14, None), VerboseLoggingOutcomeReason::Actionable, pid, + (None, None), properties.clone(), ); } diff --git a/src/mxc-sdk/src/core/learning_mode_windows/extractors.rs b/src/mxc-sdk/src/core/learning_mode_windows/extractors.rs index 273451a27..97319fe15 100644 --- a/src/mxc-sdk/src/core/learning_mode_windows/extractors.rs +++ b/src/mxc-sdk/src/core/learning_mode_windows/extractors.rs @@ -279,7 +279,6 @@ pub(crate) fn verbose_logging_provider_for_guid(provider: GUID) -> Option String { match provider { - VerboseLoggingProvider::Other => String::new(), VerboseLoggingProvider::KernelGeneral => { format_guid_braced_uppercase(KERNEL_GENERAL_PROVIDER) } @@ -1880,19 +1879,6 @@ mod tests { assert_eq!(value_for("ObjectName"), Some(REDACTED_PATH)); } - #[test] - fn future_property_names_do_not_bypass_path_redaction() { - let properties = sanitize_properties(&[ - ("FutureLocation".into(), r"C:\Users\private\file.txt".into()), - ("LogFileNameString".into(), "ReloggedFile.ETL".into()), - ( - "UnrecognizedField".into(), - r"\\server\share\private.txt".into(), - ), - ]); - assert!(properties.iter().all(|(_, value)| value == REDACTED_PATH)); - } - #[test] fn sanitize_properties_omits_sensitive_property_names() { let props = [ @@ -1928,38 +1914,42 @@ mod tests { #[test] fn sanitize_properties_redacts_embedded_file_paths() { let long_value = format!("{}C:\\Users\\alice\\secret.txt", "prefix ".repeat(100)); - for value in [ - r"cmd.exe /c type C:\Users\alice\secret.txt", - r#"--input="C:\Program Files\private\data.txt""#, - r"open \\server\share\private.txt", - r"open \??\C:\Users\alice\secret.txt", - r"open \\?\Volume{1234}\private.txt", - r"open \Device\HarddiskVolume3\Users\alice\secret.txt", - "message: C:/Users/alice/secret.txt", - "\u{03bb}: C:\\Users\\alice\\secret.txt", - ] - .into_iter() - .chain([long_value.as_str()]) - { - assert_eq!( - sanitize_properties(&[("CommandLine".into(), value.into())]), - [("CommandLine".into(), REDACTED_PATH.into())], - "{value}", - ); - } - } - - #[test] - fn sanitize_properties_redacts_paths_in_rendered_arrays() { - for value in [ - r#"["C:\Users\alice\secret.txt", "D:\private.txt"]"#, - r#"["safe", "\\server\share\private.txt"]"#, - r#"["safe", "\Device\HarddiskVolume3\private.txt"]"#, - r#"["C:\\Users\\alice\\secret.txt"]"#, + for (name, value) in [ + ("CommandLine", r"cmd.exe /c type C:\Users\alice\secret.txt"), + ( + "CommandLine", + r#"--input="C:\Program Files\private\data.txt""#, + ), + ("CommandLine", r"open \\server\share\private.txt"), + ("CommandLine", r"open \??\C:\Users\alice\secret.txt"), + ("CommandLine", r"open \\?\Volume{1234}\private.txt"), + ( + "CommandLine", + r"open \Device\HarddiskVolume3\Users\alice\secret.txt", + ), + ("CommandLine", "message: C:/Users/alice/secret.txt"), + ("CommandLine", "\u{03bb}: C:\\Users\\alice\\secret.txt"), + ("CommandLine", long_value.as_str()), + ( + "FutureLocations", + r#"["C:\Users\alice\secret.txt", "D:\private.txt"]"#, + ), + ( + "FutureLocations", + r#"["safe", "\\server\share\private.txt"]"#, + ), + ( + "FutureLocations", + r#"["safe", "\Device\HarddiskVolume3\private.txt"]"#, + ), + ("FutureLocations", r#"["C:\\Users\\alice\\secret.txt"]"#), + ("FutureLocation", r"C:\Users\private\file.txt"), + ("LogFileNameString", "ReloggedFile.ETL"), + ("UnrecognizedField", r"\\server\share\private.txt"), ] { assert_eq!( - sanitize_properties(&[("FutureLocations".into(), value.into())]), - [("FutureLocations".into(), REDACTED_PATH.into())], + sanitize_properties(&[(name.into(), value.into())]), + [(name.into(), REDACTED_PATH.into())], "{value}", ); } diff --git a/src/mxc-sdk/src/core/mxc_engine/verbose_telemetry.rs b/src/mxc-sdk/src/core/mxc_engine/verbose_telemetry.rs index 370e8ec78..3d2aefa6c 100644 --- a/src/mxc-sdk/src/core/mxc_engine/verbose_telemetry.rs +++ b/src/mxc-sdk/src/core/mxc_engine/verbose_telemetry.rs @@ -164,7 +164,6 @@ fn project_for_telemetry(mut document: VerboseLoggingDocument) -> VerboseLogging fn canonical_provider_guid(provider: VerboseLoggingProvider) -> &'static str { match provider { - VerboseLoggingProvider::Other => "", VerboseLoggingProvider::KernelGeneral => "{A68CA8B7-004F-D7B6-A698-07E2DE0F1F5D}", VerboseLoggingProvider::PrivacyAuditingPermissiveLearningMode => { "{811A1DDB-2E69-5F25-ADC0-4B186170E760}" @@ -406,7 +405,6 @@ mod tests { #[test] fn telemetry_deduplicates_after_removing_unknown_provider_guids_and_properties() { let mut first = aggregate(999, "first-secret"); - first.signature.provider = VerboseLoggingProvider::Other; first.signature.provider_guid = "first-provider".into(); first.signature.event_name = Some("first-event".into()); first.count = 3; @@ -422,7 +420,10 @@ mod tests { assert_eq!(projected.signatures.len(), 1); assert_eq!(projected.signatures[0].count, 7); - assert!(projected.signatures[0].signature.provider_guid.is_empty()); + assert_eq!( + projected.signatures[0].signature.provider_guid, + "{A68CA8B7-004F-D7B6-A698-07E2DE0F1F5D}" + ); assert!(projected.signatures[0].signature.event_name.is_none()); assert!(projected.signatures[0].signature.properties.is_empty()); assert_eq!(projected.summary.total_occurrences, 7); From 726e75f1b70136f3b997d0c522c6edb48dffcd20 Mon Sep 17 00:00:00 2001 From: Jacob Dereje Date: Wed, 7 Oct 2026 09:16:28 -0700 Subject: [PATCH 08/10] Document verbose format v4 schema handling Copilot-Session: ca558f28-d3df-4b85-9e44-b9fddef77c62 --- docs/learning-mode/capabilities.md | 21 ++++++++++++--------- 1 file changed, 12 insertions(+), 9 deletions(-) diff --git a/docs/learning-mode/capabilities.md b/docs/learning-mode/capabilities.md index e5c5dbb69..348b4845a 100644 --- a/docs/learning-mode/capabilities.md +++ b/docs/learning-mode/capabilities.md @@ -237,7 +237,7 @@ policy denial occurrences plus diagnostic outcomes omitted from the policy file: ```json { - "version": 2, + "version": 4, "signatures": [ { "signature": { @@ -268,8 +268,8 @@ policy denial occurrences plus diagnostic outcomes omitted from the policy file: ``` Signatures are keyed by symbolic provider category, provider GUID, -provider-scoped event ID, closed outcome reason, PID, and sorted sanitized -properties. SIDs, capability names, GUIDs, PIDs/process identifiers, and +provider-scoped event ID, schema name, closed outcome 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 ``. @@ -307,18 +307,21 @@ 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. +Only Learning Mode events are decoded: Kernel-General events 14, 27, and 28, +PermissiveLearningMode events 14, 27, and 4907, and NetworkDecision event 1. +Other provider and event ID pairs are ignored. 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. +as the bounded `eventName` signature field. Free-form decoder errors are +never serialized. `schemaUnavailable` means the event schema could not be +obtained. Analysis continues but sets `deniedResourcesTruncated`, except for +network decisions, because the event may have been a denial. Schema failures +remain fatal for raw decoding and for scoping brokered capability events in +guarded traces. To keep diagnostics bounded, verbose logging retains at most 4,096 distinct signatures, 24 sorted properties per signature, and 256 characters per property From ca4e2221d5145db3cee3a7e0a6448dc6a6701340 Mon Sep 17 00:00:00 2001 From: Jacob Dereje Date: Wed, 7 Oct 2026 09:49:04 -0700 Subject: [PATCH 09/10] Keep embedded path scan linear Copilot-Session: ca558f28-d3df-4b85-9e44-b9fddef77c62 --- .../src/core/learning_mode_windows/extractors.rs | 12 +++++++++++- 1 file changed, 11 insertions(+), 1 deletion(-) diff --git a/src/mxc-sdk/src/core/learning_mode_windows/extractors.rs b/src/mxc-sdk/src/core/learning_mode_windows/extractors.rs index 97319fe15..416f5ae6a 100644 --- a/src/mxc-sdk/src/core/learning_mode_windows/extractors.rs +++ b/src/mxc-sdk/src/core/learning_mode_windows/extractors.rs @@ -443,6 +443,9 @@ fn looks_like_file_path_property(name: &str, value: &str, object_type: Option<&s fn contains_file_path(value: &str) -> bool { value.match_indices(['\\', ':']).any(|(offset, marker)| { + if value[offset..].starts_with(r"\\\\") { + return false; + } let offset = if marker == ":" { offset.saturating_sub(1) } else { @@ -480,7 +483,9 @@ fn looks_like_dos_device_filesystem_path(value: &str) -> bool { let Some(volume) = strip_prefix_ignore_ascii_case(rest, "Volume{") else { return false; }; - volume.contains(r"}\") + volume + .split_once('\\') + .is_some_and(|(guid, _)| guid.ends_with('}')) } fn looks_like_drive_absolute_path(value: &str) -> bool { @@ -1792,6 +1797,11 @@ mod tests { let prefix = "ordinary text ".repeat(4096); assert!(!contains_file_path(&prefix)); assert!(contains_file_path(&format!("{prefix}C:\\private.txt"))); + assert!(!contains_file_path(&format!( + "{}server\\pipe\\mxc", + "\\".repeat(32 * 1024) + ))); + assert!(!contains_file_path(&r"\??\Volume{".repeat(4096))); } #[test] From 13ec86bfdcc50d635bac7ae4efa6173fff65fd08 Mon Sep 17 00:00:00 2001 From: Jacob Dereje Date: Wed, 7 Oct 2026 13:03:01 -0700 Subject: [PATCH 10/10] Scope relog ordinals and cache only missing schemas Copilot-Session: ca558f28-d3df-4b85-9e44-b9fddef77c62 --- docs/development/architecture/telemetry.md | 3 +- docs/logging-access-denied.md | 15 +- .../learning_mode_core/verbose_logging.rs | 6 +- .../core/learning_mode_windows/etl_decode.rs | 106 +++++--- .../core/learning_mode_windows/etl_filter.rs | 231 +++++++++++++----- .../core/learning_mode_windows/extractors.rs | 4 + .../core/learning_mode_windows/tdh_decode.rs | 137 +++++++---- 7 files changed, 358 insertions(+), 144 deletions(-) diff --git a/docs/development/architecture/telemetry.md b/docs/development/architecture/telemetry.md index ea6fc34f8..187e814ef 100644 --- a/docs/development/architecture/telemetry.md +++ b/docs/development/architecture/telemetry.md @@ -202,7 +202,8 @@ Emitted when a telemetry-enabled ProcessContainer run successfully produces a Learning Mode `captureDenials` verbose logging artifact. MXC reads the versioned `*.verbose.json` sibling, validates it as a `VerboseLoggingDocument`, derives each provider GUID from the document's -closed provider enum, drops every verbose property name and value, and +closed provider enum, drops every verbose property name and value and the +schema name, sums the counts of signatures that become identical, and serializes that telemetry-specific projection as compact JSON. The event never contains the actionable denials file, raw ETL, commands, sandbox output, or general logger text. diff --git a/docs/logging-access-denied.md b/docs/logging-access-denied.md index f61951de3..5d163a108 100644 --- a/docs/logging-access-denied.md +++ b/docs/logging-access-denied.md @@ -208,8 +208,9 @@ sandbox policy: `summary.totalDenials` equals `denials.length`. - Analysis retains at most 10,000 unique denials and processes at most 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`. + entries but continues bounded diagnostic accounting; reaching either bound, or + failing to read a non-network event's schema, sets + `summary.deniedResourcesTruncated` to `true`. - `resource` is the user-visible identifier for the denied resource, interpreted by `resourceType`: an absolute `C:\…` path for `file`, the AppContainer **capability name** (e.g. `internetClient`) for `capability`, @@ -309,7 +310,10 @@ a digest is derived from a sensitive value. Only Learning Mode events are decoded: Kernel-General events 14, 27, and 28, PermissiveLearningMode events 14, 27, and 4907, and NetworkDecision event 1. -Other provider and event ID pairs are ignored. +Other provider and event ID pairs are ignored. `unsupportedEventSchema` means +the event has no actionable extractor. NetworkDecision records are kept only by +unscoped analysis, with PID 0 and that reason; the local file keeps their +sanitized properties, including remote endpoints, while telemetry drops them. Per-event TDH failures use closed diagnostic reasons: `eventPayloadMalformed` means the payload conflicts with its declared schema, @@ -318,8 +322,9 @@ 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 field. Free-form decoder errors are never serialized. `schemaUnavailable` means the event schema could not be -obtained. Analysis continues but sets `deniedResourcesTruncated`, except for -network decisions, because the event may have been a denial. Schema failures +obtained. Analysis continues but sets `deniedResourcesTruncated` because the +unreadable event may have been a denial; network decisions are not denials, so +they do not. Schema failures remain fatal for raw decoding and for scoping brokered capability events in guarded traces. diff --git a/src/mxc-sdk/src/core/learning_mode_core/verbose_logging.rs b/src/mxc-sdk/src/core/learning_mode_core/verbose_logging.rs index 78c10bfec..1ce41ef6d 100644 --- a/src/mxc-sdk/src/core/learning_mode_core/verbose_logging.rs +++ b/src/mxc-sdk/src/core/learning_mode_core/verbose_logging.rs @@ -530,10 +530,10 @@ mod tests { #[test] fn schema_name_is_optional_and_separate_from_payload() { let old = serde_json::json!({ - "provider": "kernelGeneral", + "provider": "learningModeNetworkDecision", "providerGuid": "provider", "eventId": 0, - "reason": "unsupportedEventSchema", + "reason": "schemaUnavailable", "pid": 42, "properties": [["EventName", "payload-name"]] }); @@ -545,6 +545,8 @@ mod tests { .is_none()); signature.event_name = Some("schema-name".into()); let json = serde_json::to_value(&signature).unwrap(); + assert_eq!(json["provider"], "learningModeNetworkDecision"); + assert_eq!(json["reason"], "schemaUnavailable"); assert_eq!(json["eventName"], "schema-name"); assert_eq!(json["properties"][0][1], "payload-name"); assert_eq!( diff --git a/src/mxc-sdk/src/core/learning_mode_windows/etl_decode.rs b/src/mxc-sdk/src/core/learning_mode_windows/etl_decode.rs index de16b899f..90e7dfeed 100644 --- a/src/mxc-sdk/src/core/learning_mode_windows/etl_decode.rs +++ b/src/mxc-sdk/src/core/learning_mode_windows/etl_decode.rs @@ -40,7 +40,7 @@ use windows::Win32::System::Diagnostics::Etw::{ }; use crate::learning_mode_windows::extractors::{ - extract_denial, is_learning_mode_event, DecodedEventParts, RawDenial, NETWORK_DECISION_PROVIDER, + extract_denial, is_learning_mode_event, is_process_scoped_event, DecodedEventParts, RawDenial, }; use crate::learning_mode_windows::process_lifetime::{ attested_process_lifetimes, JobMembershipSnapshot, @@ -231,6 +231,14 @@ impl<'visitor> Accumulator<'visitor> { } } + fn selects(&self, provider: windows::core::GUID, event_id: u16) -> bool { + if self.process_lifetimes.is_some() { + is_process_scoped_event(provider, event_id) + } else { + is_learning_mode_event(provider, event_id) + } + } + fn add_raw_denial(&mut self, raw: RawDenial, event_name: Option<&str>) { if !self.event_in_scope(raw.pid, raw.filetime) { return; @@ -440,10 +448,10 @@ impl<'visitor> Accumulator<'visitor> { if !is_learning_mode_event(provider, event_id) { return; } - let pid = if provider == NETWORK_DECISION_PROVIDER { - 0 - } else { + let pid = if is_process_scoped_event(provider, event_id) { pid + } else { + 0 }; let reason = match error.event_kind() { Some(tdh_decode::EventDecodeKind::PayloadMalformed) => { @@ -458,7 +466,7 @@ impl<'visitor> Accumulator<'visitor> { None => VerboseLoggingOutcomeReason::SchemaUnavailable, }; if reason == VerboseLoggingOutcomeReason::SchemaUnavailable - && provider != NETWORK_DECISION_PROVIDER + && is_process_scoped_event(provider, event_id) { self.truncated = true; } @@ -494,6 +502,11 @@ impl<'visitor> Accumulator<'visitor> { if let Some(error) = self.decode_error { return Err(AnalyzeError::Decode(error)); } + if self.skip_relog_header { + return Err(AnalyzeError::Decode( + "relogged trace has no transport header".into(), + )); + } let mut result = AnalysisResult { denials: self.denials, denied_resources_truncated: self.truncated, @@ -570,11 +583,6 @@ impl EtlDenialAnalyzer { let mut accumulator = Accumulator::analyze_for_process_lifetimes(lifetimes); accumulator.skip_relog_header = true; process_trace_file(source_path, &mut accumulator)?; - if accumulator.skip_relog_header { - return Err(AnalyzeError::Decode( - "relogged trace has no transport header".into(), - )); - } accumulator.into_analysis() } } @@ -738,9 +746,10 @@ fn process_trace_file( // ERROR_SUCCESS (0) is end-of-file. ERROR_CANCELLED (1223) is expected // when our buffer callback stops after a processing bound or fatal error. - if status.0 != 0 - && !(status.0 == 1223 && (accumulator.stop_requested || accumulator.decode_error.is_some())) - { + if !process_trace_succeeded( + status.0, + accumulator.stop_requested || accumulator.decode_error.is_some(), + ) { return Err(AnalyzeError::Decode(format!( "ProcessTrace failed for '{}': Win32 error {}", source_path.display(), @@ -751,6 +760,10 @@ fn process_trace_file( Ok(()) } +fn process_trace_succeeded(status: u32, cancelled_by_callback: bool) -> bool { + status == 0 || (status == 1223 && cancelled_by_callback) +} + /// ETW record callback, invoked by `ProcessTrace` for every event in the /// file. Decodes the event via TDH and appends it to the [`Accumulator`] /// pointed to by `EVENT_RECORD.UserContext`. @@ -825,6 +838,9 @@ unsafe fn process_event_record(event_record: *mut EVENT_RECORD, acc: &mut Accumu } if matches!(acc.mode, CollectionMode::SelectForRelogging) { + if !acc.selects(provider, event_id) { + return; + } let event_index = acc.relog_event_count; let Some(next_event_count) = acc.relog_event_count.checked_add(1) else { acc.decode_error = @@ -833,9 +849,6 @@ unsafe fn process_event_record(event_record: *mut EVENT_RECORD, acc: &mut Accumu return; }; acc.relog_event_count = next_event_count; - if !is_learning_mode_event(provider, event_id) || provider == NETWORK_DECISION_PROVIDER { - return; - } let Some(filetime) = normalized_filetime(header.TimeStamp, acc) else { return; }; @@ -859,9 +872,7 @@ unsafe fn process_event_record(event_record: *mut EVENT_RECORD, acc: &mut Accumu let mut analyze_filetime = None; if matches!(acc.mode, CollectionMode::Analyze) { - if !is_learning_mode_event(provider, event_id) - || (provider == NETWORK_DECISION_PROVIDER && acc.process_lifetimes.is_some()) - { + if !acc.selects(provider, event_id) { return; } let Some(filetime) = normalized_filetime(header.TimeStamp, acc) else { @@ -894,7 +905,11 @@ unsafe fn process_event_record(event_record: *mut EVENT_RECORD, acc: &mut Accumu let pid = if event_id == crate::learning_mode_windows::extractors::CAPABILITY_DENIAL_EVENT_ID { - let process_id = if matches!(&error, tdh_decode::DecodeError::Schema(_)) { + let process_id = if matches!( + &error, + tdh_decode::DecodeError::Schema(_) + | tdh_decode::DecodeError::SchemaNotFound + ) { acc.truncated = true; None } else { @@ -956,7 +971,7 @@ fn select_capability_decode_result_for_relogging( header_pid, filetime, ), - Err(tdh_decode::DecodeError::Schema(_)) => { + Err(tdh_decode::DecodeError::Schema(_) | tdh_decode::DecodeError::SchemaNotFound) => { acc.decode_error = Some("could not scope brokered capability event: schema unavailable".into()); acc.stop_requested = true; @@ -1019,9 +1034,7 @@ fn handle_decoded_event( filetime: u64, acc: &mut Accumulator<'_>, ) { - if !is_learning_mode_event(parts.provider, parts.event_id) - || (parts.provider == NETWORK_DECISION_PROVIDER && acc.process_lifetimes.is_some()) - { + if !acc.selects(parts.provider, parts.event_id) { return; } let event = (parts.event_id, parts.event_name.as_deref()); @@ -1511,7 +1524,7 @@ mod tests { } #[test] - fn relog_selection_tracks_all_provider_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, @@ -1582,11 +1595,42 @@ mod tests { 150, ); - assert_eq!(accumulator.relog_event_count, 11); + assert_eq!(accumulator.relog_event_count, 3); assert_eq!(accumulator.relog_selected_event_indices, [0]); assert!(accumulator.decode_error.is_none()); } + #[test] + fn relogged_analysis_requires_a_valid_transport_header() { + for (provider, event_id, valid) in [ + (EventTraceGuid, 0, true), + ( + crate::learning_mode_windows::extractors::KERNEL_GENERAL_PROVIDER, + 14, + false, + ), + ] { + let mut accumulator = Accumulator::analyze_for_process_lifetimes(&[]); + accumulator.skip_relog_header = true; + let mut record = EVENT_RECORD::default(); + record.EventHeader.ProviderId = provider; + record.EventHeader.EventDescriptor.Id = event_id; + unsafe { process_event_record(&mut record, &mut accumulator) }; + assert_eq!(accumulator.into_analysis().is_ok(), valid); + } + let mut absent = Accumulator::analyze_for_process_lifetimes(&[]); + absent.skip_relog_header = true; + assert!(absent.into_analysis().is_err()); + } + + #[test] + fn process_trace_cancellation_succeeds_only_when_requested() { + assert!(process_trace_succeeded(0, false)); + assert!(process_trace_succeeded(1223, true)); + assert!(!process_trace_succeeded(1223, false)); + assert!(!process_trace_succeeded(5, true)); + } + #[test] fn relog_selection_scopes_brokered_capability_events_by_payload_pid() { let mut accumulator = Accumulator::select_for_relogging(&[ProcessLifetime { @@ -1716,7 +1760,8 @@ mod tests { unsafe { tdh_decode::decode_event_parts(&mut record, &mut accumulator.schema_cache) }, - Err(tdh_decode::DecodeError::Schema(_)) + Err(tdh_decode::DecodeError::Schema(_) + | tdh_decode::DecodeError::SchemaNotFound) )); } let schema_loads = accumulator.schema_cache.schema_loads; @@ -1898,7 +1943,12 @@ mod tests { (privacy, 14, true, true), (privacy, 27, true, true), (privacy, 4907, true, true), - (NETWORK_DECISION_PROVIDER, 1, true, false), + ( + crate::learning_mode_windows::extractors::NETWORK_DECISION_PROVIDER, + 1, + true, + false, + ), (kernel, 999, false, false), (privacy, 28, false, false), (windows::core::GUID::from_u128(1), 14, false, false), diff --git a/src/mxc-sdk/src/core/learning_mode_windows/etl_filter.rs b/src/mxc-sdk/src/core/learning_mode_windows/etl_filter.rs index aacff3753..157f337fc 100644 --- a/src/mxc-sdk/src/core/learning_mode_windows/etl_filter.rs +++ b/src/mxc-sdk/src/core/learning_mode_windows/etl_filter.rs @@ -1,6 +1,8 @@ // Copyright (c) Microsoft Corporation. // Licensed under the MIT License. +//! Process-scoped ETL rewriting for guarded WPR captures. + use std::collections::HashSet; use std::os::windows::ffi::OsStrExt; use std::path::Path; @@ -17,7 +19,7 @@ use windows::Win32::System::Diagnostics::Etw::{ }; use crate::learning_mode_windows::etl_decode::select_learning_mode_events_for_relogging; -use crate::learning_mode_windows::extractors::{is_learning_mode_event, NETWORK_DECISION_PROVIDER}; +use crate::learning_mode_windows::extractors::is_process_scoped_event; use crate::learning_mode_windows::process_lifetime::{ attested_process_lifetimes, JobMembershipSnapshot, }; @@ -90,16 +92,19 @@ impl RelogSelectionState { } } - fn observe_event(&self, pid: Option) -> 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) { return false; } - let Some(pid) = pid else { - return false; - }; + // The first ProcessTrace pass selected this ordinal using exact PID and + // 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-event index on mismatch: the final count reconciliation then + // fails closed and the partial destination is deleted. if self.selected_event_pids.get(selected_index) != Some(&pid) || !self.attested_pids.contains(&pid) { @@ -127,7 +132,6 @@ impl ITraceEventCallback_Impl for ProcessScopedTraceFilter_Impl { ) -> windows::core::Result<()> { let header_event = header_event.ok()?; let relogger = relogger.ok()?; - self.selection.observe_event(None); // SAFETY: both interfaces are valid for this synchronous callback. // The trace header is required for a standalone output ETL. unsafe { relogger.Inject(header_event)? }; @@ -154,11 +158,11 @@ impl ITraceEventCallback_Impl for ProcessScopedTraceFilter_Impl { )); }; let header = &record.EventHeader; - let selectable = is_learning_mode_event(header.ProviderId, header.EventDescriptor.Id) - && header.ProviderId != NETWORK_DECISION_PROVIDER; - let is_supported_capability_event = selectable - && header.EventDescriptor.Id - == crate::learning_mode_windows::extractors::CAPABILITY_DENIAL_EVENT_ID; + if !is_process_scoped_event(header.ProviderId, header.EventDescriptor.Id) { + return Ok(()); + } + let is_supported_capability_event = header.EventDescriptor.Id + == crate::learning_mode_windows::extractors::CAPABILITY_DENIAL_EVENT_ID; let effective_pid = if is_supported_capability_event { let payload_pid = self .schema_cache @@ -182,10 +186,7 @@ impl ITraceEventCallback_Impl for ProcessScopedTraceFilter_Impl { } else { header.ProcessId }; - if self - .selection - .observe_event(selectable.then_some(effective_pid)) - { + 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)? }; @@ -323,7 +324,7 @@ fn relog_trace_with( 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} 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(); @@ -367,43 +368,38 @@ fn windows_error(operation: &str, error: windows::core::Error) -> AnalyzeError { mod tests { use super::*; - #[test] - fn private_trace_relogging_excludes_unrelated_events_but_raw_decoding_preserves_them() { + fn record_private_trace( + path: &Path, + provider: &tracelogging::Provider, + guid: windows::core::GUID, + emit: impl FnOnce() -> Vec, + ) { use windows::core::PCWSTR; use windows::Win32::System::Diagnostics::Etw::{ ControlTraceW, EnableTraceEx2, StartTraceW, CONTROLTRACE_HANDLE, EVENT_TRACE_CONTROL_STOP, EVENT_TRACE_PRIVATE_IN_PROC, EVENT_TRACE_PRIVATE_LOGGER_MODE, EVENT_TRACE_PROPERTIES, WNODE_FLAG_TRACED_GUID, }; - tracelogging::define_provider!( - TEST_PROVIDER, - "MxcTest.Redaction", - id("a93bc25e-f2de-485a-90e7-a2d8970b22a9") - ); + static PRIVATE_TRACE: Mutex<()> = Mutex::new(()); + let _guard = PRIVATE_TRACE + .lock() + .unwrap_or_else(std::sync::PoisonError::into_inner); - let directory = tempfile::tempdir().unwrap(); - let source = directory.path().join("source.etl"); - let destination = directory.path().join("scoped.etl"); - let provider = windows::core::GUID::from_u128(0xa93bc25e_f2de_485a_90e7_a2d8970b22a9); let name = format!("mxc-verbose-test-{}", std::process::id()) .encode_utf16() .chain([0]) .collect::>(); - let path = source + let path = path .as_os_str() .encode_wide() .chain([0]) .collect::>(); - let mut locations = 2u16.to_le_bytes().to_vec(); - for value in [r"C:\Users\alice\secret.txt", r"D:\private.txt"] { - locations.extend(value.encode_utf16().chain([0]).flat_map(u16::to_le_bytes)); - } let mut storage = vec![0u64; 512]; let properties = storage.as_mut_ptr().cast::(); let mut session = CONTROLTRACE_HANDLE::default(); unsafe { (*properties).Wnode.BufferSize = (storage.len() * 8) as u32; - (*properties).Wnode.Guid = provider; + (*properties).Wnode.Guid = guid; (*properties).Wnode.Flags = WNODE_FLAG_TRACED_GUID; (*properties).Wnode.ClientContext = 1; (*properties).BufferSize = 64; @@ -422,13 +418,47 @@ mod tests { .cast::(), path.len(), ); - assert_eq!(TEST_PROVIDER.register(), 0); + assert_eq!(provider.register(), 0); let started = StartTraceW(&mut session, PCWSTR(name.as_ptr()), properties); if started.0 != 0 { - TEST_PROVIDER.unregister(); + provider.unregister(); panic!("private StartTraceW failed: {}", started.0); } - let enabled = EnableTraceEx2(session, &provider, 1, 5, u64::MAX, 0, 0, None); + let enabled = EnableTraceEx2(session, &guid, 1, 5, u64::MAX, 0, 0, None); + let emitted = emit(); + let stopped = ControlTraceW( + session, + PCWSTR(name.as_ptr()), + properties, + EVENT_TRACE_CONTROL_STOP, + ); + let unregistered = provider.unregister(); + for status in [enabled.0, stopped.0, unregistered] + .into_iter() + .chain(emitted) + { + assert_eq!(status, 0); + } + } + } + + #[test] + fn private_trace_relogging_excludes_unrelated_events_but_raw_decoding_preserves_them() { + tracelogging::define_provider!( + TEST_PROVIDER, + "MxcTest.Redaction", + id("a93bc25e-f2de-485a-90e7-a2d8970b22a9") + ); + + let directory = tempfile::tempdir().unwrap(); + let source = directory.path().join("source.etl"); + let destination = directory.path().join("scoped.etl"); + let provider = windows::core::GUID::from_u128(0xa93bc25e_f2de_485a_90e7_a2d8970b22a9); + let mut locations = 2u16.to_le_bytes().to_vec(); + for value in [r"C:\Users\alice\secret.txt", r"D:\private.txt"] { + locations.extend(value.encode_utf16().chain([0]).flat_map(u16::to_le_bytes)); + } + record_private_trace(&source, &TEST_PROVIDER, provider, || { let emit = || { [ tracelogging::write_event!( @@ -451,23 +481,8 @@ mod tests { ), ] }; - let first = emit(); - let second = emit(); - let stopped = ControlTraceW( - session, - PCWSTR(name.as_ptr()), - properties, - EVENT_TRACE_CONTROL_STOP, - ); - let unregistered = TEST_PROVIDER.unregister(); - for status in [enabled.0, stopped.0, unregistered] - .into_iter() - .chain(first) - .chain(second) - { - assert_eq!(status, 0); - } - } + emit().into_iter().chain(emit()).collect() + }); if let Some(path) = std::env::var_os("MXC_TEST_ETL_OUTPUT") { std::fs::copy(&source, path).expect("failed to retain the test ETL for CLI replay"); } @@ -527,6 +542,103 @@ mod tests { assert!(native.denials.is_empty()); } + #[test] + fn private_trace_relogging_preserves_selected_learning_mode_events() { + tracelogging::define_provider!( + LEARNING_MODE_PROVIDER, + "MxcTest.LearningMode", + id("811a1ddb-2e69-5f25-adc0-4b186170e760") + ); + + let directory = tempfile::tempdir().unwrap(); + let source = directory.path().join("source.etl"); + let destination = directory.path().join("scoped.etl"); + record_private_trace( + &source, + &LEARNING_MODE_PROVIDER, + crate::learning_mode_windows::extractors::PRIVACY_LEARNING_MODE_PROVIDER, + || { + let unrelated = || { + tracelogging::write_event!( + LEARNING_MODE_PROVIDER, + "Unrelated", + id_version(999, 0), + u32("Value", &1), + ) + }; + vec![ + unrelated(), + tracelogging::write_event!( + LEARNING_MODE_PROVIDER, + "AccessCheck", + id_version(14, 0), + cstr8("ObjectType", "File"), + cstr8("ObjectName", r"C:\selected.txt"), + u32("AccessMask", &1), + ), + unrelated(), + ] + }, + ); + let pid = std::process::id(); + let lifetimes = [ProcessLifetime { + pid, + start_filetime: 0, + end_filetime: u64::MAX, + }]; + + let selection = select_learning_mode_events_for_relogging(&source, &lifetimes).unwrap(); + assert_eq!(selection.total_event_count, 1); + assert_eq!(selection.selected_event_indices, [0]); + assert_eq!(selection.selected_event_pids, [pid]); + + let native = crate::learning_mode_windows::EtlDenialAnalyzer + .analyze_for_process_lifetimes(&source, &lifetimes) + .unwrap(); + filter_trace_for_process_lifetimes(&source, &destination, &lifetimes).unwrap(); + let guarded = crate::learning_mode_windows::EtlDenialAnalyzer + .analyze_relogged_for_process_lifetimes(&destination, &lifetimes) + .unwrap(); + assert_eq!(native.denials.len(), 1); + assert_eq!(native.denials[0].resource, r"C:\selected.txt"); + assert_eq!(native, guarded); + + struct ScriptedRelogger(Vec); + impl TraceRelogger for ScriptedRelogger { + fn process( + &self, + _source: &Path, + destination: &Path, + selection: RelogSelectionState, + ) -> Result<(), AnalyzeError> { + for pid in &self.0 { + selection.observe_known_provider_event(*pid); + } + std::fs::write(destination, b"etl").map_err(|source| AnalyzeError::Open { + path: destination.display().to_string(), + source, + }) + } + } + for (observed, reconciled) in [ + (vec![pid], true), + (vec![], false), + (vec![pid, pid], false), + (vec![pid + 1], false), + ] { + assert_eq!( + relog_trace_with( + &source, + &directory.path().join("scripted.etl"), + &lifetimes, + &ScriptedRelogger(observed), + ) + .is_ok(), + reconciled + ); + } + } + const START: u64 = 100; const END: u64 = 200; @@ -542,7 +654,7 @@ mod tests { fn selected_ordinal_with_foreign_pid_is_not_injected() { let selection = RelogSelectionState::new(vec![0], vec![42], &[lifetime(42)]); - assert!(!selection.observe_event(Some(99))); + assert!(!selection.observe_known_provider_event(99)); assert_eq!(selection.consumed_event_count(), 1); assert_eq!( selection.consumed_selected_event_count(), @@ -551,20 +663,11 @@ mod tests { ); } - #[test] - fn selected_ordinal_with_unrelated_event_is_not_injected() { - let selection = RelogSelectionState::new(vec![0], vec![42], &[lifetime(42)]); - - assert!(!selection.observe_event(None)); - assert_eq!(selection.consumed_event_count(), 1); - assert_eq!(selection.consumed_selected_event_count(), 0); - } - #[test] fn selected_ordinal_with_attested_pid_is_injected() { let selection = RelogSelectionState::new(vec![0], vec![42], &[lifetime(42)]); - assert!(selection.observe_event(Some(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/mxc-sdk/src/core/learning_mode_windows/extractors.rs b/src/mxc-sdk/src/core/learning_mode_windows/extractors.rs index 416f5ae6a..1d8b4d67c 100644 --- a/src/mxc-sdk/src/core/learning_mode_windows/extractors.rs +++ b/src/mxc-sdk/src/core/learning_mode_windows/extractors.rs @@ -234,6 +234,10 @@ pub(crate) fn is_learning_mode_event(provider: GUID, event_id: u16) -> bool { } } +pub(crate) fn is_process_scoped_event(provider: GUID, event_id: u16) -> bool { + provider != NETWORK_DECISION_PROVIDER && is_learning_mode_event(provider, event_id) +} + pub(crate) fn effective_event_pid(parts: &DecodedEventParts, header_pid: u32) -> Option { if parts.provider == NETWORK_DECISION_PROVIDER { Some(0) diff --git a/src/mxc-sdk/src/core/learning_mode_windows/tdh_decode.rs b/src/mxc-sdk/src/core/learning_mode_windows/tdh_decode.rs index 1e26a94b5..ce31c29d1 100644 --- a/src/mxc-sdk/src/core/learning_mode_windows/tdh_decode.rs +++ b/src/mxc-sdk/src/core/learning_mode_windows/tdh_decode.rs @@ -88,6 +88,24 @@ pub(crate) struct EventSchemaCache { schemas: HashMap>, #[cfg(test)] pub(crate) schema_loads: usize, + #[cfg(test)] + queued_loads: std::collections::VecDeque>, +} + +impl EventSchemaCache { + unsafe fn load( + &mut self, + event_record: *mut EVENT_RECORD, + ) -> Result { + #[cfg(test)] + { + self.schema_loads += 1; + if let Some(schema) = self.queued_loads.pop_front() { + return schema; + } + } + unsafe { load_event_schema(event_record) } + } } #[cfg(test)] @@ -103,6 +121,7 @@ impl EventSchemaCache { #[derive(Debug, Clone)] pub(crate) enum DecodeError { Schema(String), + SchemaNotFound, Event { kind: EventDecodeKind, event_name: Option, @@ -121,14 +140,14 @@ impl DecodeError { pub(crate) fn event_kind(&self) -> Option { match self { Self::Event { kind, .. } => Some(*kind), - Self::Schema(_) => None, + Self::Schema(_) | Self::SchemaNotFound => None, } } pub(crate) fn event_name(&self) -> Option<&str> { match self { Self::Event { event_name, .. } => event_name.as_deref(), - Self::Schema(_) => None, + Self::Schema(_) | Self::SchemaNotFound => None, } } @@ -149,6 +168,7 @@ 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::SchemaNotFound => f.write_str("event schema not found"), } } } @@ -258,11 +278,7 @@ unsafe fn event_schema<'a>( let key = EventSchemaKey::from_record(event); let cacheable = !unsafe { has_trace_logging_schema(event) }; if !cacheable || !schema_cache.schemas.contains_key(&key) { - #[cfg(test)] - { - schema_cache.schema_loads += 1; - } - let schema = unsafe { load_event_schema(event_record) }; + let schema = unsafe { schema_cache.load(event_record) }; if cacheable { cache_or_retain_schema(schema_cache, key, schema, uncached_schema); } else { @@ -278,7 +294,12 @@ fn cache_or_retain_schema( schema: Result, uncached_schema: &mut Option>, ) { - if schema_cache.schemas.len() < MAX_SCHEMA_CACHE_ENTRIES { + let limit = match &schema { + Ok(_) => MAX_SCHEMA_CACHE_ENTRIES, + Err(DecodeError::SchemaNotFound) => MAX_SCHEMA_CACHE_ENTRIES / 2, + Err(_) => 0, + }; + if schema_cache.schemas.len() < limit { schema_cache.schemas.insert(key, schema); } else { *uncached_schema = Some(schema); @@ -331,10 +352,14 @@ unsafe fn load_event_schema(event_record: *mut EVENT_RECORD) -> Result {} + 1168 => return Err(DecodeError::SchemaNotFound), + _ => { + return Err(DecodeError::Schema(format!( + "TdhGetEventInformation(size) failed with Win32 error {status}" + ))) + } } let mut buffer = TdhInfoBuffer::new(buf_size as usize); @@ -1079,11 +1104,11 @@ mod tests { for _ in 0..3 { assert!(matches!( unsafe { decode_event_parts(&mut record, &mut cache) }, - Err(DecodeError::Schema(_)) + Err(DecodeError::SchemaNotFound) )); assert!(matches!( unsafe { decode_event_property(&mut record, &mut cache, "ProcessId") }, - Err(DecodeError::Schema(_)) + Err(DecodeError::SchemaNotFound) )); } @@ -1092,39 +1117,58 @@ mod tests { } #[test] - fn successful_and_missing_schemas_share_cache_capacity() { + fn transient_schema_failures_are_retried() { 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; - let key = EventSchemaKey::from_record(&record); - let schema = if id % 2 == 0 { - Ok(TdhInfoBuffer::new(1)) - } else { - Err(DecodeError::Schema("missing schema".into())) - }; - cache_or_retain_schema(&mut cache, key, schema, &mut uncached); - assert!(uncached.is_none()); - assert_eq!(schema_buffer(&cache, &key, &uncached).is_ok(), id % 2 == 0); - } + cache.queued_loads.extend([ + Err(DecodeError::Schema("transient".into())), + Ok(uint32_property_buffer(&["ProcessId"])), + ]); + let mut record = EVENT_RECORD::default(); + let payload = 42u32.to_le_bytes(); + record.UserData = payload.as_ptr().cast_mut().cast(); + record.UserDataLength = payload.len() as u16; - 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); - for schema in [ - Ok(TdhInfoBuffer::new(std::mem::size_of::())), - Err(DecodeError::Schema("missing schema".into())), - ] { - let success = schema.is_ok(); + assert!(matches!( + unsafe { decode_event_property(&mut record, &mut cache, "ProcessId") }, + Err(DecodeError::Schema(_)) + )); + assert!( + unsafe { decode_event_property(&mut record, &mut cache, "ProcessId") } + .unwrap() + .is_some() + ); + assert_eq!(cache.schema_loads, 2); + } + + #[test] + fn missing_schemas_leave_room_for_successful_schemas() { + let mut cache = EventSchemaCache::default(); + let key = |id: usize| { + let mut record = EVENT_RECORD::default(); + record.EventHeader.EventDescriptor.Id = id as u16; + EventSchemaKey::from_record(&record) + }; + let mut cache_result = |id, schema| { let mut uncached = None; - cache_or_retain_schema(&mut cache, overflow_key, schema, &mut uncached); + cache_or_retain_schema(&mut cache, key(id), schema, &mut uncached); + uncached.is_none() + }; + let half = MAX_SCHEMA_CACHE_ENTRIES / 2; - assert_eq!(cache.schemas.len(), MAX_SCHEMA_CACHE_ENTRIES); - assert!(!cache.schemas.contains_key(&overflow_key)); + assert!(!cache_result( + 0, + Err(DecodeError::Schema("transient".into())) + )); + for id in 0..=half { assert_eq!( - schema_buffer(&cache, &overflow_key, &uncached).is_ok(), - success + cache_result(id, Err(DecodeError::SchemaNotFound)), + id < half + ); + } + for id in half + 1..=MAX_SCHEMA_CACHE_ENTRIES + 1 { + assert_eq!( + cache_result(id, Ok(TdhInfoBuffer::new(1))), + id <= MAX_SCHEMA_CACHE_ENTRIES ); } } @@ -1532,12 +1576,17 @@ mod tests { #[test] fn trace_logging_schema_failures_are_not_cached() { let mut cache = EventSchemaCache::default(); + cache.queued_loads.extend([ + Err(DecodeError::SchemaNotFound), + Err(DecodeError::SchemaNotFound), + Err(DecodeError::SchemaNotFound), + ]); let mut record = EVENT_RECORD::default(); record.EventHeader.ProviderId = GUID::from_u128(1); record.EventHeader.EventDescriptor.Channel = 11; assert!(matches!( unsafe { decode_event_parts(&mut record, &mut cache) }, - Err(DecodeError::Schema(_)) + Err(DecodeError::SchemaNotFound) )); let metadata = [0_u8; 4]; @@ -1555,7 +1604,7 @@ mod tests { for _ in 0..2 { assert!(matches!( unsafe { decode_event_parts(&mut record, &mut cache) }, - Err(DecodeError::Schema(_)) + Err(DecodeError::SchemaNotFound) )); } assert_eq!(cache.schema_loads, 3);