From 3d5bb126c51fcd716fcdb4097c6e461fd4f3aff7 Mon Sep 17 00:00:00 2001 From: DuProcess <273172371+DuProcess@users.noreply.github.com> Date: Sun, 12 Jul 2026 12:15:25 -0400 Subject: [PATCH] Trace ticket reattach recovery --- Cargo.lock | 2 +- Cargo.toml | 2 +- src/bin/dosh-client.rs | 102 +++++++++++++++++++++++++++++++++++++++-- src/bin/dosh-server.rs | 38 ++++++++++++++- 4 files changed, 136 insertions(+), 8 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index d4f8daa..d7e6868 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -436,7 +436,7 @@ dependencies = [ [[package]] name = "dosh" -version = "1.0.0-rc36" +version = "1.0.0-rc37" dependencies = [ "anyhow", "base64", diff --git a/Cargo.toml b/Cargo.toml index 417e4ec..a801ea2 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -1,6 +1,6 @@ [package] name = "dosh" -version = "1.0.0-rc36" +version = "1.0.0-rc37" edition = "2024" license = "MIT" diff --git a/src/bin/dosh-client.rs b/src/bin/dosh-client.rs index 7ea719f..9aadbc6 100644 --- a/src/bin/dosh-client.rs +++ b/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, } @@ -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={}", - report.reconnect_events, report.unknown_resume_events, report.roam_events + " reconnect: events={} unknown_resume={} ticket_attach={}/{}/{} roam={}", + 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 { 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 { "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, ) -> 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!( diff --git a/src/bin/dosh-server.rs b/src/bin/dosh-server.rs index faef1d3..fe5157a 100644 --- a/src/bin/dosh-server.rs +++ b/src/bin/dosh-server.rs @@ -1463,6 +1463,7 @@ async fn handle_ticket_attach( peer: SocketAddr, body: Vec, ) -> 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(()) }