Trace ticket reattach recovery

Cargo.lock

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

Cargo.toml

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

README.md

@@ -68,6 +68,32 @@ 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 HOST
+```
+
+The client log path is printed before the session starts. To choose it:
+
+```sh
+dosh trace --client-log /tmp/dosh-client.log HOST
+```
+
+Summarize collected traces with:
+
+```sh
+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. 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
 
 Dosh can carry VS Code Remote-SSH through its transport:

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",
@@ -191,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(
@@ -1447,6 +1463,7 @@ async fn handle_ticket_attach(
     peer: SocketAddr,
     body: Vec<u8>,
 ) -> Result<()> {
+    dosh::trace::event("server.ticket_attach_start", &[("peer", peer.to_string())]);
     let env: TicketAttachEnvelope = protocol::from_body(&body)?;
     let opened = {
         let locked = state.lock().expect("server state poisoned");
@@ -1470,10 +1487,22 @@ async fn handle_ticket_attach(
     };
     let (ticket, request_plain) = match opened {
         Ok(opened) => opened,
-        Err(err) => return send_reject(socket, peer, &err.to_string()).await,
+        Err(err) => {
+            let reason = err.to_string();
+            dosh::trace::event("server.ticket_attach_reject", &[("reason", reason.clone())]);
+            return send_reject(socket, peer, &reason).await;
+        }
     };
     let req: TicketAttachBody = protocol::from_body(&request_plain)?;
     if req.session != ticket.session || req.mode != ticket.mode {
+        dosh::trace::event(
+            "server.ticket_attach_reject",
+            &[
+                ("session", req.session.clone()),
+                ("mode", req.mode.clone()),
+                ("reason", "ticket scope mismatch".to_string()),
+            ],
+        );
         return send_reject(socket, peer, "ticket scope mismatch").await;
     }
 
@@ -1544,7 +1573,18 @@ async fn handle_ticket_attach(
     };
     let (client_id, output_seq, snapshot) = match attached {
         Ok(attached) => attached,
-        Err(err) => return send_reject(socket, peer, &err.to_string()).await,
+        Err(err) => {
+            let reason = err.to_string();
+            dosh::trace::event(
+                "server.ticket_attach_reject",
+                &[
+                    ("session", req.session.clone()),
+                    ("mode", req.mode.clone()),
+                    ("reason", reason.clone()),
+                ],
+            );
+            return send_reject(socket, peer, &reason).await;
+        }
     };
 
     let ok = AttachOk {
@@ -1575,6 +1615,16 @@ async fn handle_ticket_attach(
     let body = protocol::to_body(&envelope)?;
     let out = protocol::encode_plain(PacketKind::AttachOk, client_id, 1, 0, &body)?;
     let _ = send_udp(socket, &out, peer).await?;
+    dosh::trace::event(
+        "server.ticket_attach_ok",
+        &[
+            ("session", ok.session.clone()),
+            ("mode", ok.mode.clone()),
+            ("client", hex_id(client_id)),
+            ("output_seq", output_seq.to_string()),
+            ("bytes", ok.snapshot.len().to_string()),
+        ],
+    );
     Ok(())
 }
 
@@ -1602,9 +1652,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 +1686,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 +1742,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 +1761,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 +1772,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 +1810,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(())
 }
 

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;

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<Option<Mutex<File>>> = OnceLock::new();
+static TRACE_BYTES: OnceLock<bool> = 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<Mutex<File>> {
+    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
+}