devenv: convert logging to use tracing ecosystem

Cargo.toml

@@ -1,6 +1,13 @@
 [workspace]
 resolver = "2"
-members = ["devenv", "devenv-eval-cache", "devenv-run-tests", "devenv-tasks", "nix-conf-parser", "xtask"]
+members = [
+    "devenv",
+    "devenv-eval-cache",
+    "devenv-run-tests",
+    "devenv-tasks",
+    "nix-conf-parser",
+    "xtask",
+]
 
 [workspace.package]
 edition = "2021"
@@ -51,6 +58,8 @@ tempdir = "0.3.7"
 tempfile = "3.12.0"
 thiserror = "1.0.63"
 tracing = "0.1.40"
+tracing-core = "0.1.32"
+tracing-subscriber = { version = "0.3.18", features = ["env-filter"] }
 tokio = { version = "1.39.3", features = [
     "process",
     "fs",

devenv-eval-cache/Cargo.toml

@@ -17,6 +17,7 @@ serde_repr.workspace = true
 sqlx.workspace = true
 thiserror.workspace = true
 tokio.workspace = true
+tracing.workspace = true
 
 [dev-dependencies]
 tempdir.workspace = true

devenv-eval-cache/src/command.rs

@@ -6,6 +6,7 @@ use std::path::{Path, PathBuf};
 use std::process::{self, Command, Stdio};
 use std::time::{SystemTime, UNIX_EPOCH};
 use thiserror::Error;
+use tracing::{debug, info, trace};
 
 use crate::{
     db, hash,
@@ -19,8 +20,6 @@ pub enum CommandError {
     Io(#[from] io::Error),
     #[error(transparent)]
     Sqlx(#[from] sqlx::Error),
-    #[error("Nix command failed: {0}")]
-    NonZeroExitStatus(process::ExitStatus),
 }
 
 pub struct CachedCommand<'a> {
@@ -108,13 +107,17 @@ impl<'a> CachedCommand<'a> {
                         f(&log);
                     }
 
-                    // FIX: verbosity
-                    if let Some(msg) = log.get_log_msg_by_level(Verbosity::Info) {
-                        raw_lines.extend_from_slice(msg.as_bytes());
+                    if let Some(op) = extract_op_from_log_line(&log) {
+                        ops.push(op);
                     }
 
-                    if let Some(op) = extract_op_from_log_line(log) {
-                        ops.push(op);
+                    // FIX: verbosity
+                    if let Some(msg) = log
+                        .filter_by_level(Verbosity::Info)
+                        .and_then(InternalLog::get_msg)
+                    {
+                        raw_lines.extend_from_slice(msg.as_bytes());
+                        raw_lines.push(b'\n');
                     }
                 }
             }
@@ -129,13 +132,18 @@ impl<'a> CachedCommand<'a> {
 
         let status = child.wait().map_err(CommandError::Io)?;
 
-        if !status.success() {
-            return Err(CommandError::NonZeroExitStatus(status));
-        }
-
         let stdout = stdout_thread.await.unwrap().map_err(CommandError::Io)?;
         let (mut ops, stderr) = stderr_thread.await.unwrap();
 
+        if !status.success() {
+            return Ok(Output {
+                status,
+                stdout,
+                stderr,
+                ..Default::default()
+            });
+        }
+
         // Remove excluded paths if any are a parent directory
         ops.retain_mut(|op| {
             !self
@@ -202,7 +210,7 @@ pub fn supports_eval_caching(cmd: &Command) -> bool {
     cmd.get_program().to_string_lossy().ends_with("nix")
 }
 
-#[derive(Debug)]
+#[derive(Debug, Default)]
 pub struct Output {
     /// The status code of the command.
     pub status: process::ExitStatus,
@@ -277,15 +285,20 @@ async fn query_cached_output(
 
         let mut should_refresh = false;
 
-        let file_input_hash = hash::digest(
+        let new_input_hash = hash::digest(
             &files
                 .iter()
                 .map(|f| f.content_hash.clone())
                 .collect::<String>(),
         );
 
         // Hash of input hashes do not match
-        if cmd.input_hash != file_input_hash {
+        if cmd.input_hash != new_input_hash {
+            debug!(
+                old_hash = cmd.input_hash,
+                new_hash = new_input_hash,
+                "Input hashes do not match, refreshing command",
+            );
             should_refresh = true;
         }
 
@@ -323,6 +336,8 @@ async fn query_cached_output(
         if should_refresh {
             Ok(None)
         } else {
+            trace!("Command has not been modified, returning cached output");
+
             db::update_command_updated_at(pool, cmd.id)
                 .await
                 .map_err(CommandError::Sqlx)?;
@@ -342,9 +357,9 @@ async fn query_cached_output(
 
 /// Convert a parse log line into into an `Op`.
 /// Filters out paths that don't impact caching.
-fn extract_op_from_log_line(log: InternalLog) -> Option<Op> {
+fn extract_op_from_log_line(log: &InternalLog) -> Option<Op> {
     match log {
-        InternalLog::Msg { .. } => Op::from_internal_log(&log).and_then(|op| match op {
+        InternalLog::Msg { .. } => Op::from_internal_log(log).and_then(|op| match op {
             Op::EvaluatedFile { ref source }
             | Op::ReadFile { ref source }
             | Op::ReadDir { ref source }