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.

CONTRIBUTING.md

@@ -72,7 +72,7 @@ pub fn module<'a>(context: &'a Context) -> Option<Module<'a>> {
 
 ## Logging
 
-Debug logging in starship is done with [pretty_env_logger](https://crates.io/crates/pretty_env_logger).
+Debug logging in starship is done with our custom logger implementation.
 To run starship with debug logs, set the `STARSHIP_LOG` environment variable to the log level needed.
 For example, to enable the trace logs, run the following:
 

Cargo.lock

@@ -351,19 +351,6 @@ version = "1.6.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "cd56b59865bce947ac5958779cfa508f6c3b9497cc762b7e24a12d11ccde2c4f"
 
-[[package]]
-name = "env_logger"
-version = "0.7.1"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "44533bbbb3bb3c1fa17d9f2e4e38bbbaf8396ba82193c4cb1b6445d711445d36"
-dependencies = [
- "atty",
- "humantime",
- "log",
- "regex",
- "termcolor",
-]
-
 [[package]]
 name = "fake-simd"
 version = "0.1.2"
@@ -463,15 +450,6 @@ dependencies = [
  "itoa",
 ]
 
-[[package]]
-name = "humantime"
-version = "1.3.0"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "df004cfca50ef23c36850aaaa59ad52cc70d0e90243c3c7737a4dd32dc7a3c4f"
-dependencies = [
- "quick-error",
-]
-
 [[package]]
 name = "idna"
 version = "0.2.0"
@@ -887,16 +865,6 @@ version = "0.2.8"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "237a5ed80e274dbc66f86bd59c1e25edc039660be53194b5fe0a482e0f2612ea"
 
-[[package]]
-name = "pretty_env_logger"
-version = "0.4.0"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "926d36b9553851b8b0005f1275891b392ee4d2d833852c417ed025477350fb9d"
-dependencies = [
- "env_logger",
- "log",
-]
-
 [[package]]
 name = "proc-macro2"
 version = "1.0.19"
@@ -906,12 +874,6 @@ dependencies = [
  "unicode-xid 0.2.1",
 ]
 
-[[package]]
-name = "quick-error"
-version = "1.2.3"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "a1d01941d82fa2ab50be1e79e6714289dd7cde78eba4c074bc5a4374f650dfe0"
-
 [[package]]
 name = "quick-xml"
 version = "0.19.0"
@@ -1187,8 +1149,8 @@ dependencies = [
  "path-slash",
  "pest",
  "pest_derive",
- "pretty_env_logger",
  "quick-xml",
+ "rand",
  "rayon",
  "regex",
  "serde_json",
@@ -1306,15 +1268,6 @@ dependencies = [
  "winapi",
 ]
 
-[[package]]
-name = "termcolor"
-version = "1.1.0"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "bb6bfa289a4d7c5766392812c0a1f4c1ba45afa1ad47803c11e1f407d846d75f"
-dependencies = [
- "winapi-util",
-]
-
 [[package]]
 name = "textwrap"
 version = "0.11.0"
@@ -1480,15 +1433,6 @@ version = "0.4.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "ac3b87c63620426dd9b991e5ce0329eff545bccbbb34f3be09ff6fb6ab51b7b6"
 
-[[package]]
-name = "winapi-util"
-version = "0.1.5"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "70ec6ce85bb158151cae5e5c87f95a8e97d2c0c4b001223f33a334e3ce5de178"
-dependencies = [
- "winapi",
-]
-
 [[package]]
 name = "winapi-x86_64-pc-windows-gnu"
 version = "0.4.0"

Cargo.toml

@@ -35,8 +35,7 @@ git2 = { version = "0.13.11", default-features = false }
 toml = { version = "0.5.6", features = ["preserve_order"] }
 serde_json = "1.0.57"
 rayon = "1.4.0"
-pretty_env_logger = "0.4.0"
+log = { version = "0.4.11", features = ["std"] }
-log = "0.4.11"
 # battery is optional (on by default) because the crate doesn't currently build for Termux
 # see: https://github.com/svartalf/rust-battery/issues/33
 battery = { version = "0.7.6", optional = true }
@@ -58,6 +57,7 @@ open = "1.4.0"
 unicode-width = "0.1.8"
 term_size = "0.3.2"
 quick-xml = "0.19.0"
+rand = "0.7.3"
 notify-rust = { version = "4.0.0", optional = true }
 
 # Optional/http:

docs/config/README.md

@@ -33,6 +33,21 @@ Equivalently in PowerShell (Windows) would be adding this line to your `$PROFILE
 $ENV:STARSHIP_CONFIG = "$HOME\.starship"
 ```
 
+### Logging
+
+By default starship logs warnings and errors into a file named `~/.cache/starship/session_${STARSHIP_SESSION_KEY}.log`, where the session key is corresponding to a instance of your terminal.
+This, however can be changed using the `STARSHIP_CACHE` environment variable:
+
+```sh
+export STARSHIP_CACHE=~/.starship/cache
+```
+
+Equivalently in PowerShell (Windows) would be adding this line to your `$PROFILE`:
+
+```ps1
+$ENV:STARSHIP_CACHE = "$HOME\AppData\Local\Temp"
+```
+
 ### Terminology
 
 **Module**: A component in the prompt giving information based on contextual information from your OS. For example, the "nodejs" module shows the version of NodeJS that is currently installed on your computer, if your current directory is a NodeJS project.

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
             );

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);
             }
         }
 

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),

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)

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)

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)

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)

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)

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;

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);
+}

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),
     }
 }

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;
         }
     });

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
             }
         })

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!(
+        log::warn!(
-            "[WARN]: min_time in [cmd_duration] ({}) was less than zero",
+            "min_time in [cmd_duration] ({}) was less than zero",
             config.min_time
         );
         return None;

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
             );

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`.",
             );

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 {}",

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
     }
 }

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 {}",

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;
         }
     };

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
         }
     }

starship_module_config_derive/src/lib.rs

@@ -1,6 +1,3 @@
-extern crate proc_macro;
-extern crate proc_macro2;
-
 use proc_macro::TokenStream;
 use quote::quote;
 use syn::{parse_macro_input, DeriveInput};
@@ -50,6 +47,9 @@ fn impl_module_config(dinput: DeriveInput) -> proc_macro::TokenStream {
                 fn load_config(&self, config: &'a toml::Value) -> Self {
                     let mut new_module_config = self.clone();
                     if let toml::Value::Table(config) = config {
+                        if config.get("prefix").is_some() || config.get("suffix").is_some() {
+                            log::warn!("You're using the outdated config format! Migrate your config here: https://starship.rs/migrating-to-0.45.0/")
+                        }
                         #load_tokens
                     }
                     new_module_config