From dd955fcb443196214196c620de9de308edfacb25 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Rodolphe=20Br=C3=A9ard?= <rodolphe@what.tf>
Date: Tue, 21 Mar 2023 13:00:44 +0100
Subject: [PATCH] Add logs

---
 Cargo.toml          |  2 ++
 src/handshake.rs    |  6 +++++-
 src/logs.rs         | 10 ++++++++++
 src/main.rs         | 40 +++++++++++++++++++++++++++++++++++++++-
 src/message.rs      |  4 ++++
 src/stdin_reader.rs |  3 +++
 6 files changed, 63 insertions(+), 2 deletions(-)
 create mode 100644 src/logs.rs

diff --git a/Cargo.toml b/Cargo.toml
index 584c1df..b0ead3d 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -8,4 +8,6 @@ license = "MIT OR Apache-2.0"
 publish = false
 
 [dependencies]
+env_logger = "^0.10"
+log = "^0.4"
 nom = "^7.1"
diff --git a/src/handshake.rs b/src/handshake.rs
index 32aafce..b0c0a3d 100644
--- a/src/handshake.rs
+++ b/src/handshake.rs
@@ -1,3 +1,4 @@
+use crate::display_bytes;
 use crate::stdin_reader::StdinReader;
 
 pub const CONFIG_END: &[u8] = b"config|ready\n";
@@ -7,15 +8,18 @@ pub fn read_config(reader: &mut StdinReader) {
 	loop {
 		let line = reader.read_line();
 		if line == CONFIG_END {
+			log::trace!("configuration is ready");
 			return;
 		}
 		if !line.starts_with(CONFIG_TAG) {
-			eprintln!("invalid config line: {line:?}");
+			log::warn!("invalid config line: {}", display_bytes!(line));
 		}
 	}
 }
 
 pub fn register_filter() {
+	log::trace!("registering the filter");
 	println!("register|filter|smtp-in|data-line");
 	println!("register|ready");
+	log::trace!("filter registered");
 }
diff --git a/src/logs.rs b/src/logs.rs
new file mode 100644
index 0000000..1ffd3e0
--- /dev/null
+++ b/src/logs.rs
@@ -0,0 +1,10 @@
+use env_logger::{Builder, Env, Target};
+
+pub fn init_log_system() {
+	let env = Env::new()
+		.filter_or(crate::LOG_LEVEL_ENV_VAR, "warn")
+		.write_style_or(crate::LOG_STYLE_ENV_VAR, "never");
+	let mut builder = Builder::from_env(env);
+	builder.target(Target::Stderr);
+	builder.init();
+}
diff --git a/src/main.rs b/src/main.rs
index 1fa9d4f..028e8ea 100644
--- a/src/main.rs
+++ b/src/main.rs
@@ -1,5 +1,6 @@
 mod entry;
 mod handshake;
+mod logs;
 mod message;
 mod stdin_reader;
 
@@ -9,12 +10,43 @@ use std::collections::HashMap;
 use stdin_reader::StdinReader;
 
 const DEFAULT_BUFF_SIZE: usize = 1024;
+const LOG_LEVEL_ENV_VAR: &str = "OPENSMTPD_FILTER_DKIMOUT_LOG_LEVEL";
+const LOG_STYLE_ENV_VAR: &str = "OPENSMTPD_FILTER_DKIMOUT_LOG_STYLE";
+
+#[macro_export]
+macro_rules! display_bytes {
+	($bytes: expr) => {
+		$bytes
+			.iter()
+			.map(|b| {
+				let v: Vec<u8> = std::ascii::escape_default(*b).collect();
+				String::from_utf8_lossy(&v).to_string()
+			})
+			.collect::<String>()
+	};
+}
+
+macro_rules! log_messages {
+	($list: ident) => {
+		log::trace!(
+			"message list has {} elements: {}",
+			$list.len(),
+			$list
+				.iter()
+				.map(|(k, v)| { format!("{k} ({} lines)", v.nb_lines()) })
+				.collect::<Vec<String>>()
+				.join(", ")
+		)
+	};
+}
 
 fn main() {
+	logs::init_log_system();
 	let mut reader = StdinReader::new();
 	let mut messages: HashMap<String, Message> = HashMap::new();
 	handshake::read_config(&mut reader);
 	handshake::register_filter();
+	log_messages!(messages);
 	loop {
 		match Entry::from_bytes(&reader.read_line()) {
 			Ok(entry) => {
@@ -22,25 +54,31 @@ fn main() {
 				match messages.get_mut(&msg_id) {
 					Some(msg) => {
 						if !entry.is_end_of_message() {
+							log::debug!("new line in message: {msg_id}");
 							msg.append_line(entry.get_data());
 						} else {
+							log::debug!("message ready: {msg_id}");
 							msg.sign_and_return();
 							messages.remove(&msg_id);
+							log::debug!("message removed: {msg_id}");
 						}
 					}
 					None => {
 						let msg = Message::from_entry(&entry);
 						if !entry.is_end_of_message() {
+							log::debug!("new message: {msg_id}");
 							messages.insert(msg_id, msg);
 						} else {
+							log::debug!("empty new message: {msg_id}");
 							msg.sign_and_return();
 						}
 					}
 				}
 			}
 			Err(err) => {
-				eprintln!("{err}");
+				log::error!("invalid filter line: {err}");
 			}
 		}
+		log_messages!(messages);
 	}
 }
diff --git a/src/message.rs b/src/message.rs
index 2571915..e3214b8 100644
--- a/src/message.rs
+++ b/src/message.rs
@@ -28,6 +28,10 @@ impl Message {
 		self.lines.push(line.to_vec())
 	}
 
+	pub fn nb_lines(&self) -> usize {
+		self.lines.len()
+	}
+
 	pub fn sign_and_return(&self) {
 		// TODO: sign the message using DKIM
 		for line in &self.lines {
diff --git a/src/stdin_reader.rs b/src/stdin_reader.rs
index e818aa9..ba16ba9 100644
--- a/src/stdin_reader.rs
+++ b/src/stdin_reader.rs
@@ -1,3 +1,4 @@
+use crate::display_bytes;
 use std::io::{BufRead, BufReader};
 
 pub struct StdinReader {
@@ -15,9 +16,11 @@ impl StdinReader {
 
 	pub fn read_line(&mut self) -> Vec<u8> {
 		self.buffer.clear();
+		log::trace!("reading line from stdin");
 		if self.reader.read_until(b'\n', &mut self.buffer).unwrap() == 0 {
 			std::process::exit(0)
 		}
+		log::trace!("line read from stdin: {}", display_bytes!(self.buffer));
 		self.buffer.clone()
 	}
 }