[TRUNK-14129] Add structured logging (#380)

Switches our logging to use the tracing library, which gives us support for structured logs, using the sentry publisher so that these logs go to sentry. Adds a single span for execution so we can map out executions as we encounter issues, and converts our use of error to warn to avoid spamming oncall.

Logging with quiet flag:
![2025-02-10-075854_1119x70_scrot](https://github.com/user-attachments/assets/190f41fa-5b70-480a-a934-2ff8da2449b2)

With default verbosity:
![2025-02-10-075802_1161x70_scrot](https://github.com/user-attachments/assets/731c5369-4ef8-4dcc-b3c2-fa505fed9a0a)

With single verbosity:
![2025-02-10-075815_1119x144_scrot](https://github.com/user-attachments/assets/8f8d22c0-9445-4abe-a486-8cd422699f56)

With double verbosity:
![2025-02-10-075833_1400x231_scrot](https://github.com/user-attachments/assets/04434607-c7cf-4927-8d34-3b4754487c73)

Fake error uploaded to sentry: https://trunkio.sentry.io/issues/6293011644/?environment=development&project=4507772986982400&query=is%3Aunresolved%20issue.priority%3A%5Bhigh%2C%20medium%5D&referrer=issue-stream&statsPeriod=14d&stream_index=0

Author: cmillar-trunk

Cargo.lock

@@ -22,6 +22,7 @@ log = "0.4.14"
 http = "1.1.0"
 tokio-retry = { version = "0.3", default-features = false }
 constants = { version = "0.0.0", path = "../constants" }
+tracing = "0.1.41"
 sentry = { version = "=0.36.0", features = ["debug-images"] }
 
 [dev-dependencies]

api/Cargo.toml

@@ -129,10 +129,8 @@ where
             let duration = Duration::from_secs(REPORT_SLOW_PROGRESS_TIMEOUT_SECS);
             time::sleep(duration).await;
             let time_elapsed = Instant::now().duration_since(report_slow_progress_start);
-            sentry::capture_message(
-                report_slow_progress_message(time_elapsed).as_ref(),
-                sentry::Level::Error,
-            );
+            let message = report_slow_progress_message(time_elapsed);
+            tracing::warn!("{:?}", message);
         });
 
         let check_progress_start = time::Instant::now();
@@ -146,7 +144,7 @@ where
                 let instant = interval.tick().await;
                 let time_elapsed = instant.duration_since(check_progress_start);
                 let log_message = log_progress_message(time_elapsed, log_count);
-                log::debug!("{}", log_message);
+                tracing::debug!("{}", log_message);
                 log_count += 1;
             }
         });

api/src/call_api.rs

@@ -32,6 +32,7 @@ impl ApiClient {
             .ok()
             .and_then(|s| if s.is_empty() { None } else { Some(s) })
             .unwrap_or_else(|| DEFAULT_ORIGIN.to_string());
+        tracing::info!("Using public api address {}", host);
 
         let mut trunk_client_default_headers = HeaderMap::new();
         trunk_client_default_headers.append(
@@ -208,9 +209,11 @@ impl ApiClient {
                 )
             },
             log_progress_message: |time_elapsed, _| {
+                println!("Callled, {}", time_elapsed.as_secs());
                 format!("Uploading bundle to S3 is taking longer than expected. It has taken {} seconds so far.", time_elapsed.as_secs())
             },
             report_slow_progress_message: |time_elapsed| {
+                println!("oofed, {}", time_elapsed.as_secs());
                 format!("Uploading bundle to S3 is taking longer than {} seconds", time_elapsed.as_secs())
             },
         }
@@ -315,20 +318,15 @@ pub(crate) fn status_code_help<T: FnMut(&Response) -> String>(
 
 #[cfg(test)]
 mod tests {
-    use std::{
-        sync::{
-            atomic::{AtomicUsize, Ordering},
-            Arc,
-        },
-        time::Duration,
+    use std::sync::{
+        atomic::{AtomicUsize, Ordering},
+        Arc,
     };
 
     use axum::{http::StatusCode, response::Response};
     use context;
     use lazy_static::lazy_static;
-    use tempfile::NamedTempFile;
-    use test_utils::{mock_logger, mock_sentry, mock_server::MockServerBuilder};
-    use tokio::time;
+    use test_utils::mock_server::MockServerBuilder;
 
     use super::ApiClient;
     use crate::message;
@@ -417,52 +415,6 @@ mod tests {
         assert_eq!(CALL_COUNT.load(Ordering::Relaxed), 6);
     }
 
-    #[tokio::test(start_paused = true)]
-    async fn logs_and_reports_for_slow_api_calls() {
-        let mut mock_server_builder = MockServerBuilder::new();
-        let logs = mock_logger(None);
-        let (events, guard) = mock_sentry();
-
-        async fn slow_s3_upload_handler() -> Response<String> {
-            time::sleep(Duration::from_secs(11)).await;
-            Response::new(String::from("OK"))
-        }
-        mock_server_builder.set_s3_upload_handler(slow_s3_upload_handler);
-
-        let state = mock_server_builder.spawn_mock_server().await;
-
-        let mut api_client = ApiClient::new(String::from("mock-token")).unwrap();
-        api_client.host.clone_from(&state.host);
-
-        let bundle_file = NamedTempFile::new().unwrap();
-        api_client
-            .put_bundle_to_s3(format!("{}/s3upload", state.host), bundle_file)
-            .await
-            .unwrap();
-
-        let first_two_slow_s3_upload_logs = logs
-            .lock()
-            .unwrap()
-            .iter()
-            .filter(|(_, message)| message.starts_with("Uploading bundle to S3"))
-            .take(2)
-            .cloned()
-            .collect::<Vec<_>>();
-        assert_eq!(first_two_slow_s3_upload_logs, vec![
-            (log::Level::Debug, String::from("Uploading bundle to S3 is taking longer than expected. It has taken 2 seconds so far.")),
-            (log::Level::Debug, String::from("Uploading bundle to S3 is taking longer than expected. It has taken 4 seconds so far.")),
-        ]);
-
-        guard.flush(None);
-        assert_eq!(
-            *events.try_lock().unwrap(),
-            vec![(
-                sentry::Level::Error,
-                String::from("Uploading bundle to S3 is taking longer than 10 seconds"),
-            ),]
-        );
-    }
-
     #[tokio::test(start_paused = true)]
     async fn get_quarantining_config_not_found() {
         let mut mock_server_builder = MockServerBuilder::new();

api/src/client.rs

@@ -15,6 +15,7 @@ glob = "0.3.0"
 regex = { version = "1.10.3", default-features = false, features = ["std"] }
 serde = { version = "1.0.215", default-features = false, features = ["derive"] }
 serde_json = "1.0.133"
+tracing = "0.1.41"
 tsify-next = { version = "0.5.4", optional = true }
 wasm-bindgen = { version = "0.2.95", optional = true }
 pyo3-stub-gen = { version = "0.6.0", optional = true }

bundle/Cargo.toml

@@ -83,7 +83,7 @@ impl BundlerUtil {
                     .iter()
                     .fold(tempfile::tempfile()?, |f, event| {
                         if let Err(e) = serde_json::to_writer(&f, event) {
-                            log::error!("Failed to write BEP event: {}", e);
+                            tracing::warn!("Failed to write BEP event: {}", e);
                         }
                         f
                     });
@@ -99,7 +99,7 @@ impl BundlerUtil {
         let total_bytes_out = std::fs::metadata(bundle_path)?.len();
         let size_reduction = 1.0 - total_bytes_out as f64 / total_bytes_in as f64;
 
-        log::info!(
+        tracing::info!(
             "Total bytes in: {}, total bytes out: {} (size reduction: {:.2}%)",
             total_bytes_in,
             total_bytes_out,

bundle/src/bundler.rs

@@ -245,15 +245,15 @@ impl BundledFile {
             }
         }
         if !is_allowed {
-            log::warn!("File {:?} from glob {:?} is not allowed", path, glob_path);
+            tracing::warn!("File {:?} from glob {:?} is not allowed", path, glob_path);
             return Ok(None);
         }
 
         // When start is provided, check if file is stale
         if let Some(start) = start {
             let modified = path.metadata()?.modified()?;
             if modified < start {
-                log::warn!("File {:?} from glob {:?} is stale", path, glob_path);
+                tracing::warn!("File {:?} from glob {:?} is stale", path, glob_path);
                 return Ok(None);
             }
         }

bundle/src/files.rs

@@ -100,31 +100,31 @@ async fn quarantines_tests_regardless_of_upload() {
     // First run won't quarantine any tests
     *QUARANTINE_CONFIG_RESPONSE.lock().unwrap() = QuarantineConfigResponse::None;
     *CREATE_BUNDLE_RESPONSE.lock().unwrap() = CreateBundleResponse::Error;
-    command.assert().failure().stderr(upload_failure.clone());
+    command.assert().failure().stdout(upload_failure.clone());
 
     // Second run quarantines all, but 1 test
     *QUARANTINE_CONFIG_RESPONSE.lock().unwrap() = QuarantineConfigResponse::Some;
     *CREATE_BUNDLE_RESPONSE.lock().unwrap() = CreateBundleResponse::Error;
-    command.assert().failure().stderr(upload_failure.clone());
+    command.assert().failure().stdout(upload_failure.clone());
 
     // Third run will quarantine all tests
     *QUARANTINE_CONFIG_RESPONSE.lock().unwrap() = QuarantineConfigResponse::All;
     *CREATE_BUNDLE_RESPONSE.lock().unwrap() = CreateBundleResponse::Error;
-    command.assert().success().stderr(upload_failure.clone());
+    command.assert().success().stdout(upload_failure.clone());
 
     // Fourth run will quarantine all tests, and upload them
     *QUARANTINE_CONFIG_RESPONSE.lock().unwrap() = QuarantineConfigResponse::All;
     *CREATE_BUNDLE_RESPONSE.lock().unwrap() = CreateBundleResponse::Success;
     command
         .assert()
         .success()
-        .stderr(upload_failure.clone().not());
+        .stdout(upload_failure.clone().not());
 
     // Fifth run will run with quarantining disabled, but will log upload failure
     // there is no provided exit code, so it will default to success.
     *QUARANTINE_CONFIG_RESPONSE.lock().unwrap() = QuarantineConfigResponse::Disabled;
     *CREATE_BUNDLE_RESPONSE.lock().unwrap() = CreateBundleResponse::Error;
-    command.assert().success().stderr(upload_failure.clone());
+    command.assert().success().stdout(upload_failure.clone());
 }
 
 #[tokio::test(flavor = "multi_thread")]
@@ -200,28 +200,28 @@ async fn do_no_quarantines_tests_when_use_quarantined_disabled() {
     // First run won't quarantine any tests
     *QUARANTINE_CONFIG_RESPONSE.lock().unwrap() = QuarantineConfigResponse::None;
     *CREATE_BUNDLE_RESPONSE.lock().unwrap() = CreateBundleResponse::Error;
-    command.assert().success().stderr(upload_failure.clone());
+    command.assert().success().stdout(upload_failure.clone());
 
     // Second run won't quarantine even when config generates 1 quarantined test
     *QUARANTINE_CONFIG_RESPONSE.lock().unwrap() = QuarantineConfigResponse::Some;
     *CREATE_BUNDLE_RESPONSE.lock().unwrap() = CreateBundleResponse::Error;
-    command.assert().success().stderr(upload_failure.clone());
+    command.assert().success().stdout(upload_failure.clone());
 
     // Third run won't quarantine even when config generates all tests quarantined
     *QUARANTINE_CONFIG_RESPONSE.lock().unwrap() = QuarantineConfigResponse::All;
     *CREATE_BUNDLE_RESPONSE.lock().unwrap() = CreateBundleResponse::Error;
-    command.assert().success().stderr(upload_failure.clone());
+    command.assert().success().stdout(upload_failure.clone());
 
     // Fourth run won't quarantine tests even when config generates all tests quarantined and upload is successful
     *QUARANTINE_CONFIG_RESPONSE.lock().unwrap() = QuarantineConfigResponse::All;
     *CREATE_BUNDLE_RESPONSE.lock().unwrap() = CreateBundleResponse::Success;
     command
         .assert()
         .success()
-        .stderr(upload_failure.clone().not());
+        .stdout(upload_failure.clone().not());
 
     // Fifth run will run with quarantining disabled, but will log upload failure
     *QUARANTINE_CONFIG_RESPONSE.lock().unwrap() = QuarantineConfigResponse::Disabled;
     *CREATE_BUNDLE_RESPONSE.lock().unwrap() = CreateBundleResponse::Error;
-    command.assert().success().stderr(upload_failure.clone());
+    command.assert().success().stdout(upload_failure.clone());
 }

cli-tests/src/quarantine.rs

@@ -87,7 +87,7 @@ async fn test_command_fails_with_no_junit_files_no_quarantine_successful_upload(
     .assert()
     .failure()
     .code(128)
-    .stderr(predicate::str::contains(
+    .stdout(predicate::str::contains(
         "No JUnit files found, not quarantining any tests",
     ));
 

cli-tests/src/test.rs

@@ -433,7 +433,7 @@ async fn upload_bundle_invalid_repo_root() {
         .command()
         .assert()
         .failure()
-        .stderr(predicate::str::contains(
+        .stdout(predicate::str::contains(
             "Error: Failed to open git repository at \"../\"",
         ));
 
@@ -456,7 +456,7 @@ async fn upload_bundle_invalid_repo_root_explicit() {
         .command()
         .assert()
         .failure()
-        .stderr(predicate::str::contains(
+        .stdout(predicate::str::contains(
             "Error: Failed to open git repository at",
         ));
 
@@ -508,7 +508,7 @@ async fn upload_bundle_with_no_junit_files_no_quarantine_successful_upload() {
         .assert()
         .code(0)
         .success()
-        .stderr(predicate::str::contains(
+        .stdout(predicate::str::contains(
             "No JUnit files found, not quarantining any tests",
         ));