From c608802497ce9bfdc8c4b4f44befb888dd971c76 Mon Sep 17 00:00:00 2001
From: Justin Geibel <jtgeibel@gmail.com>
Date: Mon, 6 Sep 2021 02:04:11 -0400
Subject: [PATCH] Use a common prefix for logged errors

The `at=error ` prefix is used for Heroku error messages and using a
common prefix aids in metrics collection and is easily searchable.
---
 src/bin/background-worker.rs | 15 +++++++++++----
 src/bin/monitor.rs           |  7 +++++--
 src/bin/server.rs            |  6 +++---
 src/git.rs                   | 12 ++++++++++--
 4 files changed, 29 insertions(+), 11 deletions(-)

diff --git a/src/bin/background-worker.rs b/src/bin/background-worker.rs
index d8d5387cd9f..4e43bea22ac 100644
--- a/src/bin/background-worker.rs
+++ b/src/bin/background-worker.rs
@@ -24,6 +24,13 @@ use std::time::Duration;
 fn main() {
     println!("Booting runner");
 
+    if let Err(message) = main_impl() {
+        eprintln!("at=error mod=background_worker error=\"{}\"", message);
+        std::process::exit(1);
+    }
+}
+
+fn main_impl() -> Result<(), &'static str> {
     let db_config = config::DatabasePools::full_from_environment();
     let base_config = config::Base::from_environment();
     let uploader = base_config.uploader();
@@ -43,13 +50,13 @@ fn main() {
     let job_start_timeout = dotenv::var("BACKGROUND_JOB_TIMEOUT")
         .unwrap_or_else(|_| "30".into())
         .parse()
-        .expect("Invalid value for `BACKGROUND_JOB_TIMEOUT`");
+        .map_err(|_| "Invalid value for `BACKGROUND_JOB_TIMEOUT`")?;
 
     println!("Cloning index");
 
     let repository_config = RepositoryConfig::from_environment();
     let repository = Arc::new(Mutex::new(
-        Repository::open(&repository_config).expect("Failed to clone index"),
+        Repository::open(&repository_config).map_err(|_| "Failed to clone index")?,
     ));
     println!("Index cloned");
 
@@ -76,12 +83,12 @@ fn main() {
             failure_count += 1;
             if failure_count < 5 {
                 eprintln!(
-                    "Error running jobs (n = {}) -- retrying: {:?}",
+                    "at=error mod=background_worker error=\"Error running jobs (n = {}) -- retrying: {:?}\"",
                     failure_count, e,
                 );
                 runner = build_runner();
             } else {
-                panic!("Failed to begin running jobs 5 times. Restarting the process");
+                return Err("Failed to begin running jobs 5 times. Restarting the process");
             }
         }
         sleep(Duration::from_secs(1));
diff --git a/src/bin/monitor.rs b/src/bin/monitor.rs
index c543d8891b4..853b0778ec2 100644
--- a/src/bin/monitor.rs
+++ b/src/bin/monitor.rs
@@ -76,7 +76,7 @@ fn check_stalled_update_downloads(conn: &PgConnection) -> Result<()> {
 
     const EVENT_KEY: &str = "update_downloads_stalled";
 
-    println!("Checking for stalled background jobs");
+    println!("Checking for stalled update_downloads job");
 
     // Max job execution time in minutes
     let max_job_time = dotenv::var("MONITOR_MAX_UPDATE_DOWNLOADS_TIME")
@@ -153,7 +153,10 @@ fn log_and_trigger_event(event: on_call::Event) -> Result<()> {
     match event {
         on_call::Event::Trigger {
             ref description, ..
-        } => println!("Paging on-call: {}", description),
+        } => eprintln!(
+            "at=error mod=on_call_monitor error=\"Paging on-call: {}\"",
+            description
+        ),
         on_call::Event::Resolve {
             description: Some(ref description),
             ..
diff --git a/src/bin/server.rs b/src/bin/server.rs
index 79907e5e039..cbea976eb1a 100644
--- a/src/bin/server.rs
+++ b/src/bin/server.rs
@@ -146,7 +146,7 @@ fn main() -> Result<(), Box<dyn std::error::Error>> {
     println!("Persisting remaining downloads counters");
     match app.downloads_counter.persist_all_shards(&app) {
         Ok(stats) => stats.log(),
-        Err(err) => println!("downloads_counter error: {}", err),
+        Err(err) => eprintln!("at=error mod=downloads_counter error=\"{}\"", err),
     }
 
     println!("Server has gracefully shutdown!");
@@ -163,7 +163,7 @@ fn downloads_counter_thread(app: Arc<App>) {
 
         match app.downloads_counter.persist_next_shard(&app) {
             Ok(stats) => stats.log(),
-            Err(err) => println!("downloads_counter error: {}", err),
+            Err(err) => eprintln!("at=error mod=downloads_counter error=\"{}\"", err),
         }
     });
 }
@@ -178,7 +178,7 @@ fn log_instance_metrics_thread(app: Arc<App>) {
 
     std::thread::spawn(move || loop {
         if let Err(err) = log_instance_metrics_inner(&app) {
-            eprintln!("log_instance_metrics error: {}", err);
+            eprintln!("at=error mod=log_instance_metrics error=\"{}\"", err);
         }
         std::thread::sleep(interval);
     });
diff --git a/src/git.rs b/src/git.rs
index 87f7c71337f..3e9517d0cdb 100644
--- a/src/git.rs
+++ b/src/git.rs
@@ -252,7 +252,10 @@ impl Repository {
         self.perform_commit_and_push(message, modified_file)
             .map(|_| println!("Commit and push finished for \"{}\"", message))
             .map_err(|err| {
-                eprintln!("Commit and push for \"{}\" errored: {}", message, err);
+                eprintln!(
+                    "at=error mod=git error=\"Commit and push for \"{}\" errored: {}\"",
+                    message, err
+                );
                 err
             })
     }
@@ -272,7 +275,12 @@ impl Repository {
         let head = self.head_oid()?;
 
         if head != original_head {
-            println!("Resetting index from {} to {}", original_head, head);
+            // This isn't strictly an error, but treating it as one for monitoring as it indicates
+            // that an error has occurred while processing the previous index operation.
+            eprintln!(
+                "at=error mod=git error=\"Resetting index from {} to {}\"",
+                original_head, head
+            );
         }
 
         let obj = self.repository.find_object(head, None)?;