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}"}}}}}}}}}}"#