From 6897001fee78860bb1a2be2e39bf8da2ae7d2ee3 Mon Sep 17 00:00:00 2001 From: Charlie Marsh Date: Mon, 2 Sep 2024 15:46:09 -0400 Subject: [PATCH] Stream build backend output to `debug!` (#6903) ## Summary We need to decide whether we want this in `debug!` or `tracing!`. We also _probably_ (?) want to show this by default in `uv build`. Closes https://github.com/astral-sh/uv/issues/1567. Closes https://github.com/astral-sh/uv/issues/5893. --- crates/uv-build/src/lib.rs | 153 +++++++++++++++++-------- crates/uv-virtualenv/src/virtualenv.rs | 8 +- crates/uv/tests/pip_compile.rs | 2 +- crates/uv/tests/pip_install.rs | 2 +- crates/uv/tests/pip_sync.rs | 2 +- 5 files changed, 111 insertions(+), 56 deletions(-) diff --git a/crates/uv-build/src/lib.rs b/crates/uv-build/src/lib.rs index bf76c458f8cf..22f393ff9662 100644 --- a/crates/uv-build/src/lib.rs +++ b/crates/uv-build/src/lib.rs @@ -13,16 +13,17 @@ use std::ffi::OsString; use std::fmt::{Display, Formatter}; use std::io; use std::path::{Path, PathBuf}; -use std::process::{ExitStatus, Output}; +use std::process::ExitStatus; use std::rc::Rc; use std::str::FromStr; use std::sync::LazyLock; use std::{env, iter}; use tempfile::{tempdir_in, TempDir}; use thiserror::Error; +use tokio::io::AsyncBufReadExt; use tokio::process::Command; use tokio::sync::{Mutex, Semaphore}; -use tracing::{debug, info_span, instrument, Instrument}; +use tracing::{debug, error, info_span, instrument, Instrument}; use distribution_types::Resolution; use pep440_rs::Version; @@ -89,7 +90,7 @@ pub enum Error { RequirementsInstall(&'static str, #[source] anyhow::Error), #[error("Failed to create temporary virtualenv")] Virtualenv(#[from] uv_virtualenv::Error), - #[error("Failed to run {0}")] + #[error("Failed to run `{0}`")] CommandFailed(PathBuf, #[source] io::Error), #[error("{message} with {exit_code}\n--- stdout:\n{stdout}\n--- stderr:\n{stderr}\n---")] BuildBackend { @@ -159,14 +160,11 @@ impl Display for MissingHeaderCause { impl Error { fn from_command_output( message: String, - output: &Output, + output: &PythonRunnerOutput, version_id: impl Into, ) -> Self { - let stdout = String::from_utf8_lossy(&output.stdout).trim().to_string(); - let stderr = String::from_utf8_lossy(&output.stderr).trim().to_string(); - - // In the cases i've seen it was the 5th and 3rd last line (see test case), 10 seems like a reasonable cutoff - let missing_library = stderr.lines().rev().take(10).find_map(|line| { + // In the cases I've seen it was the 5th and 3rd last line (see test case), 10 seems like a reasonable cutoff. + let missing_library = output.stderr.iter().rev().take(10).find_map(|line| { if let Some((_, [header])) = MISSING_HEADER_RE_GCC .captures(line.trim()) .or(MISSING_HEADER_RE_CLANG.captures(line.trim())) @@ -191,8 +189,8 @@ impl Error { return Self::MissingHeader { message, exit_code: output.status, - stdout, - stderr, + stdout: output.stdout.iter().join("\n"), + stderr: output.stderr.iter().join("\n"), missing_header_cause: MissingHeaderCause { missing_library, version_id: version_id.into(), @@ -203,8 +201,8 @@ impl Error { Self::BuildBackend { message, exit_code: output.status, - stdout, - stderr, + stdout: output.stdout.iter().join("\n"), + stderr: output.stderr.iter().join("\n"), } } } @@ -454,7 +452,7 @@ impl SourceBuild { .install(&resolved_requirements, &venv) .await .map_err(|err| { - Error::RequirementsInstall("build-system.requires (install)", err) + Error::RequirementsInstall("`build-system.requires` (install)", err) })?; } @@ -540,7 +538,7 @@ impl SourceBuild { .resolve(&default_backend.requirements) .await .map_err(|err| { - Error::RequirementsInstall("setup.py build (resolve)", err) + Error::RequirementsInstall("`setup.py` build (resolve)", err) })?; *resolution = Some(resolved_requirements.clone()); resolved_requirements @@ -550,7 +548,7 @@ impl SourceBuild { .resolve(&pep517_backend.requirements) .await .map_err(|err| { - Error::RequirementsInstall("build-system.requires (resolve)", err) + Error::RequirementsInstall("`build-system.requires` (resolve)", err) })? }, ) @@ -682,8 +680,8 @@ impl SourceBuild { }; let span = info_span!( "run_python_script", - script=format!("prepare_metadata_for_build_{}", self.build_kind), - python_version = %self.venv.interpreter().python_version() + script = format!("prepare_metadata_for_build_{}", self.build_kind), + version_id = self.version_id, ); let output = self .runner @@ -808,8 +806,8 @@ impl SourceBuild { let span = info_span!( "run_python_script", - script=format!("build_{}", self.build_kind), - python_version = %self.venv.interpreter().python_version() + script = format!("build_{}", self.build_kind), + version_id = self.version_id, ); let output = self .runner @@ -909,8 +907,8 @@ async fn create_pep517_build_environment( }; let span = info_span!( "run_python_script", - script=format!("get_requires_for_build_{}", build_kind), - python_version = %venv.interpreter().python_version() + script = format!("get_requires_for_build_{}", build_kind), + version_id = version_id, ); let output = runner .run_script( @@ -971,12 +969,12 @@ async fn create_pep517_build_environment( let resolution = build_context .resolve(&requirements) .await - .map_err(|err| Error::RequirementsInstall("build-system.requires (resolve)", err))?; + .map_err(|err| Error::RequirementsInstall("`build-system.requires` (resolve)", err))?; build_context .install(&resolution, venv) .await - .map_err(|err| Error::RequirementsInstall("build-system.requires (install)", err))?; + .map_err(|err| Error::RequirementsInstall("`build-system.requires` (install)", err))?; } Ok(()) @@ -984,10 +982,18 @@ async fn create_pep517_build_environment( /// A runner that manages the execution of external python processes with a /// concurrency limit. +#[derive(Debug)] struct PythonRunner { control: Semaphore, } +#[derive(Debug)] +struct PythonRunnerOutput { + stdout: Vec, + stderr: Vec, + status: ExitStatus, +} + impl PythonRunner { /// Create a `PythonRunner` with the provided concurrency limit. fn new(concurrency: usize) -> PythonRunner { @@ -1009,36 +1015,85 @@ impl PythonRunner { source_tree: &Path, environment_variables: &FxHashMap, modified_path: &OsString, - ) -> Result { + ) -> Result { + /// Read lines from a reader and store them in a buffer. + async fn read_from( + mut reader: tokio::io::Lines>, + buffer: &mut Vec, + ) -> io::Result<()> { + loop { + match reader.next_line().await? { + Some(line) => { + debug!("{line}"); + buffer.push(line); + } + None => return Ok(()), + } + } + } + let _permit = self.control.acquire().await.unwrap(); - Command::new(venv.python_executable()) + let mut child = Command::new(venv.python_executable()) .args(["-c", script]) .current_dir(source_tree.simplified()) - // Pass in remaining environment variables .envs(environment_variables) - // Set the modified PATH .env("PATH", modified_path) - // Activate the venv .env("VIRTUAL_ENV", venv.root()) .env("CLICOLOR_FORCE", "1") - .output() + .stdout(std::process::Stdio::piped()) + .stderr(std::process::Stdio::piped()) + .spawn() + .map_err(|err| Error::CommandFailed(venv.python_executable().to_path_buf(), err))?; + + // Create buffers to capture `stdout` and `stderr`. + let mut stdout_buf = Vec::with_capacity(1024); + let mut stderr_buf = Vec::with_capacity(1024); + + // Create separate readers for `stdout` and `stderr`. + let stdout_reader = tokio::io::BufReader::new(child.stdout.take().unwrap()).lines(); + let stderr_reader = tokio::io::BufReader::new(child.stderr.take().unwrap()).lines(); + + // Asynchronously read from the in-memory pipes. + let result = tokio::join!( + read_from(stdout_reader, &mut stdout_buf), + read_from(stderr_reader, &mut stderr_buf), + ); + match result { + (Ok(()), Ok(())) => {} + (Err(err), _) | (_, Err(err)) => { + return Err(Error::CommandFailed( + venv.python_executable().to_path_buf(), + err, + )) + } + } + + // Wait for the child process to finish. + let status = child + .wait() .await - .map_err(|err| Error::CommandFailed(venv.python_executable().to_path_buf(), err)) + .map_err(|err| Error::CommandFailed(venv.python_executable().to_path_buf(), err))?; + + Ok(PythonRunnerOutput { + stdout: stdout_buf, + stderr: stderr_buf, + status, + }) } } #[cfg(test)] mod test { - use std::process::{ExitStatus, Output}; + use std::process::ExitStatus; use indoc::indoc; - use crate::Error; + use crate::{Error, PythonRunnerOutput}; #[test] fn missing_header() { - let output = Output { + let output = PythonRunnerOutput { status: ExitStatus::default(), // This is wrong but `from_raw` is platform-gated. stdout: indoc!(r" running bdist_wheel @@ -1047,7 +1102,7 @@ mod test { creating build/temp.linux-x86_64-cpython-39/pygraphviz gcc -Wno-unused-result -Wsign-compare -DNDEBUG -g -fwrapv -O3 -Wall -DOPENSSL_NO_SSL3 -fPIC -DSWIG_PYTHON_STRICT_BYTE_CHAR -I/tmp/.tmpy6vVes/.venv/include -I/home/konsti/.pyenv/versions/3.9.18/include/python3.9 -c pygraphviz/graphviz_wrap.c -o build/temp.linux-x86_64-cpython-39/pygraphviz/graphviz_wrap.o " - ).as_bytes().to_vec(), + ).lines().map(ToString::to_string).collect(), stderr: indoc!(r#" warning: no files found matching '*.png' under directory 'doc' warning: no files found matching '*.txt' under directory 'doc' @@ -1059,7 +1114,7 @@ mod test { compilation terminated. error: command '/usr/bin/gcc' failed with exit code 1 "# - ).as_bytes().to_vec(), + ).lines().map(ToString::to_string).collect(), }; let err = Error::from_command_output( @@ -1098,20 +1153,20 @@ mod test { #[test] fn missing_linker_library() { - let output = Output { + let output = PythonRunnerOutput { status: ExitStatus::default(), // This is wrong but `from_raw` is platform-gated. stdout: Vec::new(), stderr: indoc!( r" - 1099 | n = strlen(p); - | ^~~~~~~~~ + 1099 | n = strlen(p); + | ^~~~~~~~~ /usr/bin/ld: cannot find -lncurses: No such file or directory collect2: error: ld returned 1 exit status - error: command '/usr/bin/x86_64-linux-gnu-gcc' failed with exit code 1 - " + error: command '/usr/bin/x86_64-linux-gnu-gcc' failed with exit code 1" ) - .as_bytes() - .to_vec(), + .lines() + .map(ToString::to_string) + .collect(), }; let err = Error::from_command_output( @@ -1128,7 +1183,7 @@ mod test { --- stderr: 1099 | n = strlen(p); - | ^~~~~~~~~ + | ^~~~~~~~~ /usr/bin/ld: cannot find -lncurses: No such file or directory collect2: error: ld returned 1 exit status error: command '/usr/bin/x86_64-linux-gnu-gcc' failed with exit code 1 @@ -1142,7 +1197,7 @@ mod test { #[test] fn missing_wheel_package() { - let output = Output { + let output = PythonRunnerOutput { status: ExitStatus::default(), // This is wrong but `from_raw` is platform-gated. stdout: Vec::new(), stderr: indoc!( @@ -1152,11 +1207,11 @@ mod test { or: setup.py --help-commands or: setup.py cmd --help - error: invalid command 'bdist_wheel' - " + error: invalid command 'bdist_wheel'" ) - .as_bytes() - .to_vec(), + .lines() + .map(ToString::to_string) + .collect(), }; let err = Error::from_command_output( diff --git a/crates/uv-virtualenv/src/virtualenv.rs b/crates/uv-virtualenv/src/virtualenv.rs index a1d97b37dfb3..7637d42d5ad0 100644 --- a/crates/uv-virtualenv/src/virtualenv.rs +++ b/crates/uv-virtualenv/src/virtualenv.rs @@ -8,7 +8,7 @@ use std::path::Path; use fs_err as fs; use fs_err::File; use itertools::Itertools; -use tracing::info; +use tracing::debug; use pypi_types::Scheme; use uv_fs::{cachedir, Simplified, CWD}; @@ -92,16 +92,16 @@ pub(crate) fn create( ))); } else if metadata.is_dir() { if allow_existing { - info!("Allowing existing directory"); + debug!("Allowing existing directory"); } else if location.join("pyvenv.cfg").is_file() { - info!("Removing existing directory"); + debug!("Removing existing directory"); fs::remove_dir_all(location)?; fs::create_dir_all(location)?; } else if location .read_dir() .is_ok_and(|mut dir| dir.next().is_none()) { - info!("Ignoring empty directory"); + debug!("Ignoring empty directory"); } else { return Err(Error::Io(io::Error::new( io::ErrorKind::AlreadyExists, diff --git a/crates/uv/tests/pip_compile.rs b/crates/uv/tests/pip_compile.rs index 3580aa78e9ce..b78004d14bb6 100644 --- a/crates/uv/tests/pip_compile.rs +++ b/crates/uv/tests/pip_compile.rs @@ -11781,7 +11781,7 @@ fn incompatible_build_constraint() -> Result<()> { ----- stderr ----- error: Failed to download and build `requests==1.2.0` - Caused by: Failed to install requirements from setup.py build (resolve) + Caused by: Failed to install requirements from `setup.py` build (resolve) Caused by: No solution found when resolving: setuptools>=40.8.0 Caused by: Because you require setuptools>=40.8.0 and setuptools==1, we can conclude that your requirements are unsatisfiable. "### diff --git a/crates/uv/tests/pip_install.rs b/crates/uv/tests/pip_install.rs index 3b0ed90caf38..ea179e0f5954 100644 --- a/crates/uv/tests/pip_install.rs +++ b/crates/uv/tests/pip_install.rs @@ -6171,7 +6171,7 @@ fn incompatible_build_constraint() -> Result<()> { ----- stderr ----- error: Failed to download and build `requests==1.2.0` - Caused by: Failed to install requirements from setup.py build (resolve) + Caused by: Failed to install requirements from `setup.py` build (resolve) Caused by: No solution found when resolving: setuptools>=40.8.0 Caused by: Because you require setuptools>=40.8.0 and setuptools==1, we can conclude that your requirements are unsatisfiable. "### diff --git a/crates/uv/tests/pip_sync.rs b/crates/uv/tests/pip_sync.rs index fbc9e8cd4d63..bf6ed2b9d539 100644 --- a/crates/uv/tests/pip_sync.rs +++ b/crates/uv/tests/pip_sync.rs @@ -5473,7 +5473,7 @@ fn incompatible_build_constraint() -> Result<()> { ----- stderr ----- error: Failed to download and build `requests==1.2.0` - Caused by: Failed to install requirements from setup.py build (resolve) + Caused by: Failed to install requirements from `setup.py` build (resolve) Caused by: No solution found when resolving: setuptools>=40.8.0 Caused by: Because you require setuptools>=40.8.0 and setuptools==1, we can conclude that your requirements are unsatisfiable. "###