feat: add error messaging (#1576)

This creates a custom logger for the log crate which logs everything to a file (/tmp/starship/session_$STARSHIP_SESSION_KEY.log) and it logs everything above Warn to stderr, but only if the log file does not contain the line that should be logged resulting in an error or warning to be only logged at the first starship invocation after opening the shell.

21 files changed, 166 insertions, 34 deletions

diff --git a/src/config.rs b/src/config.rs
index 9099011aa..e6d3a4d4e 100644
--- a/src/config.rs
+++ b/src/config.rs
@@ -199,7 +199,7 @@ impl StarshipConfig {
     fn config_from_file() -> Option<Value> {
         let file_path = if let Ok(path) = env::var("STARSHIP_CONFIG") {
             // Use $STARSHIP_CONFIG as the config path if available
-            log::debug!("STARSHIP_CONFIG is set: \n{}", &path);
+            log::debug!("STARSHIP_CONFIG is set: {}", &path);
             path
         } else {
             // Default to using ~/.config/starship.toml
@@ -212,22 +212,22 @@ impl StarshipConfig {
 
         let toml_content = match utils::read_file(&file_path) {
             Ok(content) => {
-                log::trace!("Config file content: \n{}", &content);
+                log::trace!("Config file content: \"\n{}\"", &content);
                 Some(content)
             }
             Err(e) => {
-                log::debug!("Unable to read config file content: \n{}", &e);
+                log::debug!("Unable to read config file content: {}", &e);
                 None
             }
         }?;
 
         match toml::from_str(&toml_content) {
             Ok(parsed) => {
-                log::debug!("Config parsed: \n{:?}", &parsed);
+                log::debug!("Config parsed: {:?}", &parsed);
                 Some(parsed)
             }
             Err(error) => {
-                log::debug!("Unable to parse the config file: {}", error);
+                log::error!("Unable to parse the config file: {}", error);
                 None
             }
         }
@@ -238,7 +238,7 @@ impl StarshipConfig {
         let module_config = self.get_config(&[module_name]);
         if module_config.is_some() {
             log::debug!(
-                "Config found for \"{}\": \n{:?}",
+                "Config found for \"{}\": {:?}",
                 &module_name,
                 &module_config
             );
@@ -302,7 +302,7 @@ impl StarshipConfig {
         let module_config = self.get_config(&["custom", module_name]);
         if module_config.is_some() {
             log::debug!(
-                "Custom config found for \"{}\": \n{:?}",
+                "Custom config found for \"{}\": {:?}",
                 &module_name,
                 &module_config
             );
diff --git a/src/configs/custom.rs b/src/configs/custom.rs
index 31317f1cc..315542b21 100644
--- a/src/configs/custom.rs
+++ b/src/configs/custom.rs
@@ -52,7 +52,7 @@ impl<'a> ModuleConfig<'a> for Files<'a> {
             if let Some(file) = item.as_str() {
                 files.push(file);
             } else {
-                log::debug!("Unexpected file {:?}", item);
+                log::warn!("Unexpected file {:?}", item);
             }
         }
 
@@ -68,7 +68,7 @@ impl<'a> ModuleConfig<'a> for Extensions<'a> {
             if let Some(file) = item.as_str() {
                 extensions.push(file);
             } else {
-                log::debug!("Unexpected extension {:?}", item);
+                log::warn!("Unexpected extension {:?}", item);
             }
         }
 
@@ -84,7 +84,7 @@ impl<'a> ModuleConfig<'a> for Directories<'a> {
             if let Some(file) = item.as_str() {
                 directories.push(file);
             } else {
-                log::debug!("Unexpected directory {:?}", item);
+                log::warn!("Unexpected directory {:?}", item);
             }
         }
 
diff --git a/src/configure.rs b/src/configure.rs
index efd9007d9..ac9b93e3f 100644
--- a/src/configure.rs
+++ b/src/configure.rs
@@ -80,7 +80,6 @@ pub fn edit_configuration() {
                     environment variables correctly?",
                     editor_cmd
                 );
-                eprintln!("Full error: {:?}", error);
                 std::process::exit(1)
             }
             other_error => panic!("failed to open file: {:?}", other_error),
diff --git a/src/init/starship.bash b/src/init/starship.bash
index 822a3b0b5..f7bd2d9d0 100644
--- a/src/init/starship.bash
+++ b/src/init/starship.bash
@@ -84,3 +84,6 @@ fi
 # Set up the start time and STARSHIP_SHELL, which controls shell-specific sequences
 STARSHIP_START_TIME=$(::STARSHIP:: time)
 export STARSHIP_SHELL="bash"
+
+# Set up the session key that will be used to store logs
+export STARSHIP_SESSION_KEY=$(::STARSHIP:: session)
diff --git a/src/init/starship.fish b/src/init/starship.fish
index 6daa473d4..8236f548b 100644
--- a/src/init/starship.fish
+++ b/src/init/starship.fish
@@ -16,3 +16,6 @@ set VIRTUAL_ENV_DISABLE_PROMPT 1
 
 function fish_mode_prompt; end
 export STARSHIP_SHELL="fish"
+
+# Set up the session key that will be used to store logs
+export STARSHIP_SESSION_KEY=(::STARSHIP:: session)
diff --git a/src/init/starship.ion b/src/init/starship.ion
index 0d979df2d..5a03ab2e1 100644
--- a/src/init/starship.ion
+++ b/src/init/starship.ion
@@ -15,3 +15,6 @@ end
 
 # Export the correct name of the shell
 export STARSHIP_SHELL="ion"
+
+# Set up the session key that will be used to store logs
+export STARSHIP_SESSION_KEY=$(::STARSHIP:: session)
diff --git a/src/init/starship.ps1 b/src/init/starship.ps1
index 558d9c5ca..74c8f952f 100644
--- a/src/init/starship.ps1
+++ b/src/init/starship.ps1
@@ -54,3 +54,6 @@ function global:prompt {
 }
 
 $ENV:STARSHIP_SHELL = "powershell"
+
+# Set up the session key that will be used to store logs
+$ENV:STARSHIP_SESSION_KEY = $(::STARSHIP:: session)
diff --git a/src/init/starship.zsh b/src/init/starship.zsh
index ed8452de9..5ecb33d12 100644
--- a/src/init/starship.zsh
+++ b/src/init/starship.zsh
@@ -62,3 +62,6 @@ zle-keymap-select() {
 STARSHIP_START_TIME=$(::STARSHIP:: time)
 zle -N zle-keymap-select
 export STARSHIP_SHELL="zsh"
+
+# Set up the session key that will be used to store logs
+export STARSHIP_SESSION_KEY=$(::STARSHIP:: session)
diff --git a/src/lib.rs b/src/lib.rs
index 0b98721b0..15a38074b 100644
--- a/src/lib.rs
+++ b/src/lib.rs
@@ -3,6 +3,7 @@ pub mod config;
 pub mod configs;
 pub mod context;
 pub mod formatter;
+pub mod logger;
 pub mod module;
 pub mod modules;
 pub mod print;
diff --git a/src/logger.rs b/src/logger.rs
new file mode 100644
index 000000000..e17a368c9
--- /dev/null
+++ b/src/logger.rs
@@ -0,0 +1,112 @@
+use ansi_term::Color;
+use log::{Level, LevelFilter, Metadata, Record};
+use std::{
+    collections::HashSet,
+    env,
+    fs::{self, File, OpenOptions},
+    io::Write,
+    path::PathBuf,
+    sync::{Arc, Mutex},
+};
+
+pub struct StarshipLogger {
+    log_file: Arc<Mutex<File>>,
+    log_file_content: Arc<HashSet<String>>,
+    log_level: Level,
+}
+
+impl StarshipLogger {
+    fn new() -> Self {
+        let log_dir = env::var_os("STARSHIP_CACHE")
+            .map(PathBuf::from)
+            .unwrap_or_else(|| {
+                dirs_next::home_dir()
+                    .expect("Unable to find home directory")
+                    .join(".cache/starship")
+            });
+
+        fs::create_dir_all(&log_dir).expect("Unable to create log dir!");
+        let session_log_file = log_dir.join(format!(
+            "session_{}.log",
+            env::var("STARSHIP_SESSION_KEY").unwrap_or_default()
+        ));
+
+        Self {
+            log_file_content: Arc::new(
+                fs::read_to_string(&session_log_file)
+                    .unwrap_or_default()
+                    .lines()
+                    .map(|line| line.to_string())
+                    .collect(),
+            ),
+            log_file: Arc::new(Mutex::new(
+                OpenOptions::new()
+                    .create(true)
+                    .append(true)
+                    .open(session_log_file)
+                    .unwrap(),
+            )),
+            log_level: env::var("STARSHIP_LOG")
+                .map(|level| match level.to_lowercase().as_str() {
+                    "trace" => Level::Trace,
+                    "debug" => Level::Debug,
+                    "info" => Level::Info,
+                    "warn" => Level::Warn,
+                    "error" => Level::Error,
+                    _ => Level::Warn,
+                })
+                .unwrap_or_else(|_| Level::Warn),
+        }
+    }
+}
+
+impl log::Log for StarshipLogger {
+    fn enabled(&self, metadata: &Metadata) -> bool {
+        metadata.level() <= self.log_level
+    }
+
+    fn log(&self, record: &Record) {
+        let to_print = format!(
+            "[{}] - ({}): {}",
+            record.level(),
+            record.module_path().unwrap_or_default(),
+            record.args()
+        );
+
+        if record.metadata().level() <= Level::Warn {
+            self.log_file
+                .lock()
+                .map(|mut file| writeln!(file, "{}", to_print))
+                .expect("Log file writer mutex was poisoned!")
+                .expect("Unable to write to the log file!");
+        }
+
+        if self.enabled(record.metadata()) && !self.log_file_content.contains(to_print.as_str()) {
+            eprintln!(
+                "[{}] - ({}): {}",
+                match record.level() {
+                    Level::Trace => Color::Black.dimmed().paint(format!("{}", record.level())),
+                    Level::Debug => Color::Black.paint(format!("{}", record.level())),
+                    Level::Info => Color::White.paint(format!("{}", record.level())),
+                    Level::Warn => Color::Yellow.paint(format!("{}", record.level())),
+                    Level::Error => Color::Red.paint(format!("{}", record.level())),
+                },
+                record.module_path().unwrap_or_default(),
+                record.args()
+            );
+        }
+    }
+
+    fn flush(&self) {
+        self.log_file
+            .lock()
+            .map(|mut writer| writer.flush())
+            .expect("Log file writer mutex was poisoned!")
+            .expect("Unable to flush the log file!");
+    }
+}
+
+pub fn init() {
+    log::set_boxed_logger(Box::new(StarshipLogger::new())).unwrap();
+    log::set_max_level(LevelFilter::Trace);
+}
diff --git a/src/main.rs b/src/main.rs
index 3afcf6b3d..46dc86e25 100644
--- a/src/main.rs
+++ b/src/main.rs
@@ -9,6 +9,7 @@ mod configure;
 mod context;
 mod formatter;
 mod init;
+mod logger;
 mod module;
 mod modules;
 mod print;
@@ -20,9 +21,11 @@ mod test;
 
 use crate::module::ALL_MODULES;
 use clap::{App, AppSettings, Arg, Shell, SubCommand};
+use rand::distributions::Alphanumeric;
+use rand::Rng;
 
 fn main() {
-    pretty_env_logger::init_custom_env("STARSHIP_LOG");
+    logger::init();
 
     let status_code_arg = Arg::with_name("status_code")
         .short("s")
@@ -153,7 +156,8 @@ fn main() {
                         .required(true)
                         .env("STARSHIP_SHELL"),
                 ),
-        );
+        )
+        .subcommand(SubCommand::with_name("session").about("Generate random session key"));
 
     let matches = app.clone().get_matches();
 
@@ -209,6 +213,13 @@ fn main() {
 
             app.gen_completions_to("starship", shell, &mut io::stdout().lock());
         }
+        ("session", _) => println!(
+            "{}",
+            rand::thread_rng()
+                .sample_iter(&Alphanumeric)
+                .take(16)
+                .collect::<String>()
+        ),
         (command, _) => unreachable!("Invalid subcommand: {}", command),
     }
 }
diff --git a/src/modules/aws.rs b/src/modules/aws.rs
index b404a2a27..a73dc7561 100644
--- a/src/modules/aws.rs
+++ b/src/modules/aws.rs
@@ -108,7 +108,7 @@ pub fn module<'a>(context: &'a Context) -> Option<Module<'a>> {
     module.set_segments(match parsed {
         Ok(segments) => segments,
         Err(error) => {
-            log::error!("Error in module `aws`: \n{}", error);
+            log::warn!("Error in module `aws`: \n{}", error);
             return None;
         }
     });
diff --git a/src/modules/battery.rs b/src/modules/battery.rs
index 0ce96d8cc..2b773bf23 100644
--- a/src/modules/battery.rs
+++ b/src/modules/battery.rs
@@ -85,7 +85,7 @@ fn get_battery_status() -> Option<BatteryStatus> {
                 })
             }
             Err(e) => {
-                log::debug!("Unable to access battery information:\n{}", &e);
+                log::warn!("Unable to access battery information:\n{}", &e);
                 None
             }
         })
diff --git a/src/modules/cmd_duration.rs b/src/modules/cmd_duration.rs
index 8684b0aa5..037310842 100644
--- a/src/modules/cmd_duration.rs
+++ b/src/modules/cmd_duration.rs
@@ -11,11 +11,9 @@ pub fn module<'a>(context: &'a Context) -> Option<Module<'a>> {
     let mut module = context.new_module("cmd_duration");
     let config: CmdDurationConfig = CmdDurationConfig::try_load(module.config);
 
-    /* TODO: Once error handling is implemented, warn the user if their config
-    min time is nonsensical */
     if config.min_time < 0 {
-        log::debug!(
-            "[WARN]: min_time in [cmd_duration] ({}) was less than zero",
+        log::warn!(
+            "min_time in [cmd_duration] ({}) was less than zero",
             config.min_time
         );
         return None;
diff --git a/src/modules/directory.rs b/src/modules/directory.rs
index 3b977ff08..390480242 100644
--- a/src/modules/directory.rs
+++ b/src/modules/directory.rs
@@ -136,7 +136,7 @@ fn is_readonly_dir(path: &Path) -> bool {
         Ok(res) => !res,
         Err(e) => {
             log::debug!(
-                "Failed to detemine read only status of directory '{:?}': {}",
+                "Failed to determine read only status of directory '{:?}': {}",
                 path,
                 e
             );
diff --git a/src/modules/dotnet.rs b/src/modules/dotnet.rs
index 0e0ad52b9..71e58748a 100644
--- a/src/modules/dotnet.rs
+++ b/src/modules/dotnet.rs
@@ -321,7 +321,7 @@ fn get_latest_sdk_from_cli() -> Option<Version> {
         None => {
             // Older versions of the dotnet cli do not support the --list-sdks command
             // So, if the status code indicates failure, fall back to `dotnet --version`
-            log::warn!(
+            log::debug!(
                 "Received a non-success exit code from `dotnet --list-sdks`. \
                  Falling back to `dotnet --version`.",
             );
diff --git a/src/modules/git_branch.rs b/src/modules/git_branch.rs
index bcebd83e6..0610b530e 100644
--- a/src/modules/git_branch.rs
+++ b/src/modules/git_branch.rs
@@ -14,8 +14,6 @@ pub fn module<'a>(context: &'a Context) -> Option<Module<'a>> {
 
     let truncation_symbol = get_first_grapheme(config.truncation_symbol);
 
-    // TODO: Once error handling is implemented, warn the user if their config
-    //       truncation length is nonsensical
     let len = if config.truncation_length <= 0 {
         log::warn!(
             "\"truncation_length\" should be a positive value, found {}",
diff --git a/src/modules/git_status.rs b/src/modules/git_status.rs
index 5e3ecb8ae..9daf94c05 100644
--- a/src/modules/git_status.rs
+++ b/src/modules/git_status.rs
@@ -144,7 +144,7 @@ impl<'a> GitStatusInfo<'a> {
                 return match result.as_ref() {
                     Ok(ahead_behind) => Some(*ahead_behind),
                     Err(error) => {
-                        log::warn!("Warn: get_ahead_behind: {}", error);
+                        log::debug!("get_ahead_behind: {}", error);
                         None
                     }
                 };
@@ -159,7 +159,7 @@ impl<'a> GitStatusInfo<'a> {
             match data.as_ref().unwrap() {
                 Ok(ahead_behind) => Some(*ahead_behind),
                 Err(error) => {
-                    log::warn!("Warn: get_ahead_behind: {}", error);
+                    log::debug!("get_ahead_behind: {}", error);
                     None
                 }
             }
@@ -173,7 +173,7 @@ impl<'a> GitStatusInfo<'a> {
                 return match result.as_ref() {
                     Ok(repo_status) => Some(*repo_status),
                     Err(error) => {
-                        log::warn!("Warn: get_repo_status: {}", error);
+                        log::debug!("get_repo_status: {}", error);
                         None
                     }
                 };
@@ -187,7 +187,7 @@ impl<'a> GitStatusInfo<'a> {
             match data.as_ref().unwrap() {
                 Ok(repo_status) => Some(*repo_status),
                 Err(error) => {
-                    log::warn!("Warn: get_repo_status: {}", error);
+                    log::debug!(" get_repo_status: {}", error);
                     None
                 }
             }
@@ -201,7 +201,7 @@ impl<'a> GitStatusInfo<'a> {
                 return match result.as_ref() {
                     Ok(stashed_count) => Some(*stashed_count),
                     Err(error) => {
-                        log::warn!("Warn: get_stashed_count: {}", error);
+                        log::debug!("get_stashed_count: {}", error);
                         None
                     }
                 };
@@ -215,7 +215,7 @@ impl<'a> GitStatusInfo<'a> {
             match data.as_ref().unwrap() {
                 Ok(stashed_count) => Some(*stashed_count),
                 Err(error) => {
-                    log::warn!("Warn: get_stashed_count: {}", error);
+                    log::debug!("get_stashed_count: {}", error);
                     None
                 }
             }
@@ -356,7 +356,7 @@ where
             .parse(None)
             .ok()
     } else {
-        log::error!("Error parsing format string `{}`", &config_path);
+        log::warn!("Error parsing format string `{}`", &config_path);
         None
     }
 }
diff --git a/src/modules/hg_branch.rs b/src/modules/hg_branch.rs
index 7d29d622f..9b6c211a7 100644
--- a/src/modules/hg_branch.rs
+++ b/src/modules/hg_branch.rs
@@ -24,8 +24,6 @@ pub fn module<'a>(context: &'a Context) -> Option<Module<'a>> {
         return None;
     };
 
-    // TODO: Once error handling is implemented, warn the user if their config
-    // truncation length is nonsensical
     let len = if config.truncation_length <= 0 {
         log::warn!(
             "\"truncation_length\" should be a positive value, found {}",
diff --git a/src/modules/hostname.rs b/src/modules/hostname.rs
index cacbaff2d..feefbf5d2 100644
--- a/src/modules/hostname.rs
+++ b/src/modules/hostname.rs
@@ -24,7 +24,7 @@ pub fn module<'a>(context: &'a Context) -> Option<Module<'a>> {
     let host = match os_hostname.into_string() {
         Ok(host) => host,
         Err(bad) => {
-            log::debug!("hostname is not valid UTF!\n{:?}", bad);
+            log::warn!("hostname is not valid UTF!\n{:?}", bad);
             return None;
         }
     };
diff --git a/src/utils.rs b/src/utils.rs
index 122dd63c3..0c8a4013d 100644
--- a/src/utils.rs
+++ b/src/utils.rs
@@ -253,7 +253,7 @@ fn internal_exec_cmd(cmd: &str, args: &[&str]) -> Option<CommandOutput> {
             })
         }
         Err(error) => {
-            log::trace!("Executing command {:?} failed by: {:?}", cmd, error);
+            log::warn!("Executing command {:?} failed by: {:?}", cmd, error);
             None
         }
     }