diff --git a/docs/diagnostics.md b/docs/diagnostics.md index caa6f2f69..c6649df37 100644 --- a/docs/diagnostics.md +++ b/docs/diagnostics.md @@ -45,8 +45,39 @@ per PID, with special highlighting for `WARNING:`, `ERROR:`, and `SECTION:` mess ### Display Modes -- `--minified` (default) — reduced ETW event properties -- `--verbose` — all ETW event properties +- `--minified` (default) -- reduced ETW event properties +- `--verbose` -- all ETW event properties + +### Log Collection + +Use `--collect` to capture diagnostic logs to files: + +```powershell +mxc-diagnostic-console.exe --collect +``` + +This creates a timestamped folder in `%TEMP%` (e.g. `mxc-diagnostics-20260513-211500-12345\`) +containing: +- `verbose.log` -- all ETW event properties (full detail) +- `minified.log` -- reduced ETW event properties + +The console continues to display events normally while collecting. Press **Ctrl+C** to +stop collection, at which point the tool: +1. Flushes both log files +2. Zips the folder via PowerShell `Compress-Archive` +3. Prints the paths to the log folder and archive + +A second Ctrl+C during finalization forces an immediate exit. + +Combine with `--verbose` to see full output on the console while collecting both formats: +```powershell +mxc-diagnostic-console.exe --collect --verbose +``` + +Alternatively, you can capture the console output directly with `Tee-Object`: +```powershell +mxc-diagnostic-console.exe | Tee-Object -Encoding ascii -FilePath out.log +``` ### ETW Tracing diff --git a/src/lxc/src/main.rs b/src/lxc/src/main.rs index 8810ba7d9..35a51469a 100644 --- a/src/lxc/src/main.rs +++ b/src/lxc/src/main.rs @@ -78,7 +78,8 @@ fn log_request(request: &CodexRequest, logger: &mut Logger) { } fn display_script_results(response: &ScriptResponse, logger: &mut Logger) { - let _ = writeln!(logger, "Exit code: {}", response.exit_code); + let code = response.exit_code; + let _ = writeln!(logger, "Exit code: {} (0x{:08X})", code, code as u32); if !response.error_message.is_empty() { let _ = writeln!(logger, "Error: {}", response.error_message); } diff --git a/src/mxc_darwin/src/main.rs b/src/mxc_darwin/src/main.rs index c6103e4e0..5330bd349 100644 --- a/src/mxc_darwin/src/main.rs +++ b/src/mxc_darwin/src/main.rs @@ -66,7 +66,8 @@ fn log_request(request: &CodexRequest, logger: &mut Logger) { #[cfg(target_os = "macos")] fn display_script_results(response: &ScriptResponse, logger: &mut Logger) { - let _ = writeln!(logger, "Exit code: {}", response.exit_code); + let code = response.exit_code; + let _ = writeln!(logger, "Exit code: {} (0x{:08X})", code, code as u32); if !response.error_message.is_empty() { let _ = writeln!(logger, "Error: {}", response.error_message); } diff --git a/src/mxc_diagnostic_console/src/etw.rs b/src/mxc_diagnostic_console/src/etw.rs index b4faa0aa9..ca8605edf 100644 --- a/src/mxc_diagnostic_console/src/etw.rs +++ b/src/mxc_diagnostic_console/src/etw.rs @@ -5,7 +5,8 @@ //! //! Listens for events from: //! - **Tessera** TraceLogging provider (all events) -//! - **Microsoft-Windows-Kernel-General** (learning-mode AccessCheckLog only, event ID 0xe) +//! - **Microsoft-Windows-Kernel-General** (all events -- AccessCheckLog, AppContainerTokenCheckLog, +//! TokenSidManagementLog, learning-mode violations, etc.) //! //! Starts a trace session, enables the providers, and delivers decoded events //! to the diagnostic console's display channel. Requires administrator privileges. @@ -24,7 +25,7 @@ use windows::Win32::System::Diagnostics::Etw::{ TRACE_EVENT_INFO, TRACE_LEVEL_VERBOSE, WNODE_FLAG_TRACED_GUID, }; -use super::{display_mode, DisplayEvent, DisplayMode}; +use super::{collect_mode, display_mode, DisplayEvent, DisplayMode}; // --------------------------------------------------------------------------- // Constants @@ -39,7 +40,8 @@ const TESSERA_PROVIDER: GUID = GUID { }; /// Microsoft-Windows-Kernel-General provider GUID: {a68ca8b7-004f-d7b6-a698-07e2de0f1f5d} -/// Used to capture learning-mode access check events (event ID 0xe / 14). +/// Used to capture learning-mode diagnostics (AccessCheckLog, AppContainerTokenCheckLog, +/// TokenSidManagementLog, learning-mode violations, etc.). const KERNEL_GENERAL_PROVIDER: GUID = GUID { data1: 0xa68ca8b7, data2: 0x004f, @@ -47,9 +49,6 @@ const KERNEL_GENERAL_PROVIDER: GUID = GUID { data4: [0xa6, 0x98, 0x07, 0xe2, 0xde, 0x0f, 0x1f, 0x5d], }; -/// Event ID for SepAccessCheck learning-mode log (AccessCheckLog). -const ACCESS_CHECK_LOG_EVENT_ID: u16 = 0xe; - const SESSION_NAME: &str = "MXC-Diagnostics-ETW"; /// Global trace session handle so we can stop the session from any thread. @@ -87,7 +86,7 @@ unsafe impl Send for SendPtr {} /// Start the ETW listener for diagnostic providers. /// /// Enables the Tessera TraceLogging provider and the Kernel-General provider -/// (filtered to AccessCheckLog events for learning-mode diagnostics). +/// (all events for learning-mode diagnostics). /// Spawns a background thread that calls `ProcessTrace` (blocking). Returns /// immediately on success. Events are delivered via `tx`. pub fn start_etw_listener(tx: mpsc::Sender) -> Result<(), String> { @@ -197,7 +196,7 @@ fn enable_provider(session_handle: u64) -> Result<(), String> { )); } - // Enable the Kernel-General provider for learning-mode access check events. + // Enable the Kernel-General provider for learning-mode diagnostic events. let status = unsafe { EnableTraceEx2( h, @@ -300,45 +299,71 @@ unsafe extern "system" fn event_record_callback(event_record: *mut EVENT_RECORD) if provider == TESSERA_PROVIDER { // Tessera: accept all events. } else if provider == KERNEL_GENERAL_PROVIDER { - // Kernel-General: only accept AccessCheckLog (event ID 0xe). - if event.EventHeader.EventDescriptor.Id != ACCESS_CHECK_LOG_EVENT_ID { - return; - } + // Kernel-General: accept all events (AccessCheckLog, AppContainerTokenCheckLog, + // TokenSidManagementLog, learning-mode violations, etc.). } else { return; } let tx = unsafe { &*(event.UserContext as *const mpsc::Sender) }; - let text = match decode_event(event_record) { - Some(t) => t, - None => return, // Suppressed by display mode filtering. - }; - let _ = tx.send(DisplayEvent::EtwEvent { - pid: event.EventHeader.ProcessId, - text, - }); + let pid = event.EventHeader.ProcessId; + let collecting = collect_mode(); + let current_mode = display_mode(); + + if let Some(parts) = decode_event_parts(event_record) { + let console_text = format_event_output(&parts, current_mode); + + let (verbose_text, minified_text) = if collecting { + let verbose = format_event_output(&parts, DisplayMode::Full) + .unwrap_or_else(|| fallback_event_text(event_record)); + let minified = format_event_output(&parts, DisplayMode::Minified); + (Some(verbose), Some(minified)) + } else { + (None, None) + }; + + // In collect mode, send even if console_text is None (suppressed) since + // the verbose log still wants this event. + if console_text.is_some() || collecting { + let _ = tx.send(DisplayEvent::EtwEvent { + pid, + text: console_text.unwrap_or_else(|| fallback_event_text(event_record)), + verbose_text, + minified_text, + }); + } + } else { + let fallback = fallback_event_text(event_record); + let (verbose_text, minified_text) = if collecting { + (Some(fallback.clone()), Some(Some(fallback.clone()))) + } else { + (None, None) + }; + let _ = tx.send(DisplayEvent::EtwEvent { + pid, + text: fallback, + verbose_text, + minified_text, + }); + } } // --------------------------------------------------------------------------- // Event decoding // --------------------------------------------------------------------------- -fn decode_event(event_record: *mut EVENT_RECORD) -> Option { - match decode_with_tdh(event_record) { - Some(s) => Some(s), - None => { - let event = unsafe { &*event_record }; - Some(format!( - "Event(Id={}, Level={}, DataLen={})", - event.EventHeader.EventDescriptor.Id, - event.EventHeader.EventDescriptor.Level, - event.UserDataLength, - )) - } - } +/// Decoded ETW event parts (expensive TDH call done once, formatting done separately). +struct DecodedEventParts { + event_name: Option, + event_id: u16, + provider: GUID, + level_tag: &'static str, + props: Vec<(String, String)>, } -fn decode_with_tdh(event_record: *mut EVENT_RECORD) -> Option { +/// Decode the raw event record via TDH into reusable parts. +/// Returns `None` only when TDH decoding fails entirely. +fn decode_event_parts(event_record: *mut EVENT_RECORD) -> Option { let mut buf_size: u32 = 0; let status = unsafe { TdhGetEventInformation(event_record, None, None, &mut buf_size) }; @@ -358,20 +383,20 @@ fn decode_with_tdh(event_record: *mut EVENT_RECORD) -> Option { let info = unsafe { &*info_ptr }; - // EventNameOffset is in Anonymous1 (union with ActivityIDNameOffset). let event_name_offset = unsafe { info.Anonymous1.EventNameOffset }; let event_name = wide_str_at(&buffer, event_name_offset) .or_else(|| wide_str_at(&buffer, info.TaskNameOffset)) .unwrap_or_default(); let event_name = if event_name.is_empty() { - // No name available; don't synthesize a noisy "Event#N" label. None } else { Some(event_name) }; let level = unsafe { (*event_record).EventHeader.EventDescriptor.Level }; + let event_id = unsafe { (*event_record).EventHeader.EventDescriptor.Id }; + let provider = unsafe { (*event_record).EventHeader.ProviderId }; let level_tag = match level { 1 => "\x1b[91mCRIT\x1b[0m", 2 => "\x1b[91mERR\x1b[0m", @@ -383,7 +408,39 @@ fn decode_with_tdh(event_record: *mut EVENT_RECORD) -> Option { let props = decode_properties(&buffer, info, event_record); - let props = minify_access_check_props(props)?; + Some(DecodedEventParts { + event_name, + event_id, + provider, + level_tag, + props, + }) +} + +/// Learning mode violation event ID from Kernel-General. +const LEARNING_MODE_VIOLATION_EVENT_ID: u16 = 27; + +/// Human-readable names for learning mode violation categories. +fn learning_mode_category_name(category: &str) -> &str { + match category { + "0" => "None", + "1" => "ConvertToGui", + "2" => "UiOperation", + _ => category, + } +} + +/// Format decoded event parts into a display string for the given mode. +/// Returns `None` when the event should be suppressed (e.g. empty ObjectType in minified mode). +fn format_event_output(parts: &DecodedEventParts, mode: DisplayMode) -> Option { + // Special handling for learning mode violation events (Kernel-General, Event ID 27). + if parts.provider == KERNEL_GENERAL_PROVIDER + && parts.event_id == LEARNING_MODE_VIOLATION_EVENT_ID + { + return Some(format_learning_mode_violation(&parts.props, mode)); + } + + let props = minify_kernel_general_props(parts.props.clone(), mode)?; let props_str = if props.is_empty() { String::new() @@ -392,16 +449,79 @@ fn decode_with_tdh(event_record: *mut EVENT_RECORD) -> Option { format!(" {{ {} }}", joined.join(", ")) }; - let name_part = event_name.as_deref().unwrap_or(""); + let name_part = parts.event_name.as_deref().unwrap_or(""); - match (level_tag.is_empty(), name_part.is_empty()) { + match (parts.level_tag.is_empty(), name_part.is_empty()) { (true, true) => Some(props_str.trim_start().to_string()), (true, false) => Some(format!("{name_part}{props_str}")), - (false, true) => Some(format!("[{level_tag}]{props_str}")), - (false, false) => Some(format!("[{level_tag}] {name_part}{props_str}")), + (false, true) => Some(format!("[{}]{props_str}", parts.level_tag)), + (false, false) => Some(format!("[{}] {name_part}{props_str}", parts.level_tag)), } } +/// Format a learning mode violation event (Event ID 27) with warning colors and category name. +fn format_learning_mode_violation(props: &[(String, String)], mode: DisplayMode) -> String { + let yellow = "\x1b[33m"; + let orange = "\x1b[38;5;208m"; + let reset = "\x1b[0m"; + + // Replace the Category number with its human-readable name, colored orange. + let formatted_props: Vec<(String, String)> = props + .iter() + .map(|(k, v)| { + if k == "Category" { + let raw = v.trim_matches('"'); + let name = learning_mode_category_name(raw); + (k.clone(), format!("{orange}{name}{reset}")) + } else { + (k.clone(), v.clone()) + } + }) + .collect(); + + // In minified mode, show a reduced set of properties. + let display_props = if mode == DisplayMode::Minified { + const MINIFIED_FIELDS: &[&str] = &["ProcessName", "Category", "Denied"]; + let mut filtered: Vec<(String, String)> = formatted_props + .into_iter() + .filter(|(k, _)| MINIFIED_FIELDS.contains(&k.as_str())) + .collect(); + // Strip ProcessName to just the exe name. + for (k, v) in &mut filtered { + if k == "ProcessName" { + let stripped = v.trim_matches('"').rsplit('\\').next().unwrap_or(v); + *v = format!("\"{stripped}\""); + } + } + filtered + } else { + formatted_props + }; + + let props_str = if display_props.is_empty() { + String::new() + } else { + let joined: Vec = display_props + .iter() + .map(|(k, v)| format!("{k}={v}")) + .collect(); + format!(" {{ {} }}", joined.join(", ")) + }; + + format!("{yellow}[LearningModeViolation]{reset}{props_str}") +} + +/// Produce a generic fallback string for events that TDH cannot decode. +fn fallback_event_text(event_record: *mut EVENT_RECORD) -> String { + let event = unsafe { &*event_record }; + format!( + "Event(Id={}, Level={}, DataLen={})", + event.EventHeader.EventDescriptor.Id, + event.EventHeader.EventDescriptor.Level, + event.UserDataLength, + ) +} + fn decode_properties( info_buf: &[u8], info: &TRACE_EVENT_INFO, @@ -459,11 +579,15 @@ fn decode_properties( /// ObjectType="File" or ObjectType="Key", in the order they should appear. const MINIFIED_FILE_FIELDS: &[&str] = &["LowBoxNumber", "ProcessName", "ObjectName"]; -/// In minified mode, reduce AccessCheckLog File/Key events to a useful subset -/// of properties and strip ProcessName to just the executable name. -/// Returns `None` to suppress the event entirely (e.g. empty ObjectType). -fn minify_access_check_props(props: Vec<(String, String)>) -> Option> { - if display_mode() != DisplayMode::Minified { +/// In minified mode, reduce Kernel-General events to a useful subset of properties. +/// For AccessCheckLog File/Key events: strip to LowBoxNumber, ProcessName, ObjectName. +/// For other events: pass all properties through unmodified. +/// Returns `None` to suppress the event entirely (e.g. empty ObjectType in AccessCheckLog). +fn minify_kernel_general_props( + props: Vec<(String, String)>, + mode: DisplayMode, +) -> Option> { + if mode != DisplayMode::Minified { return Some(props); } diff --git a/src/mxc_diagnostic_console/src/main.rs b/src/mxc_diagnostic_console/src/main.rs index 2ca4dcc0a..117184ae8 100644 --- a/src/mxc_diagnostic_console/src/main.rs +++ b/src/mxc_diagnostic_console/src/main.rs @@ -13,11 +13,12 @@ mod etw; -use std::io::Read; -use std::sync::atomic::{AtomicU8, Ordering}; +use std::io::{BufWriter, Read, Write}; +use std::path::PathBuf; +use std::sync::atomic::{AtomicBool, AtomicU8, Ordering}; use std::sync::mpsc; use std::thread; -use std::time::SystemTime; +use std::time::{Duration, SystemTime}; use clap::Parser; @@ -73,6 +74,16 @@ pub fn display_mode() -> DisplayMode { } } +/// Whether `--collect` mode is active. +static COLLECT_MODE_FLAG: AtomicBool = AtomicBool::new(false); + +/// Shutdown signal set by the Ctrl+C handler to trigger graceful finalization. +static SHUTDOWN: AtomicBool = AtomicBool::new(false); + +pub fn collect_mode() -> bool { + COLLECT_MODE_FLAG.load(Ordering::Relaxed) +} + /// Events sent from reader threads to the display thread. enum DisplayEvent { /// A new client connected with the given PID. @@ -82,7 +93,15 @@ enum DisplayEvent { /// A client disconnected. Disconnected { pid: u32 }, /// An ETW event from the Tessera provider. - EtwEvent { pid: u32, text: String }, + EtwEvent { + pid: u32, + text: String, + /// Full (verbose) rendering for the verbose log (only populated in collect mode). + verbose_text: Option, + /// Minified rendering for the minified log (only in collect mode; + /// inner `None` means the event was suppressed in minified mode). + minified_text: Option>, + }, } /// Check whether the current process is running elevated (as admin). @@ -123,6 +142,11 @@ struct Cli { /// Show all ETW event properties (default: minified) #[arg(long)] verbose: bool, + + /// Collect logs to files. Captures both verbose and minified output to a + /// timestamped folder in %TEMP%, then zips the folder on exit (Ctrl+C). + #[arg(long)] + collect: bool, } fn main() { @@ -134,6 +158,29 @@ fn main() { DISPLAY_MODE.store(DisplayMode::Minified as u8, Ordering::Relaxed); } + if cli.collect { + COLLECT_MODE_FLAG.store(true, Ordering::Relaxed); + } + + // Create the collection directory (if --collect). + let collect_dir = if cli.collect { + match create_collect_dir() { + Ok(dir) => { + println!( + "\x1b[1;32m[collect]\x1b[0m Collecting logs to: {}", + dir.display() + ); + Some(dir) + } + Err(e) => { + eprintln!("\x1b[1;31m[collect]\x1b[0m Failed to create collection directory: {e}"); + std::process::exit(1); + } + } + } else { + None + }; + // Compute the per-user pipe name (includes current user's SID). let pipe_name = wxc_common::diagnostic::diagnostic_pipe_name(); @@ -147,6 +194,9 @@ fn main() { println!("\x1b[1;36m=== MXC Diagnostic Console ===\x1b[0m"); println!("{DIM}Listening on {pipe_name}{RESET}"); println!("{DIM}Display mode: {mode_label}{RESET}"); + if cli.collect { + println!("{DIM}Collection: enabled (Ctrl+C to stop and finalize){RESET}"); + } println!("{DIM}Press Ctrl+C to exit{RESET}"); println!(); @@ -219,12 +269,12 @@ fn main() { Ok(()) => { println!("\x1b[93m[ETW]\x1b[0m Listening for providers:"); println!( - "\x1b[93m[ETW]\x1b[0m Tessera \ - {{f6ec123e-314e-400b-9e0a-151365e23083}}" + "\x1b[93m[ETW]\x1b[0m ProcessModel \ + {{f6ec123e-314e-400b-9e0a-151365e23083}} (Sandboxing)" ); println!( "\x1b[93m[ETW]\x1b[0m Kernel-General \ - {{a68ca8b7-004f-d7b6-a698-07e2de0f1f5d}} (AccessCheckLog only)" + {{a68ca8b7-004f-d7b6-a698-07e2de0f1f5d}} (Learning Mode messages)" ); } Err(e) => { @@ -239,7 +289,7 @@ fn main() { // Display thread: formats and prints events. let _display_handle = thread::spawn(move || { - display_loop(rx); + display_loop(rx, collect_dir); }); // Accept loop: create pipe instances and wait for clients. @@ -456,58 +506,174 @@ struct PidInfo { } /// Display loop: reads events from the channel and prints them. -fn display_loop(rx: mpsc::Receiver) { +/// When `collect_dir` is `Some`, also writes ANSI-stripped output to log files. +fn display_loop(rx: mpsc::Receiver, collect_dir: Option) { let mut pid_info_map: Vec = Vec::new(); let mut next_color: usize = 0; - for event in rx { - let ts = format_timestamp(); - match event { - DisplayEvent::Connected { pid } => { - let color_idx = next_color % PID_COLORS.len(); - let exe = process_exe_name(pid); - pid_info_map.push(PidInfo { - pid, - color_idx, - exe_name: exe.clone(), - }); - next_color += 1; - let color = PID_COLORS[color_idx]; - println!( - "{DIM}[{ts}]{RESET} {color}>>>{RESET} {color}{exe}:{pid}{RESET} connected" - ); - } - DisplayEvent::Message { pid, text } => { - let (color, exe) = get_pid_info(&pid_info_map, pid); - for line in text.lines() { - if line.starts_with("WARNING:") { - println!("{DIM}[{ts}]{RESET} {color}[{exe}:{pid}]{RESET} \x1b[1;33m{line}\x1b[0m"); - } else if line.contains("SECTION:") { - println!("{DIM}[{ts}]{RESET} {color}[{exe}:{pid}]{RESET} \x1b[1;36m{line}\x1b[0m"); - } else if line.starts_with("ERROR:") || line.starts_with("Error:") { - println!("{DIM}[{ts}]{RESET} {color}[{exe}:{pid}]{RESET} \x1b[1;31m{line}\x1b[0m"); - } else { - println!("{DIM}[{ts}]{RESET} {color}[{exe}:{pid}]{RESET} {line}"); + // Open log files if collecting. + let mut log_writers: Option<(BufWriter, BufWriter)> = + collect_dir.as_ref().map(|dir| { + let verbose_file = std::fs::File::create(dir.join("verbose.log")) + .expect("Failed to create verbose.log"); + let minified_file = std::fs::File::create(dir.join("minified.log")) + .expect("Failed to create minified.log"); + (BufWriter::new(verbose_file), BufWriter::new(minified_file)) + }); + + let mut flush_counter: u32 = 0; + + loop { + let event = if collect_dir.is_some() { + // Use recv_timeout so we can check the SHUTDOWN flag. + match rx.recv_timeout(Duration::from_millis(250)) { + Ok(ev) => ev, + Err(mpsc::RecvTimeoutError::Timeout) => { + if SHUTDOWN.load(Ordering::Relaxed) { + // Drain remaining events before exiting. + while let Ok(ev) = rx.try_recv() { + process_display_event( + ev, + &mut pid_info_map, + &mut next_color, + &mut log_writers, + ); + } + break; + } + // Periodic flush while idle. + if let Some((ref mut v, ref mut m)) = log_writers { + let _ = v.flush(); + let _ = m.flush(); } + continue; } + Err(mpsc::RecvTimeoutError::Disconnected) => break, } - DisplayEvent::Disconnected { pid } => { - let (color, exe) = get_pid_info(&pid_info_map, pid); - println!( - "{DIM}[{ts}]{RESET} {color}<<<{RESET} {color}{exe}:{pid}{RESET} disconnected" - ); + } else { + match rx.recv() { + Ok(ev) => ev, + Err(_) => break, + } + }; + + process_display_event(event, &mut pid_info_map, &mut next_color, &mut log_writers); + + // Periodic flush every 50 events. + flush_counter += 1; + if flush_counter >= 50 { + flush_counter = 0; + if let Some((ref mut v, ref mut m)) = log_writers { + let _ = v.flush(); + let _ = m.flush(); + } + } + } + + // Final flush and finalization. + if let Some((ref mut v, ref mut m)) = log_writers { + let _ = v.flush(); + let _ = m.flush(); + } + drop(log_writers); + + if let Some(dir) = collect_dir { + finalize_collection(&dir); + std::process::exit(0); + } +} + +/// Process a single display event: print to console and optionally write to log files. +fn process_display_event( + event: DisplayEvent, + pid_info_map: &mut Vec, + next_color: &mut usize, + log_writers: &mut Option<(BufWriter, BufWriter)>, +) { + let ts = format_timestamp(); + match event { + DisplayEvent::Connected { pid } => { + let color_idx = *next_color % PID_COLORS.len(); + let exe = process_exe_name(pid); + pid_info_map.push(PidInfo { + pid, + color_idx, + exe_name: exe.clone(), + }); + *next_color += 1; + let color = PID_COLORS[color_idx]; + let line = + format!("{DIM}[{ts}]{RESET} {color}>>>{RESET} {color}{exe}:{pid}{RESET} connected"); + println!("{line}"); + if let Some((ref mut v, ref mut m)) = log_writers { + let plain = format!("[{ts}] >>> {exe}:{pid} connected\n"); + let _ = v.write_all(plain.as_bytes()); + let _ = m.write_all(plain.as_bytes()); } - DisplayEvent::EtwEvent { pid, text } => { - // ETW events may come from kernel PIDs not in our pipe map. - let (color, exe) = get_pid_info(&pid_info_map, pid); - let label = if exe == "?" { - // Try to resolve on the fly for ETW-only PIDs. - let resolved = process_exe_name(pid); - format!("{resolved}:{pid}") + } + DisplayEvent::Message { pid, text } => { + let (color, exe) = get_pid_info(pid_info_map, pid); + for line in text.lines() { + if line.starts_with("WARNING:") { + println!( + "{DIM}[{ts}]{RESET} {color}[{exe}:{pid}]{RESET} \x1b[1;33m{line}\x1b[0m" + ); + } else if line.contains("SECTION:") { + println!( + "{DIM}[{ts}]{RESET} {color}[{exe}:{pid}]{RESET} \x1b[1;36m{line}\x1b[0m" + ); + } else if line.starts_with("ERROR:") || line.starts_with("Error:") { + println!( + "{DIM}[{ts}]{RESET} {color}[{exe}:{pid}]{RESET} \x1b[1;31m{line}\x1b[0m" + ); } else { - format!("{exe}:{pid}") - }; - println!("{DIM}[{ts}]{RESET} \x1b[93m[ETW]\x1b[0m {color}[{label}]{RESET} {text}"); + println!("{DIM}[{ts}]{RESET} {color}[{exe}:{pid}]{RESET} {line}"); + } + if let Some((ref mut v, ref mut m)) = log_writers { + let plain = format!("[{ts}] [{exe}:{pid}] {line}\n"); + let _ = v.write_all(plain.as_bytes()); + let _ = m.write_all(plain.as_bytes()); + } + } + } + DisplayEvent::Disconnected { pid } => { + let (color, exe) = get_pid_info(pid_info_map, pid); + let line = format!( + "{DIM}[{ts}]{RESET} {color}<<<{RESET} {color}{exe}:{pid}{RESET} disconnected" + ); + println!("{line}"); + if let Some((ref mut v, ref mut m)) = log_writers { + let plain = format!("[{ts}] <<< {exe}:{pid} disconnected\n"); + let _ = v.write_all(plain.as_bytes()); + let _ = m.write_all(plain.as_bytes()); + } + } + DisplayEvent::EtwEvent { + pid, + text, + verbose_text, + minified_text, + } => { + let (color, exe) = get_pid_info(pid_info_map, pid); + let label = if exe == "?" { + let resolved = process_exe_name(pid); + format!("{resolved}:{pid}") + } else { + format!("{exe}:{pid}") + }; + println!("{DIM}[{ts}]{RESET} \x1b[93m[ETW]\x1b[0m {color}[{label}]{RESET} {text}"); + + if let Some((ref mut v, ref mut m)) = log_writers { + // Write verbose text to verbose.log. + if let Some(ref vt) = verbose_text { + let plain = format!("[{ts}] [ETW] [{label}] {}\n", strip_ansi(vt)); + let _ = v.write_all(plain.as_bytes()); + } + // Write minified text to minified.log (skip if suppressed). + if let Some(Some(ref mt)) = minified_text { + let plain = format!("[{ts}] [ETW] [{label}] {}\n", strip_ansi(mt)); + let _ = m.write_all(plain.as_bytes()); + } } } } @@ -558,6 +724,114 @@ fn format_timestamp() -> String { format!("{hours:02}:{minutes:02}:{seconds:02}.{millis:03}") } +/// Strip ANSI escape codes from a string for plain-text log output. +fn strip_ansi(s: &str) -> String { + let mut result = String::with_capacity(s.len()); + let mut chars = s.chars(); + while let Some(c) = chars.next() { + if c == '\x1b' { + // Skip until we hit a letter (the terminator of an ANSI sequence). + for c2 in chars.by_ref() { + if c2.is_ascii_alphabetic() { + break; + } + } + } else { + result.push(c); + } + } + result +} + +/// Create the timestamped collection directory in %TEMP%. +fn create_collect_dir() -> Result { + let temp = std::env::temp_dir(); + let now = SystemTime::now() + .duration_since(SystemTime::UNIX_EPOCH) + .unwrap_or_default(); + let secs = now.as_secs(); + let time_of_day = secs % 86400; + let days = secs / 86400; + + // Approximate date from days since epoch. + let (year, month, day) = days_to_ymd(days); + let hours = time_of_day / 3600; + let minutes = (time_of_day % 3600) / 60; + let seconds = time_of_day % 60; + let pid = std::process::id(); + + let dir_name = format!( + "mxc-diagnostics-{year:04}{month:02}{day:02}-{hours:02}{minutes:02}{seconds:02}-{pid}" + ); + let dir = temp.join(dir_name); + std::fs::create_dir_all(&dir).map_err(|e| format!("create_dir_all: {e}"))?; + Ok(dir) +} + +/// Convert days since Unix epoch to (year, month, day). +fn days_to_ymd(days: u64) -> (u64, u64, u64) { + // Civil calendar algorithm (simplified Euclidean). + let z = days + 719468; + let era = z / 146097; + let doe = z - era * 146097; + let yoe = (doe - doe / 1460 + doe / 36524 - doe / 146096) / 365; + let y = yoe + era * 400; + let doy = doe - (365 * yoe + yoe / 4 - yoe / 100); + let mp = (5 * doy + 2) / 153; + let d = doy - (153 * mp + 2) / 5 + 1; + let m = if mp < 10 { mp + 3 } else { mp - 9 }; + let y = if m <= 2 { y + 1 } else { y }; + (y, m, d) +} + +/// Finalize collection: zip the folder and print results. +fn finalize_collection(dir: &std::path::Path) { + println!(); + println!("\x1b[1;32m[collect]\x1b[0m Finalizing collection..."); + + let zip_path = dir.with_extension("zip"); + + // Use PowerShell Compress-Archive to create the zip. + let source = format!("{}\\*", dir.display()); + let dest = format!("{}", zip_path.display()); + + let result = std::process::Command::new("powershell.exe") + .args([ + "-NoProfile", + "-NonInteractive", + "-Command", + &format!( + "Compress-Archive -Path '{}' -DestinationPath '{}' -Force", + source, dest + ), + ]) + .status(); + + let zip_ok = match result { + Ok(status) if status.success() => true, + Ok(status) => { + eprintln!("\x1b[1;33m[collect]\x1b[0m Compress-Archive exited with status: {status}"); + false + } + Err(e) => { + eprintln!("\x1b[1;33m[collect]\x1b[0m Failed to run PowerShell: {e}"); + false + } + }; + + println!(); + println!("\x1b[1;36m=== Collection Complete ===\x1b[0m"); + println!(" Log folder: {}", dir.display()); + println!(" verbose.log (all ETW event properties)"); + println!(" minified.log (reduced ETW event properties)"); + if zip_ok { + println!(" Archive: {}", zip_path.display()); + } else { + println!(" Archive: (zip creation failed; logs are still in the folder above)"); + } + println!(); +} + /// Enable ANSI virtual terminal processing on the Windows console. fn enable_virtual_terminal() { use windows::Win32::System::Console::{ @@ -583,6 +857,16 @@ fn register_ctrl_handler() { unsafe extern "system" fn handler(ctrl_type: u32) -> windows_core::BOOL { if ctrl_type == CTRL_C_EVENT || ctrl_type == CTRL_CLOSE_EVENT { etw::stop_etw_listener(); + + if COLLECT_MODE_FLAG.load(Ordering::Relaxed) { + // First Ctrl+C: signal graceful shutdown and suppress default termination. + // Second Ctrl+C: allow default termination (hard exit). + if SHUTDOWN.swap(true, Ordering::SeqCst) { + // Already set -- this is the second interrupt. Hard exit. + return windows_core::BOOL(0); + } + return windows_core::BOOL(1); + } } // Return FALSE so the default handler terminates the process. windows_core::BOOL(0) diff --git a/src/wxc/src/main.rs b/src/wxc/src/main.rs index acb57e1dc..5a9edc2ba 100644 --- a/src/wxc/src/main.rs +++ b/src/wxc/src/main.rs @@ -101,7 +101,8 @@ fn log_request(request: &CodexRequest, logger: &mut Logger) { } fn display_script_results(response: &ScriptResponse, logger: &mut Logger) { - let _ = writeln!(logger, "Exit code: {}", response.exit_code); + let code = response.exit_code; + let _ = writeln!(logger, "Exit code: {} (0x{:08X})", code, code as u32); if !response.error_message.is_empty() { let _ = writeln!(logger, "Error: {}", response.error_message); } diff --git a/src/wxc_common/src/appcontainer_runner.rs b/src/wxc_common/src/appcontainer_runner.rs index 9bde6d9f3..d2ec992af 100644 --- a/src/wxc_common/src/appcontainer_runner.rs +++ b/src/wxc_common/src/appcontainer_runner.rs @@ -513,6 +513,7 @@ impl ScriptRunner for AppContainerScriptRunner { } let principal_id = self.get_principal_id(); + logger.log_line(&format!("AppContainerSID: {principal_id}")); let mut bfs_manager = FileSystemBfsManager::new(self.app_container_name.clone()); if let Err(e) = bfs_manager.configure(&request.policy, logger) { diff --git a/src/wxc_common/src/base_container_runner.rs b/src/wxc_common/src/base_container_runner.rs index 3d83ccaf3..abe156006 100644 --- a/src/wxc_common/src/base_container_runner.rs +++ b/src/wxc_common/src/base_container_runner.rs @@ -473,6 +473,10 @@ impl ScriptRunner for BaseContainerRunner { let _ = writeln!(logger, "launching: {}", request.script_code); let _ = writeln!(logger, "identity: {identity}"); + // Log the derived AppContainerSID for diagnostic correlation. + let ac_sid_str = derive_sid_string_from_name(&identity); + let _ = writeln!(logger, "AppContainerSID: {ac_sid_str}"); + // 4. Call Experimental_CreateProcessInSandbox. let success = unsafe { create_process_in_sandbox( @@ -563,6 +567,29 @@ impl ScriptRunner for BaseContainerRunner { } } +/// Derive the AppContainer SID string from a container identity name. +/// Best-effort: returns a placeholder if derivation fails. +fn derive_sid_string_from_name(name: &str) -> String { + use windows::Win32::Security::FreeSid; + use windows::Win32::Security::Isolation::DeriveAppContainerSidFromAppContainerName; + + let wide_name = string_util::to_wide(name); + let pcwstr_name = PCWSTR(wide_name.as_ptr()); + + match unsafe { DeriveAppContainerSidFromAppContainerName(pcwstr_name) } { + Ok(sid) => { + let s = unsafe { string_util::sid_to_string(sid.0, "unknown-sid") }; + // SAFETY: SID returned by DeriveAppContainerSidFromAppContainerName + // must be freed with FreeSid. + unsafe { + FreeSid(sid); + } + s + } + Err(_) => "unknown-sid".to_string(), + } +} + #[cfg(test)] mod tests { use super::*; diff --git a/src/wxc_common/src/logger.rs b/src/wxc_common/src/logger.rs index 976b6e079..ad661ba85 100644 --- a/src/wxc_common/src/logger.rs +++ b/src/wxc_common/src/logger.rs @@ -125,14 +125,10 @@ impl Logger { } } } - Err(e) => { - eprintln!( - "[MXC Diagnostics] Could not connect to diagnostic console at {pipe_path}: {e}" - ); - eprintln!( - "[MXC Diagnostics] Hint: Start mxc-diagnostic-console.exe first, \ - or disable console logging." - ); + Err(_) => { + // Diagnostic console is not running -- this is fine; continue silently. + // The user asked for console output (MXC_DIAG_CONSOLE=1) but the + // console process hasn't been started yet. } }