From 80e922957e2ef7444603bf9ade9e31e0f0630c37 Mon Sep 17 00:00:00 2001 From: DuProcess <273172371+DuProcess@users.noreply.github.com> Date: Sun, 12 Jul 2026 00:40:28 -0400 Subject: [PATCH] Trace reconnect mouse input handling --- Cargo.lock | 2 +- Cargo.toml | 2 +- README.md | 12 ++ src/bin/dosh-client.rs | 298 ++++++++++++++++++++++++++++++++++++++--- src/bin/dosh-server.rs | 80 +++++++++++ src/lib.rs | 1 + src/trace.rs | 161 ++++++++++++++++++++++ 7 files changed, 537 insertions(+), 19 deletions(-) create mode 100644 src/trace.rs diff --git a/Cargo.lock b/Cargo.lock index 9ec4132..c3729e9 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -436,7 +436,7 @@ dependencies = [ [[package]] name = "dosh" -version = "1.0.0-rc28" +version = "1.0.0-rc29" dependencies = [ "anyhow", "base64", diff --git a/Cargo.toml b/Cargo.toml index 29b91c5..c20c0cc 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,6 +1,6 @@ [package] name = "dosh" -version = "1.0.0-rc28" +version = "1.0.0-rc29" edition = "2024" license = "MIT" diff --git a/README.md b/README.md index 8e54494..80e13de 100644 --- a/README.md +++ b/README.md @@ -68,6 +68,18 @@ dosh restart HOST Agent forwarding is opt-in with `-A` and must also be enabled on the server. File copy must be enabled by the server config. +## Tracing + +For terminal/reconnect bugs, run a client with: + +```sh +DOSH_TRACE=/tmp/dosh-client.log DOSH_TRACE_BYTES=1 dosh HOST +``` + +Set `DOSH_TRACE=/tmp/dosh-server.log` on `dosh-server` for matching server +events. `DOSH_TRACE_BYTES=1` records byte prefixes, so use it only for short +reproductions. + ## VS Code Dosh can carry VS Code Remote-SSH through its transport: diff --git a/src/bin/dosh-client.rs b/src/bin/dosh-client.rs index db6a43f..3df627e 100644 --- a/src/bin/dosh-client.rs +++ b/src/bin/dosh-client.rs @@ -4878,7 +4878,12 @@ async fn run_terminal( stdin_msg = stdin_rx.recv() => { match stdin_msg { Some(mut bytes) => { + dosh::trace::event( + "client.stdin", + &[("bytes", dosh::trace::bytes_summary(&bytes))], + ); if input_matches_escape(&bytes, escape_key.as_deref()) { + dosh::trace::event("client.escape", &[]); break; } let saw_focus_in = input_contains_focus_in(&bytes); @@ -4886,6 +4891,10 @@ async fn run_terminal( && saw_focus_in && last_focus_repaint_at.elapsed() >= FOCUS_REPAINT_COOLDOWN { + dosh::trace::event( + "client.focus_reconnect_start", + &[("silent_ms", last_packet_at.elapsed().as_millis().to_string())], + ); last_focus_repaint_at = Instant::now(); if let Some(frame) = reconnect( &socket, @@ -4897,6 +4906,13 @@ async fn run_terminal( ) .await? { + dosh::trace::event( + "client.focus_reconnect_ok", + &[ + ("output_seq", frame.output_seq.to_string()), + ("bytes", frame.bytes.len().to_string()), + ], + ); refresh_live_addr(&mut addr, &cred)?; arm_stale_terminal_input_suppression( &mut stale_terminal_input_suppress_until, @@ -4917,15 +4933,60 @@ async fn run_terminal( .await?; } } + let before_focus_strip = bytes.len(); bytes = strip_terminal_focus_reports(&bytes); + if before_focus_strip != bytes.len() { + dosh::trace::event( + "client.focus_stripped", + &[ + ("before", before_focus_strip.to_string()), + ("after", bytes.len().to_string()), + ], + ); + } if bytes.is_empty() { continue; } + if should_strip_unowned_terminal_reports( + predictor.alternate_screen, + predictor.mouse_tracking, + ) { + let before_mouse_strip = bytes.len(); + bytes = strip_stale_mouse_reports(&bytes); + if before_mouse_strip != bytes.len() { + dosh::trace::event( + "client.unowned_mouse_stripped", + &[ + ("before", before_mouse_strip.to_string()), + ("after", bytes.len().to_string()), + ("summary", dosh::trace::bytes_summary(&bytes)), + ], + ); + } + if bytes.is_empty() { + continue; + } + } if should_strip_stale_terminal_reports( last_packet_at.elapsed(), stale_terminal_input_suppress_until, ) { + let before_mouse_strip = bytes.len(); bytes = strip_stale_mouse_reports(&bytes); + dosh::trace::event( + "client.stale_strip", + &[ + ("before", before_mouse_strip.to_string()), + ("after", bytes.len().to_string()), + ("silent_ms", last_packet_at.elapsed().as_millis().to_string()), + ( + "grace", + stale_terminal_input_suppress_until + .is_some_and(|deadline| Instant::now() < deadline) + .to_string(), + ), + ], + ); if bytes.is_empty() { continue; } @@ -4940,6 +5001,13 @@ async fn run_terminal( &bytes, ) { + dosh::trace::event( + "client.queue_startup_gate", + &[ + ("bytes", dosh::trace::bytes_summary(&bytes)), + ("pending", pending_user_input.len().to_string()), + ], + ); queue_pending_user_input( &mut pending_user_input, &mut pending_user_input_bytes, @@ -4967,6 +5035,10 @@ async fn run_terminal( if send_input(&socket, addr, &cred, &mut send_seq, send_now.clone()).await? { predictor.observe_input(&send_now)?; } else { + dosh::trace::event( + "client.queue_send_now_stale", + &[("bytes", dosh::trace::bytes_summary(&send_now))], + ); queue_stale_pending_user_input( &mut pending_user_input, &mut pending_user_input_bytes, @@ -4984,6 +5056,16 @@ async fn run_terminal( StartupGateMode::HoldAll }; if should_hold_post_submit_input(&hold_for_later) { + dosh::trace::event( + "client.queue_post_submit_control", + &[ + ( + "bytes", + dosh::trace::bytes_summary(&hold_for_later), + ), + ("pending", pending_user_input.len().to_string()), + ], + ); queue_pending_user_input( &mut pending_user_input, &mut pending_user_input_bytes, @@ -5002,6 +5084,13 @@ async fn run_terminal( if sent { predictor.observe_input(&hold_for_later)?; } else { + dosh::trace::event( + "client.queue_post_submit_stale", + &[( + "bytes", + dosh::trace::bytes_summary(&hold_for_later), + )], + ); queue_stale_pending_user_input( &mut pending_user_input, &mut pending_user_input_bytes, @@ -5012,6 +5101,13 @@ async fn run_terminal( continue; } if last_packet_at.elapsed() >= Duration::from_secs(2) { + dosh::trace::event( + "client.queue_disconnected", + &[ + ("bytes", dosh::trace::bytes_summary(&bytes)), + ("silent_ms", last_packet_at.elapsed().as_millis().to_string()), + ], + ); queue_stale_pending_user_input( &mut pending_user_input, &mut pending_user_input_bytes, @@ -5027,6 +5123,13 @@ async fn run_terminal( ) .await? { + dosh::trace::event( + "client.disconnected_reconnect_ok", + &[ + ("output_seq", frame.output_seq.to_string()), + ("bytes", frame.bytes.len().to_string()), + ], + ); refresh_live_addr(&mut addr, &cred)?; arm_stale_terminal_input_suppression( &mut stale_terminal_input_suppress_until, @@ -5052,6 +5155,10 @@ async fn run_terminal( if send_input(&socket, addr, &cred, &mut send_seq, bytes.clone()).await? { predictor.observe_input(&bytes)?; } else { + dosh::trace::event( + "client.queue_transient_send", + &[("bytes", dosh::trace::bytes_summary(&bytes))], + ); queue_stale_pending_user_input( &mut pending_user_input, &mut pending_user_input_bytes, @@ -6014,6 +6121,14 @@ async fn reconnect( frame_buffer: &mut FrameBuffer, predictor: &mut Predictor, ) -> Result> { + dosh::trace::event( + "client.reconnect_start", + &[ + ("session", cred.session.clone()), + ("mode", cred.mode.clone()), + ("last_rendered_seq", cred.last_rendered_seq.to_string()), + ], + ); if let Ok((frame, next)) = try_live_resume(socket, cred, send_seq, size.0, size.1).await { *cred = next; frame_buffer.clear(); @@ -6026,11 +6141,19 @@ async fn reconnect( send_seq, ) .await?; + dosh::trace::event( + "client.reconnect_live_ok", + &[ + ("output_seq", frame.output_seq.to_string()), + ("bytes", frame.bytes.len().to_string()), + ], + ); return Ok(Some(frame)); } let Ok((frame, next)) = try_ticket_attach(socket, cred, size.0, size.1, Vec::new()).await else { + dosh::trace::event("client.reconnect_none", &[]); return Ok(None); }; *cred = next; @@ -6045,6 +6168,13 @@ async fn reconnect( send_seq, ) .await?; + dosh::trace::event( + "client.reconnect_ticket_ok", + &[ + ("output_seq", frame.output_seq.to_string()), + ("bytes", frame.bytes.len().to_string()), + ], + ); Ok(Some(frame)) } @@ -6162,6 +6292,10 @@ fn should_strip_stale_terminal_reports( || suppress_until.is_some_and(|deadline| Instant::now() < deadline) } +fn should_strip_unowned_terminal_reports(alternate_screen: bool, mouse_tracking: bool) -> bool { + !alternate_screen && !mouse_tracking +} + fn input_contains_focus_in(bytes: &[u8]) -> bool { contains_bytes(bytes, b"\x1b[I") || contains_bytes(bytes, b"\x9bI") } @@ -6210,23 +6344,44 @@ async fn flush_pending_user_input( pending: &mut VecDeque, pending_bytes: &mut usize, ) -> Result<()> { + dosh::trace::event( + "client.pending_flush_start", + &[ + ("items", pending.len().to_string()), + ("bytes", pending_bytes.to_string()), + ], + ); while let Some(input) = pending.pop_front() { let PendingUserInput { bytes, strip_mouse_reports, } = input; *pending_bytes = pending_bytes.saturating_sub(bytes.len()); + let before_filter_len = bytes.len(); let bytes = if strip_mouse_reports { strip_stale_mouse_reports(&bytes) } else { bytes }; + dosh::trace::event( + "client.pending_flush_item", + &[ + ("before", before_filter_len.to_string()), + ("after", bytes.len().to_string()), + ("strip_mouse", strip_mouse_reports.to_string()), + ("summary", dosh::trace::bytes_summary(&bytes)), + ], + ); if bytes.is_empty() { continue; } if send_input(socket, addr, cred, send_seq, bytes.clone()).await? { predictor.observe_input(&bytes)?; } else { + dosh::trace::event( + "client.pending_flush_requeue", + &[("bytes", dosh::trace::bytes_summary(&bytes))], + ); requeue_pending_user_input_front( pending, pending_bytes, @@ -6397,6 +6552,8 @@ async fn send_input( send_seq: &mut u64, bytes: Vec, ) -> Result { + let seq = *send_seq; + let bytes_summary = dosh::trace::bytes_summary(&bytes); let body = protocol::to_body(&Input { bytes })?; let packet = protocol::encode_encrypted( PacketKind::Input, @@ -6408,7 +6565,17 @@ async fn send_input( &body, )?; *send_seq += 1; - send_terminal_udp(socket, &packet, addr).await + let sent = send_terminal_udp(socket, &packet, addr).await?; + dosh::trace::event( + "client.input_send", + &[ + ("seq", seq.to_string()), + ("ack", cred.last_rendered_seq.to_string()), + ("sent", sent.to_string()), + ("summary", bytes_summary), + ], + ); + Ok(sent) } async fn send_stream_open( @@ -6923,22 +7090,44 @@ const GLITCH_FORCE_MS: u128 = 250; /// without retaining arbitrary terminal output. const TERMINAL_OUTPUT_PARSE_TAIL: usize = 64; -fn alternate_screen_after_output(mut active: bool, bytes: &[u8]) -> bool { +#[derive(Clone, Copy, Debug, Default, Eq, PartialEq)] +struct TerminalModeChanges { + alternate_screen: Option, + mouse_tracking: Option, +} + +fn terminal_modes_after_output( + mut alternate_screen: bool, + mut mouse_tracking: bool, + bytes: &[u8], +) -> (bool, bool) { let mut offset = 0usize; while offset < bytes.len() { - let Some((next, transition)) = terminal_private_mode_transition(bytes, offset) else { + let Some((next, changes)) = terminal_private_mode_changes(bytes, offset) else { offset += 1; continue; }; - if let Some(enable) = transition { - active = enable; + if let Some(enable) = changes.alternate_screen { + alternate_screen = enable; + } + if let Some(enable) = changes.mouse_tracking { + mouse_tracking = enable; } offset = next.max(offset + 1); } - active + (alternate_screen, mouse_tracking) } +#[cfg(test)] fn terminal_private_mode_transition(bytes: &[u8], offset: usize) -> Option<(usize, Option)> { + terminal_private_mode_changes(bytes, offset) + .map(|(next, changes)| (next, changes.alternate_screen)) +} + +fn terminal_private_mode_changes( + bytes: &[u8], + offset: usize, +) -> Option<(usize, TerminalModeChanges)> { let mut cursor = offset; match bytes.get(cursor).copied()? { 0x1b if bytes.get(cursor + 1) == Some(&b'[') => cursor += 2, @@ -6957,10 +7146,18 @@ fn terminal_private_mode_transition(bytes: &[u8], offset: usize) -> Option<(usiz b'0'..=b'9' | b';' | b':' => cursor += 1, b'h' | b'l' => { let params = &bytes[params_start..cursor]; - let touches_alt = terminal_private_params_include_alt_screen(params); - return Some((cursor + 1, touches_alt.then_some(byte == b'h'))); + let enable = byte == b'h'; + return Some(( + cursor + 1, + TerminalModeChanges { + alternate_screen: terminal_private_params_include_alt_screen(params) + .then_some(enable), + mouse_tracking: terminal_private_params_include_mouse_tracking(params) + .then_some(enable), + }, + )); } - 0x40..=0x7e => return Some((cursor + 1, None)), + 0x40..=0x7e => return Some((cursor + 1, TerminalModeChanges::default())), _ => return None, } } @@ -6973,6 +7170,17 @@ fn terminal_private_params_include_alt_screen(params: &[u8]) -> bool { .any(|param| matches!(param, b"47" | b"1047" | b"1049")) } +fn terminal_private_params_include_mouse_tracking(params: &[u8]) -> bool { + params + .split(|byte| matches!(byte, b';' | b':')) + .any(|param| { + matches!( + param, + b"1000" | b"1001" | b"1002" | b"1003" | b"1005" | b"1006" | b"1015" + ) + }) +} + /// One speculatively-echoed character on the current line. #[derive(Clone, Debug)] struct PredictedCell { @@ -6990,6 +7198,10 @@ struct Predictor { /// as vim/htop); we never speculate there because we cannot model arbitrary /// cursor addressing safely. alternate_screen: bool, + /// True while the server-side program has requested terminal mouse reports. + /// When false, SGR mouse bytes from the local terminal are stale UI noise and + /// must not be forwarded into the shell prompt. + mouse_tracking: bool, /// Tail of recent terminal output, retained so alternate-screen transitions /// split across UDP frames are still detected. output_parse_tail: Vec, @@ -7039,6 +7251,7 @@ impl Predictor { mode, enabled: enabled && mode != PredictMode::Off, alternate_screen: false, + mouse_tracking: false, output_parse_tail: Vec::new(), cells: Vec::new(), cursor: 0, @@ -7062,6 +7275,7 @@ impl Predictor { self.epoch += 1; self.confirmed_epoch = self.epoch - 1; self.alternate_screen = false; + self.mouse_tracking = false; self.output_parse_tail.clear(); self.oldest_pending_at = None; } @@ -7223,11 +7437,27 @@ impl Predictor { parse.extend_from_slice(&self.output_parse_tail); parse.extend_from_slice(bytes); - let before = self.alternate_screen; - self.alternate_screen = alternate_screen_after_output(self.alternate_screen, &parse); - if self.alternate_screen != before { + let before_alternate_screen = self.alternate_screen; + let before_mouse_tracking = self.mouse_tracking; + let (alternate_screen, mouse_tracking) = + terminal_modes_after_output(self.alternate_screen, self.mouse_tracking, &parse); + self.alternate_screen = alternate_screen; + self.mouse_tracking = mouse_tracking; + if self.alternate_screen != before_alternate_screen { let _ = self.discard_all(); } + if self.alternate_screen != before_alternate_screen + || self.mouse_tracking != before_mouse_tracking + { + dosh::trace::event( + "client.terminal_modes", + &[ + ("alt", self.alternate_screen.to_string()), + ("mouse", self.mouse_tracking.to_string()), + ("bytes", dosh::trace::bytes_summary(bytes)), + ], + ); + } self.output_parse_tail.clear(); let keep = parse.len().min(TERMINAL_OUTPUT_PARSE_TAIL); @@ -8058,11 +8288,12 @@ mod tests { selected_predict_mode, selected_udp_host, server_version_mismatch, should_flush_terminal_input_after_contact, should_hold_during_startup_gate, should_hold_post_submit_input, should_repaint_idle_alternate_screen, - split_after_command_submit, ssh_command_target, ssh_config_uses_proxy, - ssh_destination_host, ssh_username, ssh_with_user, startup_command, status_ssh_target, - strip_stale_mouse_reports, strip_terminal_focus_reports, terminal_private_mode_transition, - toml_bare_key_or_quoted, unix_update_script, update_installer_url, update_version_status, - upsert_managed_block, valid_forward_host, vscode_safe_alias, windows_update_script, + should_strip_unowned_terminal_reports, split_after_command_submit, ssh_command_target, + ssh_config_uses_proxy, ssh_destination_host, ssh_username, ssh_with_user, startup_command, + status_ssh_target, strip_stale_mouse_reports, strip_terminal_focus_reports, + terminal_private_mode_transition, toml_bare_key_or_quoted, unix_update_script, + update_installer_url, update_version_status, upsert_managed_block, valid_forward_host, + vscode_safe_alias, windows_update_script, }; use dosh::config::{ClientConfig, CommandExtension, HostConfig}; use dosh::native::EnvVar; @@ -8832,6 +9063,33 @@ mod tests { assert!(!predictor.alternate_screen); } + #[test] + fn predictor_tracks_mouse_tracking_modes_separately_from_alternate_screen() { + let mut predictor = Predictor::new(true); + + predictor.observe_output(b"\x1b[?1000;1006h"); + assert!(!predictor.alternate_screen); + assert!(predictor.mouse_tracking); + + predictor.observe_output(b"\x1b[?1006;1000l"); + assert!(!predictor.mouse_tracking); + + predictor.observe_output(b"\x1b[?1000;1049h"); + assert!(predictor.alternate_screen); + assert!(predictor.mouse_tracking); + + predictor.observe_output(b"\x1b[?1049l"); + assert!(!predictor.alternate_screen); + assert!(predictor.mouse_tracking); + } + + #[test] + fn unowned_mouse_reports_are_stripped_only_outside_terminal_mouse_mode() { + assert!(should_strip_unowned_terminal_reports(false, false)); + assert!(!should_strip_unowned_terminal_reports(false, true)); + assert!(!should_strip_unowned_terminal_reports(true, false)); + } + #[test] fn predictor_tracks_alternate_screen_split_across_frames() { let mut predictor = Predictor::new(true); @@ -9740,6 +9998,12 @@ mod tests { assert_eq!(strip_stale_mouse_reports(b"152;1Mls\r"), b"ls\r"); } + #[test] + fn long_orphan_mouse_spam_is_stripped_from_pending_input() { + let input = b"35;152;1M35;149;1M35;147;1M35;144;2M35;141;3M0;107;10m35;106;10Mtm\r"; + assert_eq!(strip_stale_mouse_reports(input), b"tm\r"); + } + #[test] fn split_stale_mouse_suffixes_are_stripped_from_pending_input() { assert_eq!(strip_stale_mouse_reports(b"1M35;149;1Mls\r"), b"ls\r"); diff --git a/src/bin/dosh-server.rs b/src/bin/dosh-server.rs index 8ff159c..9c677a1 100644 --- a/src/bin/dosh-server.rs +++ b/src/bin/dosh-server.rs @@ -67,6 +67,15 @@ static AGENT_SOCK_COUNTER: AtomicU64 = AtomicU64::new(0); /// before it is swept by the cleanup task. const NATIVE_HANDSHAKE_TTL_SECS: u64 = 30; +fn hex_id(id: [u8; 16]) -> String { + let mut out = String::with_capacity(32); + for byte in id { + use std::fmt::Write as _; + let _ = write!(&mut out, "{byte:02x}"); + } + out +} + #[derive(Debug, Parser)] #[command( name = "dosh-server", @@ -1602,9 +1611,22 @@ async fn handle_resume( peer: SocketAddr, packet: &protocol::Packet, ) -> Result<()> { + dosh::trace::event( + "server.resume_start", + &[ + ("peer", peer.to_string()), + ("client", hex_id(packet.header.conn_id)), + ("seq", packet.header.seq.to_string()), + ("ack", packet.header.ack.to_string()), + ], + ); let (key, session_name) = match find_client_decrypt_key(state, &packet.header) { Ok(found) => found, Err(_) => { + dosh::trace::event( + "server.resume_unknown_client", + &[("client", hex_id(packet.header.conn_id))], + ); return send_reject_to_client(socket, peer, packet.header.conn_id, "unknown client") .await; } @@ -1623,8 +1645,25 @@ async fn handle_resume( .get_mut(&packet.header.conn_id) .ok_or_else(|| anyhow!("unknown client"))?; if !client.replay.accept(packet.header.seq) { + dosh::trace::event( + "server.resume_replay_drop", + &[ + ("session", req.session.clone()), + ("seq", packet.header.seq.to_string()), + ], + ); return Ok(()); } + if client.endpoint != peer { + dosh::trace::event( + "server.resume_roam", + &[ + ("session", req.session.clone()), + ("from", client.endpoint.to_string()), + ("to", peer.to_string()), + ], + ); + } client.endpoint = peer; client.last_acked = req.last_rendered_seq; client.cols = req.cols; @@ -1662,6 +1701,14 @@ async fn handle_resume( &body, )?; let _ = send_udp(socket, &out, peer).await?; + dosh::trace::event( + "server.resume_ok", + &[ + ("session", frame.session), + ("output_seq", frame.output_seq.to_string()), + ("bytes", frame.bytes.len().to_string()), + ], + ); Ok(()) } @@ -1673,6 +1720,7 @@ async fn handle_input( let (key, session_name) = find_client_decrypt_key(state, &packet.header)?; let body = protocol::decrypt_body(packet, &key, CLIENT_TO_SERVER)?; let input: Input = protocol::from_body(&body)?; + let input_summary = dosh::trace::bytes_summary(&input.bytes); let mut locked = state.lock().expect("server state poisoned"); let session = locked .sessions @@ -1683,13 +1731,37 @@ async fn handle_input( .get_mut(&packet.header.conn_id) .ok_or_else(|| anyhow!("unknown client"))?; if !client.replay.accept(packet.header.seq) { + dosh::trace::event( + "server.input_replay_drop", + &[ + ("session", session_name.clone()), + ("seq", packet.header.seq.to_string()), + ("summary", input_summary), + ], + ); return Ok(()); } if client.endpoint != peer { + dosh::trace::event( + "server.input_roam", + &[ + ("session", session_name.clone()), + ("from", client.endpoint.to_string()), + ("to", peer.to_string()), + ], + ); client.endpoint = peer; } client.last_seen = Instant::now(); if !mode_allows_terminal_updates(&client.mode) { + dosh::trace::event( + "server.input_rejected_mode", + &[ + ("session", session_name), + ("mode", client.mode.clone()), + ("summary", input_summary), + ], + ); return Ok(()); } session @@ -1697,6 +1769,14 @@ async fn handle_input( .as_ref() .context("terminal session has no pty")? .write_all(&input.bytes)?; + dosh::trace::event( + "server.pty_write", + &[ + ("session", session_name), + ("seq", packet.header.seq.to_string()), + ("summary", input_summary), + ], + ); Ok(()) } diff --git a/src/lib.rs b/src/lib.rs index e0d069d..14360cd 100644 --- a/src/lib.rs +++ b/src/lib.rs @@ -22,5 +22,6 @@ pub mod protocol; pub mod pty; pub mod server; pub mod ssh_agent; +pub mod trace; pub mod transport; pub mod udp; diff --git a/src/trace.rs b/src/trace.rs new file mode 100644 index 0000000..eaffc5d --- /dev/null +++ b/src/trace.rs @@ -0,0 +1,161 @@ +use std::fs::{File, OpenOptions}; +use std::io::Write; +use std::path::PathBuf; +use std::sync::{Mutex, OnceLock}; +use std::time::{SystemTime, UNIX_EPOCH}; + +static TRACE_FILE: OnceLock>> = OnceLock::new(); +static TRACE_BYTES: OnceLock = OnceLock::new(); + +pub fn enabled() -> bool { + TRACE_FILE.get_or_init(open_trace_file).is_some() +} + +pub fn bytes_enabled() -> bool { + *TRACE_BYTES.get_or_init(|| truthy_env("DOSH_TRACE_BYTES")) +} + +pub fn event(name: &str, fields: &[(&str, String)]) { + let Some(file) = TRACE_FILE.get_or_init(open_trace_file) else { + return; + }; + let now = SystemTime::now() + .duration_since(UNIX_EPOCH) + .map(|duration| duration.as_millis()) + .unwrap_or(0); + let mut line = format!( + "ts_ms={} pid={} event={}", + now, + std::process::id(), + shell_escape(name) + ); + for (key, value) in fields { + line.push(' '); + line.push_str(key); + line.push('='); + line.push_str(&shell_escape(value)); + } + line.push('\n'); + if let Ok(mut file) = file.lock() { + let _ = file.write_all(line.as_bytes()); + let _ = file.flush(); + } +} + +pub fn bytes_summary(bytes: &[u8]) -> String { + let mut parts = vec![ + format!("len={}", bytes.len()), + format!( + "esc={}", + contains_byte(bytes, 0x1b) || contains_byte(bytes, 0x9b) + ), + format!("focus={}", has_focus_report(bytes)), + format!("mouseish={}", looks_mouseish(bytes)), + format!("printable={}", printable_count(bytes)), + ]; + if bytes_enabled() { + parts.push(format!("hex={}", hex_prefix(bytes, 160))); + } + parts.join(",") +} + +fn open_trace_file() -> Option> { + let raw = std::env::var_os("DOSH_TRACE")?; + let normalized = raw.to_string_lossy().to_ascii_lowercase(); + if normalized.is_empty() || matches!(normalized.as_str(), "0" | "false" | "off") { + return None; + } + let path = if matches!(normalized.as_str(), "1" | "true" | "on") { + default_trace_path() + } else { + PathBuf::from(raw) + }; + if let Some(parent) = path.parent() { + let _ = std::fs::create_dir_all(parent); + } + OpenOptions::new() + .create(true) + .append(true) + .open(&path) + .ok() + .map(Mutex::new) +} + +fn default_trace_path() -> PathBuf { + let root = dirs::cache_dir() + .unwrap_or_else(std::env::temp_dir) + .join("dosh") + .join("trace"); + let exe = std::env::current_exe() + .ok() + .and_then(|path| { + path.file_stem() + .map(|stem| stem.to_string_lossy().to_string()) + }) + .unwrap_or_else(|| "dosh".to_string()); + root.join(format!("{}-{}.log", exe, std::process::id())) +} + +fn truthy_env(name: &str) -> bool { + std::env::var_os(name).is_some_and(|value| { + let normalized = value.to_string_lossy().to_ascii_lowercase(); + !normalized.is_empty() && !matches!(normalized.as_str(), "0" | "false" | "off") + }) +} + +fn shell_escape(value: &str) -> String { + if value.bytes().all(|byte| { + byte.is_ascii_alphanumeric() + || matches!(byte, b'.' | b'-' | b'_' | b':' | b'/' | b',' | b'=') + }) { + return value.to_string(); + } + let mut out = String::from("'"); + for ch in value.chars() { + if ch == '\'' { + out.push_str("'\\''"); + } else { + out.push(ch); + } + } + out.push('\''); + out +} + +fn contains_byte(bytes: &[u8], needle: u8) -> bool { + bytes.contains(&needle) +} + +fn has_focus_report(bytes: &[u8]) -> bool { + bytes + .windows(3) + .any(|window| matches!(window, b"\x1b[I" | b"\x1b[O")) + || bytes + .windows(2) + .any(|window| matches!(window, b"\x9bI" | b"\x9bO")) +} + +fn looks_mouseish(bytes: &[u8]) -> bool { + bytes.windows(3).any(|window| window == b"\x1b[<") + || bytes.windows(2).any(|window| window == b"\x9b<") + || bytes.iter().filter(|byte| **byte == b';').take(3).count() >= 2 +} + +fn printable_count(bytes: &[u8]) -> usize { + bytes + .iter() + .filter(|byte| byte.is_ascii_graphic() || **byte == b' ') + .count() +} + +fn hex_prefix(bytes: &[u8], max: usize) -> String { + let mut out = String::with_capacity(bytes.len().min(max) * 2); + for byte in bytes.iter().take(max) { + use std::fmt::Write as _; + let _ = write!(&mut out, "{byte:02x}"); + } + if bytes.len() > max { + out.push_str("..."); + } + out +}