Trace ticket reattach recovery

Cargo.lock

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

Cargo.toml

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

src/bin/dosh-client.rs

@@ -828,6 +828,9 @@ struct TraceReport {
     pty_write_events: usize,
     reconnect_events: usize,
     unknown_resume_events: usize,
+    ticket_attach_start_events: usize,
+    ticket_attach_ok_events: usize,
+    ticket_attach_reject_events: usize,
     roam_events: usize,
     recent_events: VecDeque<String>,
 }
@@ -1344,6 +1347,15 @@ fn summarize_trace_file_with_mode(
         if event == "server.resume_unknown_client" {
             report.unknown_resume_events += 1;
         }
+        if event.ends_with("ticket_attach_start") {
+            report.ticket_attach_start_events += 1;
+        }
+        if event.ends_with("ticket_attach_ok") {
+            report.ticket_attach_ok_events += 1;
+        }
+        if event.ends_with("ticket_attach_reject") {
+            report.ticket_attach_reject_events += 1;
+        }
         if event.contains("roam") {
             report.roam_events += 1;
         }
@@ -1400,8 +1412,13 @@ fn print_trace_report(label: &str, report: &TraceReport) {
         report.hex_events
     );
     println!(
-        "  reconnect: events={} unknown_resume={} roam={}",
+        "  reconnect: events={} unknown_resume={} ticket_attach={}/{}/{} roam={}",
-        report.reconnect_events, report.unknown_resume_events, report.roam_events
+        report.reconnect_events,
+        report.unknown_resume_events,
+        report.ticket_attach_start_events,
+        report.ticket_attach_ok_events,
+        report.ticket_attach_reject_events,
+        report.roam_events
     );
     for warning in trace_report_warnings(report) {
         println!("  alert: {warning}");
@@ -1422,12 +1439,18 @@ 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 {
+    if report.unknown_resume_events > 0 && report.ticket_attach_ok_events == 0 {
         warnings.push(format!(
-            "{} unknown live resume event(s); ticket reattach should follow after server restart",
+            "{} unknown live resume event(s) without ticket attach recovery",
             report.unknown_resume_events
         ));
     }
+    if report.ticket_attach_reject_events > 0 {
+        warnings.push(format!(
+            "{} ticket attach reject event(s) observed",
+            report.ticket_attach_reject_events
+        ));
+    }
     if report.server_mouseish_pty_write_events > 0 {
         warnings.push(format!(
             "{} mouse-like input event(s) reached the server PTY",
@@ -1488,6 +1511,10 @@ fn render_trace_event(fields: &BTreeMap<String, String>) -> String {
         "summary",
         "bytes",
         "silent_ms",
+        "session",
+        "mode",
+        "reason",
+        "output_seq",
     ] {
         if let Some(value) = fields.get(key) {
             parts.push(format!("{key}={value}"));
@@ -5370,6 +5397,14 @@ async fn try_ticket_attach(
     requested_env: Vec<EnvVar>,
 ) -> Result<(Frame, CachedCredential)> {
     let addr = resolve_addr(&cached.udp_host, cached.udp_port)?;
+    dosh::trace::event(
+        "client.ticket_attach_start",
+        &[
+            ("server", cached.server.clone()),
+            ("session", cached.session.clone()),
+            ("mode", cached.mode.clone()),
+        ],
+    );
     let client_nonce = crypto::random_12();
     let request_key = crypto::hkdf32(
         &cached.attach_ticket_psk,
@@ -5406,6 +5441,10 @@ async fn try_ticket_attach(
     let ok = recv_response_until(socket, Duration::from_millis(700), |packet| {
         if packet.header.kind == PacketKind::AttachReject && packet.header.conn_id == [0u8; 16] {
             let reject: AttachReject = protocol::from_body(&packet.body)?;
+            dosh::trace::event(
+                "client.ticket_attach_reject",
+                &[("reason", reject.reason.clone())],
+            );
             return Err(anyhow!("ticket attach rejected: {}", reject.reason));
         }
         if packet.header.kind != PacketKind::AttachOk {
@@ -5451,6 +5490,15 @@ async fn try_ticket_attach(
     next.session_key = ok.session_key;
     next.session_key_id = ok.session_key_id;
     next.last_rendered_seq = ok.initial_seq;
+    dosh::trace::event(
+        "client.ticket_attach_ok",
+        &[
+            ("session", next.session.clone()),
+            ("mode", next.mode.clone()),
+            ("output_seq", next.last_rendered_seq.to_string()),
+            ("bytes", frame.bytes.len().to_string()),
+        ],
+    );
     Ok((frame, next))
 }
 
@@ -10734,6 +10782,52 @@ mod tests {
         assert_eq!(all.server_mouseish_pty_write_events, 1);
     }
 
+    #[test]
+    fn trace_report_correlates_unknown_resume_with_ticket_recovery() {
+        let dir = tempfile::tempdir().unwrap();
+        let path = dir.path().join("server.log");
+        fs::write(
+            &path,
+            concat!(
+                "ts_ms=10 pid=1 event=server.start version=1.0.0 bind=0.0.0.0:50000\n",
+                "ts_ms=11 pid=1 event=server.resume_start client=abc seq=2 ack=1\n",
+                "ts_ms=12 pid=1 event=server.resume_unknown_client client=abc\n",
+                "ts_ms=13 pid=1 event=server.ticket_attach_start peer=1.2.3.4:5\n",
+                "ts_ms=14 pid=1 event=server.ticket_attach_ok session=term mode=read-write client=def output_seq=9 bytes=100\n",
+            ),
+        )
+        .unwrap();
+
+        let recovered = summarize_trace_file(&path, 10).unwrap();
+        assert_eq!(recovered.unknown_resume_events, 1);
+        assert_eq!(recovered.ticket_attach_start_events, 1);
+        assert_eq!(recovered.ticket_attach_ok_events, 1);
+        assert!(trace_report_warnings(&recovered).is_empty());
+
+        fs::write(
+            &path,
+            concat!(
+                "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_unknown_client client=abc\n",
+                "ts_ms=22 pid=2 event=server.ticket_attach_reject reason='ticket expired'\n",
+            ),
+        )
+        .unwrap();
+
+        let rejected = summarize_trace_file(&path, 10).unwrap();
+        let warnings = trace_report_warnings(&rejected);
+        assert_eq!(rejected.unknown_resume_events, 1);
+        assert_eq!(rejected.ticket_attach_reject_events, 1);
+        assert!(warnings.iter().any(|warning| {
+            warning == "1 unknown live resume event(s) without ticket attach recovery"
+        }));
+        assert!(
+            warnings
+                .iter()
+                .any(|warning| warning == "1 ticket attach reject event(s) observed")
+        );
+    }
+
     #[test]
     fn update_installer_uses_platform_native_script() {
         assert_eq!(

src/bin/dosh-server.rs

@@ -1463,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");
@@ -1486,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;
     }
 
@@ -1560,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 {
@@ -1591,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(())
 }