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 7b16eccf6..3173c4958 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`, @@ -237,7 +238,7 @@ policy denial occurrences plus diagnostic outcomes omitted from the policy file: ```json { - "version": 3, + "version": 4, "signatures": [ { "signature": { @@ -268,8 +269,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 ``. @@ -311,18 +312,25 @@ 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. `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 is malformed or 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` 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. To keep diagnostics bounded, verbose logging retains at most 4,096 distinct signatures, 24 sorted properties per signature, and 256 characters per property diff --git a/src/mxc-sdk/src/backends/process_container/common/capture_output.rs b/src/mxc-sdk/src/backends/process_container/common/capture_output.rs index 5e5be87d3..909dab7c0 100644 --- a/src/mxc-sdk/src/backends/process_container/common/capture_output.rs +++ b/src/mxc-sdk/src/backends/process_container/common/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/mxc-sdk/src/core/learning_mode_core/analyze.rs b/src/mxc-sdk/src/core/learning_mode_core/analyze.rs index 3747e63c1..47a9a04cc 100644 --- a/src/mxc-sdk/src/core/learning_mode_core/analyze.rs +++ b/src/mxc-sdk/src/core/learning_mode_core/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, @@ -429,6 +432,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/mxc-sdk/src/core/learning_mode_core/verbose_logging.rs b/src/mxc-sdk/src/core/learning_mode_core/verbose_logging.rs index d0f28ff18..eaf366681 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 @@ -25,6 +25,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. @@ -35,6 +37,8 @@ pub enum VerboseLoggingOutcomeReason { Actionable, /// The provider is known, but the event ID is not a supported denial schema. UnsupportedEventSchema, + /// TDH could not resolve the event schema. + SchemaUnavailable, /// The event payload was malformed or conflicted with its declared TDH schema. EventPayloadMalformed, /// A decoder safety bound prevented full payload processing. @@ -77,6 +81,9 @@ pub struct VerboseLoggingSignature { pub provider_guid: String, /// Provider-scoped ETW schema identifier. pub event_id: u16, + /// Sanitized schema name. + #[serde(default, skip_serializing_if = "Option::is_none")] + pub event_name: Option, /// Closed exclusion category. pub reason: VerboseLoggingOutcomeReason, /// Process identifier from the event header. @@ -307,7 +314,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] @@ -375,6 +382,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, @@ -411,6 +419,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, @@ -422,6 +431,7 @@ mod tests { } summary.record(VerboseLoggingSignature { provider: VerboseLoggingProvider::PrivacyAuditingPermissiveLearningMode, + event_name: None, provider_guid: "privacy".to_string(), event_id: u16::MAX, reason: VerboseLoggingOutcomeReason::UnsupportedEventSchema, @@ -443,6 +453,7 @@ mod tests { summary.record(VerboseLoggingSignature { provider: VerboseLoggingProvider::KernelGeneral, provider_guid: "kernel".to_string(), + event_name: None, event_id, reason: VerboseLoggingOutcomeReason::UnsupportedEventSchema, pid: 1, @@ -456,6 +467,7 @@ mod tests { provider_guid: "kernel".to_string(), event_id: u16::MAX, reason: VerboseLoggingOutcomeReason::Actionable, + event_name: None, pid: 1, access_type: Some(crate::learning_mode_core::AccessType::Read), resource_type: Some(crate::learning_mode_core::ResourceType::File), @@ -510,6 +522,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, @@ -548,6 +561,34 @@ mod tests { assert_eq!(parsed, document); } + #[test] + fn schema_name_is_optional_and_separate_from_payload() { + let old = serde_json::json!({ + "provider": "learningModeNetworkDecision", + "providerGuid": "provider", + "eventId": 0, + "reason": "schemaUnavailable", + "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["provider"], "learningModeNetworkDecision"); + assert_eq!(json["reason"], "schemaUnavailable"); + 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(); @@ -555,6 +596,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::learning_mode_core::AccessType::Read), @@ -565,7 +607,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/mxc-sdk/src/core/learning_mode_windows/capability_dacl.rs b/src/mxc-sdk/src/core/learning_mode_windows/capability_dacl.rs index 5322e537a..085dd4791 100644 --- a/src/mxc-sdk/src/core/learning_mode_windows/capability_dacl.rs +++ b/src/mxc-sdk/src/core/learning_mode_windows/capability_dacl.rs @@ -676,6 +676,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()), @@ -854,6 +855,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/mxc-sdk/src/core/learning_mode_windows/etl_decode.rs b/src/mxc-sdk/src/core/learning_mode_windows/etl_decode.rs index a7df1aae0..43fa86493 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,12 +35,12 @@ 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, }; use crate::learning_mode_windows::extractors::{ - extract_denial, is_learning_mode_event, DecodedEventParts, RawDenial, + extract_denial, is_learning_mode_event, is_process_scoped_event, DecodedEventParts, RawDenial, }; use crate::learning_mode_windows::process_lifetime::{ attested_process_lifetimes, JobMembershipSnapshot, @@ -148,6 +148,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> { @@ -171,6 +172,7 @@ impl<'visitor> Accumulator<'visitor> { schema_cache: tdh_decode::EventSchemaCache::default(), verbose_logging: VerboseLoggingSummary::default(), verbose_logging_signature_bytes: 0, + skip_relog_header: false, } } @@ -201,6 +203,7 @@ impl<'visitor> Accumulator<'visitor> { schema_cache: tdh_decode::EventSchemaCache::default(), verbose_logging: VerboseLoggingSummary::default(), verbose_logging_signature_bytes: 0, + skip_relog_header: false, } } @@ -224,10 +227,19 @@ 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 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; } @@ -239,6 +251,7 @@ impl<'visitor> Accumulator<'visitor> { &raw, &candidate, VerboseLoggingOutcomeReason::UnusableResourcePath, + event_name, ); return; } @@ -251,6 +264,7 @@ impl<'visitor> Accumulator<'visitor> { &raw, &candidate, VerboseLoggingOutcomeReason::UnusableResourcePath, + event_name, ); return; } @@ -258,7 +272,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 { crate::learning_mode_core::ResourceType::File | crate::learning_mode_core::ResourceType::Other => resource.to_ascii_lowercase(), @@ -298,6 +317,7 @@ impl<'visitor> Accumulator<'visitor> { raw: &RawDenial, resource: &str, reason: VerboseLoggingOutcomeReason, + event_name: Option<&str>, ) { let mut properties = raw .verbose_logging_properties @@ -337,7 +357,7 @@ impl<'visitor> Accumulator<'visitor> { ); self.record_outcome( raw.provider, - raw.event_id, + (raw.event_id, event_name), reason, raw.pid, (Some(raw.access_type), Some(raw.resource_type)), @@ -345,25 +365,10 @@ 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`. - fn record_exclusion( - &mut self, - provider: VerboseLoggingProvider, - event_id: u16, - reason: VerboseLoggingOutcomeReason, - pid: u32, - properties: Vec<(String, String)>, - ) { - self.record_outcome(provider, event_id, reason, pid, (None, None), properties); - } - fn record_outcome( &mut self, provider: VerboseLoggingProvider, - event_id: u16, + event: (u16, Option<&str>), reason: VerboseLoggingOutcomeReason, pid: u32, classification: ( @@ -378,7 +383,8 @@ impl<'visitor> Accumulator<'visitor> { provider_guid: crate::learning_mode_windows::extractors::verbose_logging_provider_guid( provider, ), - event_id, + event_id: event.0, + event_name: crate::learning_mode_windows::extractors::sanitize_event_name(event.1), reason, pid, access_type, @@ -424,14 +430,6 @@ impl<'visitor> Accumulator<'visitor> { } /// Handles a TDH decode failure for one event. - /// - /// Schema-level failures (the event's manifest itself could not be - /// resolved) are fatal in every mode: they indicate the trace/schema - /// state is unreliable beyond this single event. Per-event decode - /// failures are fatal only for the raw diagnostic visitor (which needs - /// every event to succeed); in [`CollectionMode::Analyze`] they are - /// aggregated into the verbose logging summary for a known provider instead of - /// silently dropped. fn record_event_decode_error( &mut self, provider: windows::core::GUID, @@ -439,7 +437,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 = @@ -447,28 +445,35 @@ impl<'visitor> Accumulator<'visitor> { } return; } + if !is_learning_mode_event(provider, event_id) { + return; + } + let pid = if is_process_scoped_event(provider, event_id) { + pid + } else { + 0 + }; + 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_process_scoped_event(provider, event_id) + { + self.truncated = true; + } + let event = (event_id, error.event_name()); if let Some(category) = crate::learning_mode_windows::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::learning_mode_windows::extractors::bound_properties) - .unwrap_or_default(); let classification = match event_id { crate::learning_mode_windows::extractors::LEARNING_MODE_VIOLATION_EVENT_ID => ( Some(crate::learning_mode_core::AccessType::Unknown), @@ -489,7 +494,7 @@ 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()); } } @@ -497,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, @@ -555,6 +565,26 @@ impl EtlDenialAnalyzer { let process_lifetimes = attested_process_lifetimes(membership)?; self.analyze_for_process_lifetimes(source_path, &process_lifetimes) } + + 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)?; + accumulator.into_analysis() + } } impl DenialAnalyzer for EtlDenialAnalyzer { @@ -654,7 +684,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() @@ -716,7 +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 { + 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(), @@ -727,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`. @@ -792,10 +829,16 @@ unsafe fn process_event_record(event_record: *mut EVENT_RECORD, acc: &mut Accumu let provider = header.ProviderId; let event_id = header.EventDescriptor.Id; + if acc.skip_relog_header { + acc.skip_relog_header = false; + if provider != EventTraceGuid || 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) { - if crate::learning_mode_windows::extractors::verbose_logging_provider_for_guid(provider) - .is_none() - { + if !acc.selects(provider, event_id) { return; } let event_index = acc.relog_event_count; @@ -809,9 +852,7 @@ unsafe fn process_event_record(event_record: *mut EVENT_RECORD, acc: &mut Accumu let Some(filetime) = normalized_filetime(header.TimeStamp, acc) else { return; }; - if event_id == crate::learning_mode_windows::extractors::CAPABILITY_DENIAL_EVENT_ID - && is_learning_mode_event(provider, event_id) - { + if event_id == crate::learning_mode_windows::extractors::CAPABILITY_DENIAL_EVENT_ID { let process_id = unsafe { tdh_decode::decode_event_property(event_record, &mut acc.schema_cache, "ProcessId") }; @@ -828,38 +869,19 @@ 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; all other supported events can use the - // header PID directly. let mut analyze_filetime = None; if matches!(acc.mode, CollectionMode::Analyze) { - let Some(category) = - crate::learning_mode_windows::extractors::verbose_logging_provider_for_guid(provider) - else { - // Unrelated provider: unrelated host traffic, ignored entirely - // (not aggregated as an excluded Learning Mode outcome). + if !acc.selects(provider, event_id) { 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::learning_mode_windows::extractors::CAPABILITY_DENIAL_EVENT_ID; + if !brokered && !acc.event_in_scope(header.ProcessId, filetime) { return; } } @@ -879,23 +901,28 @@ 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::learning_mode_windows::extractors::CAPABILITY_DENIAL_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(_) + | tdh_decode::DecodeError::SchemaNotFound + ) { + 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, @@ -944,10 +971,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(_) | tdh_decode::DecodeError::SchemaNotFound) => { + acc.decode_error = + Some("could not scope brokered capability event: schema unavailable".into()); acc.stop_requested = true; } Err(_) => { @@ -1008,30 +1034,22 @@ fn handle_decoded_event( filetime: u64, acc: &mut Accumulator<'_>, ) { + if !acc.selects(parts.provider, parts.event_id) { + return; + } + let event = (parts.event_id, parts.event_name.as_deref()); let Some(category) = crate::learning_mode_windows::extractors::verbose_logging_provider_for_guid(parts.provider) else { return; }; - if !is_learning_mode_event(parts.provider, parts.event_id) { - if acc.event_in_scope(header_pid, filetime) && acc.begin_event() { - acc.record_exclusion( - category, - parts.event_id, - VerboseLoggingOutcomeReason::UnsupportedEventSchema, - header_pid, - crate::learning_mode_windows::extractors::sanitize_properties(&parts.props), - ); - } - return; - } let Some(pid) = crate::learning_mode_windows::extractors::effective_event_pid(parts, header_pid) else { if acc.event_in_scope(header_pid, filetime) && acc.begin_event() { acc.record_outcome( category, - parts.event_id, + event, VerboseLoggingOutcomeReason::EventPayloadMalformed, header_pid, crate::learning_mode_windows::extractors::verbose_logging_classification(parts), @@ -1053,18 +1071,18 @@ fn handle_decoded_event( let capability_candidates = crate::learning_mode_windows::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::learning_mode_windows::extractors::verbose_logging_classification(parts), @@ -1099,6 +1117,371 @@ 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::learning_mode_windows::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::learning_mode_windows::extractors::KERNEL_GENERAL_PROVIDER; + let privacy = crate::learning_mode_windows::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::learning_mode_windows::extractors::KERNEL_GENERAL_PROVIDER, + 14, + ), + ( + crate::learning_mode_windows::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, event_id, names) in [ + ( + crate::learning_mode_windows::extractors::KERNEL_GENERAL_PROVIDER, + 14, + Some(vec!["ObjectType"]), + ), + ( + crate::learning_mode_windows::extractors::PRIVACY_LEARNING_MODE_PROVIDER, + 4907, + Some(vec!["ObjectType"]), + ), + ( + crate::learning_mode_windows::extractors::KERNEL_GENERAL_PROVIDER, + 27, + Some(vec!["First", "Missing"]), + ), + ( + crate::learning_mode_windows::extractors::KERNEL_GENERAL_PROVIDER, + 28, + None, + ), + ] { + for time in [100, 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 = 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::UnsupportedObjectType + }) + .collect::>(); + assert_eq!(decoded.len(), 2); + assert!(decoded + .iter() + .all(|group| property(&group.signature, "ObjectType") == "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::KernelGeneral + ); + } + assert!(analysis.denials.is_empty()); + } + + #[test] + fn unknown_resource_dedup_preserves_provider_identity_and_process_scope() { + let properties = [ + ("ObjectType", "FutureObject"), + ("ObjectName", "future-resource"), + ("ProcessId", "99"), + ]; + let first = crate::learning_mode_windows::extractors::KERNEL_GENERAL_PROVIDER; + let second = crate::learning_mode_windows::extractors::PRIVACY_LEARNING_MODE_PROVIDER; + let events = [ + 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, + 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::learning_mode_windows::extractors::format_guid_braced_uppercase(first) + && group.signature.reason == VerboseLoggingOutcomeReason::UnsupportedObjectType + }) + .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(); + crate::learning_mode_core::write_document( + &mut bytes, + &crate::learning_mode_core::DenialsDocument::new( + denials, + crate::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(&[ @@ -1185,12 +1568,69 @@ mod tests { 43, 150, ); + visit( + windows::core::GUID::from_u128(0x2cb15d1d_5fc1_11d2_abe1_00a0c911f518), + 0, + 42, + 150, + ); + visit(EventTraceGuid, 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, 4); - assert_eq!(accumulator.relog_selected_event_indices, [0, 2]); + 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 { @@ -1238,6 +1678,7 @@ mod tests { }]); let parts = DecodedEventParts { provider: crate::learning_mode_windows::extractors::KERNEL_GENERAL_PROVIDER, + event_name: None, event_id: crate::learning_mode_windows::extractors::CAPABILITY_DENIAL_EVENT_ID, props: Vec::new(), }; @@ -1277,29 +1718,107 @@ 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::learning_mode_windows::extractors::KERNEL_GENERAL_PROVIDER, + 28, + true, + ), + ( + crate::learning_mode_windows::extractors::KERNEL_GENERAL_PROVIDER, + 14, + false, + ), + ( + crate::learning_mode_windows::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 { + 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) + }, + Err(tdh_decode::DecodeError::Schema(_) + | tdh_decode::DecodeError::SchemaNotFound) + )); + } + 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); + 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::learning_mode_windows::extractors::KERNEL_GENERAL_PROVIDER; + record.EventHeader.EventDescriptor.Id = + crate::learning_mode_windows::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] @@ -1327,6 +1846,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(), }; @@ -1350,7 +1870,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::learning_mode_windows::extractors::KERNEL_GENERAL_PROVIDER, 14, 1, tdh_decode::DecodeError::event( @@ -1384,17 +1904,105 @@ 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), + crate::learning_mode_windows::extractors::KERNEL_GENERAL_PROVIDER, 14, 1, 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(); + crate::learning_mode_core::write_verbose_logging_document( + &mut bytes, + &crate::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::learning_mode_windows::extractors::KERNEL_GENERAL_PROVIDER; + let privacy = crate::learning_mode_windows::extractors::PRIVACY_LEARNING_MODE_PROVIDER; + 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), + ( + 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), + ] { + 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, + 1 + u64::from(retained) + ); + assert_eq!( + analysis.verbose_logging.signatures.iter().any(|group| { + group.signature.reason == VerboseLoggingOutcomeReason::SchemaUnavailable + }), + retained + ); + let mut bytes = Vec::new(); + let summary = crate::learning_mode_core::DenialSummary::new( + 0, + analysis.denials.len(), + analysis.denied_resources_truncated, + ); + crate::learning_mode_core::write_document( + &mut bytes, + &crate::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 { @@ -1545,11 +2153,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, @@ -1570,12 +2181,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!( @@ -1688,6 +2305,7 @@ mod tests { parts: DecodedEventParts { provider, event_id, + event_name: None, props: kv .iter() .map(|(k, v)| ((*k).to_string(), (*v).to_string())) @@ -2112,21 +2730,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] @@ -2185,10 +2794,6 @@ 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. #[test] fn non_actionable_events_are_dropped() { let events = vec![ @@ -2214,10 +2819,7 @@ mod tests { reason_for(28), Some(VerboseLoggingOutcomeReason::NotActionable) ); - assert_eq!( - reason_for(9999), - Some(VerboseLoggingOutcomeReason::UnsupportedEventSchema) - ); + assert_eq!(reason_for(9999), None); } #[test] @@ -2278,6 +2880,7 @@ mod tests { parts: DecodedEventParts { provider: crate::learning_mode_windows::extractors::KERNEL_GENERAL_PROVIDER, event_id: 14, + event_name: None, props: vec![ ("Mode".to_string(), "\"Permissive\"".to_string()), ("ObjectType".to_string(), format!("\"{object_type}\"")), @@ -2328,6 +2931,7 @@ mod tests { parts: DecodedEventParts { provider: crate::learning_mode_windows::extractors::KERNEL_GENERAL_PROVIDER, event_id: 14, + event_name: None, props: vec![ ("ObjectType".to_string(), "\"Section\"".to_string()), ("ObjectName".to_string(), format!("\"{object_name}\"")), @@ -2437,38 +3041,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 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_ignored_even_with_a_learning_mode_event_id() { let events = vec![event_with_provider( windows::core::GUID::from_u128(0xdead_beef), 14, @@ -2483,16 +3060,13 @@ 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!(out.verbose_logging.is_empty()); } #[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, @@ -2502,7 +3076,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)]; @@ -2524,6 +3100,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" @@ -2587,7 +3167,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, @@ -2599,6 +3179,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); @@ -2608,6 +3189,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( @@ -2646,11 +3228,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, + (14, None), VerboseLoggingOutcomeReason::Actionable, pid, + (None, None), properties.clone(), ); } @@ -2661,20 +3244,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"), @@ -2727,8 +3313,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); @@ -2738,13 +3324,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, &[ @@ -2755,7 +3341,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 @@ -2810,7 +3396,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 @@ -2826,11 +3415,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() })); } @@ -2876,4 +3461,29 @@ mod tests { None ); } + + #[test] + fn decode_failure_schema_names_are_sanitized_for_learning_mode_providers() { + for provider in [ + crate::learning_mode_windows::extractors::KERNEL_GENERAL_PROVIDER, + crate::learning_mode_windows::extractors::PRIVACY_LEARNING_MODE_PROVIDER, + ] { + let mut accumulator = Accumulator::analyze(); + accumulator.record_event_decode_error( + provider, + 14, + 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/mxc-sdk/src/core/learning_mode_windows/etl_filter.rs b/src/mxc-sdk/src/core/learning_mode_windows/etl_filter.rs index d22f75b43..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 @@ -19,9 +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, verbose_logging_provider_for_guid, -}; +use crate::learning_mode_windows::extractors::is_process_scoped_event; use crate::learning_mode_windows::process_lifetime::{ attested_process_lifetimes, JobMembershipSnapshot, }; @@ -160,12 +158,11 @@ impl ITraceEventCallback_Impl for ProcessScopedTraceFilter_Impl { )); }; let header = &record.EventHeader; - if verbose_logging_provider_for_guid(header.ProviderId).is_none() { + 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 - && is_learning_mode_event(header.ProviderId, 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 @@ -371,6 +368,277 @@ fn windows_error(operation: &str, error: windows::core::Error) -> AnalyzeError { mod tests { use super::*; + 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, + }; + static PRIVATE_TRACE: Mutex<()> = Mutex::new(()); + let _guard = PRIVATE_TRACE + .lock() + .unwrap_or_else(std::sync::PoisonError::into_inner); + + let name = format!("mxc-verbose-test-{}", std::process::id()) + .encode_utf16() + .chain([0]) + .collect::>(); + let path = path + .as_os_str() + .encode_wide() + .chain([0]) + .collect::>(); + 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 = guid; + (*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!(provider.register(), 0); + let started = StartTraceW(&mut session, PCWSTR(name.as_ptr()), properties); + if started.0 != 0 { + provider.unregister(); + panic!("private StartTraceW failed: {}", started.0); + } + 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!( + 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"), + ), + ] + }; + 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"); + } + let lifetimes = [ProcessLifetime { + pid: std::process::id(), + start_filetime: 0, + end_filetime: u64::MAX, + }]; + 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(); + let mut decoded = Vec::new(); + crate::learning_mode_windows::visit_raw_events(&source, &mut |parts| { + if parts.provider == provider { + decoded.push(parts.clone()); + } + Ok(()) + }) + .unwrap(); + assert_eq!(decoded.len(), 4); + assert_eq!( + decoded + .iter() + .map(|parts| parts.event_name.as_deref()) + .collect::>(), + [ + Some("CompositeProperties"), + Some("OtherCompositeProperties"), + Some("CompositeProperties"), + Some("OtherCompositeProperties") + ] + ); + for parts in decoded { + let properties = + crate::learning_mode_windows::extractors::sanitize_properties(&parts.props); + for name in ["CommandLine", "FutureLocations"] { + assert_eq!( + properties.iter().find(|(key, _)| key == name), + Some(&( + name.to_string(), + crate::learning_mode_windows::extractors::REDACTED_PATH.to_string() + )), + ); + } + 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, guarded); + assert!(native.verbose_logging.is_empty()); + 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; 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 08ea72e26..145e59f61 100644 --- a/src/mxc-sdk/src/core/learning_mode_windows/extractors.rs +++ b/src/mxc-sdk/src/core/learning_mode_windows/extractors.rs @@ -21,9 +21,7 @@ //! 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 [`crate::learning_mode_core::VerboseLoggingSummary`] rather than -//! silently dropped. The IDs handled today: +//! extracted. The IDs handled today: //! //! - **14 / 4907 — access check** — the primary denial event //! (`ObjectType` / `ObjectName` / `AccessMask`). `ObjectType` selects the @@ -72,6 +70,10 @@ pub(crate) const PRIVACY_LEARNING_MODE_PROVIDER: GUID = GUID { data4: [0xad, 0xc0, 0x4b, 0x18, 0x61, 0x70, 0xe7, 0x60], }; +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; @@ -90,6 +92,7 @@ pub struct DecodedEventParts { pub provider: GUID, /// Originating ETW event ID. pub event_id: u16, + 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)>, @@ -229,13 +232,21 @@ 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 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.event_id == CAPABILITY_DENIAL_EVENT_ID { + if parts.provider == NETWORK_DECISION_PROVIDER { + 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), ) @@ -264,6 +275,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) + } } } // 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, @@ -418,23 +434,49 @@ 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| com_outcome_reason(object_type).is_some()) { - return !is_guid_identifier(value); - } - if object_type.is_some_and(|object_type| object_type.eq_ignore_ascii_case("File")) { - return true; + if normalized.equals("objectname") || normalized.equals("resource") { + if object_type.is_some_and(|object_type| com_outcome_reason(object_type).is_some()) { + return !is_guid_identifier(value); + } + if object_type.is_some_and(|object_type| object_type.eq_ignore_ascii_case("File")) { + return true; + } } - crate::learning_mode_windows::path_norm::is_user_visible_absolute(value) - || looks_like_dos_device_filesystem_path(value) - || looks_like_nt_filesystem_path(value) + contains_file_path(value) +} + +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 { + 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() + || matches!(value.as_bytes()[offset - 1], b'+' | b'-' | b'.')) + { + return false; + } + crate::learning_mode_windows::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 { @@ -453,7 +495,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 { @@ -555,7 +599,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) || contains_file_path(name) { continue; } let value = raw_value.trim_matches('"'); @@ -614,6 +658,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 @@ -1063,6 +1115,7 @@ mod tests { DecodedEventParts { provider, event_id, + event_name: None, props: kv .iter() .map(|(k, v)| ((*k).to_string(), (*v).to_string())) @@ -1832,7 +1885,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, @@ -1841,6 +1900,36 @@ 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"))); + assert!(!contains_file_path(&format!( + "{}server\\pipe\\mxc", + "\\".repeat(32 * 1024) + ))); + assert!(!contains_file_path(&r"\??\Volume{".repeat(4096))); + } + #[test] fn sanitize_properties_drops_timestamp_like_properties() { let props = vec![ @@ -1926,6 +2015,82 @@ mod tests { assert_eq!(value_for("ObjectName"), Some(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 (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(&[(name.into(), value.into())]), + [(name.into(), REDACTED_PATH.into())], + "{value}", + ); + } + } + #[test] fn sanitize_properties_redacts_absolute_path_despite_non_file_object_type() { for path in [ 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 543d2b537..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 @@ -85,12 +85,43 @@ impl EventSchemaKey { #[derive(Default)] pub(crate) struct EventSchemaCache { - schemas: HashMap, + schemas: HashMap>, + #[cfg(test)] + pub(crate) schema_loads: usize, + #[cfg(test)] + queued_loads: std::collections::VecDeque>, } -#[derive(Debug)] +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)] +impl EventSchemaCache { + pub(crate) fn insert_test_schema(&mut self, record: &EVENT_RECORD, names: &[&str]) { + self.schemas.insert( + EventSchemaKey::from_record(record), + Ok(tests::uint32_property_buffer(names)), + ); + } +} + +#[derive(Debug, Clone)] pub(crate) enum DecodeError { Schema(String), + SchemaNotFound, Event { kind: EventDecodeKind, event_name: Option, @@ -106,21 +137,17 @@ 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), - 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, } } @@ -141,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"), } } } @@ -189,9 +217,6 @@ 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). -/// /// # Safety /// `event_record` must point to a valid `EVENT_RECORD` provided by the /// ETW callback; the caller must not retain references to its fields @@ -210,11 +235,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, }) } @@ -247,15 +273,17 @@ 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) { + let schema = unsafe { schema_cache.load(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) } @@ -263,10 +291,15 @@ 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 { + 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); @@ -276,15 +309,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( @@ -320,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); @@ -1005,7 +1041,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() @@ -1060,34 +1096,81 @@ 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(); - for id in 0..MAX_SCHEMA_CACHE_ENTRIES { - let mut record: EVENT_RECORD = unsafe { core::mem::zeroed() }; - record.EventHeader.EventDescriptor.Id = id as u16; - let mut uncached = None; - cache_or_retain_schema( - &mut cache, - EventSchemaKey::from_record(&record), - TdhInfoBuffer::new(1), - &mut uncached, - ); - assert!(uncached.is_none()); + let mut 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::SchemaNotFound) + )); + assert!(matches!( + unsafe { decode_event_property(&mut record, &mut cache, "ProcessId") }, + Err(DecodeError::SchemaNotFound) + )); } - let mut overflow_record: EVENT_RECORD = unsafe { core::mem::zeroed() }; - overflow_record.EventHeader.EventDescriptor.Id = MAX_SCHEMA_CACHE_ENTRIES as u16; - let overflow_key = EventSchemaKey::from_record(&overflow_record); - let mut uncached = None; - cache_or_retain_schema( - &mut cache, - overflow_key, - TdhInfoBuffer::new(std::mem::size_of::()), - &mut uncached, + assert_eq!(cache.schema_loads, 1); + assert_eq!(cache.schemas.len(), 1); + } + + #[test] + fn transient_schema_failures_are_retried() { + let mut cache = EventSchemaCache::default(); + 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; + + 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); + } - assert_eq!(cache.schemas.len(), MAX_SCHEMA_CACHE_ENTRIES); - assert!(schema_buffer(&cache, &overflow_key, &uncached).is_ok()); + #[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, key(id), schema, &mut uncached); + uncached.is_none() + }; + let half = MAX_SCHEMA_CACHE_ENTRIES / 2; + + assert!(!cache_result( + 0, + Err(DecodeError::Schema("transient".into())) + )); + for id in 0..=half { + assert_eq!( + 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 + ); + } } #[test] @@ -1491,15 +1574,41 @@ 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(); + 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::SchemaNotFound) + )); + + 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::SchemaNotFound) + )); + } + assert_eq!(cache.schema_loads, 3); + assert_eq!(cache.schemas.len(), 1); } #[test] 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 6e9ae2608..05d2ab6d5 100644 --- a/src/mxc-sdk/src/core/mxc_engine/verbose_telemetry.rs +++ b/src/mxc-sdk/src/core/mxc_engine/verbose_telemetry.rs @@ -7,7 +7,8 @@ use std::io::Read; use std::path::Path; use crate::learning_mode_core::{ - verbose_logging_sibling_path, VerboseLoggingDocument, VerboseLoggingProvider, + verbose_logging_sibling_path, VerboseLoggingAggregate, VerboseLoggingDocument, + VerboseLoggingProvider, }; use crate::mxc_common::hashing::sha256_hex; use crate::mxc_common::models::{ContainmentBackend, ScriptResponse}; @@ -145,11 +146,19 @@ 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 } @@ -159,6 +168,9 @@ fn canonical_provider_guid(provider: VerboseLoggingProvider) -> &'static str { VerboseLoggingProvider::PrivacyAuditingPermissiveLearningMode => { "{811A1DDB-2E69-5F25-ADC0-4B186170E760}" } + VerboseLoggingProvider::LearningModeNetworkDecision => { + "{71237669-21C3-4101-BD2F-FF38945D725A}" + } } } @@ -222,6 +234,7 @@ mod tests { ) -> VerboseLoggingAggregate { VerboseLoggingAggregate { signature: VerboseLoggingSignature { + event_name: None, provider: VerboseLoggingProvider::KernelGeneral, provider_guid: "{a68ca8b7-004f-d7b6-a698-07e2de0f1f5d}".to_string(), event_id, @@ -389,6 +402,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); @@ -401,4 +415,51 @@ 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"); + 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_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); + } } diff --git a/src/mxc-sdk/src/core/plm/elevated.rs b/src/mxc-sdk/src/core/plm/elevated.rs index d1c0ef10e..b9a3b9b66 100644 --- a/src/mxc-sdk/src/core/plm/elevated.rs +++ b/src/mxc-sdk/src/core/plm/elevated.rs @@ -2139,7 +2139,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/mxc-sdk/src/core/plm/stop.rs b/src/mxc-sdk/src/core/plm/stop.rs index 712e9ead5..42c4cad5f 100644 --- a/src/mxc-sdk/src/core/plm/stop.rs +++ b/src/mxc-sdk/src/core/plm/stop.rs @@ -528,7 +528,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/mxc-sdk/tests/wxc_e2e_tests_e2e_telemetry_etw.rs b/src/mxc-sdk/tests/wxc_e2e_tests_e2e_telemetry_etw.rs index aadc1ce2c..9628dccb1 100644 --- a/src/mxc-sdk/tests/wxc_e2e_tests_e2e_telemetry_etw.rs +++ b/src/mxc-sdk/tests/wxc_e2e_tests_e2e_telemetry_etw.rs @@ -137,6 +137,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. @@ -238,12 +240,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": { @@ -299,7 +303,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) @@ -476,7 +480,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");