From 01e88705789461b9a529aa06002c16bda19a8221 Mon Sep 17 00:00:00 2001 From: DuProcess <273172371+DuProcess@users.noreply.github.com> Date: Sun, 12 Jul 2026 00:59:15 -0400 Subject: [PATCH] Add trace report summarizer --- Cargo.lock | 2 +- Cargo.toml | 2 +- README.md | 6 + src/bin/dosh-client.rs | 513 ++++++++++++++++++++++++++++++++++++++++- 4 files changed, 514 insertions(+), 9 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index bc184e1..531d7db 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -436,7 +436,7 @@ dependencies = [ [[package]] name = "dosh" -version = "1.0.0-rc30" +version = "1.0.0-rc31" dependencies = [ "anyhow", "base64", diff --git a/Cargo.toml b/Cargo.toml index 7d08590..6155aa3 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,6 +1,6 @@ [package] name = "dosh" -version = "1.0.0-rc30" +version = "1.0.0-rc31" edition = "2024" license = "MIT" diff --git a/README.md b/README.md index 07e6394..44d35f5 100644 --- a/README.md +++ b/README.md @@ -82,6 +82,12 @@ The client log path is printed before the session starts. To choose it: dosh trace --client-log /tmp/dosh-client.log HOST ``` +Summarize collected traces with: + +```sh +dosh trace report --client-log /tmp/dosh-client.log +``` + Set `DOSH_TRACE=/tmp/dosh-server.log` on `dosh-server` for matching server events. Trace byte prefixes are enabled for `dosh trace`, so use it only for short reproductions. diff --git a/src/bin/dosh-client.rs b/src/bin/dosh-client.rs index 725968a..2fb8b80 100644 --- a/src/bin/dosh-client.rs +++ b/src/bin/dosh-client.rs @@ -47,6 +47,8 @@ use std::collections::HashMap; use std::collections::HashSet; use std::collections::VecDeque; use std::fs; +use std::fs::File; +use std::io::{BufRead, BufReader}; use std::io::{Read, Seek, Write}; use std::net::{ Ipv4Addr, Ipv6Addr, SocketAddr, TcpListener as StdTcpListener, TcpStream as StdTcpStream, @@ -787,6 +789,35 @@ struct TraceOptions { bytes: bool, } +#[derive(Debug, Clone, PartialEq, Eq)] +struct TraceReportOptions { + client_log: Option, + server_log: Option, + tail: usize, +} + +#[derive(Debug, Default, Clone, PartialEq, Eq)] +struct TraceReport { + path: PathBuf, + total_lines: usize, + parsed_lines: usize, + first_ts_ms: Option, + last_ts_ms: Option, + events: BTreeMap, + mouseish_events: usize, + focus_events: usize, + escape_events: usize, + hex_events: usize, + stripped_mouse_events: usize, + queued_input_events: usize, + flushed_input_events: usize, + sent_input_events: usize, + pty_write_events: usize, + reconnect_events: usize, + roam_events: usize, + recent_events: VecDeque, +} + fn parse_trace_options(command: &[String]) -> Result { let mut client_log: Option = None; let mut bytes = true; @@ -851,6 +882,90 @@ fn parse_trace_options(command: &[String]) -> Result { }) } +fn parse_trace_report_options(command: &[String]) -> Result { + let mut client_log: Option = None; + let mut server_log: Option = Some(PathBuf::from("/tmp/dosh-server.log")); + let mut tail = 20usize; + let mut index = 0usize; + while index < command.len() { + match command[index].as_str() { + "--client-log" => { + let path = command.get(index + 1).ok_or_else(|| { + anyhow!("usage: dosh trace report [--client-log PATH] [--server-log PATH|none] [--tail N]") + })?; + client_log = Some(expand_tilde(path)); + index += 2; + } + value if value.starts_with("--client-log=") => { + let path = value + .strip_prefix("--client-log=") + .filter(|value| !value.is_empty()) + .ok_or_else(|| anyhow!("--client-log requires a path"))?; + client_log = Some(expand_tilde(path)); + index += 1; + } + "--server-log" => { + let path = command.get(index + 1).ok_or_else(|| { + anyhow!("usage: dosh trace report [--client-log PATH] [--server-log PATH|none] [--tail N]") + })?; + server_log = parse_optional_trace_path(path); + index += 2; + } + value if value.starts_with("--server-log=") => { + let path = value + .strip_prefix("--server-log=") + .ok_or_else(|| anyhow!("--server-log requires a path"))?; + server_log = parse_optional_trace_path(path); + index += 1; + } + "--no-server" => { + server_log = None; + index += 1; + } + "--tail" => { + let value = command.get(index + 1).ok_or_else(|| { + anyhow!("usage: dosh trace report [--client-log PATH] [--server-log PATH|none] [--tail N]") + })?; + tail = parse_trace_tail(value)?; + index += 2; + } + value if value.starts_with("--tail=") => { + let value = value + .strip_prefix("--tail=") + .ok_or_else(|| anyhow!("--tail requires a count"))?; + tail = parse_trace_tail(value)?; + index += 1; + } + value => { + return Err(anyhow!( + "usage: dosh trace report [--client-log PATH] [--server-log PATH|none] [--tail N] (unknown option {value})" + )); + } + } + } + Ok(TraceReportOptions { + client_log, + server_log, + tail, + }) +} + +fn parse_optional_trace_path(value: &str) -> Option { + if matches!(value, "" | "none" | "off" | "0") { + None + } else { + Some(expand_tilde(value)) + } +} + +fn parse_trace_tail(value: &str) -> Result { + let tail = value + .parse::() + .with_context(|| format!("parse trace tail count {value}"))?; + anyhow::ensure!(tail <= 500, "--tail must be 500 or less"); + Ok(tail) +} + fn default_client_trace_path(host: &str) -> PathBuf { let root = dirs::cache_dir() .unwrap_or_else(|| expand_tilde("~/.cache")) @@ -885,6 +1000,9 @@ fn sanitize_trace_name(value: &str) -> String { } fn run_trace_command(args: &Args) -> Result<()> { + if args.command.first().is_some_and(|value| value == "report") { + return run_trace_report_command(&args.command[1..]); + } let options = parse_trace_options(&args.command)?; if let Some(parent) = options.client_log.parent() { fs::create_dir_all(parent) @@ -919,6 +1037,297 @@ fn run_trace_command(args: &Args) -> Result<()> { Ok(()) } +fn run_trace_report_command(command: &[String]) -> Result<()> { + let options = parse_trace_report_options(command)?; + let client_log = match options.client_log { + Some(path) => Some(path), + None => newest_client_trace_path()?, + }; + println!("Dosh trace report"); + if let Some(path) = client_log { + match summarize_trace_file(&path, options.tail) { + Ok(report) => print_trace_report("client", &report), + Err(err) => println!("[warn] client log {}: {err:#}", path.display()), + } + } else { + println!( + "[warn] client log: none found under {}", + trace_cache_dir().display() + ); + } + if let Some(path) = options.server_log { + match summarize_trace_file(&path, options.tail) { + Ok(report) => print_trace_report("server", &report), + Err(err) + if err + .downcast_ref::() + .is_some_and(|io| io.kind() == std::io::ErrorKind::NotFound) => + { + println!("[warn] server log {}: not found", path.display()); + } + Err(err) => println!("[warn] server log {}: {err:#}", path.display()), + } + } + Ok(()) +} + +fn trace_cache_dir() -> PathBuf { + dirs::cache_dir() + .unwrap_or_else(|| expand_tilde("~/.cache")) + .join("dosh") + .join("trace") +} + +fn newest_client_trace_path() -> Result> { + let root = trace_cache_dir(); + let Ok(entries) = fs::read_dir(&root) else { + return Ok(None); + }; + let mut newest: Option<(SystemTime, PathBuf)> = None; + for entry in entries { + let entry = entry?; + let path = entry.path(); + if !path.is_file() { + continue; + } + let Some(name) = path.file_name().and_then(|value| value.to_str()) else { + continue; + }; + if !(name.starts_with("client-") + || name.starts_with("dosh-client-") + || name.starts_with("dosh-")) + || !name.ends_with(".log") + { + continue; + } + let modified = entry + .metadata() + .and_then(|metadata| metadata.modified()) + .unwrap_or(SystemTime::UNIX_EPOCH); + if newest + .as_ref() + .is_none_or(|(old_modified, _)| modified > *old_modified) + { + newest = Some((modified, path)); + } + } + Ok(newest.map(|(_, path)| path)) +} + +fn summarize_trace_file(path: &Path, tail: usize) -> Result { + let file = File::open(path).with_context(|| format!("open trace log {}", path.display()))?; + let mut report = TraceReport { + path: path.to_path_buf(), + ..TraceReport::default() + }; + for line in BufReader::new(file).lines() { + let line = line?; + report.total_lines += 1; + let Some(fields) = parse_trace_line(&line) else { + continue; + }; + report.parsed_lines += 1; + if let Some(ts) = fields + .get("ts_ms") + .and_then(|value| value.parse::().ok()) + { + report.first_ts_ms.get_or_insert(ts); + report.last_ts_ms = Some(ts); + } + let event = fields + .get("event") + .cloned() + .unwrap_or_else(|| "".to_string()); + *report.events.entry(event.clone()).or_insert(0) += 1; + let summary = fields + .get("bytes") + .or_else(|| fields.get("summary")) + .map(|value| parse_trace_summary(value)) + .unwrap_or_default(); + if summary.get("mouseish").is_some_and(|value| value == "true") { + report.mouseish_events += 1; + } + if summary.get("focus").is_some_and(|value| value == "true") { + report.focus_events += 1; + } + if summary.get("esc").is_some_and(|value| value == "true") { + report.escape_events += 1; + } + if summary.contains_key("hex") { + report.hex_events += 1; + } + if event.contains("mouse_stripped") || event == "client.stale_strip" { + report.stripped_mouse_events += 1; + } + if event.starts_with("client.queue_") { + report.queued_input_events += 1; + } + if event.starts_with("client.pending_flush") { + report.flushed_input_events += 1; + } + if event == "client.input_send" { + report.sent_input_events += 1; + } + if event == "server.pty_write" { + report.pty_write_events += 1; + } + if event.contains("reconnect") || event.contains("resume") { + report.reconnect_events += 1; + } + if event.contains("roam") { + report.roam_events += 1; + } + if tail > 0 { + let rendered = render_trace_event(&fields); + if report.recent_events.len() == tail { + report.recent_events.pop_front(); + } + report.recent_events.push_back(rendered); + } + } + Ok(report) +} + +fn print_trace_report(label: &str, report: &TraceReport) { + println!(); + println!("{label}: {}", report.path.display()); + println!( + " lines={} parsed={} span_ms={}", + report.total_lines, + report.parsed_lines, + report + .first_ts_ms + .zip(report.last_ts_ms) + .map(|(first, last)| last.saturating_sub(first).to_string()) + .unwrap_or_else(|| "unknown".to_string()) + ); + println!( + " input: sent={} queued={} flushed={} pty_writes={}", + report.sent_input_events, + report.queued_input_events, + report.flushed_input_events, + report.pty_write_events + ); + println!( + " terminal: mouseish={} stripped={} focus={} esc={} hex={}", + report.mouseish_events, + report.stripped_mouse_events, + report.focus_events, + report.escape_events, + report.hex_events + ); + println!( + " reconnect: events={} roam={}", + report.reconnect_events, report.roam_events + ); + if !report.events.is_empty() { + println!(" top events:"); + for (event, count) in top_trace_events(&report.events, 8) { + println!(" {count:>5} {event}"); + } + } + if !report.recent_events.is_empty() { + println!(" recent:"); + for event in &report.recent_events { + println!(" {event}"); + } + } +} + +fn top_trace_events(events: &BTreeMap, limit: usize) -> Vec<(String, usize)> { + let mut entries: Vec<_> = events + .iter() + .map(|(event, count)| (event.clone(), *count)) + .collect(); + entries.sort_by(|left, right| right.1.cmp(&left.1).then_with(|| left.0.cmp(&right.0))); + entries.truncate(limit); + entries +} + +fn render_trace_event(fields: &BTreeMap) -> String { + let ts = fields.get("ts_ms").map(String::as_str).unwrap_or("?"); + let event = fields + .get("event") + .map(String::as_str) + .unwrap_or(""); + let mut parts = vec![format!("{ts} {event}")]; + for key in [ + "seq", + "ack", + "sent", + "before", + "after", + "summary", + "bytes", + "silent_ms", + ] { + if let Some(value) = fields.get(key) { + parts.push(format!("{key}={value}")); + } + } + parts.join(" ") +} + +fn parse_trace_line(line: &str) -> Option> { + let mut fields = BTreeMap::new(); + for token in split_trace_tokens(line)? { + let (key, value) = token.split_once('=')?; + fields.insert(key.to_string(), value.to_string()); + } + Some(fields) +} + +fn split_trace_tokens(line: &str) -> Option> { + let mut tokens = Vec::new(); + let mut current = String::new(); + let mut chars = line.chars().peekable(); + let mut quoted = false; + while let Some(ch) = chars.next() { + if quoted { + if ch == '\'' { + if chars.peek() == Some(&'\\') { + chars.next(); + if chars.next() != Some('\'') || chars.next() != Some('\'') { + return None; + } + current.push('\''); + } else { + quoted = false; + } + } else { + current.push(ch); + } + continue; + } + if ch == '\'' { + quoted = true; + } else if ch.is_ascii_whitespace() { + if !current.is_empty() { + tokens.push(std::mem::take(&mut current)); + } + } else { + current.push(ch); + } + } + if quoted { + return None; + } + if !current.is_empty() { + tokens.push(current); + } + Some(tokens) +} + +fn parse_trace_summary(summary: &str) -> BTreeMap { + let mut fields = BTreeMap::new(); + for part in summary.split(',') { + if let Some((key, value)) = part.split_once('=') { + fields.insert(key.to_string(), value.to_string()); + } + } + fields +} + fn push_trace_passthrough_args(command: &mut Command, args: &Args) { if let Some(session) = &args.session { command.arg("--session").arg(session); @@ -8501,7 +8910,8 @@ mod tests { input_matches_escape, is_local_status_target, is_resume_response_for_client, latest_release_download_url, load_first_native_identity_with_prompt, native_proxy_udp_warning, parse_dynamic_forward, parse_escape_key, parse_local_forward, - parse_remote_forward, parse_ssh_config, parse_trace_options, parse_update_options, + parse_remote_forward, parse_ssh_config, parse_trace_line, parse_trace_options, + parse_trace_report_options, parse_trace_summary, parse_update_options, post_submit_hold_duration, queue_pending_user_input, raw_contains_host_table, recv_response_until, refresh_live_addr, release_tag_download_url, release_tag_from_effective_url, release_version_from_tag, render_status_clear, @@ -8510,12 +8920,13 @@ 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, - 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, + should_strip_unowned_terminal_reports, split_after_command_submit, split_trace_tokens, + 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, summarize_trace_file, terminal_private_mode_transition, + toml_bare_key_or_quoted, top_trace_events, 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; @@ -9819,6 +10230,32 @@ mod tests { assert!(parse_trace_options(&[]).is_err()); } + #[test] + fn trace_report_options_parse_defaults_and_overrides() { + let parsed = parse_trace_report_options(&[]).unwrap(); + assert_eq!(parsed.client_log, None); + assert_eq!( + parsed.server_log, + Some(std::path::PathBuf::from("/tmp/dosh-server.log")) + ); + assert_eq!(parsed.tail, 20); + + let parsed = parse_trace_report_options(&[ + "--client-log=/tmp/client.log".to_string(), + "--server-log".to_string(), + "none".to_string(), + "--tail".to_string(), + "3".to_string(), + ]) + .unwrap(); + assert_eq!( + parsed.client_log, + Some(std::path::PathBuf::from("/tmp/client.log")) + ); + assert_eq!(parsed.server_log, None); + assert_eq!(parsed.tail, 3); + } + #[test] fn trace_log_name_is_shell_and_path_safe() { assert_eq!(sanitize_trace_name("palav"), "palav"); @@ -9826,6 +10263,68 @@ mod tests { assert_eq!(sanitize_trace_name(""), "host"); } + #[test] + fn trace_line_parser_handles_shell_quoted_values() { + let tokens = + split_trace_tokens("ts_ms=1 event='client stdin' bytes='len=1,hex=27'").unwrap(); + assert_eq!( + tokens, + vec![ + "ts_ms=1".to_string(), + "event=client stdin".to_string(), + "bytes=len=1,hex=27".to_string() + ] + ); + let parsed = + parse_trace_line("ts_ms=1 event=client.stdin bytes=len=3,esc=true,mouseish=false") + .unwrap(); + assert_eq!(parsed["event"], "client.stdin"); + assert_eq!(parsed["bytes"], "len=3,esc=true,mouseish=false"); + } + + #[test] + fn trace_summary_parser_counts_properties() { + let parsed = parse_trace_summary("len=3,esc=true,focus=false,mouseish=true,hex=1b5b41"); + assert_eq!(parsed["len"], "3"); + assert_eq!(parsed["esc"], "true"); + assert_eq!(parsed["mouseish"], "true"); + assert_eq!(parsed["hex"], "1b5b41"); + } + + #[test] + fn trace_report_summarizes_terminal_and_reconnect_events() { + let dir = tempfile::tempdir().unwrap(); + let path = dir.path().join("client.log"); + fs::write( + &path, + concat!( + "ts_ms=10 pid=1 event=client.stdin bytes=len=9,esc=true,focus=false,mouseish=true,printable=7,hex=313b324d\n", + "ts_ms=12 pid=1 event=client.unowned_mouse_stripped before=9 after=0 summary=len=0,esc=false,focus=false,mouseish=false,printable=0\n", + "ts_ms=15 pid=1 event=client.queue_disconnected bytes=len=1,esc=false,focus=false,mouseish=false,printable=1 silent_ms=2000\n", + "ts_ms=20 pid=1 event=client.reconnect_live_ok output_seq=3 bytes=12\n", + "ts_ms=25 pid=1 event=client.input_send seq=4 ack=3 sent=true summary=len=1,esc=false,focus=false,mouseish=false,printable=1\n", + ), + ) + .unwrap(); + + let report = summarize_trace_file(&path, 2).unwrap(); + + assert_eq!(report.total_lines, 5); + assert_eq!(report.parsed_lines, 5); + assert_eq!(report.mouseish_events, 1); + assert_eq!(report.escape_events, 1); + assert_eq!(report.hex_events, 1); + assert_eq!(report.stripped_mouse_events, 1); + assert_eq!(report.queued_input_events, 1); + assert_eq!(report.sent_input_events, 1); + assert_eq!(report.reconnect_events, 1); + assert_eq!(report.recent_events.len(), 2); + assert_eq!( + top_trace_events(&report.events, 1), + vec![("client.input_send".to_string(), 1)] + ); + } + #[test] fn update_installer_uses_platform_native_script() { assert_eq!(