Rewrite logging: Types

This is the first part of a series of patches that reimplements the
logging backend to be more powerful and configurable.

This first patch adds types and infrastructure to be able to implement a
powerful logging abstraction.

It does not implement much functionality, except for a check whether a
module is enabled or not when logging (if configured in the config
file).

lib/core/libimagrt/src/error.rs

@@ -23,7 +23,13 @@ use std::io::Error as IOError;
 generate_error_types!(RuntimeError, RuntimeErrorKind,
     Instantiate        => "Could not instantiate",
     IOError            => "IO Error",
-    ProcessExitFailure => "Process exited with failure"
+    IOLogFileOpenError => "IO Error: Could not open logfile",
+    ProcessExitFailure => "Process exited with failure",
+    ConfigReadError    => "Error while reading the configuration",
+    ConfigTypeError    => "Error while reading the configuration: Type Error",
+    GlobalLogLevelConfigMissing => "Global config 'imag.logging.level' missing",
+    InvalidLogLevelSpec => "Invalid log level specification: Only 'trace', 'debug', 'info', 'warn', 'error' are allowed",
+    TomlReadError => "Error while reading in TOML document"
 );
 
 impl From<IOError> for RuntimeError {

lib/core/libimagrt/src/lib.rs

@@ -38,6 +38,7 @@ extern crate itertools;
 #[cfg(unix)] extern crate xdg_basedir;
 extern crate env_logger;
 extern crate ansi_term;
+extern crate handlebars;
 
 extern crate clap;
 extern crate toml;

lib/core/libimagrt/src/logger.rs

@@ -19,67 +19,75 @@
 
 use std::io::Write;
 use std::io::stderr;
+use std::collections::BTreeMap;
 
+use configuration::Configuration;
+use error::RuntimeErrorKind as EK;
+use error::RuntimeError;
+use error::MapErrInto;
+use runtime::Runtime;
+
+use libimagerror::into::IntoError;
+
+use clap::ArgMatches;
 use log::{Log, LogLevel, LogRecord, LogMetadata};
+use toml::Value;
+use toml_query::read::TomlValueReadExt;
 
-use ansi_term::Style;
+type ModuleName = String;
-use ansi_term::Colour;
+type Result<T> = ::std::result::Result<T, RuntimeError>;
-use ansi_term::ANSIString;
+
+enum LogDestination {
+    Stderr,
+    File(::std::fs::File),
+}
+
+impl Default for LogDestination {
+    fn default() -> LogDestination {
+        LogDestination::Stderr
+    }
+}
+
+struct ModuleSettings {
+    enabled: bool,
+    level: LogLevel,
+
+    #[allow(unused)]
+    destinations: Vec<LogDestination>,
+}
 
 /// Logger implementation for `log` crate.
 pub struct ImagLogger {
-    prefix: String,
+    global_loglevel     : LogLevel,
-    dbg_fileline: bool,
+
-    lvl: LogLevel,
+    #[allow(unused)]
-    color_enabled: bool,
+    global_destinations : Vec<LogDestination>,
+    // global_format_trace : ,
+    // global_format_debug : ,
+    // global_format_info  : ,
+    // global_format_warn  : ,
+    // global_format_error : ,
+    module_settings     : BTreeMap<ModuleName, ModuleSettings>,
 }
 
 impl ImagLogger {
 
     /// Create a new ImagLogger object with a certain level
-    pub fn new(lvl: LogLevel) -> ImagLogger {
+    pub fn new(matches: &ArgMatches, config: Option<&Configuration>) -> Result<ImagLogger> {
-        ImagLogger {
+        Ok(ImagLogger {
-            prefix: "[imag]".to_owned(),
+            global_loglevel     : try!(aggregate_global_loglevel(matches, config)),
-            dbg_fileline: true,
+            global_destinations : try!(aggregate_global_destinations(matches, config)),
-            lvl: lvl,
+            // global_format_trace : try!(aggregate_global_format_trace(matches, config)),
-            color_enabled: true
+            // global_format_debug : try!(aggregate_global_format_debug(matches, config)),
-        }
+            // global_format_info  : try!(aggregate_global_format_info(matches, config)),
+            // global_format_warn  : try!(aggregate_global_format_warn(matches, config)),
+            // global_format_error : try!(aggregate_global_format_error(matches, config)),
+            module_settings     : try!(aggregate_module_settings(matches, config)),
+        })
     }
 
-    /// Set debugging to include file and line
+    pub fn global_loglevel(&self) -> LogLevel {
-    pub fn with_dbg_file_and_line(mut self, b: bool) -> ImagLogger {
+        self.global_loglevel
-        self.dbg_fileline = b;
-        self
-    }
-
-    /// Set debugging to include prefix
-    pub fn with_prefix(mut self, pref: String) -> ImagLogger {
-        self.prefix = pref;
-        self
-    }
-
-    /// Set debugging to have color
-    pub fn with_color(mut self, b: bool) -> ImagLogger {
-        self.color_enabled = b;
-        self
-    }
-
-    /// Helper function to colorize a string with a certain Style
-    fn style_or_not(&self, c: Style, s: String) -> ANSIString {
-        if self.color_enabled {
-            c.paint(s)
-        } else {
-            ANSIString::from(s)
-        }
-    }
-
-    /// Helper function to colorize a string with a certain Color
-    fn color_or_not(&self, c: Colour, s: String) -> ANSIString {
-        if self.color_enabled {
-            c.paint(s)
-        } else {
-            ANSIString::from(s)
-        }
     }
 
 }
@@ -87,47 +95,217 @@ impl ImagLogger {
 impl Log for ImagLogger {
 
     fn enabled(&self, metadata: &LogMetadata) -> bool {
-        metadata.level() <= self.lvl
+        metadata.level() <= self.global_loglevel
     }
 
     fn log(&self, record: &LogRecord) {
-        use ansi_term::Colour::Red;
+        let log_level = record.level();
-        use ansi_term::Colour::Yellow;
+        let log_location = record.location();
-        use ansi_term::Colour::Cyan;
+        let log_target = record.target();
 
-        if self.enabled(record.metadata()) {
+        self.module_settings
-            // TODO: This is just simple logging. Maybe we can enhance this lateron
+            .get(log_target)
-            let loc = record.location();
+            .map(|module_setting| {
-            match record.metadata().level() {
+                if module_setting.enabled && module_setting.level >= log_level {
-                LogLevel::Debug => {
+                    write!(stderr(), "[imag][{}]: {}", log_level, record.args()).ok();
-                    let lvl  = self.color_or_not(Cyan, format!("{}", record.level()));
+                }
-                    let args = self.color_or_not(Cyan, format!("{}", record.args()));
+            })
-                    if self.dbg_fileline {
+            .unwrap_or_else(|| {
-                        let file = self.color_or_not(Cyan, format!("{}", loc.file()));
+                if self.global_loglevel >= log_level {
-                        let ln   = self.color_or_not(Cyan, format!("{}", loc.line()));
+                    // Yes, we log
+                    write!(stderr(), "[imag][{}]: {}", log_level, record.args()).ok();
+                }
+            });
+    }
+}
 
-                        writeln!(stderr(), "{}[{: <5}][{}][{: >5}]: {}", self.prefix, lvl, file, ln, args).ok();
+fn match_log_level_str(s: &str) -> Result<LogLevel> {
+    match s {
+        "trace" => Ok(LogLevel::Trace),
+        "debug" => Ok(LogLevel::Debug),
+        "info"  => Ok(LogLevel::Info),
+        "warn"  => Ok(LogLevel::Warn),
+        "error" => Ok(LogLevel::Error),
+        _       => return Err(EK::InvalidLogLevelSpec.into_error()),
+    }
+}
+
+fn aggregate_global_loglevel(matches: &ArgMatches, config: Option<&Configuration>)
+    -> Result<LogLevel>
+{
+    match config {
+        Some(cfg) => match cfg
+            .read("imag.logging.level")
+            .map_err_into(EK::ConfigReadError)
+            {
+                Ok(Some(&Value::String(ref s))) => match_log_level_str(s),
+                Ok(Some(_)) => Err(EK::ConfigTypeError.into_error()),
+                Ok(None)    => Err(EK::GlobalLogLevelConfigMissing.into_error()),
+                Err(e)      => Err(e)
+            },
+        None => {
+            if matches.is_present(Runtime::arg_debugging_name()) {
+                return Ok(LogLevel::Debug)
+            }
+
+            matches
+                .value_of(Runtime::arg_verbosity_name())
+                .map(match_log_level_str)
+                .unwrap_or(Ok(LogLevel::Info))
+        }
+    }
+}
+
+fn translate_destination(raw: &str) -> Result<LogDestination> {
+    use std::fs::OpenOptions;
+
+    match raw {
+        "-" => Ok(LogDestination::Stderr),
+        other => {
+            OpenOptions::new()
+                .append(true)
+                .create(true)
+                .open(other)
+                .map(LogDestination::File)
+                .map_err_into(EK::IOLogFileOpenError)
+        }
+    }
+}
+
+
+fn translate_destinations(raw: &Vec<Value>) -> Result<Vec<LogDestination>> {
+    raw.iter()
+        .fold(Ok(vec![]), |acc, val| {
+            acc.and_then(|mut v| {
+                let dest = match *val {
+                    Value::String(ref s) => try!(translate_destination(s)),
+                    _ => return Err(EK::ConfigTypeError.into_error()),
+                };
+                v.push(dest);
+                Ok(v)
+            })
+        })
+}
+
+fn aggregate_global_destinations(matches: &ArgMatches, config: Option<&Configuration>)
+    -> Result<Vec<LogDestination>>
+{
+
+    match config {
+        Some(cfg) => match cfg
+            .read("imag.logging.destinations")
+            .map_err_into(EK::ConfigReadError)
+            {
+                Ok(Some(&Value::Array(ref a))) => translate_destinations(a),
+                Ok(Some(_)) => Err(EK::ConfigTypeError.into_error()),
+                Ok(None)    => Err(EK::GlobalLogLevelConfigMissing.into_error()),
+                Err(e)      => Err(e)
+            },
+        None => {
+            if let Some(values) = matches.value_of(Runtime::arg_logdest_name()) {
+                // parse logdest specification from commandline
+
+                values.split(",")
+                    .fold(Ok(vec![]), move |acc, dest| {
+                        acc.and_then(|mut v| {
+                            v.push(try!(translate_destination(dest)));
+                            Ok(v)
+                        })
+                    })
             } else {
-                        writeln!(stderr(), "{}[{: <5}]: {}", self.prefix, lvl, args).ok();
+                Ok(vec![ LogDestination::default() ])
-                    }
-                },
-                LogLevel::Warn | LogLevel::Error => {
-                    let lvl  = self.style_or_not(Red.blink(), format!("{}", record.level()));
-                    let args = self.color_or_not(Red, format!("{}", record.args()));
-
-                    writeln!(stderr(), "{}[{: <5}]: {}", self.prefix, lvl, args).ok();
-                },
-                LogLevel::Info => {
-                    let lvl  = self.color_or_not(Yellow, format!("{}", record.level()));
-                    let args = self.color_or_not(Yellow, format!("{}", record.args()));
-
-                    writeln!(stderr(), "{}[{: <5}]: {}", self.prefix, lvl, args).ok();
-                },
-                _ => {
-                    writeln!(stderr(), "{}[{: <5}]: {}", self.prefix, record.level(), record.args()).ok();
-                },
             }
         }
     }
 }
 
+// fn aggregate_global_format_trace(matches: &ArgMatches, config: Option<&Configuration>)
+//     ->
+// {
+//     unimplemented!()
+// }
+//
+// fn aggregate_global_format_debug(matches: &ArgMatches, config: Option<&Configuration>)
+//     ->
+// {
+//     unimplemented!()
+// }
+//
+// fn aggregate_global_format_info(matches: &ArgMatches, config: Option<&Configuration>)
+//     ->
+// {
+//     unimplemented!()
+// }
+//
+// fn aggregate_global_format_warn(matches: &ArgMatches, config: Option<&Configuration>)
+//     ->
+// {
+//     unimplemented!()
+// }
+//
+// fn aggregate_global_format_error(matches: &ArgMatches, config: Option<&Configuration>)
+//     ->
+// {
+//     unimplemented!()
+// }
+
+fn aggregate_module_settings(matches: &ArgMatches, config: Option<&Configuration>)
+    -> Result<BTreeMap<ModuleName, ModuleSettings>>
+{
+    match config {
+        Some(cfg) => match cfg
+            .read("imag.logging.modules")
+            .map_err_into(EK::ConfigReadError)
+            {
+                Ok(Some(&Value::Table(ref t))) => {
+                    // translate the module settings from the table `t`
+                    let mut settings = BTreeMap::new();
+
+                    for (module_name, v) in t {
+                        let destinations = try!(match v.read("destinations") {
+                            Ok(Some(&Value::Array(ref a))) => translate_destinations(a),
+                            Ok(Some(_)) => Err(EK::ConfigTypeError.into_error()),
+                            Ok(None)    => Err(EK::GlobalLogLevelConfigMissing.into_error()),
+                            Err(e)      => Err(e).map_err_into(EK::TomlReadError),
+                        });
+
+                        let level = try!(match v.read("level") {
+                            Ok(Some(&Value::String(ref s))) => match_log_level_str(s),
+                            Ok(Some(_)) => Err(EK::ConfigTypeError.into_error()),
+                            Ok(None)    => Err(EK::GlobalLogLevelConfigMissing.into_error()),
+                            Err(e)      => Err(e).map_err_into(EK::TomlReadError),
+                        });
+
+                        let enabled = try!(match v.read("enabled") {
+                            Ok(Some(&Value::Boolean(b))) => Ok(b),
+                            Ok(Some(_)) => Err(EK::ConfigTypeError.into_error()),
+                            Ok(None)    => Err(EK::GlobalLogLevelConfigMissing.into_error()),
+                            Err(e)      => Err(e).map_err_into(EK::TomlReadError),
+                        });
+
+                        let module_settings = ModuleSettings {
+                            enabled: enabled,
+                            level: level,
+                            destinations: destinations,
+                        };
+
+                        // We don't care whether there was a value, we override it.
+                        let _ = settings.insert(module_name.to_owned(), module_settings);
+                    }
+
+                    Ok(settings)
+                },
+                Ok(Some(_)) => Err(EK::ConfigTypeError.into_error()),
+                Ok(None)    => Err(EK::GlobalLogLevelConfigMissing.into_error()),
+                Err(e)      => Err(e),
+            },
+        None => {
+            write!(stderr(), "No Configuration.").ok();
+            write!(stderr(), "cannot find module-settings for logging.").ok();
+            write!(stderr(), "Will use global defaults").ok();
+
+            Ok(BTreeMap::new())
+        }
+    }
+}
+

lib/core/libimagrt/src/runtime.rs

@@ -20,14 +20,12 @@
 use std::path::PathBuf;
 use std::process::Command;
 use std::env;
-use std::io::stderr;
+use std::process::exit;
-use std::io::Write;
 
 pub use clap::App;
 
 use clap::{Arg, ArgMatches};
 use log;
-use log::LogLevelFilter;
 
 use configuration::{Configuration, InternalConfiguration};
 use error::RuntimeError;
@@ -35,6 +33,7 @@ use error::RuntimeErrorKind;
 use error::MapErrInto;
 use logger::ImagLogger;
 
+use libimagerror::trace::*;
 use libimagstore::store::Store;
 use libimagstore::file_abstraction::InMemoryFileAbstraction;
 use spec::CliSpec;
@@ -112,16 +111,10 @@ impl<'a> Runtime<'a> {
     where C: Clone + CliSpec<'a> + InternalConfiguration
     {
         use std::io::stdout;
-
         use clap::Shell;
 
-        let is_debugging = matches.is_present(Runtime::arg_debugging_name());
-
         if cli_app.enable_logging() {
-            let is_verbose = matches.is_present(Runtime::arg_verbosity_name());
+            Runtime::init_logger(&matches, config.as_ref())
-            let colored    = !matches.is_present(Runtime::arg_no_color_output_name());
-
-            Runtime::init_logger(is_debugging, is_verbose, colored);
         }
 
         match matches.value_of(Runtime::arg_generate_compl()) {
@@ -151,9 +144,9 @@ impl<'a> Runtime<'a> {
             None        => None,
         };
 
-        if is_debugging {
+        if matches.is_present(Runtime::arg_debugging_name()) {
-            write!(stderr(), "Config: {:?}\n", config).ok();
+            debug!("Config: {:?}\n", config);
-            write!(stderr(), "Store-config: {:?}\n", store_config).ok();
+            debug!("Store-config: {:?}\n", store_config);
         }
 
         let store_result = if cli_app.use_inmemory_fs() {
@@ -200,9 +193,11 @@ impl<'a> Runtime<'a> {
             .arg(Arg::with_name(Runtime::arg_verbosity_name())
                 .short("v")
                 .long("verbose")
-                .help("Enables verbosity")
+                .help("Enables verbosity, can be used to set log level to one of 'trace', 'debug', 'info', 'warn' or 'error'")
                 .required(false)
-                .takes_value(false))
+                .takes_value(true)
+                .possible_values(&["trace", "debug", "info", "warn", "error"])
+                .value_name("LOGLEVEL"))
 
             .arg(Arg::with_name(Runtime::arg_debugging_name())
                 .long("debug")
@@ -254,6 +249,21 @@ impl<'a> Runtime<'a> {
                 .value_name("SHELL")
                 .possible_values(&["bash", "fish", "zsh"]))
 
+            .arg(Arg::with_name(Runtime::arg_logdest_name())
+                .long(Runtime::arg_logdest_name())
+                .help("Override the logging destinations from the configuration: values can be seperated by ',', a value of '-' marks the stderr output, everything else is expected to be a path")
+                .required(false)
+                .takes_value(true)
+                .value_name("LOGDESTS"))
+
+            .arg(Arg::with_name(Runtime::arg_override_module_logging_setting_name())
+                .long(Runtime::arg_override_module_logging_setting_name())
+                .help("Override a module logging setting for one module. Format: <modulename>=<setting>=<value>, whereas <setting> is either 'enabled', 'level' or 'destinations' - This commandline argument is CURRENTLY NOT IMPLEMENTED")
+                .multiple(true)
+                .required(false)
+                .takes_value(true)
+                .value_name("SPEC"))
+
     }
 
     /// Get the argument names of the Runtime which are available
@@ -338,26 +348,30 @@ impl<'a> Runtime<'a> {
         self
     }
 
+    /// Get the argument name for the logging destination
+    pub fn arg_logdest_name() -> &'static str {
+        "logging-destinations"
+    }
+
+    pub fn arg_override_module_logging_setting_name() -> &'static str {
+        "override-module-log-setting"
+    }
+
     /// Initialize the internal logger
-    fn init_logger(is_debugging: bool, is_verbose: bool, colored: bool) {
+    fn init_logger(matches: &ArgMatches, config: Option<&Configuration>) {
         use std::env::var as env_var;
         use env_logger;
 
         if env_var("IMAG_LOG_ENV").is_ok() {
             env_logger::init().unwrap();
         } else {
-            let lvl = if is_debugging {
-                LogLevelFilter::Debug
-            } else if is_verbose {
-                LogLevelFilter::Info
-            } else {
-                LogLevelFilter::Warn
-            };
-
             log::set_logger(|max_log_lvl| {
-                max_log_lvl.set(lvl);
+                let logger = ImagLogger::new(matches, config)
-                debug!("Init logger with {}", lvl);
+                    .map_err_trace()
-                Box::new(ImagLogger::new(lvl.to_log_level().unwrap()).with_color(colored))
+                    .unwrap_or_else(|_| exit(1));
+                max_log_lvl.set(logger.global_loglevel().to_log_level_filter());
+                debug!("Init logger with {}", logger.global_loglevel());
+                Box::new(logger)
             })
             .map_err(|e| panic!("Could not setup logger: {:?}", e))
             .ok();