Filter trace reports to latest run

Cargo.lock

@@ -436,7 +436,7 @@ dependencies = [
 
 [[package]]
 name = "dosh"
-version = "1.0.0-rc35"
+version = "1.0.0-rc36"
 dependencies = [
  "anyhow",
  "base64",

Cargo.toml

@@ -1,6 +1,6 @@
 [package]
 name = "dosh"
-version = "1.0.0-rc35"
+version = "1.0.0-rc36"
 edition = "2024"
 license = "MIT"
 

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
 

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<PathBuf>,
     server_log: Option<String>,
     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<u128>,
     last_ts_ms: Option<u128>,
     events: BTreeMap<String, usize>,
@@ -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<String>,
 }
@@ -893,12 +901,13 @@ fn parse_trace_report_options(command: &[String]) -> Result<TraceReportOptions>
     let mut client_log: Option<PathBuf> = None;
     let mut server_log: Option<String> = 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<TraceReportOptions>
             }
             "--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<TraceReportOptions>
                 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<TraceReportOptions>
             }
             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<TraceReportOptions>
         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<Option<PathBuf>> {
 }
 
 fn summarize_trace_file(path: &Path, tail: usize) -> Result<TraceReport> {
+    summarize_trace_file_with_mode(path, tail, true)
+}
+
+fn summarize_trace_file_for_report(
+    path: &Path,
+    tail: usize,
+    latest_run: bool,
+) -> Result<TraceReport> {
+    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<TraceReport> {
     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<TraceReport> {
         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<TraceReport> {
             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<String> {
     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<String> {
     warnings
 }
 
+fn trace_run_marker(event: &str) -> bool {
+    matches!(event, "client.start" | "server.start")
+}
+
 fn top_trace_events(events: &BTreeMap<String, usize>, 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!(

src/bin/dosh-server.rs

@@ -200,6 +200,13 @@ async fn serve(config_path: Option<std::path::PathBuf>) -> 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(