Merge pull request #60 from DeterminateSystems/log-and-cat-after-workflow-finished

Record and print tracing logs in debug mode

Cargo.lock

@@ -2554,6 +2554,7 @@ dependencies = [
  "tokio-util",
  "tower-http",
  "tracing",
+ "tracing-appender",
  "tracing-subscriber",
  "uuid",
 ]
@@ -4665,6 +4666,18 @@ dependencies = [
  "tracing-core",
 ]
 
+[[package]]
+name = "tracing-appender"
+version = "0.2.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "3566e8ce28cc0a3fe42519fc80e6b4c943cc4c8cef275620eb8dac2d3d4e06cf"
+dependencies = [
+ "crossbeam-channel",
+ "thiserror",
+ "time",
+ "tracing-subscriber",
+]
+
 [[package]]
 name = "tracing-attributes"
 version = "0.1.26"
@@ -4698,12 +4711,12 @@ dependencies = [
 
 [[package]]
 name = "tracing-log"
-version = "0.1.3"
+version = "0.2.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "78ddad33d2d10b1ed7eb9d1f518a5674713876e97e5bb9b7345a7984fbb4f922"
+checksum = "ee855f1f400bd0e5c02d150ae5de3840039a3f54b025156404e34c23c03f47c3"
 dependencies = [
- "lazy_static",
  "log",
+ "once_cell",
  "tracing-core",
 ]
 
@@ -4719,9 +4732,9 @@ dependencies = [
 
 [[package]]
 name = "tracing-subscriber"
-version = "0.3.17"
+version = "0.3.18"
 source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "30a651bc37f915e81f087d86e62a18eec5f79550c7faff886f7090b4ea757c77"
+checksum = "ad0f048c97dbd9faa9b7df56362b8ebcaa52adb06b498c050d2f4e32f90a7a8b"
 dependencies = [
  "matchers",
  "nu-ansi-term",

magic-nix-cache/Cargo.toml

@@ -50,6 +50,7 @@ tempfile = "3.9"
 uuid = { version = "1.4.0", features = ["serde", "v7", "rand", "std"] }
 futures = "0.3"
 async-compression = "0.4"
+tracing-appender = "0.2.3"
 
 [dependencies.tokio]
 version = "1.28.0"

magic-nix-cache/src/api.rs

@@ -49,12 +49,18 @@ async fn workflow_finish(
         sender
             .send(())
             .map_err(|_| Error::Internal("Sending shutdown server message".to_owned()))?;
+    }
 
-        // Wait for the Attic push workers to finish.
     if let Some(attic_state) = state.flakehub_state.write().await.take() {
         tracing::info!("Waiting for FlakeHub cache uploads to finish");
-            attic_state.push_session.wait().await?;
+        let _paths = attic_state.push_session.wait().await?;
     }
+
+    // NOTE(cole-h): see `init_logging`
+    if let Some(logfile) = &state.logfile {
+        let logfile_contents = std::fs::read_to_string(logfile)?;
+        println!("Every log line throughout the lifetime of the program:");
+        println!("\n{logfile_contents}\n");
     }
 
     let reply = WorkflowFinishResponse {};
@@ -73,6 +79,7 @@ pub struct EnqueuePathsRequest {
 pub struct EnqueuePathsResponse {}
 
 /// Schedule paths in the local Nix store for uploading.
+#[tracing::instrument(skip_all)]
 async fn enqueue_paths(
     Extension(state): Extension<State>,
     Json(req): Json<EnqueuePathsRequest>,

magic-nix-cache/src/flakehub.rs

@@ -1,5 +1,6 @@
 use crate::env::Environment;
 use crate::error::{Error, Result};
+use anyhow::Context;
 use attic::cache::CacheName;
 use attic::nix_store::{NixStore, StorePath};
 use attic_client::push::{PushSession, PushSessionConfig};
@@ -209,6 +210,7 @@ pub async fn enqueue_paths(state: &State, store_paths: Vec<StorePath>) -> Result
 
 /// Refresh the GitHub Actions JWT every 2 minutes (slightly less than half of the default validity
 /// period) to ensure pushing / pulling doesn't stop working.
+#[tracing::instrument(skip_all)]
 async fn refresh_github_actions_jwt_worker(
     netrc_path: std::path::PathBuf,
     mut github_jwt: String,
@@ -220,6 +222,10 @@ async fn refresh_github_actions_jwt_worker(
     // breaks this.
     let next_refresh = std::time::Duration::from_secs(2 * 60);
 
+    // NOTE(cole-h): we sleep until the next refresh at first because we already got a token from
+    // GitHub recently, don't need to try again until we actually might need to get a new one.
+    tokio::time::sleep(next_refresh).await;
+
     // NOTE(cole-h): https://docs.github.com/en/actions/deployment/security-hardening-your-deployments/configuring-openid-connect-in-cloud-providers#requesting-the-jwt-using-environment-variables
     let mut headers = reqwest::header::HeaderMap::new();
     headers.insert(
@@ -270,6 +276,7 @@ async fn refresh_github_actions_jwt_worker(
     }
 }
 
+#[tracing::instrument(skip_all)]
 async fn rewrite_github_actions_token(
     client: &reqwest::Client,
     netrc_path: &Path,
@@ -287,29 +294,44 @@ async fn rewrite_github_actions_token(
         ))
     })?;
 
+    let token_request_url = format!("{runtime_url}&audience=api.flakehub.com");
+    let token_response = client
+        .request(reqwest::Method::GET, &token_request_url)
+        .bearer_auth(runtime_token)
+        .send()
+        .await
+        .with_context(|| format!("sending request to {token_request_url}"))?;
+
+    if let Err(e) = token_response.error_for_status_ref() {
+        tracing::error!(?e, "Got error response when requesting token");
+        return Err(e)?;
+    }
+
     #[derive(serde::Deserialize)]
     struct TokenResponse {
         value: String,
     }
 
-    let res: TokenResponse = client
+    let token_response: TokenResponse = token_response
-        .request(
-            reqwest::Method::GET,
-            format!("{runtime_url}&audience=api.flakehub.com"),
-        )
-        .bearer_auth(runtime_token)
-        .send()
-        .await?
         .json()
-        .await?;
+        .await
+        .with_context(|| format!("converting response into json"))?;
 
-    let new_github_jwt_string = res.value;
+    let new_github_jwt_string = token_response.value;
-
+    let netrc_contents = tokio::fs::read_to_string(netrc_path)
-    let netrc_contents = tokio::fs::read_to_string(netrc_path).await?;
+        .await
+        .with_context(|| format!("failed to read {netrc_path:?} to string"))?;
     let new_netrc_contents = netrc_contents.replace(old_github_jwt, &new_github_jwt_string);
-    let netrc_path_new = tempfile::NamedTempFile::new()?;
+
-    tokio::fs::write(&netrc_path_new, new_netrc_contents).await?;
+    // NOTE(cole-h): create the temporary file right next to the real one so we don't run into
-    tokio::fs::rename(&netrc_path_new, netrc_path).await?;
+    // cross-device linking issues when renaming
+    let netrc_path_tmp = netrc_path.with_extension("tmp");
+    tokio::fs::write(&netrc_path_tmp, new_netrc_contents)
+        .await
+        .with_context(|| format!("writing new JWT to {netrc_path_tmp:?}"))?;
+    tokio::fs::rename(&netrc_path_tmp, &netrc_path)
+        .await
+        .with_context(|| format!("renaming {netrc_path_tmp:?} to {netrc_path:?}"))?;
 
     Ok(new_github_jwt_string)
 }

magic-nix-cache/src/main.rs

@@ -21,7 +21,7 @@ mod gha;
 mod telemetry;
 
 use std::collections::HashSet;
-use std::fs::{self, create_dir_all, OpenOptions};
+use std::fs::{self, create_dir_all};
 use std::io::Write;
 use std::net::SocketAddr;
 use std::os::unix::fs::PermissionsExt;
@@ -38,6 +38,8 @@ use tokio::io::AsyncWriteExt;
 use tokio::process::Command;
 use tokio::sync::{oneshot, Mutex, RwLock};
 use tracing_subscriber::filter::EnvFilter;
+use tracing_subscriber::layer::SubscriberExt;
+use tracing_subscriber::util::SubscriberInitExt;
 
 use gha_cache::Credentials;
 
@@ -159,10 +161,14 @@ struct StateInner {
 
     /// FlakeHub cache state.
     flakehub_state: RwLock<Option<flakehub::State>>,
+
+    /// Where all of tracing will log to when GitHub Actions is run in debug mode
+    logfile: Option<PathBuf>,
 }
 
 async fn main_cli() -> Result<()> {
-    init_logging();
+    let guard = init_logging()?;
+    let _tracing_guard = guard.appender_guard;
 
     let args = Args::parse();
     let environment = env::Environment::determine();
@@ -175,10 +181,10 @@ async fn main_cli() -> Result<()> {
         create_dir_all(parent).with_context(|| "Creating parent directories of nix.conf")?;
     }
 
-    let mut nix_conf = OpenOptions::new()
+    let mut nix_conf = std::fs::OpenOptions::new()
         .create(true)
         .append(true)
-        .open(args.nix_conf)
+        .open(&args.nix_conf)
         .with_context(|| "Creating nix.conf")?;
 
     let store = Arc::new(NixStore::connect()?);
@@ -354,6 +360,7 @@ async fn main_cli() -> Result<()> {
         metrics,
         store,
         flakehub_state: RwLock::new(flakehub_state),
+        logfile: guard.logfile,
     });
 
     let app = Router::new()
@@ -485,7 +492,16 @@ async fn main() -> Result<()> {
     }
 }
 
-fn init_logging() {
+pub(crate) fn debug_logfile() -> PathBuf {
+    std::env::temp_dir().join("magic-nix-cache-tracing.log")
+}
+
+pub struct LogGuard {
+    appender_guard: Option<tracing_appender::non_blocking::WorkerGuard>,
+    logfile: Option<PathBuf>,
+}
+
+fn init_logging() -> Result<LogGuard> {
     let filter = EnvFilter::try_from_default_env().unwrap_or_else(|_| {
         #[cfg(debug_assertions)]
         return EnvFilter::new("info")
@@ -496,11 +512,47 @@ fn init_logging() {
         return EnvFilter::new("info");
     });
 
-    tracing_subscriber::fmt()
+    let stderr_layer = tracing_subscriber::fmt::layer()
         .with_writer(std::io::stderr)
-        .pretty()
+        .pretty();
-        .with_env_filter(filter)
+
+    let (guard, file_layer) = match std::env::var("RUNNER_DEBUG") {
+        Ok(val) if val == "1" => {
+            let logfile = debug_logfile();
+            let file = std::fs::OpenOptions::new()
+                .create(true)
+                .write(true)
+                .truncate(true)
+                .open(&logfile)?;
+            let (nonblocking, guard) = tracing_appender::non_blocking(file);
+            let file_layer = tracing_subscriber::fmt::layer()
+                .with_writer(nonblocking)
+                .pretty();
+
+            (
+                LogGuard {
+                    appender_guard: Some(guard),
+                    logfile: Some(logfile),
+                },
+                Some(file_layer),
+            )
+        }
+        _ => (
+            LogGuard {
+                appender_guard: None,
+                logfile: None,
+            },
+            None,
+        ),
+    };
+
+    tracing_subscriber::registry()
+        .with(filter)
+        .with(stderr_layer)
+        .with(file_layer)
         .init();
+
+    Ok(guard)
 }
 
 #[cfg(debug_assertions)]