From 6f3c6309e4d6f444257febe511b26a4340ff8f31 Mon Sep 17 00:00:00 2001 From: Cole Helbling Date: Tue, 23 Apr 2024 07:54:02 -0700 Subject: [PATCH] Record and print tracing logs in debug mode --- Cargo.lock | 23 ++++++++--- magic-nix-cache/Cargo.toml | 1 + magic-nix-cache/src/api.rs | 17 ++++++--- magic-nix-cache/src/flakehub.rs | 52 +++++++++++++++++-------- magic-nix-cache/src/main.rs | 68 +++++++++++++++++++++++++++++---- 5 files changed, 128 insertions(+), 33 deletions(-) diff --git a/Cargo.lock b/Cargo.lock index 679c7c5..8175c8d 100644 --- a/Cargo.lock +++ b/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", diff --git a/magic-nix-cache/Cargo.toml b/magic-nix-cache/Cargo.toml index 0253343..51685fc 100644 --- a/magic-nix-cache/Cargo.toml +++ b/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" diff --git a/magic-nix-cache/src/api.rs b/magic-nix-cache/src/api.rs index ae643bd..5b1cdb8 100644 --- a/magic-nix-cache/src/api.rs +++ b/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?; - } + if let Some(attic_state) = state.flakehub_state.write().await.take() { + tracing::info!("Waiting for FlakeHub cache uploads to finish"); + 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, Json(req): Json, diff --git a/magic-nix-cache/src/flakehub.rs b/magic-nix-cache/src/flakehub.rs index b3d3a6f..52507a9 100644 --- a/magic-nix-cache/src/flakehub.rs +++ b/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) -> 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 - .request( - reqwest::Method::GET, - format!("{runtime_url}&audience=api.flakehub.com"), - ) - .bearer_auth(runtime_token) - .send() - .await? + let token_response: TokenResponse = token_response .json() - .await?; + .await + .with_context(|| format!("converting response into json"))?; - let new_github_jwt_string = res.value; - - let netrc_contents = tokio::fs::read_to_string(netrc_path).await?; + let new_github_jwt_string = token_response.value; + let netrc_contents = tokio::fs::read_to_string(netrc_path) + .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?; - tokio::fs::rename(&netrc_path_new, netrc_path).await?; + + // NOTE(cole-h): create the temporary file right next to the real one so we don't run into + // 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) } diff --git a/magic-nix-cache/src/main.rs b/magic-nix-cache/src/main.rs index e0af249..ec75316 100644 --- a/magic-nix-cache/src/main.rs +++ b/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>, + + /// Where all of tracing will log to when GitHub Actions is run in debug mode + logfile: Option, } 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, + logfile: Option, +} + +fn init_logging() -> Result { 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() - .with_env_filter(filter) + .pretty(); + + 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)]