diff --git a/crates/openshell-driver-mxc/README.md b/crates/openshell-driver-mxc/README.md index 81511deabd..b518dc67a4 100644 --- a/crates/openshell-driver-mxc/README.md +++ b/crates/openshell-driver-mxc/README.md @@ -124,7 +124,26 @@ PID from inheriting the previous process's attribution regardless of delivery delay. The process monitor retires the live PID at exit. Established identity, activity, and correlation-vector links remain available for five seconds so already in-flight ETW records can arrive, but retired PID evidence cannot resolve -them. Records without matching generation evidence remain unattributed. +them. Records without matching generation evidence remain unattributed -- +deliberately: misattributing an ETW record to the wrong `sandbox_id` would +corrupt the audit trail, which is worse than a coverage gap. Unrelated, +non-OpenShell AppContainer or UAC activity shares this same OS Sandboxing +provider and cannot be told apart from OpenShell's own records without this +generation evidence, so guessing (for example, by assuming a lone pending +launch owns an unmatched record) is not a safe substitute for it. + +An unattributed record is dropped after five seconds, and the driver warns +once immediately, then coalesces further drops to at most one aggregated +warning every 30 seconds while they continue -- unattributed drops are +expected, ordinary activity, not a rare condition, so warning once per record +would let a burst of that activity flood operator logs. + +If the real-time ETW session itself never matches a single record from the +Sandboxing provider despite observed sandbox activity -- for example a +provider-identity mismatch, or the provider not firing at all on a given +host/build -- the driver warns once per session and emits a `mxc-etw-zero-events` +OCSF Detection Finding [2004] naming the gap, distinct from the per-record +unattributed-drop warning above. Each sandbox receives a distinct proxy listener and a random per-sandbox credential through its proxy environment. Missing, incorrect, duplicate, or another sandbox's proxy credentials receive HTTP 407 before policy evaluation or forwarding. This authenticates requests to the OpenShell proxy; it does not restrict access to unrelated host-loopback services or authenticate individual processes inside a sandbox. Proxy credentials and command/environment payloads must not be logged. diff --git a/crates/openshell-driver-mxc/src/etw_consumer.rs b/crates/openshell-driver-mxc/src/etw_consumer.rs index 09b8079868..612412bf5f 100644 --- a/crates/openshell-driver-mxc/src/etw_consumer.rs +++ b/crates/openshell-driver-mxc/src/etw_consumer.rs @@ -111,6 +111,20 @@ const EVENT_QUEUE_BYTE_CAPACITY: usize = 16 * 1024 * 1024; /// while the consumer remains behind. const OVERLOAD_WARNING_INTERVAL: Duration = Duration::from_secs(30); +/// Emit the first dropped-unattributed warning immediately, then coalesce +/// additional drops the same way [`OVERLOAD_WARNING_INTERVAL`] does for queue +/// overload. Unattributed drops are expected, ordinary system-wide activity +/// (unrelated AppContainer/UAC events sharing this same OS Sandboxing +/// provider) rather than a rare condition, so warning once per record would +/// let a burst of that unrelated activity flood operator logs. +const UNATTRIBUTED_DROP_WARNING_INTERVAL: Duration = Duration::from_secs(30); + +/// Grace period, after the first sandbox activity is observed, before the +/// zero-events watchdog warns that the session has matched no provider +/// events at all. Generous on purpose: the goal is to catch a genuinely +/// non-firing provider, not to flag normal per-sandbox event latency. +const ZERO_EVENTS_GRACE: Duration = Duration::from_secs(30); + /// `EVENT_CONTROL_CODE_ENABLE_PROVIDER`. const EVENT_CONTROL_CODE_ENABLE_PROVIDER: u32 = 1; @@ -291,6 +305,14 @@ struct CaptureHealth { queued_bytes: AtomicUsize, /// Largest observed value of `queued_bytes`, retained for diagnostics. queue_high_water_bytes: AtomicUsize, + /// Count of raw events the callback matched to [`SANDBOXING_PROVIDER_GUID`] + /// and forwarded to the consumer thread, regardless of whether TDH decode + /// later succeeded. Zero here after real sandbox activity means the OS + /// session is not delivering *any* events under this GUID at all -- a + /// provider-identity mismatch or a provider that isn't firing on this + /// host/build, not a decode/attribution bug. See the zero-events watchdog + /// in `start_session`'s consumer loop. + events_matched: AtomicU64, } struct CallbackContext { @@ -298,6 +320,50 @@ struct CallbackContext { health: Arc, } +/// Rate-limits the dropped-unattributed warning the same way +/// [`OverloadReporter`] rate-limits the queue-overload warning: report the +/// first drop immediately, then at most once every +/// [`UNATTRIBUTED_DROP_WARNING_INTERVAL`] while drops continue, aggregating +/// the count instead of warning per record. Unrelated, non-OpenShell +/// AppContainer/UAC activity shares this OS Sandboxing provider and cannot be +/// attributed without authoritative per-sandbox evidence, so a burst of that +/// ordinary activity must not flood operator logs one line per event. +#[derive(Default)] +struct UnattributedDropReporter { + total_dropped: u64, + last_reported_dropped: u64, + last_warning: Option, +} + +impl UnattributedDropReporter { + /// Record one more dropped-unattributed event and warn if due. Returns + /// `true` when a warning was actually emitted (useful for tests). + fn record_drop(&mut self, reason: &str, summary: &str) -> bool { + self.total_dropped += 1; + + let now = Instant::now(); + if self + .last_warning + .is_some_and(|last| now.duration_since(last) < UNATTRIBUTED_DROP_WARNING_INTERVAL) + { + return false; + } + + let dropped_since_last_warning = self.total_dropped - self.last_reported_dropped; + self.last_reported_dropped = self.total_dropped; + self.last_warning = Some(now); + tracing::warn!( + target: "mxc_etw", + total_dropped = self.total_dropped, + dropped_since_last_warning, + reason, + last_summary = summary, + "MXC ETW events dropped unattributed; audit coverage has a gap" + ); + true + } +} + #[derive(Default)] struct OverloadReporter { last_reported_drops: u64, @@ -380,6 +446,13 @@ impl EtwSession { pub fn dropped_event_count(&self) -> u64 { self.health.dropped_events.load(Ordering::Relaxed) } + + /// Count of raw provider-matched events received since the session + /// started. Exposed so the backend can surface "capture is running but + /// producing nothing" in status/diagnostics, alongside `is_capture_alive`. + pub fn events_received(&self) -> u64 { + self.health.events_matched.load(Ordering::Relaxed) + } } impl Drop for EtwSession { @@ -420,10 +493,12 @@ pub(crate) fn start_session(index: Arc>) -> Result(EVENT_QUEUE_CAPACITY); - let consumer_thread = std::thread::Builder::new() .name("etw-ocsf-consumer".into()) .spawn(move || { @@ -435,10 +510,23 @@ pub(crate) fn start_session(index: Arc>) -> Result = None; + let mut warned_no_events = false; loop { match rx.recv_timeout(Duration::from_millis(200)) { Ok(mut raw) => { release_queue_bytes(&consumer_health, raw.queued_bytes); + consumer_health + .events_matched + .fetch_add(1, Ordering::Relaxed); if let Some(ev) = decode_raw(&mut raw) { process_event(&index, ev); } else { @@ -462,6 +550,18 @@ pub(crate) fn start_session(index: Arc>) -> Result, + /// Total sandboxes ever registered, never decremented by [`Self::forget`]. + /// Used to gate the zero-events watchdog: a session that hasn't seen any + /// sandbox activity yet is expected to be quiet, so only warn once real + /// activity has happened and still produced nothing. + total_launches: u64, + /// Rate-limits the dropped-unattributed warning; see + /// [`UnattributedDropReporter`]. + unattributed_drops: UnattributedDropReporter, } impl AttributionIndex { @@ -1300,6 +1408,7 @@ impl AttributionIndex { wxc_pid: u32, process_start_key: u64, ) { + self.total_launches += 1; let now = Instant::now(); self.purge_expired_retirements(now); let previous = self.by_pid.remove(&wxc_pid); @@ -1371,6 +1480,12 @@ impl AttributionIndex { .any(|registration| registration.sid == sandbox_id) } + /// Total sandboxes ever registered via [`Self::register_launch`], including + /// ones since [`Self::forget`]-ten. Used to gate the zero-events watchdog. + pub fn total_launches(&self) -> u64 { + self.total_launches + } + /// Drop all keys for a finished sandbox to bound memory. pub fn forget(&mut self, sandbox_id: &str) { self.by_pid @@ -1480,7 +1595,15 @@ impl AttributionIndex { if now.duration_since(front.at) > PENDING_TTL { let stale = self.pending.pop_front(); if let Some(p) = stale { - tracing::debug!(target: "mxc_etw", pid = p.ev.process_id, "dropping unattributed (aged out) {}", p.ev.summary()); + // A permanently dropped event is an audit-trail gap (the + // OS action it represents will never appear in the OCSF + // log), so it's worth surfacing above debug level by + // default rather than only under `--log-level debug`. + // Rate-limited and aggregated: unattributed drops are + // expected, ordinary activity from unrelated AppContainer/ + // UAC events sharing this provider, not a rare condition. + self.unattributed_drops + .record_drop("aged_out", &p.ev.summary()); } } else { break; @@ -1489,7 +1612,8 @@ impl AttributionIndex { if self.pending.len() >= PENDING_MAX && let Some(p) = self.pending.pop_front() { - tracing::debug!(target: "mxc_etw", pid = p.ev.process_id, "dropping unattributed (buffer full) {}", p.ev.summary()); + self.unattributed_drops + .record_drop("buffer_full", &p.ev.summary()); } self.pending.push_back(PendingEvent { at: now, ev }); } @@ -1509,7 +1633,8 @@ impl AttributionIndex { let mut keep = VecDeque::with_capacity(drained.len()); for p in drained { if now.duration_since(p.at) > PENDING_TTL { - tracing::debug!(target: "mxc_etw", pid = p.ev.process_id, "dropping unattributed (aged out) {}", p.ev.summary()); + self.unattributed_drops + .record_drop("aged_out", &p.ev.summary()); continue; } match self.resolve(&p.ev) { @@ -1828,6 +1953,74 @@ fn map_finding(ctx: &EventContext, ev: &DecodedEtwEvent) -> OcsfEvent { .build() } +/// Decide whether the zero-events watchdog should fire, and track when +/// sandbox activity was first observed. Pure aside from `*activity_since`, +/// which the caller retains across calls (and across a loop tick that +/// doesn't warn) so the grace period is measured from first activity, not +/// re-armed on every tick. +/// +/// Gates on `total_launches` (not the index's current size) specifically so +/// a quiet, idle gateway with `etw_audit=true` but zero sandboxes created +/// never warns -- only genuine "activity happened, nothing arrived" does. +fn should_warn_zero_events( + events_matched: u64, + total_launches: u64, + activity_since: &mut Option, + grace: Duration, +) -> bool { + if events_matched != 0 { + return false; + } + if activity_since.is_none() && total_launches > 0 { + *activity_since = Some(Instant::now()); + } + activity_since.is_some_and(|since| since.elapsed() >= grace) +} + +/// Fired once per session by the zero-events watchdog when real sandbox +/// activity has happened but the session has never matched a single event to +/// [`SANDBOXING_PROVIDER_GUID`]. `EnableTraceEx2` success only proves the +/// *request* to enable the provider succeeded, not that the provider exists +/// on this host/build or will ever actually fire -- this is the detection gap +/// that made a real-world provider-identity mismatch silently produce an +/// empty OCSF audit trail with no diagnostic at all. +fn warn_zero_events_received() { + tracing::warn!( + target: "mxc_etw", + provider = ?SANDBOXING_PROVIDER_GUID, + session = SESSION_NAME_PREFIX, + "MXC ETW->OCSF consumer has received zero events from the Sandboxing \ + provider despite sandbox activity; the OS-sourced audit trail is \ + empty for this session. EnableTraceEx2 succeeding does not prove the \ + provider exists on this host/build or will ever fire -- verify with \ + `logman query providers` and confirm wxc-exec targets this GUID." + ); + emit_ocsf( + "", + DetectionFindingBuilder::new(&etw_ctx("", "mxc-etw-consumer")) + .activity(ActivityId::Open) // finding label = "Create" + .severity(SeverityId::High) + .is_alert(true) + .finding_info( + FindingInfo::new( + "mxc-etw-zero-events", + "MXC ETW audit consumer received zero provider events", + ) + .with_desc( + "The Sandboxing ETW provider produced zero events despite \ + observed sandbox activity; the OS-sourced portion of the \ + audit trail is empty for this session.", + ), + ) + .message( + "MXC ETW->OCSF consumer active but received zero events from \ + the Sandboxing provider after sandbox activity" + .to_string(), + ) + .build(), + ); +} + /// Best-effort executable name from a command line: first whitespace-delimited /// token, stripped of any directory prefix and surrounding quotes. fn exe_name(cmd_line: &str) -> String { @@ -2009,6 +2202,38 @@ mod tests { assert_eq!(reporter.last_reported_drops, 3); } + #[test] + fn unattributed_drop_reporter_warns_immediately_then_coalesces() { + let mut reporter = UnattributedDropReporter::default(); + + // The very first drop, ever, warns immediately (no prior warning to + // rate-limit against). + assert!(reporter.record_drop("aged_out", "SandboxConfig (id=0)")); + assert_eq!(reporter.total_dropped, 1); + assert_eq!(reporter.last_reported_dropped, 1); + + // Further drops within the interval are aggregated, not re-warned, + // but still counted so the next warning reports the true total. + assert!(!reporter.record_drop("aged_out", "EnforceOsPolicy (id=0)")); + assert!(!reporter.record_drop("buffer_full", "ProcessLaunched (id=0)")); + assert_eq!( + reporter.total_dropped, 3, + "every drop is counted even when coalesced" + ); + assert_eq!( + reporter.last_reported_dropped, 1, + "the reported total only advances when a warning actually fires" + ); + + // Force the rate limit open by backdating the last warning, then + // confirm the next drop reports the two that were coalesced since. + reporter.last_warning = Instant::now() + .checked_sub(UNATTRIBUTED_DROP_WARNING_INTERVAL + Duration::from_millis(1)); + assert!(reporter.record_drop("aged_out", "SetUILimitsOnJob (id=0)")); + assert_eq!(reporter.total_dropped, 4); + assert_eq!(reporter.last_reported_dropped, 4); + } + #[test] fn gateway_processes_and_restarts_use_distinct_session_names() { let first_gateway = format_session_name(1001, 0x1111, 0); @@ -2198,6 +2423,74 @@ mod tests { assert_eq!(idx.resolve(&ev_b).as_deref(), Some("sbx-B")); } + // Regression test for the zero-events watchdog: it must gate on whether + // sandbox activity has *ever* happened, not on the index's current size, + // since `forget` empties the index for every sandbox that completes + // normally -- `total_launches` must keep counting past that. + #[test] + fn total_launches_survives_forget() { + let mut idx = AttributionIndex::new(); + assert_eq!(idx.total_launches(), 0); + + idx.register_launch("sbx-1", "s1", 100, 1); + idx.forget("sbx-1"); + assert_eq!(idx.total_launches(), 1); + + idx.register_launch("sbx-2", "s2", 200, 2); + idx.register_launch("sbx-3", "s3", 300, 3); + assert_eq!(idx.total_launches(), 3); + } + + #[test] + fn zero_events_watchdog_stays_quiet_without_sandbox_activity() { + // An idle gateway with etw_audit=true but no sandboxes created yet + // must never warn, however long it's been running. + let mut activity_since = None; + assert!(!should_warn_zero_events( + 0, + 0, + &mut activity_since, + Duration::ZERO + )); + assert!(activity_since.is_none()); + } + + #[test] + fn zero_events_watchdog_stays_quiet_once_any_event_matched() { + let mut activity_since = None; + assert!(!should_warn_zero_events( + 1, + 5, + &mut activity_since, + Duration::ZERO + )); + } + + #[test] + fn zero_events_watchdog_waits_out_the_grace_period() { + let mut activity_since = None; + let grace = Duration::from_hours(1); + // First tick after activity starts: grace hasn't elapsed yet. + assert!(!should_warn_zero_events(0, 1, &mut activity_since, grace)); + assert!(activity_since.is_some()); + // A later tick still within the (long) grace window: still quiet. + assert!(!should_warn_zero_events(0, 1, &mut activity_since, grace)); + } + + #[test] + fn zero_events_watchdog_fires_once_grace_elapses() { + let mut activity_since = Some(Instant::now().checked_sub(Duration::from_mins(1)).unwrap()); + assert!(should_warn_zero_events( + 0, + 1, + &mut activity_since, + Duration::from_secs(30) + )); + } + + // Shailendra #1 (cmd ambiguity): two sandboxes running the identical command + // line must not let that command line resolve anything (it's ambiguous); a + // unique command line still works as a fallback. #[test] fn displaced_live_pid_does_not_claim_new_pre_registration_event() { let mut idx = AttributionIndex::new();