diff --git a/Cargo.lock b/Cargo.lock index 663eef320bd18..9874366dee52a 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -5509,6 +5509,7 @@ dependencies = [ "turborepo-vercel-api-mock", "twox-hash", "uds_windows", + "uuid", "wax", "webbrowser", "which", diff --git a/Cargo.toml b/Cargo.toml index 2c5d4623019f6..78bde944610e8 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -188,6 +188,7 @@ triomphe = "0.1.13" tui-term = { version = "0.1.9", default-features = false } url = "2.2.2" urlencoding = "2.1.2" +uuid = "1.5.0" webbrowser = "0.8.7" which = "4.4.0" unicode-segmentation = "1.10.1" diff --git a/crates/turborepo-lib/Cargo.toml b/crates/turborepo-lib/Cargo.toml index 98eeb115c7835..6fdc912a463b2 100644 --- a/crates/turborepo-lib/Cargo.toml +++ b/crates/turborepo-lib/Cargo.toml @@ -131,6 +131,7 @@ turborepo-unescape = { workspace = true } turborepo-vercel-api = { path = "../turborepo-vercel-api" } twox-hash = "1.6.3" uds_windows = "1.0.2" +uuid = { workspace = true } wax = { workspace = true } webbrowser = { workspace = true } which = { workspace = true } diff --git a/crates/turborepo-lib/src/cli/mod.rs b/crates/turborepo-lib/src/cli/mod.rs index 0495fe64f2457..a8176f3340928 100644 --- a/crates/turborepo-lib/src/cli/mod.rs +++ b/crates/turborepo-lib/src/cli/mod.rs @@ -1270,7 +1270,7 @@ pub async fn run( } run_args.track(&event); - let exit_code = run::run(base, event).await.inspect(|code| { + let exit_code = run::run(base, event, logger).await.inspect(|code| { if *code != 0 { error!("run failed: command exited ({code})"); } @@ -1282,7 +1282,7 @@ pub async fn run( event.track_call(); let base = CommandBase::new(cli_args, repo_root, version, color_config); - let mut client = WatchClient::new(base, event).await?; + let mut client = WatchClient::new(base, event, logger).await?; client.start().await?; // We only exit if we get a signal, so we return a non-zero exit code return Ok(1); diff --git a/crates/turborepo-lib/src/commands/run.rs b/crates/turborepo-lib/src/commands/run.rs index fe9c251eedbe7..d7467ec0b7bad 100644 --- a/crates/turborepo-lib/src/commands/run.rs +++ b/crates/turborepo-lib/src/commands/run.rs @@ -3,7 +3,12 @@ use std::future::Future; use tracing::error; use turborepo_telemetry::events::command::CommandEventBuilder; -use crate::{commands::CommandBase, run, run::builder::RunBuilder, signal::SignalHandler}; +use crate::{ + commands::CommandBase, + run::{self, builder::RunBuilder}, + signal::SignalHandler, + tracing::TurboSubscriber, +}; #[cfg(windows)] pub fn get_signal() -> Result>, run::Error> { @@ -31,7 +36,11 @@ pub fn get_signal() -> Result>, run::Error> { }) } -pub async fn run(base: CommandBase, telemetry: CommandEventBuilder) -> Result { +pub async fn run( + base: CommandBase, + telemetry: CommandEventBuilder, + logger: &TurboSubscriber, +) -> Result { let signal = get_signal()?; let handler = SignalHandler::new(signal); @@ -44,7 +53,7 @@ pub async fn run(base: CommandBase, telemetry: CommandEventBuilder) -> Result Result>)>, Error> { // Print prelude here as this needs to happen before the UI is started if self.should_print_prelude { @@ -205,6 +207,11 @@ impl Run { if task_names.is_empty() { return Ok(None); } + // Redirect any tracing logs to a file to prevent logs from corrupting + // the TUI + if let Err(e) = logger.redirect_logs_to_file(&self.repo_root) { + warn!("failed to redirect logs to file: {e}"); + } let (sender, receiver) = AppSender::new(); let handle = tokio::task::spawn_blocking(move || tui::run_app(task_names, receiver)); diff --git a/crates/turborepo-lib/src/run/watch.rs b/crates/turborepo-lib/src/run/watch.rs index 721f50c260d81..2e7ae848c689f 100644 --- a/crates/turborepo-lib/src/run/watch.rs +++ b/crates/turborepo-lib/src/run/watch.rs @@ -14,12 +14,12 @@ use turborepo_ui::{tui, tui::AppSender}; use crate::{ cli::{Command, RunArgs}, - commands, - commands::CommandBase, + commands::{self, CommandBase}, daemon::{proto, DaemonConnectorError, DaemonError}, - get_version, opts, run, - run::{builder::RunBuilder, scope::target_selector::InvalidSelectorError, Run}, + get_version, opts, + run::{self, builder::RunBuilder, scope::target_selector::InvalidSelectorError, Run}, signal::SignalHandler, + tracing::TurboSubscriber, DaemonConnector, DaemonPaths, }; @@ -103,7 +103,11 @@ pub enum Error { } impl WatchClient { - pub async fn new(base: CommandBase, telemetry: CommandEventBuilder) -> Result { + pub async fn new( + base: CommandBase, + telemetry: CommandEventBuilder, + logger: &TurboSubscriber, + ) -> Result { let signal = commands::run::get_signal()?; let handler = SignalHandler::new(signal); @@ -123,7 +127,7 @@ impl WatchClient { let watched_packages = run.get_relevant_packages(); - let (sender, handle) = run.start_experimental_ui()?.unzip(); + let (sender, handle) = run.start_experimental_ui(logger)?.unzip(); let connector = DaemonConnector { can_start_server: true, diff --git a/crates/turborepo-lib/src/tracing.rs b/crates/turborepo-lib/src/tracing.rs index 28b54768e1f91..b57dc94c99c89 100644 --- a/crates/turborepo-lib/src/tracing.rs +++ b/crates/turborepo-lib/src/tracing.rs @@ -1,4 +1,4 @@ -use std::{io::Stderr, marker::PhantomData, path::Path, sync::Mutex}; +use std::{fs, io, marker::PhantomData, path::Path, sync::Mutex}; use chrono::Local; use owo_colors::{ @@ -6,84 +6,69 @@ use owo_colors::{ Color, OwoColorize, }; use tracing::{field::Visit, metadata::LevelFilter, trace, Event, Level, Subscriber}; -use tracing_appender::{non_blocking::NonBlocking, rolling::RollingFileAppender}; -use tracing_chrome::ChromeLayer; +use tracing_appender::rolling::RollingFileAppender; pub use tracing_subscriber::reload::Error; use tracing_subscriber::{ - filter::Filtered, - fmt::{ - self, - format::{DefaultFields, Writer}, - FmtContext, FormatEvent, FormatFields, MakeWriter, - }, + fmt::{self, format::Writer, FmtContext, FormatEvent, FormatFields}, layer, prelude::*, registry::LookupSpan, reload::{self, Handle}, EnvFilter, Layer, Registry, }; +use turbopath::{AbsoluteSystemPath, AbsoluteSystemPathBuf}; use turborepo_ui::ColorConfig; +use uuid::Uuid; -// a lot of types to make sure we record the right relationships +/// Helper type definition for hiding exact type information +/// It still leaks the underlying subscriber type that the layer targets +type DynamicLayer = Box + Send + Sync + 'static>; -/// Note that we cannot express the type of `std::io::stderr` directly, so -/// use zero-size wrapper to call the function. -struct StdErrWrapper {} +/// Expressing layer::Layered by hand results in us specifying the subscriber +/// twice even though they will always be the same. +/// These are created by using `with` on a subscriber hence the nesting that +/// happens. +type DynamicLayered = layer::Layered, S>; -impl<'a> MakeWriter<'a> for StdErrWrapper { - type Writer = Stderr; +/// The subscriber we set up for logs written to stderr +type StdErrSubscriber = DynamicLayered; - fn make_writer(&'a self) -> Self::Writer { - std::io::stderr() - } -} - -/// A basic logger that logs to stderr using the TurboFormatter. -/// The first generic parameter refers to the previous layer, which -/// is in this case the default layer (`Registry`). -type StdErrLog = fmt::Layer; -/// We filter this using an EnvFilter. -type StdErrLogFiltered = Filtered; -/// When the `StdErrLogFiltered` is applied to the `Registry`, we get a -/// `StdErrLogLayered`, which forms the base for the next layer. -type StdErrLogLayered = layer::Layered; - -/// A logger that spits lines into a file, using the standard formatter. -/// It is applied on top of the `StdErrLogLayered` layer. -type DaemonLog = fmt::Layer; -/// This layer can be reloaded. `None` means the layer is disabled. -type DaemonReload = reload::Layer, StdErrLogLayered>; -/// We filter this using a custom filter that only logs events -/// - with evel `TRACE` or higher for the `turborepo` target -/// - with level `INFO` or higher for all other targets -type DaemonLogFiltered = Filtered; -/// When the `DaemonLogFiltered` is applied to the `StdErrLogLayered`, we get a -/// `DaemonLogLayered`, which forms the base for the next layer. -type DaemonLogLayered = layer::Layered; - -/// A logger that converts events to chrome tracing format and writes them -/// to a file. It is applied on top of the `DaemonLogLayered` layer. -type ChromeLog = ChromeLayer; -/// This layer can be reloaded. `None` means the layer is disabled. -type ChromeReload = reload::Layer, DaemonLogLayered>; -/// When the `ChromeLogFiltered` is applied to the `DaemonLogLayered`, we get a -/// `ChromeLogLayered`, which forms the base for the next layer. -type ChromeLogLayered = layer::Layered; +/// The subscriber for daemon +type DaemonLogSubscriber = DynamicLayered; pub struct TurboSubscriber { - daemon_update: Handle, StdErrLogLayered>, + config: TracingConfig, + stderr_update: Handle, Registry>, + file_guard: Mutex>, + + daemon_update: Handle>, StdErrSubscriber>, /// The non-blocking file logger only continues to log while this guard is /// held. We keep it here so that it doesn't get dropped. daemon_guard: Mutex>, - chrome_update: Handle, DaemonLogLayered>, + chrome_update: Handle>, DaemonLogSubscriber>, chrome_guard: Mutex>, #[cfg(feature = "pprof")] pprof_guard: pprof::ProfilerGuard<'static>, } +/// Configuration options for the TurboSubscriber +#[derive(Debug, Clone, Copy)] +struct TracingConfig { + level_override: Option, + emit_ansi: bool, +} + +/// Guard for writing logs to a given file +/// Will print log file location on drop +#[derive(Debug)] +struct LogFileGuard { + log_path: AbsoluteSystemPathBuf, + guard: tracing_appender::non_blocking::WorkerGuard, +} + impl TurboSubscriber { /// Sets up the tracing subscriber, with a default stderr layer using the /// TurboFormatter. @@ -103,41 +88,23 @@ impl TurboSubscriber { /// - `enable_chrome_tracing` enables logging to a file, using the chrome /// tracing formatter. pub fn new_with_verbosity(verbosity: usize, color_config: &ColorConfig) -> Self { - let level_override = match verbosity { - 0 => None, - 1 => Some(LevelFilter::INFO), - 2 => Some(LevelFilter::DEBUG), - _ => Some(LevelFilter::TRACE), - }; + let config = TracingConfig::new(verbosity, color_config); - let env_filter = |level: LevelFilter| { - let filter = EnvFilter::builder() - .with_default_directive(level.into()) - .with_env_var("TURBO_LOG_VERBOSITY") - .from_env_lossy() - .add_directive("reqwest=error".parse().unwrap()) - .add_directive("hyper=warn".parse().unwrap()) - .add_directive("h2=warn".parse().unwrap()); - - if let Some(max_level) = level_override { - filter.add_directive(max_level.into()) - } else { - filter - } - }; - - let stderr = fmt::layer() - .with_writer(StdErrWrapper {}) - .event_format(TurboFormatter::new_with_ansi( - !color_config.should_strip_ansi, - )) - .with_filter(env_filter(LevelFilter::WARN)); + let (stderr, stderr_guard) = config.stderr_subscriber(None); + debug_assert!( + stderr_guard.is_none(), + "no guard should be created when writing to stderr" + ); + let (stderr, stderr_update) = reload::Layer::new(stderr); + let stderr = stderr.boxed(); // we set this layer to None to start with, effectively disabling it - let (logrotate, daemon_update) = reload::Layer::new(Option::::None); - let logrotate: DaemonLogFiltered = logrotate.with_filter(env_filter(LevelFilter::INFO)); + let (logrotate, daemon_update) = reload::Layer::new(None); + let logrotate = logrotate + .with_filter(config.env_filter(LevelFilter::INFO)) + .boxed(); - let (chrome, chrome_update) = reload::Layer::new(Option::::None); + let (chrome, chrome_update) = reload::Layer::new(None); let registry = Registry::default() .with(stderr) @@ -154,6 +121,9 @@ impl TurboSubscriber { registry.init(); Self { + config, + stderr_update, + file_guard: Mutex::default(), daemon_update, daemon_guard: Mutex::new(None), chrome_update, @@ -171,9 +141,10 @@ impl TurboSubscriber { let (file_writer, guard) = tracing_appender::non_blocking(appender); trace!("created non-blocking file writer"); - let layer: DaemonLog = tracing_subscriber::fmt::layer() + let layer = tracing_subscriber::fmt::layer() .with_writer(file_writer) - .with_ansi(false); + .with_ansi(false) + .boxed(); self.daemon_update.reload(Some(layer))?; self.daemon_guard @@ -198,6 +169,8 @@ impl TurboSubscriber { .trace_style(tracing_chrome::TraceStyle::Async) .build(); + let layer = layer.boxed(); + self.chrome_update.reload(Some(layer))?; self.chrome_guard .lock() @@ -206,6 +179,32 @@ impl TurboSubscriber { Ok(()) } + + pub fn redirect_logs_to_file(&self, repo_root: &AbsoluteSystemPath) -> Result<(), Error> { + let (log_writer_layer, log_file_guard) = self.config.stderr_subscriber(Some(repo_root)); + + self.stderr_update.reload(log_writer_layer)?; + let mut file_guard_lock = self.file_guard.lock().expect("file guard lock poisoned"); + *file_guard_lock = log_file_guard; + + Ok(()) + } + + fn env_filter(level: LevelFilter, level_override: Option) -> EnvFilter { + let filter = EnvFilter::builder() + .with_default_directive(level.into()) + .with_env_var("TURBO_LOG_VERBOSITY") + .from_env_lossy() + .add_directive("reqwest=error".parse().unwrap()) + .add_directive("hyper=warn".parse().unwrap()) + .add_directive("h2=warn".parse().unwrap()); + + if let Some(max_level) = level_override { + filter.add_directive(max_level.into()) + } else { + filter + } + } } impl Drop for TurboSubscriber { @@ -236,6 +235,82 @@ impl Drop for TurboSubscriber { } } +impl TracingConfig { + pub fn new(verbosity: usize, color_config: &ColorConfig) -> Self { + let level_override = match verbosity { + 0 => None, + 1 => Some(LevelFilter::INFO), + 2 => Some(LevelFilter::DEBUG), + _ => Some(LevelFilter::TRACE), + }; + Self { + level_override, + emit_ansi: !color_config.should_strip_ansi, + } + } + + pub fn env_filter(&self, level: LevelFilter) -> EnvFilter { + let filter = EnvFilter::builder() + .with_default_directive(level.into()) + .with_env_var("TURBO_LOG_VERBOSITY") + .from_env_lossy() + .add_directive("reqwest=error".parse().unwrap()) + .add_directive("hyper=warn".parse().unwrap()) + .add_directive("h2=warn".parse().unwrap()); + + if let Some(max_level) = self.level_override { + filter.add_directive(max_level.into()) + } else { + filter + } + } + + pub fn stderr_subscriber( + &self, + repo_root: Option<&AbsoluteSystemPath>, + ) -> (DynamicLayer, Option) { + let layer = fmt::layer().event_format(TurboFormatter::new_with_ansi(self.emit_ansi)); + let filter = self.env_filter(LevelFilter::WARN); + if let Some((log_path, log_file)) = repo_root.and_then(|path| { + Self::open_log_file(path) + .inspect_err(|e| tracing::warn!("unable to setup log file: {e}")) + .ok() + }) { + let (non_blocking, guard) = tracing_appender::non_blocking(log_file); + ( + layer.with_writer(non_blocking).boxed(), + Some(LogFileGuard { log_path, guard }), + ) + } else { + ( + layer.with_writer(io::stderr).with_filter(filter).boxed(), + None, + ) + } + } + + fn open_log_file( + repo_root: &AbsoluteSystemPath, + ) -> io::Result<(AbsoluteSystemPathBuf, fs::File)> { + let uuid = Uuid::new_v4().hyphenated().to_string(); + let log_path = repo_root.join_components(&[".turbo", "logs", uuid.as_str()]); + log_path.ensure_dir()?; + let mut open_opts = fs::OpenOptions::new(); + let file = open_opts + .create(true) + .write(true) + .truncate(true) + .open(&log_path)?; + Ok((log_path, file)) + } +} + +impl Drop for LogFileGuard { + fn drop(&mut self) { + eprintln!("turbo logs written to {}", self.log_path); + } +} + /// The formatter for TURBOREPO /// /// This is a port of the go formatter, which follows a few main rules: