Trace reconnect mouse input handling

Cargo.lock

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

Cargo.toml

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

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:

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<Option<Frame>> {
+    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<PendingUserInput>,
     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<u8>,
 ) -> Result<bool> {
+    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<bool>,
+    mouse_tracking: Option<bool>,
+}
+
+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<bool>)> {
+    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<u8>,
@@ -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");

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(())
 }
 

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
+}