📖 Add logging and term writes

println works for a while. Was time to set up something better. Worth
to not that there is a big difference between logging and writing to
the terminal which is why both slog and console was dragged in. Might
seem similar but purpose is not the same.

Most of the time the log is interesting during runtime but user
messages does not belong in the log.

7 files changed, 118 insertions, 18 deletions

diff --git a/racer-tracer/src/error.rs b/racer-tracer/src/error.rs
index b7cb46d..d9b13ab 100644
--- a/racer-tracer/src/error.rs
+++ b/racer-tracer/src/error.rs
@@ -46,6 +46,9 @@ pub enum TracerError {
 
     #[error("Key callback failed: {0}")]
     KeyError(String),
+
+    #[error("Failed to create log: {0}")]
+    CreateLogError(String),
 }
 
 impl From<TracerError> for i32 {
@@ -69,6 +72,7 @@ impl From<TracerError> for i32 {
             TracerError::SceneLoad(_) => 13,
             TracerError::ArgumentParsingError(_) => 14,
             TracerError::KeyError(_) => 15,
+            TracerError::CreateLogError(_) => 16,
         }
     }
 }
diff --git a/racer-tracer/src/image_action.rs b/racer-tracer/src/image_action.rs
index d6d212c..3f984a1 100644
--- a/racer-tracer/src/image_action.rs
+++ b/racer-tracer/src/image_action.rs
@@ -3,10 +3,12 @@ pub mod wait_for_signal;
 
 use std::sync::RwLock;
 
+use slog::Logger;
 use synchronoise::SignalEvent;
 
 use crate::image_action::{png::SavePng, wait_for_signal::WaitForSignal};
 
+use crate::terminal::Terminal;
 use crate::{
     config::{Config, ImageAction as CImageAction},
     error::TracerError,
@@ -18,6 +20,8 @@ pub trait ImageAction: Send + Sync {
         screen_buffer: &RwLock<Vec<u32>>,
         event: &SignalEvent,
         config: &Config,
+        log: Logger,
+        term: &Terminal,
     ) -> Result<(), TracerError>;
 }
 
diff --git a/racer-tracer/src/image_action/png.rs b/racer-tracer/src/image_action/png.rs
index 4887d3d..dbed285 100644
--- a/racer-tracer/src/image_action/png.rs
+++ b/racer-tracer/src/image_action/png.rs
@@ -1,9 +1,10 @@
 use std::{path::PathBuf, sync::RwLock};
 
 use sha2::{Digest, Sha256};
+use slog::Logger;
 use synchronoise::SignalEvent;
 
-use crate::{config::Config, error::TracerError};
+use crate::{config::Config, error::TracerError, terminal::Terminal};
 
 use super::ImageAction;
 
@@ -15,6 +16,8 @@ impl ImageAction for SavePng {
         screen_buffer: &RwLock<Vec<u32>>,
         event: &SignalEvent,
         config: &Config,
+        log: Logger,
+        _term: &Terminal,
     ) -> Result<(), TracerError> {
         let status = event.status();
         event.reset();
@@ -40,7 +43,7 @@ impl ImageAction for SavePng {
                 })
                 .and_then(|buf| match &config.image_output_dir {
                     Some(image_dir) => {
-                        println!("Saving image...");
+                        info!(log, "Saving image...");
                         let mut sha = Sha256::new();
 
                         sha.update(buf.as_slice());
@@ -60,7 +63,7 @@ impl ImageAction for SavePng {
                             TracerError::ImageSave(error)
                         })
                         .map(|_| {
-                            println!("Saved image to: {}", file_path.to_string_lossy());
+                            info!(log, "Saved image to: {}", file_path.to_string_lossy());
                         })
                     }
                     None => Ok(()),
diff --git a/racer-tracer/src/image_action/wait_for_signal.rs b/racer-tracer/src/image_action/wait_for_signal.rs
index 54480ac..0ffe5e7 100644
--- a/racer-tracer/src/image_action/wait_for_signal.rs
+++ b/racer-tracer/src/image_action/wait_for_signal.rs
@@ -1,8 +1,13 @@
 use std::sync::RwLock;
 
+use slog::Logger;
 use synchronoise::SignalEvent;
 
-use crate::{config::Config, error::TracerError};
+use crate::{
+    config::Config,
+    error::TracerError,
+    terminal::{write_term, Terminal},
+};
 
 use super::ImageAction;
 
@@ -14,9 +19,11 @@ impl ImageAction for WaitForSignal {
         _screen_buffer: &RwLock<Vec<u32>>,
         event: &SignalEvent,
         _config: &Config,
+        _log: Logger,
+        term: &Terminal,
     ) -> Result<(), TracerError> {
         if !event.status() {
-            println!("Press R to resume.");
+            write_term!(term, "Press R to resume.");
             event.wait();
         }
         event.reset();
diff --git a/racer-tracer/src/key_inputs.rs b/racer-tracer/src/key_inputs.rs
index 06e0f99..1e3505e 100644
--- a/racer-tracer/src/key_inputs.rs
+++ b/racer-tracer/src/key_inputs.rs
@@ -1,6 +1,7 @@
 use std::collections::HashMap;
 
 use minifb::{Key, Window};
+use slog::Logger;
 
 use crate::error::TracerError;
 
@@ -9,13 +10,15 @@ pub type KeyClosure<'a> = &'a (dyn Fn(f64) -> Result<(), TracerError> + Send + S
 pub struct KeyInputs<'a> {
     is_down_callbacks: HashMap<Key, Vec<KeyClosure<'a>>>,
     is_released_callbacks: HashMap<Key, Vec<KeyClosure<'a>>>,
+    log: Logger,
 }
 
 impl<'a> KeyInputs<'a> {
-    pub fn new() -> Self {
+    pub fn new(log: Logger) -> Self {
         KeyInputs {
             is_down_callbacks: HashMap::new(),
             is_released_callbacks: HashMap::new(),
+            log,
         }
     }
 
@@ -39,7 +42,7 @@ impl<'a> KeyInputs<'a> {
             .for_each(|(_key, callbacks)| {
                 callbacks.iter_mut().for_each(|callback| {
                     if let Err(e) = callback(dt) {
-                        println!("Key callback error: {}", e)
+                        error!(self.log, "Key callback error: {}", e);
                     }
                 })
             });
@@ -49,7 +52,7 @@ impl<'a> KeyInputs<'a> {
             .for_each(|(_key, callbacks)| {
                 callbacks.iter_mut().for_each(|callback| {
                     if let Err(e) = callback(dt) {
-                        println!("Key callback error: {}", e)
+                        error!(self.log, "Key callback error: {}", e);
                     }
                 })
             });
diff --git a/racer-tracer/src/main.rs b/racer-tracer/src/main.rs
index 59c9208..b70a140 100644
--- a/racer-tracer/src/main.rs
+++ b/racer-tracer/src/main.rs
@@ -10,22 +10,31 @@ mod material;
 mod ray;
 mod render;
 mod scene;
+mod terminal;
 mod util;
 mod vec3;
 
 extern crate image as img;
 
+#[macro_use]
+extern crate slog;
+extern crate slog_async;
+extern crate slog_term;
+
 use std::{
     convert::TryFrom,
+    fs::OpenOptions,
+    path::Path,
     sync::RwLock,
     time::{Duration, Instant},
     vec::Vec,
 };
 
-use image_action::ImageAction;
-use key_inputs::KeyInputs;
 use minifb::{Key, Window, WindowOptions};
+use slog::{Drain, Logger};
+use structopt::StructOpt;
 use synchronoise::SignalEvent;
+use terminal::Terminal;
 
 use crate::vec3::Vec3;
 
@@ -33,11 +42,15 @@ use crate::{
     camera::Camera,
     config::{Args, Config},
     error::TracerError,
+    image_action::ImageAction,
+    key_inputs::KeyInputs,
     render::render,
     scene::Scene,
 };
 
-fn run(config: Config) -> Result<(), TracerError> {
+fn run(config: Config, log: Logger, term: Terminal) -> Result<(), TracerError> {
+    info!(log, "Starting racer-tracer {}", env!("CARGO_PKG_VERSION"));
+
     let image = image::Image::new(config.screen.width, config.screen.height);
     let screen_buffer: RwLock<Vec<u32>> = RwLock::new(vec![0; image.width * image.height]);
     let look_from = Vec3::new(13.0, 2.0, 3.0);
@@ -64,7 +77,7 @@ fn run(config: Config) -> Result<(), TracerError> {
     let image_action: Box<dyn ImageAction> = (&config.image_action).into();
 
     // Setting up controls
-    let mut key_inputs = KeyInputs::new();
+    let mut key_inputs = KeyInputs::new(log.new(o!("scope" => "key-intputs")));
     let render_image_fn = |_| {
         render_image.signal();
         Ok(())
@@ -148,11 +161,18 @@ fn run(config: Config) -> Result<(), TracerError> {
                                         None,
                                     )
                                     .and_then(|_| {
-                                        println!(
+                                        info!(
+                                            log,
                                             "It took {} seconds to render the image.",
                                             Instant::now().duration_since(render_time).as_secs()
                                         );
-                                        image_action.action(&screen_buffer, &render_image, &config)
+                                        image_action.action(
+                                            &screen_buffer,
+                                            &render_image,
+                                            &config,
+                                            log.new(o!("scope" => "image-action")),
+                                            &term,
+                                        )
                                     })
                                 },
                             )
@@ -203,14 +223,47 @@ fn run(config: Config) -> Result<(), TracerError> {
 
     window_res.and(render_res)
 }
-use structopt::StructOpt;
+
+fn create_log(log_file: &Path) -> Result<Logger, TracerError> {
+    OpenOptions::new()
+        .create(true)
+        .write(true)
+        .truncate(true)
+        .open(log_file)
+        .map(slog_term::PlainDecorator::new)
+        .map(|log| slog_term::FullFormat::new(log).build().fuse())
+        .map_err(|e| TracerError::CreateLogError(e.to_string()))
+        .map(|file_drain| {
+            let term_drain = slog_term::FullFormat::new(slog_term::TermDecorator::new().build())
+                .build()
+                .fuse();
+            (file_drain, term_drain)
+        })
+        .map(|(file_drain, term_drain)| {
+            let combined =
+                slog_async::Async::new(slog::Duplicate::new(term_drain, file_drain).fuse())
+                    .build()
+                    .fuse();
+            Logger::root(combined, o!())
+        })
+}
+
 fn main() {
-    match Config::try_from(Args::from_args()).and_then(run) {
+    let log_file = std::env::temp_dir().join("racer-tracer.log");
+    let log = create_log(log_file.as_ref()).expect("Expected to be able to create a log");
+    let term = Terminal::new(log.new(o!("scope" => "terminal")));
+    terminal::write_term!(term, &format!("Log file: {}", log_file.display()));
+
+    match Config::try_from(Args::from_args())
+        .and_then(|config| run(config, log.new(o!("scope" => "run")), term))
+    {
         Err(TracerError::ExitEvent) => {}
         Ok(_) => {}
         Err(e) => {
-            eprintln!("{}", e);
-            std::process::exit(e.into())
+            error!(log, "{}", e);
+            let exit_code = i32::from(e);
+            error!(log, "Exiting with: {}", exit_code);
+            std::process::exit(exit_code)
         }
     }
 }
diff --git a/racer-tracer/src/terminal.rs b/racer-tracer/src/terminal.rs
new file mode 100644
index 0000000..48eb599
--- /dev/null
+++ b/racer-tracer/src/terminal.rs
@@ -0,0 +1,26 @@
+use console::Term;
+use slog::Logger;
+
+pub struct Terminal {
+    pub logger: Logger,
+    pub terminal: Term,
+}
+
+impl Terminal {
+    pub fn new(logger: Logger) -> Self {
+        Self {
+            logger,
+            terminal: Term::stdout(),
+        }
+    }
+}
+
+macro_rules! write_term {
+    ($term:expr, $text:expr) => {{
+        if let Err(e) = $term.terminal.write_line($text) {
+            debug!($term.logger, "Failed to write to terminal: {}", e)
+        }
+    }};
+}
+
+pub(crate) use write_term;