Use tracing for user-facing output (#63)

The setup is now as follows:

- All user-facing logging goes through `tracing` at an `info` leve.
(This excludes messages that go to `stdout`, like the compiled
`requirements.txt` file.)
- We have `--quiet` and `--verbose` command-line flags to set the
tracing filter and format defaults. So if you use `--verbose`, we
include timestamps and targets, and filter at `puffin=debug` level.
- However, we always respect `RUST_LOG`. So you can override the
_filter_ via `RUST_LOG`.

For example: the standard setup filters to `puffin=info`, and doesn't
show timestamps or targets:

<img width="1235" alt="Screen Shot 2023-10-08 at 3 41 22 PM"
src="54ca4db6-c66a-439e-bfa3-b86dee136e45">

If you run with `--verbose`, you get debug logging, but confined to our
crates:

<img width="1235" alt="Screen Shot 2023-10-08 at 3 41 57 PM"
src="c5c1af11-7f7a-4038-a173-d9eca4c3630b">

If you want verbose logging with _all_ crates, you can add
`RUST_LOG=debug`:

<img width="1235" alt="Screen Shot 2023-10-08 at 3 42 39 PM"
src="0b5191f4-4db0-4db9-86ba-6f9fa521bcb6">

I think this is a reasonable setup, though we can see how it feels and
refine over time.

Closes https://github.com/astral-sh/puffin/issues/57.

crates/puffin-cli/src/commands/clean.rs

@@ -12,10 +12,11 @@ pub(crate) async fn clean(cache: Option<&Path>) -> Result<ExitStatus> {
     };
 
     if !cache.exists() {
+        info!("No cache found at: {}", cache.display());
         return Ok(ExitStatus::Success);
     }
 
-    info!("Clearing cache at {}", cache.display());
+    info!("Clearing cache at: {}", cache.display());
 
     for entry in cache
         .read_dir()

crates/puffin-cli/src/commands/compile.rs

@@ -2,7 +2,7 @@ use std::path::Path;
 use std::str::FromStr;
 
 use anyhow::Result;
-use tracing::debug;
+use tracing::{debug, info};
 
 use platform_host::Platform;
 use platform_tags::Tags;
@@ -10,16 +10,23 @@ use puffin_client::PypiClientBuilder;
 use puffin_interpreter::PythonExecutable;
 use puffin_package::requirements::Requirements;
 
-use crate::commands::ExitStatus;
+use crate::commands::{elapsed, ExitStatus};
 
 /// Resolve a set of requirements into a set of pinned versions.
 pub(crate) async fn compile(src: &Path, cache: Option<&Path>) -> Result<ExitStatus> {
+    let start = std::time::Instant::now();
+
     // Read the `requirements.txt` from disk.
     let requirements_txt = std::fs::read_to_string(src)?;
 
     // Parse the `requirements.txt` into a list of requirements.
     let requirements = Requirements::from_str(&requirements_txt)?;
 
+    if requirements.is_empty() {
+        info!("No requirements found");
+        return Ok(ExitStatus::Success);
+    }
+
     // Detect the current Python interpreter.
     let platform = Platform::current()?;
     let python = PythonExecutable::from_env(platform, cache)?;
@@ -53,6 +60,14 @@ pub(crate) async fn compile(src: &Path, cache: Option<&Path>) -> Result<ExitStat
     )
     .await?;
 
+    let s = if resolution.len() == 1 { "" } else { "s" };
+    info!(
+        "Resolved {} package{} in {}",
+        resolution.len(),
+        s,
+        elapsed(start.elapsed())
+    );
+
     for (name, package) in resolution.iter() {
         #[allow(clippy::print_stdout)]
         {

crates/puffin-cli/src/commands/mod.rs

@@ -1,4 +1,5 @@
 use std::process::ExitCode;
+use std::time::Duration;
 
 pub(crate) use clean::clean;
 pub(crate) use compile::compile;
@@ -34,3 +35,16 @@ impl From<ExitStatus> for ExitCode {
         }
     }
 }
+
+/// Format a duration as a human-readable string, Cargo-style.
+pub(super) fn elapsed(duration: Duration) -> String {
+    let secs = duration.as_secs();
+
+    if secs >= 60 {
+        format!("{}m {:02}s", secs / 60, secs % 60)
+    } else if secs > 0 {
+        format!("{}.{:02}s", secs, duration.subsec_nanos() / 10_000_000)
+    } else {
+        format!("{}ms", duration.subsec_millis())
+    }
+}

crates/puffin-cli/src/commands/sync.rs

@@ -3,7 +3,7 @@ use std::str::FromStr;
 
 use anyhow::Result;
 use bitflags::bitflags;
-use tracing::debug;
+use tracing::{debug, info};
 
 use platform_host::Platform;
 use platform_tags::Tags;
@@ -12,7 +12,7 @@ use puffin_interpreter::{PythonExecutable, SitePackages};
 use puffin_package::package_name::PackageName;
 use puffin_package::requirements::Requirements;
 
-use crate::commands::ExitStatus;
+use crate::commands::{elapsed, ExitStatus};
 
 bitflags! {
     #[derive(Debug, Copy, Clone, Default)]
@@ -24,14 +24,16 @@ bitflags! {
 
 /// Install a set of locked requirements into the current Python environment.
 pub(crate) async fn sync(src: &Path, cache: Option<&Path>, flags: SyncFlags) -> Result<ExitStatus> {
+    let start = std::time::Instant::now();
+
     // Read the `requirements.txt` from disk.
     let requirements_txt = std::fs::read_to_string(src)?;
 
     // Parse the `requirements.txt` into a list of requirements.
     let requirements = Requirements::from_str(&requirements_txt)?;
+    let initial_requirements = requirements.len();
 
     // Detect the current Python interpreter.
-    // TODO(charlie): This is taking a _lot_ of time, like 20ms.
     let platform = Platform::current()?;
     let python = PythonExecutable::from_env(platform, cache)?;
     debug!(
@@ -49,7 +51,7 @@ pub(crate) async fn sync(src: &Path, cache: Option<&Path>, flags: SyncFlags) ->
             if let Some(version) = site_packages.get(&package) {
                 #[allow(clippy::print_stdout)]
                 {
-                    println!("Requirement already satisfied: {package} ({version})");
+                    info!("Requirement already satisfied: {package} ({version})");
                 }
                 false
             } else {
@@ -59,6 +61,13 @@ pub(crate) async fn sync(src: &Path, cache: Option<&Path>, flags: SyncFlags) ->
     };
 
     if requirements.is_empty() {
+        let s = if initial_requirements == 1 { "" } else { "s" };
+        info!(
+            "Audited {} package{} in {}",
+            initial_requirements,
+            s,
+            elapsed(start.elapsed())
+        );
         return Ok(ExitStatus::Success);
     }
 
@@ -91,10 +100,13 @@ pub(crate) async fn sync(src: &Path, cache: Option<&Path>, flags: SyncFlags) ->
     let wheels = resolution.into_files().collect::<Vec<_>>();
     puffin_installer::install(&wheels, &python, &client, cache).await?;
 
-    #[allow(clippy::print_stdout)]
+    let s = if requirements.len() == 1 { "" } else { "s" };
-    {
+    info!(
-        println!("Installed {} wheels", wheels.len());
+        "Installed {} package{} in {}",
-    }
+        requirements.len(),
+        s,
+        elapsed(start.elapsed())
+    );
 
     Ok(ExitStatus::Success)
 }

crates/puffin-cli/src/logging.rs

@@ -1,27 +1,79 @@
-use anyhow::Result;
 use tracing::level_filters::LevelFilter;
-use tracing_subscriber::filter::Targets;
 use tracing_subscriber::layer::SubscriberExt;
-use tracing_subscriber::{EnvFilter, Layer, Registry};
+use tracing_subscriber::util::SubscriberInitExt;
+use tracing_subscriber::EnvFilter;
 use tracing_tree::time::Uptime;
+use tracing_tree::HierarchicalLayer;
 
-pub(crate) fn setup_logging() -> Result<()> {
+#[derive(Debug, Default, Clone, Copy, PartialEq, Eq)]
-    let targets = Targets::new()
+pub(crate) enum Level {
-        .with_target("hyper", LevelFilter::WARN)
+    /// Show deliberately user-facing messages and errors.
-        .with_target("reqwest", LevelFilter::WARN)
+    #[default]
-        .with_target("tokio", LevelFilter::WARN)
+    Default,
-        .with_target("blocking", LevelFilter::OFF)
+    /// Suppress all user-facing output.
-        .with_default(LevelFilter::TRACE);
+    Quiet,
-
+    /// Show all messages, including debug messages.
-    let subscriber = Registry::default().with(
+    Verbose,
-        tracing_tree::HierarchicalLayer::default()
+}
-            .with_targets(true)
+
-            .with_writer(|| Box::new(std::io::stderr()))
+/// Configure `tracing` based on the given [`Level`], taking into account the `RUST_LOG` environment
-            .with_timer(Uptime::default())
+/// variable.
-            .with_filter(EnvFilter::from_default_env())
+///
-            .with_filter(targets),
+/// The [`Level`] is used to dictate the default filters (which can be overridden by the `RUST_LOG`
-    );
+/// environment variable) along with the formatting of the output. For example, [`Level::Verbose`]
-    tracing::subscriber::set_global_default(subscriber)?;
+/// includes targets and timestamps, while [`Level::Default`] excludes both.
-
+pub(crate) fn setup_logging(level: Level) {
-    Ok(())
+    match level {
+        Level::Default => {
+            // Show `INFO` messages from the CLI crate, but allow `RUST_LOG` to override.
+            let filter = EnvFilter::try_from_default_env()
+                .or_else(|_| EnvFilter::try_new("puffin=info"))
+                .unwrap();
+
+            // Regardless of the tracing level, show messages without any adornment.
+            tracing_subscriber::registry()
+                .with(filter)
+                .with(
+                    tracing_subscriber::fmt::layer()
+                        .without_time()
+                        .with_target(false)
+                        .with_writer(std::io::stderr),
+                )
+                .init();
+        }
+        Level::Quiet => {
+            // Show nothing, but allow `RUST_LOG` to override.
+            let filter = EnvFilter::builder()
+                .with_default_directive(LevelFilter::OFF.into())
+                .from_env_lossy();
+
+            // Regardless of the tracing level, show messages without any adornment.
+            tracing_subscriber::registry()
+                .with(filter)
+                .with(
+                    tracing_subscriber::fmt::layer()
+                        .without_time()
+                        .with_target(false)
+                        .with_writer(std::io::sink),
+                )
+                .init();
+        }
+        Level::Verbose => {
+            // Show `DEBUG` messages from the CLI crate, but allow `RUST_LOG` to override.
+            let filter = EnvFilter::try_from_default_env()
+                .or_else(|_| EnvFilter::try_new("puffin=debug"))
+                .unwrap();
+
+            // Regardless of the tracing level, include the uptime and target for each message.
+            tracing_subscriber::registry()
+                .with(filter)
+                .with(
+                    HierarchicalLayer::default()
+                        .with_targets(true)
+                        .with_timer(Uptime::default())
+                        .with_writer(std::io::stderr),
+                )
+                .init();
+        }
+    }
 }

crates/puffin-cli/src/main.rs

@@ -16,6 +16,14 @@ mod logging;
 struct Cli {
     #[command(subcommand)]
     command: Commands,
+
+    /// Do not print any output.
+    #[arg(global = true, long, short, conflicts_with = "verbose")]
+    quiet: bool,
+
+    /// Use verbose output.
+    #[arg(global = true, long, short, conflicts_with = "quiet")]
+    verbose: bool,
 }
 
 #[derive(Subcommand)]
@@ -65,7 +73,13 @@ struct FreezeArgs {
 async fn main() -> ExitCode {
     let cli = Cli::parse();
 
-    let _ = logging::setup_logging();
+    logging::setup_logging(if cli.quiet {
+        logging::Level::Quiet
+    } else if cli.verbose {
+        logging::Level::Verbose
+    } else {
+        logging::Level::Default
+    });
 
     let dirs = ProjectDirs::from("", "", "puffin");
 

crates/puffin-installer/src/lib.rs

@@ -7,7 +7,7 @@ use rayon::iter::ParallelBridge;
 use rayon::iter::ParallelIterator;
 use tokio::task::JoinSet;
 use tokio_util::compat::FuturesAsyncReadCompatExt;
-use tracing::debug;
+use tracing::{debug, info};
 use url::Url;
 use zip::ZipArchive;
 
@@ -35,6 +35,10 @@ pub async fn install(
         tokio::fs::create_dir_all(cache.join(WHEEL_CACHE)).await?;
     }
 
+    if wheels.is_empty() {
+        return Ok(());
+    }
+
     // Phase 1: Fetch the wheels in parallel.
     debug!("Phase 1: Fetching wheels");
     let mut fetches = JoinSet::new();
@@ -44,12 +48,12 @@ pub async fn install(
         let key = cache_key(wheel)?;
         if let Some(cache) = cache {
             if cache.join(WHEEL_CACHE).join(&key).exists() {
-                debug!("Found wheel in cache: {:?}", wheel.filename);
+                debug!("Found wheel in cache: {}", wheel.filename);
                 continue;
             }
         }
 
-        debug!("Fetching wheel: {:?}", wheel.filename);
+        debug!("Downloading: {}", wheel.filename);
 
         fetches.spawn(fetch_wheel(
             wheel.clone(),
@@ -57,6 +61,12 @@ pub async fn install(
             cache.map(Path::to_path_buf),
         ));
     }
+
+    if !fetches.is_empty() {
+        let s = if fetches.len() == 1 { "" } else { "s" };
+        info!("Downloading {} wheel{}", fetches.len(), s);
+    }
+
     while let Some(result) = fetches.join_next().await.transpose()? {
         downloads.push(result?);
     }
@@ -69,7 +79,7 @@ pub async fn install(
         let filename = wheel.file.filename.clone();
         let key = cache_key(&wheel.file)?;
 
-        debug!("Unpacking wheel: {:?}", filename);
+        debug!("Unpacking: {}", filename);
 
         // Unzip the wheel.
         tokio::task::spawn_blocking({
@@ -80,7 +90,7 @@ pub async fn install(
 
         // Write the unzipped wheel to the cache (atomically).
         if let Some(cache) = cache {
-            debug!("Caching wheel: {:?}", filename);
+            debug!("Caching wheel: {}", filename);
             tokio::fs::rename(
                 temp_dir.path().join(&key),
                 cache.join(WHEEL_CACHE).join(&key),
@@ -89,6 +99,17 @@ pub async fn install(
         }
     }
 
+    let s = if wheels.len() == 1 { "" } else { "s" };
+    info!(
+        "Linking package{}: {}",
+        s,
+        wheels
+            .iter()
+            .map(cache_key)
+            .collect::<Result<Vec<_>>>()?
+            .join(" ")
+    );
+
     // Phase 3: Install each wheel.
     debug!("Phase 3: Installing wheels");
     let location = InstallLocation::Venv {

crates/puffin-resolver/src/lib.rs

@@ -6,7 +6,7 @@ use bitflags::bitflags;
 use futures::future::Either;
 use futures::{StreamExt, TryFutureExt};
 use thiserror::Error;
-use tracing::debug;
+use tracing::{debug, info};
 
 use pep440_rs::Version;
 use pep508_rs::{MarkerEnvironment, Requirement, VersionOrUrl};
@@ -30,6 +30,16 @@ impl Resolution {
     pub fn into_files(self) -> impl Iterator<Item = File> {
         self.0.into_values().map(|package| package.file)
     }
+
+    /// Return the number of pinned packages in this resolution.
+    pub fn len(&self) -> usize {
+        self.0.len()
+    }
+
+    /// Return `true` if there are no pinned packages in this resolution.
+    pub fn is_empty(&self) -> bool {
+        self.0.is_empty()
+    }
 }
 
 #[derive(Debug)]
@@ -158,6 +168,11 @@ pub async fn resolve(
                         metadata.version, requirement
                     );
 
+                    info!(
+                        "Selecting: {}=={} ({})",
+                        metadata.name, metadata.version, file.filename
+                    );
+
                     // Add to the resolved set.
                     let normalized_name = PackageName::normalize(&requirement.name);
                     in_flight.remove(&normalized_name);

requirements.txt

@@ -2,7 +2,7 @@
 # This file is autogenerated by pip-compile with Python 3.11
 # by the following command:
 #
-#    pip-compile --pip-args='--no-cache-dir' requirements.in
+#    pip-compile requirements.in
 #
 attrs==23.1.0
     # via