diff --git a/Cargo.lock b/Cargo.lock index 91fb275..d4f8daa 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -436,7 +436,7 @@ dependencies = [ [[package]] name = "dosh" -version = "1.0.0-rc35" +version = "1.0.0-rc36" dependencies = [ "anyhow", "base64", diff --git a/Cargo.toml b/Cargo.toml index b70ac73..417e4ec 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,6 +1,6 @@ [package] name = "dosh" -version = "1.0.0-rc35" +version = "1.0.0-rc36" edition = "2024" license = "MIT" diff --git a/README.md b/README.md index 8e4b5f9..c967482 100644 --- a/README.md +++ b/README.md @@ -90,8 +90,9 @@ dosh trace report HOST --client-log /tmp/dosh-client.log When `HOST` is given, Dosh fetches `/tmp/dosh-server.log` over SSH before building the report. 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. +matching server events. Reports default to the latest traced client/server +process run; add `--all-runs` to include older appended log entries. Trace byte +prefixes are enabled for `dosh trace`, so use it only for short reproductions. ## VS Code diff --git a/src/bin/dosh-client.rs b/src/bin/dosh-client.rs index 9575ffe..7ea719f 100644 --- a/src/bin/dosh-client.rs +++ b/src/bin/dosh-client.rs @@ -246,6 +246,10 @@ enum StartupGateMode { #[tokio::main(flavor = "current_thread")] async fn main() -> Result<()> { let mut args = Args::parse(); + dosh::trace::event( + "client.start", + &[("version", dosh::build_info::VERSION.to_string())], + ); let config = load_client_config(None).unwrap_or_default(); if args.server.as_deref() == Some("cp") { return run_cp_command(&config, &args); @@ -796,6 +800,7 @@ struct TraceReportOptions { client_log: Option, server_log: Option, tail: usize, + latest_run: bool, } #[derive(Debug, Default, Clone, PartialEq, Eq)] @@ -803,6 +808,8 @@ struct TraceReport { path: PathBuf, total_lines: usize, parsed_lines: usize, + skipped_old_run_lines: usize, + latest_run_filtered: bool, first_ts_ms: Option, last_ts_ms: Option, events: BTreeMap, @@ -820,6 +827,7 @@ struct TraceReport { sent_input_events: usize, pty_write_events: usize, reconnect_events: usize, + unknown_resume_events: usize, roam_events: usize, recent_events: VecDeque, } @@ -893,12 +901,13 @@ fn parse_trace_report_options(command: &[String]) -> Result let mut client_log: Option = None; let mut server_log: Option = Some("/tmp/dosh-server.log".to_string()); let mut tail = 20usize; + let mut latest_run = true; 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 [HOST] [--client-log PATH] [--server-log PATH|none] [--tail N]") + anyhow!("usage: dosh trace report [HOST] [--client-log PATH] [--server-log PATH|none] [--latest-run|--all-runs] [--tail N]") })?; client_log = Some(expand_tilde(path)); index += 2; @@ -913,7 +922,7 @@ fn parse_trace_report_options(command: &[String]) -> Result } "--server-log" => { let path = command.get(index + 1).ok_or_else(|| { - anyhow!("usage: dosh trace report [HOST] [--client-log PATH] [--server-log PATH|none] [--tail N]") + anyhow!("usage: dosh trace report [HOST] [--client-log PATH] [--server-log PATH|none] [--latest-run|--all-runs] [--tail N]") })?; server_log = parse_optional_trace_path(path); index += 2; @@ -929,9 +938,17 @@ fn parse_trace_report_options(command: &[String]) -> Result server_log = None; index += 1; } + "--latest-run" => { + latest_run = true; + index += 1; + } + "--all-runs" => { + latest_run = false; + index += 1; + } "--tail" => { let value = command.get(index + 1).ok_or_else(|| { - anyhow!("usage: dosh trace report [HOST] [--client-log PATH] [--server-log PATH|none] [--tail N]") + anyhow!("usage: dosh trace report [HOST] [--client-log PATH] [--server-log PATH|none] [--latest-run|--all-runs] [--tail N]") })?; tail = parse_trace_tail(value)?; index += 2; @@ -945,13 +962,13 @@ fn parse_trace_report_options(command: &[String]) -> Result } value if value.starts_with('-') => { return Err(anyhow!( - "usage: dosh trace report [HOST] [--client-log PATH] [--server-log PATH|none] [--tail N] (unknown option {value})" + "usage: dosh trace report [HOST] [--client-log PATH] [--server-log PATH|none] [--latest-run|--all-runs] [--tail N] (unknown option {value})" )); } value => { if host.is_some() { return Err(anyhow!( - "usage: dosh trace report [host] [--client-log PATH] [--server-log PATH|none] [--tail N]" + "usage: dosh trace report [HOST] [--client-log PATH] [--server-log PATH|none] [--latest-run|--all-runs] [--tail N]" )); } host = Some(value.to_string()); @@ -964,6 +981,7 @@ fn parse_trace_report_options(command: &[String]) -> Result client_log, server_log, tail, + latest_run, }) } @@ -1067,7 +1085,7 @@ fn run_trace_report_command( }; println!("Dosh trace report"); if let Some(path) = client_log { - match summarize_trace_file(&path, options.tail) { + match summarize_trace_file_for_report(&path, options.tail, options.latest_run) { Ok(report) => print_trace_report("client", &report), Err(err) => println!("[warn] client log {}: {err:#}", path.display()), } @@ -1092,7 +1110,7 @@ fn run_trace_report_command( let Some(path) = server_log else { return Ok(()); }; - match summarize_trace_file(&path, options.tail) { + match summarize_trace_file_for_report(&path, options.tail, options.latest_run) { Ok(report) => print_trace_report("server", &report), Err(err) if err @@ -1211,17 +1229,56 @@ fn newest_client_trace_path() -> Result> { } fn summarize_trace_file(path: &Path, tail: usize) -> Result { + summarize_trace_file_with_mode(path, tail, true) +} + +fn summarize_trace_file_for_report( + path: &Path, + tail: usize, + latest_run: bool, +) -> Result { + if latest_run { + summarize_trace_file(path, tail) + } else { + summarize_trace_file_with_mode(path, tail, false) + } +} + +fn summarize_trace_file_with_mode( + path: &Path, + tail: usize, + latest_run: bool, +) -> 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() - }; + let mut parsed = Vec::new(); + let mut file_lines = 0usize; for line in BufReader::new(file).lines() { let line = line?; - report.total_lines += 1; - let Some(fields) = parse_trace_line(&line) else { - continue; - }; + file_lines += 1; + if let Some(fields) = parse_trace_line(&line) { + parsed.push(fields); + } + } + let latest_run_start = if latest_run { + parsed.iter().rposition(|fields| { + fields + .get("event") + .is_some_and(|event| trace_run_marker(event)) + }) + } else { + None + }; + let parsed_len = parsed.len(); + let skipped_old_run_lines = latest_run_start.unwrap_or(0); + let latest_run_filtered = latest_run_start.is_some_and(|index| index > 0); + let mut report = TraceReport { + path: path.to_path_buf(), + total_lines: file_lines.saturating_sub(skipped_old_run_lines), + skipped_old_run_lines, + latest_run_filtered, + ..TraceReport::default() + }; + for fields in parsed.into_iter().skip(skipped_old_run_lines) { report.parsed_lines += 1; if let Some(ts) = fields .get("ts_ms") @@ -1284,6 +1341,9 @@ fn summarize_trace_file(path: &Path, tail: usize) -> Result { if event.contains("reconnect") || event.contains("resume") { report.reconnect_events += 1; } + if event == "server.resume_unknown_client" { + report.unknown_resume_events += 1; + } if event.contains("roam") { report.roam_events += 1; } @@ -1295,12 +1355,21 @@ fn summarize_trace_file(path: &Path, tail: usize) -> Result { report.recent_events.push_back(rendered); } } + if report.total_lines == 0 && parsed_len > 0 { + report.total_lines = parsed_len; + } Ok(report) } fn print_trace_report(label: &str, report: &TraceReport) { println!(); println!("{label}: {}", report.path.display()); + if report.latest_run_filtered { + println!( + " latest_run=true skipped_old_lines={}", + report.skipped_old_run_lines + ); + } println!( " lines={} parsed={} span_ms={}", report.total_lines, @@ -1331,8 +1400,8 @@ fn print_trace_report(label: &str, report: &TraceReport) { report.hex_events ); println!( - " reconnect: events={} roam={}", - report.reconnect_events, report.roam_events + " reconnect: events={} unknown_resume={} roam={}", + report.reconnect_events, report.unknown_resume_events, report.roam_events ); for warning in trace_report_warnings(report) { println!(" alert: {warning}"); @@ -1353,6 +1422,12 @@ fn print_trace_report(label: &str, report: &TraceReport) { fn trace_report_warnings(report: &TraceReport) -> Vec { let mut warnings = Vec::new(); + if report.unknown_resume_events > 0 { + warnings.push(format!( + "{} unknown live resume event(s); ticket reattach should follow after server restart", + report.unknown_resume_events + )); + } if report.server_mouseish_pty_write_events > 0 { warnings.push(format!( "{} mouse-like input event(s) reached the server PTY", @@ -1383,6 +1458,10 @@ fn trace_report_warnings(report: &TraceReport) -> Vec { warnings } +fn trace_run_marker(event: &str) -> bool { + matches!(event, "client.start" | "server.start") +} + fn top_trace_events(events: &BTreeMap, limit: usize) -> Vec<(String, usize)> { let mut entries: Vec<_> = events .iter() @@ -9174,10 +9253,10 @@ mod tests { 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, strip_unowned_terminal_reports, - summarize_trace_file, terminal_private_mode_transition, toml_bare_key_or_quoted, - top_trace_events, trace_report_warnings, unix_update_script, update_installer_url, - update_version_status, upsert_managed_block, valid_forward_host, vscode_safe_alias, - windows_update_script, + summarize_trace_file, summarize_trace_file_with_mode, terminal_private_mode_transition, + toml_bare_key_or_quoted, top_trace_events, trace_report_warnings, 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; @@ -10488,12 +10567,14 @@ mod tests { assert_eq!(parsed.client_log, None); assert_eq!(parsed.server_log, Some("/tmp/dosh-server.log".to_string())); assert_eq!(parsed.tail, 20); + assert!(parsed.latest_run); let parsed = parse_trace_report_options(&[ "palav".to_string(), "--client-log=/tmp/client.log".to_string(), "--server-log".to_string(), "/tmp/server.log".to_string(), + "--all-runs".to_string(), "--tail".to_string(), "3".to_string(), ]) @@ -10505,9 +10586,15 @@ mod tests { ); assert_eq!(parsed.server_log.as_deref(), Some("/tmp/server.log")); assert_eq!(parsed.tail, 3); + assert!(!parsed.latest_run); - let parsed = parse_trace_report_options(&["--server-log=none".to_string()]).unwrap(); + let parsed = parse_trace_report_options(&[ + "--server-log=none".to_string(), + "--latest-run".to_string(), + ]) + .unwrap(); assert_eq!(parsed.server_log, None); + assert!(parsed.latest_run); } #[test] @@ -10618,6 +10705,35 @@ mod tests { ); } + #[test] + fn trace_report_defaults_to_latest_process_run_when_marker_exists() { + let dir = tempfile::tempdir().unwrap(); + let path = dir.path().join("server.log"); + fs::write( + &path, + concat!( + "ts_ms=10 pid=1 event=server.pty_write session=term seq=1 summary=len=12,esc=false,focus=false,mouseish=true,printable=12\n", + "ts_ms=20 pid=2 event=server.start version=1.0.0 bind=0.0.0.0:50000\n", + "ts_ms=21 pid=2 event=server.resume_start seq=2 ack=1\n", + "ts_ms=22 pid=2 event=server.resume_ok bytes=20\n", + ), + ) + .unwrap(); + + let latest = summarize_trace_file(&path, 10).unwrap(); + assert!(latest.latest_run_filtered); + assert_eq!(latest.skipped_old_run_lines, 1); + assert_eq!(latest.total_lines, 3); + assert_eq!(latest.server_mouseish_pty_write_events, 0); + assert_eq!(latest.reconnect_events, 2); + + let all = summarize_trace_file_with_mode(&path, 10, false).unwrap(); + assert!(!all.latest_run_filtered); + assert_eq!(all.skipped_old_run_lines, 0); + assert_eq!(all.total_lines, 4); + assert_eq!(all.server_mouseish_pty_write_events, 1); + } + #[test] fn update_installer_uses_platform_native_script() { assert_eq!( diff --git a/src/bin/dosh-server.rs b/src/bin/dosh-server.rs index 9c677a1..faef1d3 100644 --- a/src/bin/dosh-server.rs +++ b/src/bin/dosh-server.rs @@ -200,6 +200,13 @@ async fn serve(config_path: Option) -> Result<()> { .with_context(|| format!("bind {bind}"))?, ); eprintln!("dosh-server listening on {bind}"); + dosh::trace::event( + "server.start", + &[ + ("version", dosh::build_info::VERSION.to_string()), + ("bind", bind.clone()), + ], + ); let (pty_tx, mut pty_rx) = mpsc::unbounded_channel(); let state = Arc::new(Mutex::new(ServerState::new(