Repaint terminal after local sleep

Cargo.lock

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

Cargo.toml

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

src/bin/dosh-client.rs

@@ -74,6 +74,7 @@ const STALE_TERMINAL_INPUT_AFTER: Duration = Duration::from_secs(2);
 const POST_RECONNECT_STALE_INPUT_GRACE: Duration = Duration::from_secs(2);
 const FOCUS_REPAINT_COOLDOWN: Duration = Duration::from_secs(1);
 const ALT_SCREEN_IDLE_REPAINT_AFTER: Duration = Duration::from_secs(15);
+const LOCAL_SLEEP_REPAINT_AFTER: Duration = Duration::from_secs(5);
 
 /// Sentinel `target_host` the server uses on a server-initiated `StreamOpen` that
 /// represents an SSH-agent connection (rather than a TCP target). The client
@@ -809,6 +810,10 @@ struct TraceReport {
     escape_events: usize,
     hex_events: usize,
     stripped_mouse_events: usize,
+    client_mouseish_sent_events: usize,
+    server_mouseish_pty_write_events: usize,
+    server_rejected_input_events: usize,
+    replay_drop_events: usize,
     queued_input_events: usize,
     flushed_input_events: usize,
     sent_input_events: usize,
@@ -1159,6 +1164,11 @@ fn summarize_trace_file(path: &Path, tail: usize) -> Result<TraceReport> {
         if event.contains("mouse_stripped") || event == "client.stale_strip" {
             report.stripped_mouse_events += 1;
         }
+        if event == "client.input_send"
+            && summary.get("mouseish").is_some_and(|value| value == "true")
+        {
+            report.client_mouseish_sent_events += 1;
+        }
         if event.starts_with("client.queue_") {
             report.queued_input_events += 1;
         }
@@ -1170,6 +1180,15 @@ fn summarize_trace_file(path: &Path, tail: usize) -> Result<TraceReport> {
         }
         if event == "server.pty_write" {
             report.pty_write_events += 1;
+            if summary.get("mouseish").is_some_and(|value| value == "true") {
+                report.server_mouseish_pty_write_events += 1;
+            }
+        }
+        if event == "server.input_rejected_mode" {
+            report.server_rejected_input_events += 1;
+        }
+        if event.contains("replay_drop") {
+            report.replay_drop_events += 1;
         }
         if event.contains("reconnect") || event.contains("resume") {
             report.reconnect_events += 1;
@@ -1202,15 +1221,19 @@ fn print_trace_report(label: &str, report: &TraceReport) {
             .unwrap_or_else(|| "unknown".to_string())
     );
     println!(
-        "  input: sent={} queued={} flushed={} pty_writes={}",
+        "  input: sent={} queued={} flushed={} pty_writes={} rejected={} replay_drops={}",
         report.sent_input_events,
         report.queued_input_events,
         report.flushed_input_events,
-        report.pty_write_events
+        report.pty_write_events,
+        report.server_rejected_input_events,
+        report.replay_drop_events
     );
     println!(
-        "  terminal: mouseish={} stripped={} focus={} esc={} hex={}",
+        "  terminal: mouseish={} client_mouse_sent={} server_mouse_pty={} stripped={} focus={} esc={} hex={}",
         report.mouseish_events,
+        report.client_mouseish_sent_events,
+        report.server_mouseish_pty_write_events,
         report.stripped_mouse_events,
         report.focus_events,
         report.escape_events,
@@ -1220,6 +1243,9 @@ fn print_trace_report(label: &str, report: &TraceReport) {
         "  reconnect: events={} roam={}",
         report.reconnect_events, report.roam_events
     );
+    for warning in trace_report_warnings(report) {
+        println!("  alert: {warning}");
+    }
     if !report.events.is_empty() {
         println!("  top events:");
         for (event, count) in top_trace_events(&report.events, 8) {
@@ -1234,6 +1260,38 @@ fn print_trace_report(label: &str, report: &TraceReport) {
     }
 }
 
+fn trace_report_warnings(report: &TraceReport) -> Vec<String> {
+    let mut warnings = Vec::new();
+    if report.server_mouseish_pty_write_events > 0 {
+        warnings.push(format!(
+            "{} mouse-like input event(s) reached the server PTY",
+            report.server_mouseish_pty_write_events
+        ));
+    }
+    if report.client_mouseish_sent_events > report.stripped_mouse_events
+        && report.server_mouseish_pty_write_events == 0
+    {
+        warnings.push(format!(
+            "{} mouse-like input event(s) left the client; check the matching server log",
+            report.client_mouseish_sent_events
+        ));
+    }
+    if report.replay_drop_events > 0 {
+        warnings.push(format!(
+            "{} replay/drop event(s) observed",
+            report.replay_drop_events
+        ));
+    }
+    if report.reconnect_events > 0
+        && report.flushed_input_events == 0
+        && report.queued_input_events > 0
+    {
+        warnings
+            .push("queued input was observed around reconnect without a later flush".to_string());
+    }
+    warnings
+}
+
 fn top_trace_events(events: &BTreeMap<String, usize>, limit: usize) -> Vec<(String, usize)> {
     let mut entries: Vec<_> = events
         .iter()
@@ -5449,6 +5507,7 @@ async fn run_terminal(
     let mut last_terminal_frame_at = Instant::now();
     let mut last_focus_repaint_at = Instant::now() - FOCUS_REPAINT_COOLDOWN;
     let mut last_idle_repaint_attempt_at = Instant::now() - ALT_SCREEN_IDLE_REPAINT_AFTER;
+    let mut last_status_tick_at = Instant::now();
     if let Some(frame) = first_frame {
         if !forward_only {
             render_frame(&frame)?;
@@ -5577,22 +5636,22 @@ async fn run_terminal(
                         if bytes.is_empty() {
                             continue;
                         }
-                        if should_strip_unowned_terminal_reports(
+                        let before_mouse_strip = bytes.len();
+                        let (stripped_bytes, stripped_unowned_mouse) = strip_unowned_terminal_reports(
+                            bytes,
                             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)),
-                                    ],
-                                );
-                            }
+                        );
+                        bytes = stripped_bytes;
+                        if stripped_unowned_mouse {
+                            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;
                             }
@@ -6431,6 +6490,10 @@ async fn run_terminal(
                 }
             }
             _ = status_tick.tick() => {
+                let status_tick_at = Instant::now();
+                let status_tick_gap = status_tick_at.duration_since(last_status_tick_at);
+                last_status_tick_at = status_tick_at;
+                let mut repainted_this_tick = false;
                 let stale = last_packet_at.elapsed();
                 if stale >= Duration::from_secs(reconnect_timeout_secs.max(1)) {
                     if let Some(frame) = reconnect(
@@ -6451,6 +6514,8 @@ async fn run_terminal(
                             render_frame(&frame)?;
                             predictor.observe_output(&frame.bytes);
                             last_terminal_frame_at = Instant::now();
+                            last_idle_repaint_attempt_at = Instant::now();
+                            repainted_this_tick = true;
                         }
                         last_packet_at = Instant::now();
                         flush_pending_user_input(
@@ -6493,13 +6558,22 @@ async fn run_terminal(
                     )
                     .await?;
                     let now = Instant::now();
-                    if should_repaint_idle_alternate_screen(
+                    if !repainted_this_tick && should_repaint_idle_terminal(
                         predictor.alternate_screen,
                         last_terminal_frame_at,
                         last_idle_repaint_attempt_at,
+                        status_tick_gap,
                         now,
                     ) {
                         last_idle_repaint_attempt_at = now;
+                        dosh::trace::event(
+                            "client.idle_repaint_start",
+                            &[
+                                ("alt", predictor.alternate_screen.to_string()),
+                                ("tick_gap_ms", status_tick_gap.as_millis().to_string()),
+                                ("silent_ms", stale.as_millis().to_string()),
+                            ],
+                        );
                         if let Some(frame) = reconnect(
                             &socket,
                             &mut cred,
@@ -6926,6 +7000,20 @@ fn should_strip_unowned_terminal_reports(alternate_screen: bool, mouse_tracking:
     !alternate_screen && !mouse_tracking
 }
 
+fn strip_unowned_terminal_reports(
+    bytes: Vec<u8>,
+    alternate_screen: bool,
+    mouse_tracking: bool,
+) -> (Vec<u8>, bool) {
+    if !should_strip_unowned_terminal_reports(alternate_screen, mouse_tracking) {
+        return (bytes, false);
+    }
+    let before = bytes.len();
+    let stripped = strip_stale_mouse_reports(&bytes);
+    let changed = stripped.len() != before;
+    (stripped, changed)
+}
+
 fn input_contains_focus_in(bytes: &[u8]) -> bool {
     contains_bytes(bytes, b"\x1b[I") || contains_bytes(bytes, b"\x9bI")
 }
@@ -6950,14 +7038,16 @@ fn strip_terminal_focus_reports(bytes: &[u8]) -> Vec<u8> {
     out
 }
 
-fn should_repaint_idle_alternate_screen(
+fn should_repaint_idle_terminal(
     alternate_screen: bool,
     last_terminal_frame_at: Instant,
     last_attempt_at: Instant,
+    status_tick_gap: Duration,
     now: Instant,
 ) -> bool {
-    alternate_screen
+    (alternate_screen
         && now.duration_since(last_terminal_frame_at) >= ALT_SCREEN_IDLE_REPAINT_AFTER
+        || status_tick_gap >= LOCAL_SLEEP_REPAINT_AFTER)
         && now.duration_since(last_attempt_at) >= ALT_SCREEN_IDLE_REPAINT_AFTER
 }
 
@@ -8901,30 +8991,31 @@ const TERMINAL_CLEANUP: &[u8] = concat!(
 mod tests {
     use super::{
         ALT_SCREEN_IDLE_REPAINT_AFTER, CachedCredential, DisconnectStatus, DynamicForward,
-        FRAME_GAP_RESYNC_AFTER_MS, FrameBuffer, LocalForward, MAX_PENDING_USER_INPUT_BYTES,
-        NativeIdentityContext, POST_SUBMIT_ALL_INPUT_HOLD, PendingStreamOpen, PredictMode,
-        Predictor, RESTART_STATUS_SCRIPT, RemoteForward, STARTUP_INPUT_HOLD, SshConfig,
-        SshPathTokenContext, StartupGateMode, StatusAction, UpdateOptions, UpdateRole, auth_allows,
-        cache_key, cache_server_prefix, cleanup_stream_state, clear_cached_credentials,
-        ensure_tui_safe_status_overlay, expand_ssh_path_tokens, input_contains_focus_in,
-        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_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,
-        render_status_overlay, requested_env, resolved_startup_command, retire_stream_state,
-        retransmit_stream_opens, rewrite_forward_command, sanitize_trace_name,
-        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, 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,
+        FRAME_GAP_RESYNC_AFTER_MS, FrameBuffer, LOCAL_SLEEP_REPAINT_AFTER, LocalForward,
+        MAX_PENDING_USER_INPUT_BYTES, NativeIdentityContext, POST_SUBMIT_ALL_INPUT_HOLD,
+        PendingStreamOpen, PredictMode, Predictor, RESTART_STATUS_SCRIPT, RemoteForward,
+        STARTUP_INPUT_HOLD, SshConfig, SshPathTokenContext, StartupGateMode, StatusAction,
+        UpdateOptions, UpdateRole, auth_allows, cache_key, cache_server_prefix,
+        cleanup_stream_state, clear_cached_credentials, ensure_tui_safe_status_overlay,
+        expand_ssh_path_tokens, input_contains_focus_in, 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_line, parse_trace_options, parse_trace_report_options, parse_trace_summary,
+        parse_update_options, post_submit_hold_duration, queue_pending_user_input,
+        queue_stale_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, render_status_overlay, requested_env,
+        resolved_startup_command, retire_stream_state, retransmit_stream_opens,
+        rewrite_forward_command, sanitize_trace_name, 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_terminal, 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, 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,
     };
@@ -10318,11 +10409,50 @@ mod tests {
         assert_eq!(report.queued_input_events, 1);
         assert_eq!(report.sent_input_events, 1);
         assert_eq!(report.reconnect_events, 1);
+        assert_eq!(report.client_mouseish_sent_events, 0);
+        assert_eq!(report.server_mouseish_pty_write_events, 0);
         assert_eq!(report.recent_events.len(), 2);
         assert_eq!(
             top_trace_events(&report.events, 1),
             vec![("client.input_send".to_string(), 1)]
         );
+        assert_eq!(
+            trace_report_warnings(&report),
+            vec!["queued input was observed around reconnect without a later flush".to_string()]
+        );
+    }
+
+    #[test]
+    fn trace_report_warns_when_mouse_input_reaches_server_pty() {
+        let dir = tempfile::tempdir().unwrap();
+        let path = dir.path().join("server.log");
+        fs::write(
+            &path,
+            concat!(
+                "ts_ms=30 pid=2 event=server.input_roam session=term from=1.1.1.1:1 to=2.2.2.2:2\n",
+                "ts_ms=31 pid=2 event=server.pty_write session=term seq=9 summary=len=12,esc=false,focus=false,mouseish=true,printable=12\n",
+                "ts_ms=32 pid=2 event=server.input_replay_drop session=term seq=8 summary=len=1,esc=false,focus=false,mouseish=false,printable=1\n",
+            ),
+        )
+        .unwrap();
+
+        let report = summarize_trace_file(&path, 10).unwrap();
+        let warnings = trace_report_warnings(&report);
+
+        assert_eq!(report.pty_write_events, 1);
+        assert_eq!(report.server_mouseish_pty_write_events, 1);
+        assert_eq!(report.replay_drop_events, 1);
+        assert_eq!(report.roam_events, 1);
+        assert!(
+            warnings
+                .iter()
+                .any(|warning| { warning == "1 mouse-like input event(s) reached the server PTY" })
+        );
+        assert!(
+            warnings
+                .iter()
+                .any(|warning| { warning == "1 replay/drop event(s) observed" })
+        );
     }
 
     #[test]
@@ -10721,6 +10851,47 @@ mod tests {
         assert_eq!(pending_bytes, MAX_PENDING_USER_INPUT_BYTES);
     }
 
+    #[test]
+    fn stale_pending_user_input_is_marked_for_mouse_stripping() {
+        let mut pending = VecDeque::new();
+        let mut pending_bytes = 0usize;
+
+        queue_pending_user_input(&mut pending, &mut pending_bytes, b"\x1b[<35;10;1M".to_vec())
+            .unwrap();
+        queue_stale_pending_user_input(
+            &mut pending,
+            &mut pending_bytes,
+            b"\x1b[<35;11;1M".to_vec(),
+        )
+        .unwrap();
+
+        let normal = pending.pop_front().unwrap();
+        assert!(!normal.strip_mouse_reports);
+        assert_eq!(strip_stale_mouse_reports(&normal.bytes), b"");
+
+        let stale = pending.pop_front().unwrap();
+        assert!(stale.strip_mouse_reports);
+        assert_eq!(strip_stale_mouse_reports(&stale.bytes), b"");
+    }
+
+    #[test]
+    fn unowned_terminal_mouse_reports_strip_only_without_mouse_owner() {
+        let input = b"\x1b[<35;10;1Mcmd\r".to_vec();
+
+        let (stripped, changed) = strip_unowned_terminal_reports(input.clone(), false, false);
+        assert!(changed);
+        assert_eq!(stripped, b"cmd\r");
+
+        let (preserved, changed) = strip_unowned_terminal_reports(input.clone(), false, true);
+        assert!(!changed);
+        assert_eq!(preserved, input);
+
+        let (preserved, changed) =
+            strip_unowned_terminal_reports(b"\x1b[<35;10;1M".to_vec(), true, false);
+        assert!(!changed);
+        assert_eq!(preserved, b"\x1b[<35;10;1M");
+    }
+
     #[test]
     fn transient_udp_send_errors_are_not_terminal_fatal() {
         #[cfg(unix)]
@@ -10828,21 +10999,44 @@ mod tests {
     }
 
     #[test]
-    fn idle_repaint_only_runs_for_stale_alternate_screen() {
+    fn idle_repaint_runs_for_stale_alternate_screen_or_sleep_gap() {
         let now = Instant::now();
         let stale = now - ALT_SCREEN_IDLE_REPAINT_AFTER - Duration::from_secs(1);
         let recent = now - Duration::from_secs(1);
-        assert!(should_repaint_idle_alternate_screen(
-            true, stale, stale, now
+        assert!(should_repaint_idle_terminal(
+            true,
+            stale,
+            stale,
+            Duration::from_secs(1),
+            now
         ));
-        assert!(!should_repaint_idle_alternate_screen(
-            false, stale, stale, now
+        assert!(should_repaint_idle_terminal(
+            false,
+            recent,
+            stale,
+            LOCAL_SLEEP_REPAINT_AFTER + Duration::from_secs(1),
+            now
         ));
-        assert!(!should_repaint_idle_alternate_screen(
-            true, recent, stale, now
+        assert!(!should_repaint_idle_terminal(
+            false,
+            stale,
+            stale,
+            Duration::from_secs(1),
+            now
         ));
-        assert!(!should_repaint_idle_alternate_screen(
-            true, stale, recent, now
+        assert!(!should_repaint_idle_terminal(
+            true,
+            recent,
+            stale,
+            Duration::from_secs(1),
+            now
+        ));
+        assert!(!should_repaint_idle_terminal(
+            true,
+            stale,
+            recent,
+            LOCAL_SLEEP_REPAINT_AFTER + Duration::from_secs(1),
+            now
         ));
     }