add structured logging, fix docker exit code

4 files changed, 121 insertions, 41 deletions

diff --git a/src/config.rs b/src/config.rs
index 0cd9019..5a92a9a 100644
--- a/src/config.rs
+++ b/src/config.rs
@@ -3,6 +3,7 @@ use std::sync::LazyLock;
 use anyhow::Result;
 use confique::Config;
 use opentelemetry_otlp::Protocol;
+use crate::s_log::*;
 
 #[derive(Config)]
 pub struct CspyConfig {
@@ -26,7 +27,16 @@ pub static CONFIG: LazyLock<CspyConfig> = LazyLock::new(|| {
 		.ok()
 		.unwrap_or("/etc/containerspy/config.json");
 
-	CspyConfig::builder().env().file(cfg_loc).load().unwrap()
+	let cfg = CspyConfig::builder().env().file(cfg_loc).load().unwrap();
+
+	info("Loaded config at startup", [
+		("docker_socket", &*format!("{:?}", cfg.docker_socket)),
+		("otlp_protocol", &*format!("{:?}", cfg.otlp_protocol)),
+		("otlp_endpoint", &*format!("{:?}", cfg.otlp_endpoint)),
+		("otlp_export_interval", &*format!("{:?}", cfg.otlp_export_interval)),
+	]);
+	
+	cfg
 });
 
 /// deserialization boilerplate
diff --git a/src/main.rs b/src/main.rs
index 07ebeb0..26b2a4b 100644
--- a/src/main.rs
+++ b/src/main.rs
@@ -8,9 +8,11 @@ use std::{collections::BTreeMap, sync::Arc, time::Duration};
 use tokio::task::JoinHandle;
 use tokio::time::MissedTickBehavior;
 use tokio_util::sync::CancellationToken;
+use crate::s_log::*;
 
 mod config;
 mod stats_task;
+mod s_log;
 
 // includes data from Cargo.toml and other sources using the `built` crate
 pub mod built_info {
@@ -101,10 +103,11 @@ async fn main() -> Result<()> {
 	let st2 = shutdown_token.clone(); // to be moved into the task
 
 	tokio::spawn(async move {
-		tokio::signal::ctrl_c()
-			.await
-			.expect("Failed to setup ctrl-c handler");
-		st2.cancel();
+		if tokio::signal::ctrl_c().await.is_ok() {
+			st2.cancel();
+		} else {
+			warn("Failed to setup SIGINT handler, metrics may be dropped on exit", []);
+		}
 	});
 
 	let mut container_search_interval =
@@ -132,6 +135,7 @@ async fn main() -> Result<()> {
 				.binary_search_by(|c| c.id.as_ref().unwrap().cmp(cont))
 				.is_err()
 			{
+				debug(format_args!("Killing worker for {}", cont), [("container_id", &**cont)]);
 				handle.abort();
 				to_remove.push(cont.clone());
 			}
@@ -145,6 +149,7 @@ async fn main() -> Result<()> {
 		for cont in containers {
 			let id_string = cont.id.as_ref().unwrap();
 			if !tasks.contains_key(id_string) {
+				debug(format_args!("Launching worker for {}", id_string), [("container_id", &**id_string)]);
 				// all this string cloning hurts me
 				tasks.insert(
 					id_string.clone(),
@@ -159,7 +164,9 @@ async fn main() -> Result<()> {
 		task.abort();
 	}
 
-	println!("clean shutdown.");
+	debug("Exiting cleanly", []);
+	
+	let _ = meter_provider.force_flush();
 
 	Ok(())
 }
diff --git a/src/s_log.rs b/src/s_log.rs
new file mode 100644
index 0000000..16b4726
--- /dev/null
+++ b/src/s_log.rs
@@ -0,0 +1,95 @@
+// containerspy structured logger
+
+use std::fmt::{Display, Formatter};
+use chrono::Utc;
+
+#[allow(dead_code)]
+pub fn debug<'a>(args: impl Display, rich: impl IntoIterator<Item = (&'a str, &'a str)>) {
+	log_impl(LogLevel::Debug, args.to_string().as_str(), rich);
+}
+
+pub fn info<'a>(args: impl Display, rich: impl IntoIterator<Item = (&'a str, &'a str)>) {
+	log_impl(LogLevel::Info, args.to_string().as_str(), rich);
+}
+
+#[allow(dead_code)]
+pub fn warn<'a>(args: impl Display, rich: impl IntoIterator<Item = (&'a str, &'a str)>) {
+	log_impl(LogLevel::Warn, args.to_string().as_str(), rich);
+}
+
+#[allow(dead_code)]
+pub fn error<'a>(args: impl Display, rich: impl IntoIterator<Item = (&'a str, &'a str)>) {
+	log_impl(LogLevel::Error, args.to_string().as_str(), rich);
+}
+
+#[allow(dead_code)]
+pub fn fatal<'a>(args: impl Display, rich: impl IntoIterator<Item = (&'a str, &'a str)>) {
+	log_impl(LogLevel::Fatal, args.to_string().as_str(), rich);
+}
+
+enum LogLevel {
+	Fatal,
+	Error,
+	Warn,
+	Info,
+	Debug,
+}
+
+impl Display for LogLevel {
+	fn fmt(&self, f: &mut Formatter<'_>) -> std::fmt::Result {
+		f.write_str(
+			match self {
+				LogLevel::Fatal => "fatal",
+				LogLevel::Error => "error",
+				LogLevel::Warn => "warn",
+				LogLevel::Info => "info",
+				LogLevel::Debug => "debug",
+			}
+		)
+	}
+}
+
+fn log_impl<'a>(level: LogLevel, msg: &str, rich: impl IntoIterator<Item = (&'a str, &'a str)>) {
+	let time = Utc::now();
+	let nice_time = time.format("%F %X%.3f");
+	let full_time = time.format("%+");
+
+	let mut final_rich = vec![
+		("ts", full_time.to_string()),
+		("level", level.to_string()),
+		("msg", msg.to_string())
+	];
+
+	// i don't care anymore, just clone it all temporarily.
+	final_rich.extend(rich.into_iter().map(|(a, b)| (a, b.to_string())));
+
+	let mut buf = format!("{nice_time}");
+	for (k, v) in final_rich {
+		if needs_escaping(k) {
+			continue;
+		}
+
+		if needs_escaping(&v) {
+			buf += &format!(" {k}=\"{}\"", escape(&v));
+		} else {
+			buf += &format!(" {k}={v}");
+		}
+	}
+
+	println!("{buf}");
+}
+
+static SAFE_ALPHABET: &str = r#"abcdefghijklmnopqrstuvxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789-_+.,/\\|!@#$%^&*()[]{}"#;
+
+fn needs_escaping(val: &str) -> bool {
+	for char in val.chars() {
+		if !SAFE_ALPHABET.contains(char) {
+			return true
+		}
+	}
+	false
+}
+
+fn escape(val: &str) -> String {
+	val.replace("\n", "\\n").replace("\\", "\\\\").replace("\"", "\\\"")
+}
\ No newline at end of file
diff --git a/src/stats_task.rs b/src/stats_task.rs
index 34fa6fb..4434f08 100644
--- a/src/stats_task.rs
+++ b/src/stats_task.rs
@@ -9,6 +9,7 @@ use std::sync::Arc;
 use std::time::{Duration, SystemTime, UNIX_EPOCH};
 use tokio::task::JoinHandle;
 use tokio_stream::StreamExt;
+use crate::s_log::*;
 
 // I do not enjoy taking a bunch of Rcs but tokio needs ownership so fine.
 pub fn launch_stats_task(
@@ -51,8 +52,7 @@ pub fn launch_stats_task(
 					break;
 				}
 				Some(Err(err)) => {
-					// TODO: use json logging or syslog so loki can understand this lol
-					println!("Failed to get stats for container {container_id}!: {err:?}");
+					error(format_args!("Failed to get stats for container {container_id}!: {err:?}"), [("container_id", &*container_id)]);
 				}
 			}
 		}
@@ -468,11 +468,7 @@ pub fn launch_stats_task(
 				}
 			} else {
 				// failed to get stats, log as such:
-				// TODO: use json logging or syslog so loki can understand this lol
-				println!(
-					"Failed to get stats for container {container_id}!: {:?}",
-					val.unwrap_err()
-				);
+				error(format_args!("Failed to get stats for container {container_id}!: {:?}", val.unwrap_err()), [("container_id", &*container_id)]);
 			}
 		}
 	})
@@ -502,31 +498,3 @@ fn get_rw_totals<'a>(iter: impl IntoIterator<Item = &'a BlkioStatsEntry>) -> (u6
 
 	(read, write)
 }
-
-// LMAO i built this entire string pool around the idea of needing &'static str but turns out i can just use owned strings
-// guuuh okay whatever that's fine i guess, i'll keep this around just in case i need it -- sink
-
-/*
-// labels have to have 'static values so i have to make a string pool or i'll leak ram, eugh
-// technically this does mean each possible kv combo is never dropped, but we only have one copy in ram at all times
-// Arc would also work, but that would require a lot of refcounting for a count we know will NEVER hit zero
-// so just use a Cow that borrows a leaked box instead.
-// I checked, OtelString can either be owned (from String), borrowed (from Cow<'static, str>), or refcounted (Arc<str>).
-
-static LABEL_POOL: LazyLock<RwLock<HashMap<(Cow<str>, Cow<str>), KeyValue>>> = LazyLock::new(|| RwLock::new(HashMap::new()));
-fn pool_kv(key: &str, val: &str) -> KeyValue {
-	let leaked_k = &*Box::leak(key.to_string().into_boxed_str());
-	let leaked_v = &*Box::leak(val.to_string().into_boxed_str());
-
-	let cows = (Cow::from(leaked_k), Cow::from(leaked_v));
-
-	if let Some(kv) = LABEL_POOL.read().unwrap().get(&cows) {
-		// this should borrow the same value thanks to OtelString::Borrowed :)
-		kv.clone()
-	} else {
-		// we know upfront that the cow is borrowed, so just clone it
-		let kv = KeyValue::new(cows.0.clone(), cows.1.clone());
-		LABEL_POOL.write().unwrap().insert(cows, kv.clone());
-		kv
-	}
-}*/