From 90aa77fc8244a6f5f50205ab281b49884112829e Mon Sep 17 00:00:00 2001 From: Taehoon Moon Date: Thu, 22 Oct 2026 13:09:28 +0900 Subject: [PATCH] Log Tailscale's output and host details when Serve fails When a Tailscale Serve command ran past its 10-second limit, Caffold dropped what the CLI had printed, so the log said only "did not finish within 10 seconds". The CLI's output is now read while it runs and kept on a timeout, and each Serve failure line ends with the Tailscale version, whether this host has the HTTPS capability, Tailscale's health warnings, and where the CLI's links resolve. --- caffold/src/app/tailscale.rs | 172 +++++++++++++++++++++++---- caffold/src/app/tailscale/cli.rs | 178 +++++++++++++++++++++++----- caffold/src/app/tailscale/status.rs | 90 ++++++++++++++ 3 files changed, 388 insertions(+), 52 deletions(-) diff --git a/caffold/src/app/tailscale.rs b/caffold/src/app/tailscale.rs index 418ba735..db848c31 100644 --- a/caffold/src/app/tailscale.rs +++ b/caffold/src/app/tailscale.rs @@ -26,10 +26,13 @@ use tracing::warn; use url::Url; use super::error::ApiError; -use cli::{ProcessTailscaleRunner, TailscaleExecutables, TailscaleRunner, summarize_output}; +use cli::{ + ProcessTailscaleRunner, TailscaleExecutable, TailscaleExecutables, TailscaleRunner, + summarize_output, +}; use status::{ TailscaleNodeResponse, TailscaleReason, TailscaleState, TailscaleStatus, - canonical_tailnet_url_value, classify_serve_status, command_failed_status, + canonical_tailnet_url_value, classify_serve_status, command_failed_status, describe_node, }; const STATUS_COMMAND: &[&str] = &["status", "--json"]; @@ -178,7 +181,7 @@ impl TailscaleService { } else { current.status.state == TailscaleState::Ready }; - let Some(cli) = current.cli.filter(|_| should_run) else { + let Some((cli, node_description)) = current.cli.filter(|_| should_run) else { return Ok(self.publish(current.status, current.failure).await); }; @@ -222,7 +225,10 @@ impl TailscaleService { } else { "tailscale serve could not be disabled" }, - detail: format!("{} {error}", command_line(&cli, arguments)), + detail: format!( + "{} {error}; {node_description}", + command_line(&cli, arguments) + ), }; return Ok(self.publish(failed, Some(failure)).await); } @@ -257,7 +263,7 @@ impl TailscaleService { let failure = Failure { event: "tailscale serve did not reach the requested state", detail: format!( - "{} succeeded, but Tailscale then reported: {}", + "{} succeeded, but Tailscale then reported: {}; {node_description}", command_line(&cli, arguments), inspected.status.diagnostic_message ), @@ -296,7 +302,11 @@ impl TailscaleService { }; let mut reported = None; let mut attempts = Vec::new(); - for cli in candidates { + for TailscaleExecutable { + path: cli, + resolved, + } in candidates + { let stdout = match self.runner.run(&cli, STATUS_COMMAND).await { Ok(stdout) => stdout, Err(error) => { @@ -319,7 +329,16 @@ impl TailscaleService { )); continue; }; - return self.inspect_connection(cli, node).await; + let node_description = if resolved == cli { + describe_node(&stdout) + } else { + format!( + "{}, executable resolves to {}", + describe_node(&stdout), + resolved.display() + ) + }; + return self.inspect_connection(cli, node, node_description).await; } Inspection { status: reported.unwrap_or_else(command_failed), @@ -331,7 +350,12 @@ impl TailscaleService { } } - async fn inspect_connection(&self, cli: PathBuf, node: TailscaleNodeResponse) -> Inspection { + async fn inspect_connection( + &self, + cli: PathBuf, + node: TailscaleNodeResponse, + node_description: String, + ) -> Inspection { if node.backend_state != "Running" { return Inspection { status: TailscaleStatus::new( @@ -340,7 +364,7 @@ impl TailscaleService { "Tailscale is installed but disconnected.", ), failure: None, - cli: Some(cli), + cli: Some((cli, node_description)), }; } @@ -354,9 +378,12 @@ impl TailscaleService { ), failure: Some(Failure { event: "tailscale serve status could not be read", - detail: format!("{} {error}", command_line(&cli, SERVE_STATUS_COMMAND)), + detail: format!( + "{} {error}; {node_description}", + command_line(&cli, SERVE_STATUS_COMMAND) + ), }), - cli: Some(cli), + cli: Some((cli, node_description)), }; } }; @@ -364,7 +391,7 @@ impl TailscaleService { let failure = (status.state == TailscaleState::Failed).then(|| Failure { event: "tailscale serve status could not be read", detail: format!( - "{}: {} Output: {}", + "{}: {} Output: {}; {node_description}", command_line(&cli, SERVE_STATUS_COMMAND), status.diagnostic_message, summarize_output(&stdout) @@ -373,7 +400,7 @@ impl TailscaleService { Inspection { status, failure, - cli: Some(cli), + cli: Some((cli, node_description)), } } @@ -394,7 +421,9 @@ impl TailscaleService { struct Inspection { status: TailscaleStatus, failure: Option, - cli: Option, + /// The CLI that answered, with what its `status --json` said about this + /// host. The description only goes into failure logs. + cli: Option<(PathBuf, String)>, } #[derive(PartialEq)] @@ -534,6 +563,17 @@ mod tests { .await; assert_eq!(off.state, TailscaleState::ServeOff); + let differently_shaped_details = service(MockTailscaleRunner::with_responses([ + response( + true, + r#"{"BackendState":"Running","Version":7,"Self":[],"Health":"degraded"}"#, + ), + response(true, r#"{"Web":{}}"#), + ])) + .refresh() + .await; + assert_eq!(differently_shaped_details.state, TailscaleState::ServeOff); + let ready = service(MockTailscaleRunner::with_responses([ response(true, node_status("Running")), response(true, serve_status("http://127.0.0.1:5178")), @@ -676,16 +716,25 @@ mod tests { response(true, node_status("Running")), response(true, serve_status("http://127.0.0.1:5178")), ]); - let incomplete_disable = service(disable_runner.clone()) - .set_serve(false) - .await - .unwrap(); + let disable = service(disable_runner.clone()); + let incomplete_disable = disable.set_serve(false).await.unwrap(); assert_eq!(incomplete_disable.state, TailscaleState::Failed); assert_eq!( incomplete_disable.reason_code, TailscaleReason::ServeDisableIncomplete ); assert_eq!(disable_runner.calls().len(), 5); + assert_eq!( + logged_failure(&disable).await, + Some(( + "tailscale serve did not reach the requested state", + format!( + "{CLI} serve --yes --https=443 off succeeded, but Tailscale then reported: \ + Caffold is available through Tailscale Serve.; \ + Tailscale unknown version, HTTPS capability unknown, health: none" + ) + )) + ); } #[tokio::test] @@ -787,7 +836,8 @@ mod tests { "tailscale serve could not be enabled", format!( "{CLI} serve --bg --yes --https=443 http://127.0.0.1:5178 exited with code 1: \ - Serve is not enabled on your tailnet." + Serve is not enabled on your tailnet.; \ + Tailscale unknown version, HTTPS capability unknown, health: none" ) )) ); @@ -802,7 +852,26 @@ mod tests { logged_failure(&disable).await, Some(( "tailscale serve could not be disabled", - format!("{CLI} serve --yes --https=443 off exited with code 1: permission denied") + format!( + "{CLI} serve --yes --https=443 off exited with code 1: permission denied; \ + Tailscale unknown version, HTTPS capability unknown, health: none" + ) + )) + ); + + let serve_status_failed = service(MockTailscaleRunner::with_responses([ + response(true, node_status("Running")), + response(false, "failed to connect"), + ])); + serve_status_failed.refresh().await; + assert_eq!( + logged_failure(&serve_status_failed).await, + Some(( + "tailscale serve status could not be read", + format!( + "{CLI} serve status --json exited with code 1: failed to connect; \ + Tailscale unknown version, HTTPS capability unknown, health: none" + ) )) ); @@ -820,7 +889,46 @@ mod tests { "tailscale serve status could not be read", format!( "{CLI} serve status --json: Tailscale returned an invalid Serve status response. \ - Output: not json" + Output: not json; \ + Tailscale unknown version, HTTPS capability unknown, health: none" + ) + )) + ); + } + + #[tokio::test] + async fn logs_what_a_timed_out_serve_printed_and_what_tailscale_reports_about_the_host() { + let mut runner = MockTailscaleRunner::with_mock_responses([ + immediate( + true, + r#"{"BackendState":"Running","Version":"1.90.0","Self":{"CapMap":{}},"Health":[]}"#, + ), + immediate(true, r#"{"Web":{}}"#), + MockResponse::Immediate(Err(TailscaleCommandError::TimedOut { + stdout: "Serve is not enabled on your tailnet. To enable, visit: \ + https://login.tailscale.com/f/serve?node=n1" + .to_string(), + stderr: "Warning: client version differs".to_string(), + })), + ]); + runner.executables[0].1 = PathBuf::from(APP_CLI); + let enable = service(runner); + let failed = enable.set_serve(true).await.unwrap(); + assert_eq!(failed.reason_code, TailscaleReason::ServeEnableFailed); + assert_eq!( + failed.diagnostic_message, + "Caffold's Tailscale Serve mapping could not be enabled." + ); + assert_eq!( + logged_failure(&enable).await, + Some(( + "tailscale serve could not be enabled", + format!( + "{CLI} serve --bg --yes --https=443 http://127.0.0.1:5178 did not finish within \ + 10 seconds; stdout: Serve is not enabled on your tailnet. To enable, visit: \ + https://login.tailscale.com/f/serve?node=n1; stderr: Warning: client version \ + differs; Tailscale 1.90.0, HTTPS capability absent, health: none, executable \ + resolves to {APP_CLI}" ) )) ); @@ -985,7 +1093,10 @@ mod tests { } fn timed_out() -> MockResponse { - MockResponse::Immediate(Err(TailscaleCommandError::TimedOut)) + MockResponse::Immediate(Err(TailscaleCommandError::TimedOut { + stdout: String::new(), + stderr: String::new(), + })) } async fn logged_failure(service: &TailscaleService) -> Option<(&'static str, String)> { @@ -997,7 +1108,8 @@ mod tests { #[derive(Clone)] struct MockTailscaleRunner { - executables: Vec, + /// Each executable's path and the path its links resolve to. + executables: Vec<(PathBuf, PathBuf)>, responses: Arc>>, calls: Arc>>, } @@ -1025,7 +1137,9 @@ mod tests { responses: [MockResponse; N], ) -> Self { Self { - executables: executables.map(PathBuf::from).into(), + executables: executables + .map(|path| (PathBuf::from(path), PathBuf::from(path))) + .into(), responses: Arc::new(StdMutex::new(responses.into())), calls: Arc::new(StdMutex::new(Vec::new())), } @@ -1049,7 +1163,15 @@ mod tests { searched: vec![PathBuf::from(CLI)], } } else { - TailscaleExecutables::Found(self.executables.clone()) + TailscaleExecutables::Found( + self.executables + .iter() + .map(|(path, resolved)| TailscaleExecutable { + path: path.clone(), + resolved: resolved.clone(), + }) + .collect(), + ) } } diff --git a/caffold/src/app/tailscale/cli.rs b/caffold/src/app/tailscale/cli.rs index 30483667..d89a270a 100644 --- a/caffold/src/app/tailscale/cli.rs +++ b/caffold/src/app/tailscale/cli.rs @@ -7,10 +7,15 @@ use std::{ io, iter, path::{Path, PathBuf}, pin::Pin, + process::Stdio, time::Duration, }; -use tokio::{process::Command, time::timeout}; +use tokio::{ + io::{AsyncRead, AsyncReadExt}, + process::Command, + time::timeout, +}; const TAILSCALE_COMMAND_TIMEOUT: Duration = Duration::from_secs(10); const COMMAND_DIRECTORIES: [&str; 4] = [ @@ -32,14 +37,21 @@ pub(super) trait TailscaleRunner: Send + Sync { } pub(super) enum TailscaleExecutables { - Found(Vec), + Found(Vec), Missing { searched: Vec }, } +pub(super) struct TailscaleExecutable { + pub(super) path: PathBuf, + /// `path` with every symbolic link followed, or `path` itself when it + /// cannot be resolved. + pub(super) resolved: PathBuf, +} + #[derive(Debug)] pub(super) enum TailscaleCommandError { Start(io::Error), - TimedOut, + TimedOut { stdout: String, stderr: String }, Exited { code: Option, output: String }, } @@ -47,11 +59,19 @@ impl fmt::Display for TailscaleCommandError { fn fmt(&self, formatter: &mut fmt::Formatter<'_>) -> fmt::Result { match self { Self::Start(error) => write!(formatter, "could not start: {error}"), - Self::TimedOut => write!( - formatter, - "did not finish within {} seconds", - TAILSCALE_COMMAND_TIMEOUT.as_secs() - ), + Self::TimedOut { stdout, stderr } => { + write!( + formatter, + "did not finish within {} seconds", + TAILSCALE_COMMAND_TIMEOUT.as_secs() + )?; + for (stream, output) in [("stdout", stdout), ("stderr", stderr)] { + if !output.is_empty() { + write!(formatter, "; {stream}: {output}")?; + } + } + Ok(()) + } Self::Exited { code, output } => { match code { Some(code) => write!(formatter, "exited with code {code}")?, @@ -76,30 +96,64 @@ impl TailscaleRunner for ProcessTailscaleRunner { fn run(&self, executable: &Path, arguments: &[&str]) -> TailscaleCommandFuture { let mut command = Command::new(executable); - command.kill_on_drop(true).args(arguments); + command + .kill_on_drop(true) + .args(arguments) + .stdout(Stdio::piped()) + .stderr(Stdio::piped()); Box::pin(async move { - let output = timeout(TAILSCALE_COMMAND_TIMEOUT, command.output()) - .await - .map_err(|_| TailscaleCommandError::TimedOut)? - .map_err(TailscaleCommandError::Start)?; - let stdout = String::from_utf8_lossy(&output.stdout).into_owned(); - if output.status.success() { + let mut child = command.spawn().map_err(TailscaleCommandError::Start)?; + let mut stdout_pipe = child.stdout.take(); + let mut stderr_pipe = child.stderr.take(); + let mut stdout = Vec::new(); + let mut stderr = Vec::new(); + let finished = timeout(TAILSCALE_COMMAND_TIMEOUT, async { + tokio::try_join!( + child.wait(), + read_until_closed(stdout_pipe.as_mut(), &mut stdout), + read_until_closed(stderr_pipe.as_mut(), &mut stderr), + ) + }) + .await; + let Ok(finished) = finished else { + // Keep what was read so far without waiting for the pipes to + // close: a process the command started may hold them open. + let _ = child.start_kill(); + return Err(TailscaleCommandError::TimedOut { + stdout: summarize_output(&String::from_utf8_lossy(&stdout)), + stderr: summarize_output(&String::from_utf8_lossy(&stderr)), + }); + }; + let (status, (), ()) = finished.map_err(TailscaleCommandError::Start)?; + let stdout = String::from_utf8_lossy(&stdout).into_owned(); + if status.success() { return Ok(stdout); } - let stderr = String::from_utf8_lossy(&output.stderr); + let stderr = String::from_utf8_lossy(&stderr); let reported: &str = if stderr.trim().is_empty() { &stdout } else { &stderr }; Err(TailscaleCommandError::Exited { - code: output.status.code(), + code: status.code(), output: summarize_output(reported), }) }) } } +async fn read_until_closed( + pipe: Option<&mut (impl AsyncRead + Unpin)>, + output: &mut Vec, +) -> io::Result<()> { + let Some(pipe) = pipe else { + return Ok(()); + }; + while pipe.read_buf(output).await? != 0 {} + Ok(()) +} + fn candidate_paths(search_path: Option, home: Option) -> Vec { let home = home.map(PathBuf::from); let command_directories = search_path @@ -127,13 +181,18 @@ fn candidate_paths(search_path: Option, home: Option) -> Vec fn find_executables(candidates: Vec) -> TailscaleExecutables { let mut targets = HashSet::new(); - let found: Vec = candidates + let found: Vec = candidates .iter() .filter(|candidate| is_executable_file(candidate)) - .filter(|candidate| { - targets.insert(fs::canonicalize(candidate).unwrap_or_else(|_| candidate.to_path_buf())) + .filter_map(|candidate| { + let resolved = fs::canonicalize(candidate).unwrap_or_else(|_| candidate.clone()); + targets + .insert(resolved.clone()) + .then(|| TailscaleExecutable { + path: candidate.clone(), + resolved, + }) }) - .cloned() .collect(); if found.is_empty() { TailscaleExecutables::Missing { @@ -172,7 +231,10 @@ pub(super) fn summarize_output(output: &str) -> String { #[cfg(all(test, unix))] mod tests { - use std::{fs, os::unix::fs::PermissionsExt}; + use std::{fs, os::unix::fs::PermissionsExt, thread, time::Instant}; + + use futures_util::poll; + use rustix::process::{Pid, Signal, kill_process}; use super::*; @@ -247,10 +309,15 @@ mod tests { link.join("tailscale"), binary.join("tailscale"), ]); - assert!(matches!( - found, - TailscaleExecutables::Found(paths) if paths == [link.join("tailscale")] - )); + let TailscaleExecutables::Found(found) = found else { + panic!("the linked executable was not found"); + }; + assert_eq!(found.len(), 1); + assert_eq!(found[0].path, link.join("tailscale")); + assert_eq!( + found[0].resolved, + fs::canonicalize(binary.join("tailscale")).unwrap() + ); let searched = vec![plain.join("tailscale"), temp.path().join("missing")]; let missing = find_executables(searched.clone()); @@ -311,10 +378,67 @@ mod tests { .run(Path::new("/bin/sh"), &["-c", "exec sleep 30"]) .await .unwrap_err(); - assert!(matches!(error, TailscaleCommandError::TimedOut)); + assert!(matches!(error, TailscaleCommandError::TimedOut { .. })); assert_eq!(error.to_string(), "did not finish within 10 seconds"); } + #[tokio::test(start_paused = true)] + async fn keeps_what_a_command_wrote_before_it_timed_out() { + let temp = tempfile::tempdir().unwrap(); + let written = temp.path().join("written"); + let mut run = ProcessTailscaleRunner.run( + Path::new("/bin/sh"), + &[ + "-c", + r#"echo 'To enable, visit: https://example.test/enable'; echo warning >&2; : > "$0"; exec sleep 30"#, + written.to_str().unwrap(), + ], + ); + // Start the command, and let the paused clock reach the timeout only + // after its output is in the pipes. + assert!(poll!(&mut run).is_pending()); + let deadline = Instant::now() + Duration::from_secs(10); + while !written.exists() { + assert!(Instant::now() < deadline, "the command wrote nothing"); + thread::sleep(Duration::from_millis(10)); + } + + let error = run.await.unwrap_err(); + assert_eq!( + error.to_string(), + "did not finish within 10 seconds; \ + stdout: To enable, visit: https://example.test/enable; stderr: warning" + ); + } + + #[tokio::test(start_paused = true)] + async fn returns_at_the_timeout_while_a_process_the_command_started_holds_its_pipes() { + let temp = tempfile::tempdir().unwrap(); + let holder = temp.path().join("holder"); + let mut run = ProcessTailscaleRunner.run( + Path::new("/bin/sh"), + &[ + "-c", + r#"echo started; sleep 30 & echo $! > "$0.tmp"; mv "$0.tmp" "$0"; exec sleep 30"#, + holder.to_str().unwrap(), + ], + ); + assert!(poll!(&mut run).is_pending()); + let deadline = Instant::now() + Duration::from_secs(10); + while !holder.exists() { + assert!(Instant::now() < deadline, "the command started nothing"); + thread::sleep(Duration::from_millis(10)); + } + + let error = run.await.unwrap_err(); + let holder_pid = fs::read_to_string(&holder).unwrap().trim().parse().unwrap(); + let _ = kill_process(Pid::from_raw(holder_pid).unwrap(), Signal::KILL); + assert_eq!( + error.to_string(), + "did not finish within 10 seconds; stdout: started" + ); + } + #[test] fn summarizes_output_on_one_bounded_line() { assert_eq!(summarize_output(" first\n\tsecond "), "first second"); diff --git a/caffold/src/app/tailscale/status.rs b/caffold/src/app/tailscale/status.rs index a47a65ac..3bd6c020 100644 --- a/caffold/src/app/tailscale/status.rs +++ b/caffold/src/app/tailscale/status.rs @@ -2,6 +2,8 @@ use serde::{Deserialize, Serialize}; use serde_json::Value; use url::Url; +use super::cli::summarize_output; + const MAX_TAILNET_URL_BYTES: usize = 512; #[derive(Debug, Clone, Copy, Serialize, Deserialize, PartialEq, Eq)] @@ -197,6 +199,55 @@ pub(super) struct TailscaleNodeResponse { pub(super) backend_state: String, } +/// Summarizes what `tailscale status --json` reports about this host, for +/// failure logs only. +pub(super) fn describe_node(status_json: &str) -> String { + let status = serde_json::from_str::(status_json).unwrap_or(Value::Null); + let version = status + .get("Version") + .and_then(Value::as_str) + .unwrap_or("unknown version"); + let https = match status.get("Self") { + Some(Value::Object(node)) => { + let in_cap_map = node + .get("CapMap") + .and_then(Value::as_object) + .is_some_and(|capabilities| capabilities.contains_key("https")); + let in_capabilities = node + .get("Capabilities") + .and_then(Value::as_array) + .is_some_and(|capabilities| { + capabilities + .iter() + .any(|capability| capability.as_str() == Some("https")) + }); + if in_cap_map || in_capabilities { + "present" + } else { + "absent" + } + } + _ => "unknown", + }; + let warnings = status + .get("Health") + .and_then(Value::as_array) + .map(|warnings| { + warnings + .iter() + .filter_map(Value::as_str) + .collect::>() + .join("; ") + }) + .unwrap_or_default(); + let health = if warnings.is_empty() { + "none".to_string() + } else { + summarize_output(&warnings) + }; + format!("Tailscale {version}, HTTPS capability {https}, health: {health}") +} + #[cfg(test)] mod tests { use super::*; @@ -269,6 +320,45 @@ mod tests { assert_eq!(canonical_tailnet_url_value(&"x".repeat(513)), None); } + #[test] + fn describes_the_node_for_failure_logs() { + assert_eq!( + describe_node( + r#"{"BackendState":"Running","Version":"1.104.1-t7f4efe814","Self":{"CapMap":{"https":null},"Capabilities":["https"]},"Health":[]}"# + ), + "Tailscale 1.104.1-t7f4efe814, HTTPS capability present, health: none" + ); + assert_eq!( + describe_node(r#"{"Version":"1.90.0","Self":{"Capabilities":["https"]}}"#), + "Tailscale 1.90.0, HTTPS capability present, health: none" + ); + assert_eq!( + describe_node( + r#"{"Version":"1.90.0","Self":{"CapMap":{"funnel":null}},"Health":["DNS is unreachable.","Peers are offline."]}"# + ), + "Tailscale 1.90.0, HTTPS capability absent, health: DNS is unreachable.; Peers are offline." + ); + + let health = describe_node(&format!(r#"{{"Health":["{}"]}}"#, "x".repeat(500))); + assert!(health.ends_with('…'), "{health}"); + assert!(health.len() < 500, "{health}"); + } + + #[test] + fn reads_missing_or_differently_shaped_node_fields_as_unknown() { + for body in [ + r#"{"BackendState":"Running"}"#, + r#"{"Version":7,"Self":[],"Health":"degraded"}"#, + "not json", + ] { + assert_eq!( + describe_node(body), + "Tailscale unknown version, HTTPS capability unknown, health: none", + "{body}" + ); + } + } + fn serve_status(target: &str) -> String { format!( r#"{{"Web":{{"studio.example.ts.net:443":{{"Handlers":{{"/":{{"Proxy":"{target}"}}}}}}}}}}"#