Kanidmd is a bit noisy (#1765)

* the log_level config option works in kanidmd now
* anon event -> debug
* some more debuggy things
* removing some dupe events for the same thing

examples/insecure_server.toml

@@ -6,9 +6,14 @@ db_path = "/tmp/kanidm/kanidm.db"
 tls_chain = "/tmp/kanidm/chain.pem"
 tls_key = "/tmp/kanidm/key.pem"
 
-# log_level = "perfbasic"
-# log_level = "quiet"
-log_level = "verbose"
+#   The log level of the server. May be one of info, debug, trace
+#
+#   NOTE: this is overridden by environment variables at runtime
+#   Defaults to "info"
+#
+log_level = "info"
+# log_level = "debug"
+# log_level = "trace"
 
 domain = "localhost"
 origin = "https://localhost:8443"

examples/server.toml

@@ -27,10 +27,13 @@ db_path = "/var/lib/kanidm/kanidm.db"
 tls_chain = "/data/chain.pem"
 tls_key = "/data/key.pem"
 #
-#   The log level of the server. May be default, verbose, perfbasic, perffull
-#   Defaults to "default"
-# log_level = "default"
+#   The log level of the server. May be one of info, debug, trace
 #
+#   NOTE: this is overridden by environment variables
+#
+#   Defaults to "info"
+# log_level = "info"
+
 #   The DNS domain name of the server. This is used in a
 #   number of security-critical contexts
 #   such as webauthn, so it *must* match your DNS

examples/server_container.toml

@@ -46,10 +46,11 @@ db_path = "/data/kanidm.db"
 tls_chain = "/data/chain.pem"
 tls_key = "/data/key.pem"
 #
-#   The log level of the server. May be default, verbose,
-#   perfbasic, perffull
-#   Defaults to "default"
-# log_level = "default"
+#   The log level of the server. May be one of info, debug, trace
+#
+#   NOTE: this is overridden by environment variables at runtime
+#   Defaults to "info"
+# log_level = "info"
 #
 #   The DNS domain name of the server. This is used in a
 #   number of security-critical contexts

libs/sketching/src/lib.rs

@@ -38,6 +38,7 @@ pub enum EventTag {
     RequestInfo,
     RequestTrace,
     SecurityCritical,
+    SecurityDebug,
     SecurityInfo,
     SecurityAccess,
     SecurityError,
@@ -60,6 +61,7 @@ impl EventTag {
             EventTag::RequestInfo => "request.info",
             EventTag::RequestTrace => "request.trace",
             EventTag::SecurityCritical => "security.critical",
+            EventTag::SecurityDebug => "security.debug",
             EventTag::SecurityInfo => "security.info",
             EventTag::SecurityAccess => "security.access",
             EventTag::SecurityError => "security.error",
@@ -74,10 +76,10 @@ impl EventTag {
     pub fn emoji(self) -> &'static str {
         use EventTag::*;
         match self {
-            AdminDebug => "🐛",
+            AdminDebug | SecurityDebug => "🐛",
             AdminError | FilterError | RequestError | SecurityError => "🚨",
             AdminWarn | FilterWarn | RequestWarn => "⚠️",
-            AdminInfo | FilterInfo | RequestInfo | SecurityInfo => "  ",
+            AdminInfo | FilterInfo | RequestInfo | SecurityInfo => "ℹ️",
             RequestTrace | FilterTrace | PerfTrace => "📍",
             SecurityCritical => "🔐",
             SecurityAccess => "🔓",

libs/sketching/src/macros.rs

@@ -80,6 +80,11 @@ macro_rules! security_info {
     ($($arg:tt)*) => { tagged_event!(INFO, EventTag::SecurityInfo, $($arg)*) }
 }
 
+#[macro_export]
+macro_rules! security_debug {
+    ($($arg:tt)*) => { tagged_event!(DEBUG, EventTag::SecurityDebug, $($arg)*) }
+}
+
 #[macro_export]
 macro_rules! security_access {
     ($($arg:tt)*) => { tagged_event!(INFO, EventTag::SecurityAccess, $($arg)*) }

server/core/src/config.rs

@@ -13,6 +13,7 @@ use std::str::FromStr;
 
 use kanidm_proto::messages::ConsoleOutputMode;
 use serde::{Deserialize, Serialize};
+use sketching::tracing_subscriber::EnvFilter;
 
 #[derive(Serialize, Deserialize, Debug)]
 pub struct IntegrationTestConfig {
@@ -59,6 +60,7 @@ pub struct ServerConfig {
     pub origin: String,
     #[serde(default)]
     pub role: ServerRole,
+    pub log_level: Option<LogLevel>,
 }
 
 impl ServerConfig {
@@ -106,6 +108,50 @@ impl FromStr for ServerRole {
     }
 }
 
+#[derive(Clone, Serialize, Deserialize, Debug, Default)]
+pub enum LogLevel {
+    #[default]
+    #[serde(rename = "info")]
+    Info,
+    #[serde(rename = "debug")]
+    Debug,
+    #[serde(rename = "trace")]
+    Trace,
+}
+
+impl FromStr for LogLevel {
+    type Err = &'static str;
+
+    fn from_str(s: &str) -> Result<Self, Self::Err> {
+        match s {
+            "info" => Ok(LogLevel::Info),
+            "debug" => Ok(LogLevel::Debug),
+            "trace" => Ok(LogLevel::Trace),
+            _ => Err("Must be one of info, debug, trace"),
+        }
+    }
+}
+
+impl ToString for LogLevel {
+    fn to_string(&self) -> String {
+        match self {
+            LogLevel::Info => "info".to_string(),
+            LogLevel::Debug => "debug".to_string(),
+            LogLevel::Trace => "trace".to_string(),
+        }
+    }
+}
+
+impl Into<EnvFilter> for LogLevel {
+    fn into(self) -> EnvFilter {
+        match self {
+            LogLevel::Info => EnvFilter::new("info"),
+            LogLevel::Debug => EnvFilter::new("debug"),
+            LogLevel::Trace => EnvFilter::new("trace"),
+        }
+    }
+}
+
 #[derive(Serialize, Deserialize, Debug, Default)]
 pub struct Configuration {
     pub address: String,
@@ -125,6 +171,7 @@ pub struct Configuration {
     pub origin: String,
     pub role: ServerRole,
     pub output_mode: ConsoleOutputMode,
+    pub log_level: LogLevel,
 }
 
 impl fmt::Display for Configuration {
@@ -159,6 +206,7 @@ impl fmt::Display for Configuration {
                 )
             })
             .and_then(|_| write!(f, "console output format: {:?} ", self.output_mode))
+            .and_then(|_| write!(f, "log_level: {}", self.log_level.clone().to_string()))
     }
 }
 
@@ -188,6 +236,7 @@ impl Configuration {
             origin: "https://idm.example.com".to_string(),
             role: ServerRole::WriteReplica,
             output_mode: ConsoleOutputMode::default(),
+            log_level: Default::default(),
         }
     }
 
@@ -207,6 +256,11 @@ impl Configuration {
         }
     }
 
+    pub fn update_log_level(&mut self, level: &Option<LogLevel>) {
+        let level = level.clone();
+        self.log_level = level.unwrap_or_default();
+    }
+
     // Startup config action, used in kanidmd server etc
     pub fn update_config_for_server_mode(&mut self, sconfig: &ServerConfig) {
         #[cfg(debug_assertions)]
@@ -215,6 +269,7 @@ impl Configuration {
         self.update_bind(&sconfig.bindaddress);
         self.update_ldapbind(&sconfig.ldapbindaddress);
         self.update_online_backup(&sconfig.online_backup);
+        self.update_log_level(&sconfig.log_level);
     }
 
     pub fn update_trust_x_forward_for(&mut self, t: Option<bool>) {

server/daemon/src/main.rs

@@ -23,7 +23,7 @@ use std::path::PathBuf;
 use std::process::ExitCode;
 
 use clap::{Args, Parser, Subcommand};
-use kanidmd_core::config::{Configuration, ServerConfig};
+use kanidmd_core::config::{Configuration, LogLevel, ServerConfig};
 use kanidmd_core::{
     backup_server_core, cert_generate_core, create_server_core, dbscan_get_id2entry_core,
     dbscan_list_id2entry_core, dbscan_list_index_analysis_core, dbscan_list_index_core,
@@ -98,22 +98,68 @@ fn get_user_details_windows() {
 
 #[tokio::main(flavor = "multi_thread")]
 async fn main() -> ExitCode {
+    // Read CLI args, determine what the user has asked us to do.
+    let opt = KanidmdParser::parse();
+
+    let mut config_error: Vec<String> = Vec::new();
+    let mut config = Configuration::new();
+    // Check the permissions are OK.
+    let cfg_path = &opt.commands.commonopt().config_path; // TODO: this needs to be pulling from the default or something?
+    if format!("{}", cfg_path.display()) == "".to_string() {
+        config_error.push(format!("Refusing to run - config file path is empty"));
+    }
+    if !cfg_path.exists() {
+        config_error.push(format!(
+            "Refusing to run - config file {} does not exist",
+            cfg_path.to_str().unwrap_or("invalid file path")
+        ));
+    }
+
+    // Read our config
+    let sconfig: Option<ServerConfig> =
+        match ServerConfig::new(&(opt.commands.commonopt().config_path)) {
+            Ok(c) => Some(c),
+            Err(e) => {
+                format!("Config Parse failure {:?}", e);
+                None
+            }
+        };
+
+    // if they specified it in the environment then that overrides everything
+    let log_level = match EnvFilter::try_from_default_env() {
+        Ok(val) => val,
+        Err(_e) => {
+            // we couldn't get it from the env, so we'll try the config file!
+            match sconfig.as_ref() {
+                Some(val) => {
+                    let tmp = val.log_level.clone();
+                    tmp.unwrap_or_default()
+                }
+                None => LogLevel::Info,
+            }
+            .into()
+        }
+    };
     tracing_forest::worker_task()
         .set_global(true)
         .set_tag(sketching::event_tagger)
         // Fall back to stderr
         .map_sender(|sender| sender.or_stderr())
         .build_on(|subscriber| subscriber
-            .with(EnvFilter::try_from_default_env()
-                .or_else(|_| EnvFilter::try_new("info"))
-                .expect("Failed to init envfilter")
-            )
+            .with(log_level)
         )
         .on(async {
             // Get information on the windows username
             #[cfg(target_family = "windows")]
             get_user_details_windows();
 
+            if !config_error.is_empty() {
+                for e in config_error {
+                    error!("{}", e);
+                }
+                return ExitCode::FAILURE
+            }
+
             // Get info about who we are.
             #[cfg(target_family = "unix")]
             let (cuid, ceuid) = {
@@ -136,31 +182,17 @@ async fn main() -> ExitCode {
                 (cuid, ceuid)
             };
 
-            // Read cli args, determine if we should backup/restore
-            let opt = KanidmdParser::parse();
-
             // print the app version and bail
             if let KanidmdOpt::Version(_) = &opt.commands {
                 kanidm_proto::utils::show_version("kanidmd");
                 return ExitCode::SUCCESS
             };
 
-            let mut config = Configuration::new();
-            // Check the permissions are OK.
+            let sconfig = sconfig.expect("Somehow you got an empty ServerConfig after error checking?");
+
+
             #[cfg(target_family = "unix")]
             {
-                let cfg_path = &opt.commands.commonopt().config_path; // TODO: this needs to be pulling from the default or something?
-                if format!("{}", cfg_path.display()) == "".to_string() {
-                    error!("Refusing to run - config file path is empty");
-                    return ExitCode::FAILURE
-                }
-                if !cfg_path.exists() {
-                    error!(
-                        "Refusing to run - config file {} does not exist",
-                        cfg_path.to_str().unwrap_or("invalid file path")
-                    );
-                    return ExitCode::FAILURE
-                }
                 let cfg_meta = match metadata(cfg_path) {
                     Ok(m) => m,
                     Err(e) => {
@@ -191,14 +223,6 @@ async fn main() -> ExitCode {
                 }
             }
 
-            // Read our config
-            let sconfig = match ServerConfig::new(&(opt.commands.commonopt().config_path)) {
-                Ok(c) => c,
-                Err(e) => {
-                    error!("Config Parse failure {:?}", e);
-                    return ExitCode::FAILURE
-                }
-            };
             // Check the permissions of the files from the configuration.
 
             let db_path = PathBuf::from(sconfig.db_path.as_str());

server/lib/src/be/mod.rs

@@ -3355,7 +3355,7 @@ mod tests {
     }
 
     #[test]
-    fn test_be_mulitple_create() {
+    fn test_be_multiple_create() {
         sketching::test_init();
 
         // This is a demo idxmeta, purely for testing.

server/lib/src/idm/account.rs

@@ -524,7 +524,7 @@ impl Account {
         // of the token. This is already done for us as noted above.
 
         if uat.uuid == UUID_ANONYMOUS {
-            security_info!("Anonymous sessions do not have session records, session is valid.");
+            security_debug!("Anonymous sessions do not have session records, session is valid.");
             true
         } else {
             // Get the sessions.

server/lib/src/idm/authsession.rs

@@ -317,7 +317,7 @@ impl CredHandler {
         match cred {
             AuthCredential::Anonymous => {
                 // For anonymous, no claims will ever be issued.
-                security_info!("Handler::Anonymous -> Result::Success");
+                security_debug!("Handler::Anonymous -> Result::Success");
                 CredState::Success {
                     auth_type: AuthType::Anonymous,
                     cred_id,
@@ -1097,7 +1097,7 @@ impl AuthSession {
         async_tx: &Sender<DelayedAction>,
         cred_id: Uuid,
     ) -> Result<UserAuthToken, OperationError> {
-        security_info!("Successful cred handling");
+        security_debug!("Successful cred handling");
         match self.intent {
             AuthIntent::InitialAuth => {
                 let session_id = Uuid::new_v4();

server/lib/src/lib.rs

@@ -58,7 +58,8 @@ pub mod prelude {
     pub use sketching::{
         admin_debug, admin_error, admin_info, admin_warn, filter_error, filter_info, filter_trace,
         filter_warn, perf_trace, request_error, request_info, request_trace, request_warn,
-        security_access, security_critical, security_error, security_info, tagged_event, EventTag,
+        security_access, security_critical, security_debug, security_error, security_info,
+        tagged_event, EventTag,
     };
     pub use smartstring::alias::String as AttrString;
     pub use std::time::Duration;

server/lib/src/server/access/mod.rs

@@ -220,7 +220,7 @@ pub trait AccessControlsTransaction<'a> {
                     SearchResult::Allow(allowed_attrs) => {
                         // The allow set constrained.
                         let decision = requested_attrs.is_subset(&allowed_attrs);
-                        security_access!(
+                        security_debug!(
                             ?decision,
                             allowed = ?allowed_attrs,
                             requested = ?requested_attrs,

server/lib/src/server/access/search.rs

@@ -96,12 +96,12 @@ fn search_filter_entry<'a>(
         .filter_map(|(acs, f_res)| {
             // if it applies
             if entry.entry_match_no_index(f_res) {
-                security_access!(entry = ?entry.get_display_id(), acs = %acs.acp.name, "acs applied to entry");
+                security_debug!(entry = ?entry.get_display_id(), acs = %acs.acp.name, "acs applied to entry");
                 // add search_attrs to allowed.
                 Some(acs.attrs.iter().map(|s| s.as_str()))
             } else {
                 // should this be `security_access`?
-                trace!(entry = ?entry.get_uuid(), acs = %acs.acp.name, "entry DOES NOT match acs");
+                security_debug!(entry = ?entry.get_uuid(), acs = %acs.acp.name, "entry DOES NOT match acs");
                 None
             }
         })

server/lib/src/server/mod.rs

@@ -200,7 +200,7 @@ pub trait QueryServerTransaction<'a> {
             trace!(internal_filter = ?se.filter, "search");
         } else {
             security_info!(initiator = %se.ident, "search");
-            admin_info!(external_filter = ?se.filter, "search");
+            admin_debug!(external_filter = ?se.filter, "search");
         }
 
         // This is an important security step because it prevents us from