969 improve errors 1 (#987)

Cargo.lock

@@ -1082,6 +1082,7 @@ dependencies = [
  "profiles",
  "score",
  "serde",
+ "sketching",
  "tikv-jemallocator",
  "tokio",
  "toml",
@@ -2107,6 +2108,7 @@ dependencies = [
  "serde",
  "serde_cbor",
  "serde_json",
+ "sketching",
  "smartstring",
  "smolset",
  "sshkeys",
@@ -2117,8 +2119,6 @@ dependencies = [
  "toml",
  "touch",
  "tracing",
- "tracing-serde",
- "tracing-subscriber",
  "url",
  "urlencoding",
  "users",
@@ -2212,11 +2212,11 @@ dependencies = [
  "score",
  "serde",
  "serde_json",
+ "sketching",
  "tokio",
  "tokio-util",
  "toml",
  "tracing",
- "tracing-subscriber",
  "users",
 ]
 
@@ -3398,6 +3398,7 @@ dependencies = [
  "reqwest",
  "serde",
  "serde_json",
+ "sketching",
  "tide",
  "tide-compress",
  "tide-openssl",
@@ -3405,7 +3406,6 @@ dependencies = [
  "tokio-openssl",
  "tokio-util",
  "tracing",
- "tracing-subscriber",
  "url",
  "uuid 1.1.2",
  "webauthn-authenticator-rs",
@@ -3649,6 +3649,18 @@ dependencies = [
  "event-listener",
 ]
 
+[[package]]
+name = "sketching"
+version = "0.1.0"
+dependencies = [
+ "async-trait",
+ "num_enum",
+ "tide",
+ "tracing",
+ "tracing-forest",
+ "tracing-subscriber",
+]
+
 [[package]]
 name = "slab"
 version = "0.4.7"
@@ -4185,6 +4197,19 @@ dependencies = [
  "valuable",
 ]
 
+[[package]]
+name = "tracing-forest"
+version = "0.1.4"
+source = "git+https://github.com/Firstyear/tracing-forest.git?rev=18d242a4dde060c4946ade0a2c4d5be1df048aea#18d242a4dde060c4946ade0a2c4d5be1df048aea"
+dependencies = [
+ "smallvec",
+ "thiserror",
+ "tokio",
+ "tracing",
+ "tracing-subscriber",
+ "uuid 1.1.2",
+]
+
 [[package]]
 name = "tracing-log"
 version = "0.1.3"
@@ -4196,16 +4221,6 @@ dependencies = [
  "tracing-core",
 ]
 
-[[package]]
-name = "tracing-serde"
-version = "0.1.3"
-source = "registry+https://github.com/rust-lang/crates.io-index"
-checksum = "bc6b213177105856957181934e4920de57730fc69bf42c37ee5bb664d406d9e1"
-dependencies = [
- "serde",
- "tracing-core",
-]
-
 [[package]]
 name = "tracing-subscriber"
 version = "0.3.15"

Cargo.toml

@@ -17,6 +17,7 @@ members = [
     "kanidmd/score",
     "orca",
     "profiles",
+    "sketching",
 ]
 
 exclude = [

kanidm_unix_int/Cargo.toml

@@ -48,7 +48,7 @@ kanidm_proto = { path = "../kanidm_proto" }
 kanidm = { path = "../kanidmd/idm" }
 
 tracing = "^0.1.35"
-tracing-subscriber = "^0.3.14"
+sketching = { path = "../sketching" }
 
 toml = "^0.5.9"
 rpassword = "^7.0.0"

kanidm_unix_int/src/cache_clear.rs

@@ -30,7 +30,7 @@ async fn main() {
     if opt.debug {
         ::std::env::set_var("RUST_LOG", "kanidm=debug,kanidm_client=debug");
     }
-    tracing_subscriber::fmt::init();
+    sketching::tracing_subscriber::fmt::init();
 
     debug!("Starting cache invalidate tool ...");
 

kanidm_unix_int/src/cache_invalidate.rs

@@ -30,7 +30,7 @@ async fn main() {
     if opt.debug {
         ::std::env::set_var("RUST_LOG", "kanidm=debug,kanidm_client=debug");
     }
-    tracing_subscriber::fmt::init();
+    sketching::tracing_subscriber::fmt::init();
 
     debug!("Starting cache invalidate tool ...");
 

kanidm_unix_int/src/daemon.rs

@@ -10,9 +10,6 @@
 #![deny(clippy::needless_pass_by_value)]
 #![deny(clippy::trivially_copy_pass_by_ref)]
 
-#[macro_use]
-extern crate tracing;
-
 use users::{get_current_gid, get_current_uid, get_effective_gid, get_effective_uid};
 
 use std::fs::metadata;
@@ -25,10 +22,12 @@ use bytes::{BufMut, BytesMut};
 use futures::SinkExt;
 use futures::StreamExt;
 use libc::umask;
+use sketching::tracing_forest::{self, traits::*, util::*};
 use std::error::Error;
 use std::io;
 use std::sync::Arc;
 use std::time::Duration;
+
 use tokio::net::{UnixListener, UnixStream};
 use tokio::sync::mpsc::{channel, Receiver, Sender};
 use tokio::sync::oneshot;
@@ -380,8 +379,17 @@ async fn main() {
         std::process::exit(1);
     }
 
-    tracing_subscriber::fmt::init();
+    tracing_forest::worker_task()
-
+        .set_global(true)
+        // 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")
+            )
+        )
+        .on(async {
             debug!("Profile -> {}", env!("KANIDM_PROFILE_NAME"));
             debug!("CPU Flags -> {}", env!("KANIDM_CPU_FLAGS"));
 
@@ -678,4 +686,6 @@ async fn main() {
             info!("Server started ...");
 
             server.await;
+    })
+    .await;
 }

kanidm_unix_int/src/daemon_status.rs

@@ -31,7 +31,7 @@ fn main() {
     if opt.debug {
         ::std::env::set_var("RUST_LOG", "kanidm=debug,kanidm_client=debug");
     }
-    tracing_subscriber::fmt::init();
+    sketching::tracing_subscriber::fmt::init();
 
     trace!("Starting cache status tool ...");
 

kanidm_unix_int/src/db.rs

@@ -724,7 +724,7 @@ mod tests {
 
     #[tokio::test]
     async fn test_cache_db_account_basic() {
-        let _ = tracing_subscriber::fmt::try_init();
+        let _ = sketching::test_init();
         let db = Db::new("").expect("failed to create.");
         let dbtxn = db.write().await;
         assert!(dbtxn.migrate().is_ok());
@@ -808,7 +808,7 @@ mod tests {
 
     #[tokio::test]
     async fn test_cache_db_group_basic() {
-        let _ = tracing_subscriber::fmt::try_init();
+        let _ = sketching::test_init();
         let db = Db::new("").expect("failed to create.");
         let dbtxn = db.write().await;
         assert!(dbtxn.migrate().is_ok());
@@ -883,7 +883,7 @@ mod tests {
 
     #[tokio::test]
     async fn test_cache_db_account_group_update() {
-        let _ = tracing_subscriber::fmt::try_init();
+        let _ = sketching::test_init();
         let db = Db::new("").expect("failed to create.");
         let dbtxn = db.write().await;
         assert!(dbtxn.migrate().is_ok());
@@ -951,7 +951,7 @@ mod tests {
 
     #[tokio::test]
     async fn test_cache_db_account_password() {
-        let _ = tracing_subscriber::fmt::try_init();
+        let _ = sketching::test_init();
         let db = Db::new("").expect("failed to create.");
         let dbtxn = db.write().await;
         assert!(dbtxn.migrate().is_ok());
@@ -1000,7 +1000,7 @@ mod tests {
 
     #[tokio::test]
     async fn test_cache_db_group_rename_duplicate() {
-        let _ = tracing_subscriber::fmt::try_init();
+        let _ = sketching::test_init();
         let db = Db::new("").expect("failed to create.");
         let dbtxn = db.write().await;
         assert!(dbtxn.migrate().is_ok());
@@ -1055,7 +1055,7 @@ mod tests {
 
     #[tokio::test]
     async fn test_cache_db_account_rename_duplicate() {
-        let _ = tracing_subscriber::fmt::try_init();
+        let _ = sketching::test_init();
         let db = Db::new("").expect("failed to create.");
         let dbtxn = db.write().await;
         assert!(dbtxn.migrate().is_ok());

kanidm_unix_int/src/ssh_authorizedkeys.rs

@@ -31,7 +31,7 @@ async fn main() {
     if opt.debug {
         ::std::env::set_var("RUST_LOG", "kanidm=debug,kanidm_client=debug");
     }
-    tracing_subscriber::fmt::init();
+    sketching::tracing_subscriber::fmt::init();
 
     debug!("Starting authorized keys tool ...");
 

kanidm_unix_int/src/tasks_daemon.rs

@@ -10,9 +10,6 @@
 #![deny(clippy::needless_pass_by_value)]
 #![deny(clippy::trivially_copy_pass_by_ref)]
 
-#[macro_use]
-extern crate tracing;
-
 use users::{get_effective_gid, get_effective_uid};
 
 use std::os::unix::fs::symlink;
@@ -23,6 +20,7 @@ use std::ffi::CString;
 use bytes::{BufMut, BytesMut};
 use futures::SinkExt;
 use futures::StreamExt;
+use sketching::tracing_forest::{self, traits::*, util::*};
 use std::fs;
 use std::io;
 use std::path::Path;
@@ -213,8 +211,18 @@ async fn main() {
         std::process::exit(1);
     }
 
-    tracing_subscriber::fmt::init();
+    tracing_forest::worker_task()
-
+        .set_global(true)
+        // 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"),
+            )
+        })
+        .on(async {
             let unixd_path = Path::new(DEFAULT_CONFIG_PATH);
             let unixd_path_str = match unixd_path.to_str() {
                 Some(cps) => cps,
@@ -258,4 +266,6 @@ async fn main() {
             };
 
             server.await;
+        })
+        .await;
 }

kanidm_unix_int/src/test_auth.rs

@@ -25,7 +25,7 @@ async fn main() {
     if opt.debug {
         ::std::env::set_var("RUST_LOG", "kanidm=debug,kanidm_client=debug");
     }
-    tracing_subscriber::fmt::init();
+    sketching::tracing_subscriber::fmt::init();
 
     debug!("Starting pam auth tester tool ...");
 

kanidm_unix_int/tests/cache_layer_test.rs

@@ -7,7 +7,6 @@ use kanidm::audit::LogLevel;
 use kanidm::config::{Configuration, IntegrationTestConfig, ServerRole};
 use score::create_server_core;
 
-use kanidm::tracing_tree;
 use kanidm_unix_common::cache::{CacheLayer, Id};
 use kanidm_unix_common::constants::{
     DEFAULT_GID_ATTR_MAP, DEFAULT_HOME_ALIAS, DEFAULT_HOME_ATTR, DEFAULT_HOME_PREFIX,
@@ -46,7 +45,7 @@ where
 }
 
 async fn setup_test(fix_fn: Fixture) -> (CacheLayer, KanidmClient) {
-    let _ = tracing_tree::test_init();
+    let _ = sketching::test_init();
 
     let mut counter = 0;
     let port = loop {

kanidmd/daemon/Cargo.toml

@@ -20,6 +20,8 @@ path = "src/main.rs"
 kanidm = { path = "../idm" }
 kanidm_proto = { path = "../../kanidm_proto" }
 score = { path = "../score" }
+sketching = { path = "../../sketching" }
+
 clap = { version = "^3.2", features = ["derive", "env"] }
 serde = { version = "^1.0.142", features = ["derive"] }
 tokio = { version = "^1.20.0", features = ["rt-multi-thread", "macros", "signal"] }

kanidmd/daemon/run_insecure_dev_server.sh

@@ -25,4 +25,4 @@ if [ -n "${1}" ]; then
 fi
 
 #shellcheck disable=SC2086
-RUST_LOG=debug cargo run --bin kanidmd -- ${COMMAND} -c "${CONFIG_FILE}"
+cargo run --bin kanidmd -- ${COMMAND} -c "${CONFIG_FILE}"

kanidmd/daemon/src/main.rs

@@ -30,9 +30,10 @@ use std::path::Path;
 use std::path::PathBuf;
 use std::str::FromStr;
 
+use sketching::tracing_forest::{self, traits::*, util::*};
+
 use kanidm::audit::LogLevel;
 use kanidm::config::{Configuration, OnlineBackup, ServerRole};
-use kanidm::tracing_tree;
 #[cfg(not(target_family = "windows"))]
 use kanidm::utils::file_permissions_readonly;
 use score::{
@@ -167,10 +168,20 @@ fn get_user_details_windows() {
     );
 }
 
-#[tokio::main]
+#[tokio::main(flavor = "multi_thread")]
 async fn main() {
-    tracing_tree::main_init();
+    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")
+            )
+        )
+        .on(async {
             // Get information on the windows username
             #[cfg(target_family = "windows")]
             get_user_details_windows();
@@ -253,7 +264,7 @@ async fn main() {
                 // TODO: windows support for DB folder permissions checks
                 #[cfg(target_family = "unix")]
                 {
-            if !file_permissions_readonly(&i_meta) {
+                    if file_permissions_readonly(&i_meta) {
                         eprintln!("WARNING: DB folder permissions on {} indicate it may not be RW. This could cause the server start up to fail!", db_par_path_buf.to_str().unwrap_or("invalid file path"));
                     }
                     if i_meta.mode() & 0o007 != 0 {
@@ -437,4 +448,6 @@ async fn main() {
                     vacuum_server_core(&config);
                 }
             }
+        })
+        .await;
 }

kanidmd/idm/Cargo.toml

@@ -54,9 +54,10 @@ tokio = { version = "^1.20.0", features = ["net", "sync", "time"] }
 tokio-util = { version = "^0.7.3", features = ["codec"] }
 toml = "^0.5.9"
 touch = "^0.0.1"
-tracing = { version = "^0.1.35", features = ["attributes", "max_level_trace", "release_max_level_debug"] }
+
-tracing-serde = "^0.1.3"
+sketching = { path = "../../sketching" }
-tracing-subscriber = { version = "^0.3.14", features = ["env-filter"] }
+tracing = { version = "^0.1.35", features = ["attributes"] }
+
 url = { version = "^2.2.2", features = ["serde"] }
 urlencoding = "2.1.0"
 uuid = { version = "^1.1.2", features = ["serde", "v4" ] }

kanidmd/idm/src/access.rs

@@ -2529,7 +2529,7 @@ mod tests {
 
     #[test]
     fn test_access_effective_permission_check_1() {
-        let _ = crate::tracing_tree::test_init();
+        let _ = sketching::test_init();
 
         let admin = unsafe { Identity::from_impersonate_entry_ser(JSON_ADMIN_V1) };
 
@@ -2567,7 +2567,7 @@ mod tests {
 
     #[test]
     fn test_access_effective_permission_check_2() {
-        let _ = crate::tracing_tree::test_init();
+        let _ = sketching::test_init();
 
         let admin = unsafe { Identity::from_impersonate_entry_ser(JSON_ADMIN_V1) };
 

kanidmd/idm/src/be/idl_arc_sqlite.rs

@@ -707,7 +707,7 @@ impl<'a> IdlArcSqliteWriteTransaction<'a> {
         self.idl_cache.iter_mut_dirty().for_each(|(k, maybe_idl)| {
             if let Some(idl) = maybe_idl {
                 if idl.maybe_compress() {
-                    filter_info!(?k, "Compressed idl");
+                    filter_trace!(?k, "Compressed idl");
                 }
             }
         })

kanidmd/idm/src/be/idl_sqlite.rs

@@ -1412,7 +1412,7 @@ mod tests {
 
     #[test]
     fn test_idl_sqlite_verify() {
-        let _ = crate::tracing_tree::test_init();
+        let _ = sketching::test_init();
         let cfg = BackendConfig::new_test();
         let be = IdlSqlite::new(&cfg, false).unwrap();
         let be_w = be.write();

kanidmd/idm/src/be/mod.rs

@@ -1792,7 +1792,7 @@ mod tests {
 
     macro_rules! run_test {
         ($test_fn:expr) => {{
-            let _ = crate::tracing_tree::test_init();
+            let _ = sketching::test_init();
 
             // This is a demo idxmeta, purely for testing.
             let idxmeta = vec![

kanidmd/idm/src/filter.rs

@@ -1375,7 +1375,7 @@ mod tests {
 
     #[test]
     fn test_filter_optimise() {
-        let _ = tracing_subscriber::fmt().try_init();
+        let _ = sketching::test_init();
         // Given sets of "optimisable" filters, optimise them.
         filter_optimise_assert!(
             f_and(vec![f_and(vec![f_eq(

kanidmd/idm/src/idm/authsession.rs

@@ -7,7 +7,6 @@ use crate::idm::account::Account;
 use crate::idm::delayed::BackupCodeRemoval;
 use crate::idm::AuthState;
 use crate::prelude::*;
-use crate::tracing_tree;
 use hashbrown::HashSet;
 use kanidm_proto::v1::OperationError;
 use kanidm_proto::v1::{AuthAllowed, AuthCredential, AuthMech, AuthType};
@@ -745,13 +744,16 @@ impl AuthSession {
                         // Can't `unwrap` the uuid until full integration, because some unit tests
                         // call functions that call this indirectly without opening a span first,
                         // and this returns `None` when not in a span (and panics if the tree isn't initialized).
-                        let tracing_id = tracing_tree::operation_id().unwrap_or_else(|| {
+                        let session_id = Uuid::new_v4();
-                            admin_warn!("Recoverable - Invalid Tracing Operation ID State");
+                        security_info!(
-                            Uuid::new_v4()
+                            "Starting session {} for {} {}",
-                        });
+                            session_id,
+                            self.account.spn,
+                            self.account.uuid
+                        );
                         let uat = self
                             .account
-                            .to_userauthtoken(tracing_id, *time, auth_type)
+                            .to_userauthtoken(session_id, *time, auth_type)
                             .ok_or(OperationError::InvalidState)?;
 
                         let jwt = Jws { inner: uat };
@@ -840,7 +842,6 @@ mod tests {
     use crate::idm::delayed::DelayedAction;
     use crate::idm::AuthState;
     use crate::prelude::*;
-    use crate::tracing_tree;
     use hashbrown::HashSet;
     pub use std::collections::BTreeSet as Set;
 
@@ -874,7 +875,8 @@ mod tests {
 
     #[test]
     fn test_idm_authsession_anonymous_auth_mech() {
-        let _ = tracing_tree::test_init();
+        let _ = sketching::test_init();
+
         let webauthn = create_webauthn();
 
         let anon_account = entry_str_to_account!(JSON_ANONYMOUS_V1);
@@ -935,7 +937,7 @@ mod tests {
 
     #[test]
     fn test_idm_authsession_simple_password_mech() {
-        let _ = tracing_tree::test_init();
+        let _ = sketching::test_init();
         let webauthn = create_webauthn();
         // create the ent
         let mut account = entry_str_to_account!(JSON_ADMIN_V1);
@@ -988,7 +990,7 @@ mod tests {
 
     #[test]
     fn test_idm_authsession_simple_password_badlist() {
-        let _ = tracing_tree::test_init();
+        let _ = sketching::test_init();
         let jws_signer = create_jwt_signer();
         let webauthn = create_webauthn();
         // create the ent
@@ -1076,7 +1078,7 @@ mod tests {
 
     #[test]
     fn test_idm_authsession_totp_password_mech() {
-        let _ = tracing_tree::test_init();
+        let _ = sketching::test_init();
         let webauthn = create_webauthn();
         let jws_signer = create_jwt_signer();
         // create the ent
@@ -1231,7 +1233,7 @@ mod tests {
 
     #[test]
     fn test_idm_authsession_password_mfa_badlist() {
-        let _ = tracing_tree::test_init();
+        let _ = sketching::test_init();
         let webauthn = create_webauthn();
         let jws_signer = create_jwt_signer();
         // create the ent
@@ -1391,7 +1393,7 @@ mod tests {
 
     #[test]
     fn test_idm_authsession_webauthn_only_mech() {
-        let _ = tracing_tree::test_init();
+        let _ = sketching::test_init();
         let (async_tx, mut async_rx) = unbounded();
         let ts = duration_from_epoch_now();
         // create the ent
@@ -1522,7 +1524,7 @@ mod tests {
 
     #[test]
     fn test_idm_authsession_webauthn_password_mech() {
-        let _ = tracing_tree::test_init();
+        let _ = sketching::test_init();
         let (async_tx, mut async_rx) = unbounded();
         let ts = duration_from_epoch_now();
         // create the ent
@@ -1692,7 +1694,7 @@ mod tests {
 
     #[test]
     fn test_idm_authsession_webauthn_password_totp_mech() {
-        let _ = tracing_tree::test_init();
+        let _ = sketching::test_init();
         let (async_tx, mut async_rx) = unbounded();
         let ts = duration_from_epoch_now();
         // create the ent
@@ -1929,7 +1931,7 @@ mod tests {
 
     #[test]
     fn test_idm_authsession_backup_code_mech() {
-        let _ = tracing_tree::test_init();
+        let _ = sketching::test_init();
         let jws_signer = create_jwt_signer();
         let webauthn = create_webauthn();
         // create the ent

kanidmd/idm/src/idm/server.rs

@@ -24,7 +24,6 @@ use crate::idm::unix::{UnixGroup, UnixUserAccount};
 use crate::idm::AuthState;
 use crate::ldap::LdapBoundToken;
 use crate::prelude::*;
-use crate::tracing_tree;
 use crate::utils::{
     backup_code_from_random, password_from_random, readable_password_from_random,
     uuid_from_duration, Sid,
@@ -954,16 +953,19 @@ impl<'a> IdmServerAuthTransaction<'a> {
                 return Ok(None);
             }
 
-            let tracing_id = tracing_tree::operation_id().unwrap_or_else(|| {
+            let session_id = Uuid::new_v4();
-                admin_warn!("Recoverable - Invalid Tracing Operation ID State");
+            security_info!(
-                Uuid::new_v4()
+                "Starting session {} for {} {}",
-            });
+                session_id,
+                account.spn,
+                account.uuid
+            );
 
             // Account must be anon, so we can gen the uat.
             Ok(Some(LdapBoundToken {
                 uuid: UUID_ANONYMOUS,
                 effective_uat: account
-                    .to_userauthtoken(tracing_id, ct, AuthType::Anonymous)
+                    .to_userauthtoken(session_id, ct, AuthType::Anonymous)
                     .ok_or(OperationError::InvalidState)
                     .map_err(|e| {
                         admin_error!("Unable to generate effective_uat -> {:?}", e);
@@ -1037,16 +1039,19 @@ impl<'a> IdmServerAuthTransaction<'a> {
                     let anon_account =
                         Account::try_from_entry_ro(anon_entry.as_ref(), &mut self.qs_read)?;
 
-                    let tracing_id = tracing_tree::operation_id().unwrap_or_else(|| {
+                    let session_id = Uuid::new_v4();
-                        admin_warn!("Recoverable - Invalid Tracing Operation ID State");
+                    security_info!(
-                        Uuid::new_v4()
+                        "Starting session {} for {} {}",
-                    });
+                        session_id,
+                        account.spn,
+                        account.uuid
+                    );
 
                     Ok(Some(LdapBoundToken {
                         spn: account.spn,
                         uuid: account.uuid,
                         effective_uat: anon_account
-                            .to_userauthtoken(tracing_id, ct, AuthType::UnixPassword)
+                            .to_userauthtoken(session_id, ct, AuthType::UnixPassword)
                             .ok_or(OperationError::InvalidState)
                             .map_err(|e| {
                                 admin_error!("Unable to generate effective_uat -> {:?}", e);

kanidmd/idm/src/lib.rs

@@ -25,6 +25,9 @@ extern crate tracing;
 #[macro_use]
 extern crate lazy_static;
 
+// #[macro_use]
+// extern crate sketching;
+
 // This has to be before 'be' so the import order works
 #[macro_use]
 pub mod macros;
@@ -66,9 +69,6 @@ pub mod prelude {
     pub use url::Url;
     pub use uuid::Uuid;
 
-    pub use crate::tagged_event;
-    pub use crate::tracing_tree::EventTag;
-
     pub use crate::constants::*;
     pub use crate::filter::{
         f_and, f_andnot, f_eq, f_id, f_inc, f_lt, f_or, f_pres, f_self, f_spn_name, f_sub,
@@ -92,11 +92,10 @@ pub mod prelude {
         ValueSetSecret, ValueSetSpn, ValueSetSyntax, ValueSetT, ValueSetUint32, ValueSetUtf8,
         ValueSetUuid,
     };
-    pub use crate::{
+    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, spanned,
+        security_access, security_critical, security_error, security_info, spanned, tagged_event,
+        EventTag,
     };
 }
-
-pub mod tracing_tree;

kanidmd/idm/src/macros.rs

@@ -1,16 +1,6 @@
 macro_rules! setup_test {
     () => {{
-        /*
+        let _ = sketching::test_init();
-        use env_logger;
-        ::std::env::set_var("RUST_LOG", "actix_web=debug,kanidm=debug");
-        let _ = env_logger::builder()
-            .format_timestamp(None)
-            .format_level(false)
-            .is_test(true)
-            .try_init();
-        */
-
-        let _ = crate::tracing_tree::test_init();
 
         // Create an in memory BE
         let schema_outer = Schema::new().expect("Failed to init schema");
@@ -32,16 +22,7 @@ macro_rules! setup_test {
         use crate::utils::duration_from_epoch_now;
         use async_std::task;
 
-        /*
+        let _ = sketching::test_init();
-        use env_logger;
-        ::std::env::set_var("RUST_LOG", "actix_web=debug,kanidm=debug");
-        let _ = env_logger::builder()
-            .format_timestamp(None)
-            .format_level(false)
-            .is_test(true)
-            .try_init();
-        */
-        let _ = crate::tracing_tree::test_init();
 
         // Create an in memory BE
         let schema_outer = Schema::new().expect("Failed to init schema");
@@ -75,16 +56,7 @@ macro_rules! run_test_no_init {
         use crate::schema::Schema;
         use crate::utils::duration_from_epoch_now;
 
-        let _ = crate::tracing_tree::test_init();
+        let _ = sketching::test_init();
-        /*
-        use env_logger;
-        ::std::env::set_var("RUST_LOG", "actix_web=debug,kanidm=debug");
-        let _ = env_logger::builder()
-            .format_timestamp(None)
-            .format_level(false)
-            .is_test(true)
-            .try_init();
-        */
 
         let schema_outer = Schema::new().expect("Failed to init schema");
         let idxmeta = {
@@ -117,16 +89,7 @@ macro_rules! run_test {
         #[allow(unused_imports)]
         use crate::utils::duration_from_epoch_now;
 
-        let _ = crate::tracing_tree::test_init();
+        let _ = sketching::test_init();
-        /*
-        use env_logger;
-        ::std::env::set_var("RUST_LOG", "actix_web=debug,kanidm=debug");
-        let _ = env_logger::builder()
-            .format_timestamp(None)
-            .format_level(false)
-            .is_test(true)
-            .try_init();
-        */
 
         let test_server = setup_test!();
 
@@ -198,7 +161,7 @@ macro_rules! run_idm_test_inner {
 #[cfg(test)]
 macro_rules! run_idm_test {
     ($test_fn:expr) => {{
-        let _ = crate::tracing_tree::test_init();
+        let _ = sketching::test_init();
         run_idm_test_inner!($test_fn);
     }};
 }
@@ -211,7 +174,7 @@ where
         &crate::idm::server::IdmServerDelayed,
     ),
 {
-    let _ = crate::tracing_tree::test_level(tracing::Level::ERROR);
+    let _ = sketching::test_init();
     let _ = run_idm_test_inner!(test_fn);
 }
 
@@ -382,7 +345,7 @@ macro_rules! run_delete_test {
 #[cfg(test)]
 macro_rules! run_entrychangelog_test {
     ($test_fn:expr) => {{
-        let _ = crate::tracing_tree::test_init();
+        let _ = sketching::test_init();
         let schema_outer = Schema::new().expect("Failed to init schema");
 
         let schema_txn = schema_outer.read();

kanidmd/idm/src/schema.rs

@@ -1847,7 +1847,7 @@ mod tests {
 
     #[test]
     fn test_schema_entries() {
-        let _ = crate::tracing_tree::test_init();
+        let _ = sketching::test_init();
         // Given an entry, assert it's schema is valid
         // We do
         let schema_outer = Schema::new().expect("failed to create schema");

kanidmd/idm/src/server.rs

@@ -1892,8 +1892,9 @@ impl<'a> QueryServerWriteTransaction<'a> {
 
             let res: Result<Vec<Entry<EntrySealed, EntryCommitted>>, OperationError> = candidates
                 .into_iter()
-                .map(|e| {
+                .map(|entry| {
-                    e.validate(&self.schema)
+                    entry
+                        .validate(&self.schema)
                         .map_err(|e| {
                             admin_error!(
                                 "Schema Violation in validation of modify_pre_apply {:?}",
@@ -1901,7 +1902,7 @@ impl<'a> QueryServerWriteTransaction<'a> {
                             );
                             OperationError::SchemaViolation(e)
                         })
-                        .map(|e| e.seal(&self.schema))
+                        .map(|entry| entry.seal(&self.schema))
                 })
                 .collect();
 

kanidmd/idm/src/tracing_tree/formatter.rs

@@ -1,325 +0,0 @@
-use super::subscriber::{TreeEvent, TreeProcessed, TreeSpanProcessed};
-use super::EventTag;
-use serde::ser::{Serialize, SerializeMap, SerializeStruct};
-use std::fmt::{self, Write as _};
-use std::io::{self, Write as _};
-use tracing_serde::AsSerde;
-use tracing_subscriber::registry::ScopeFromRoot;
-use tracing_subscriber::Registry;
-
-#[derive(Clone, Copy, Debug)]
-pub enum LogFmt {
-    Json,
-    Pretty,
-}
-
-const EVENT_UUID: &str = "00000000-0000-0000-0000-000000000000";
-
-impl LogFmt {
-    pub(crate) fn format(self, processed_logs: &TreeProcessed) -> Vec<u8> {
-        match self {
-            LogFmt::Json => format_json(processed_logs),
-            LogFmt::Pretty => format_pretty(processed_logs),
-        }
-    }
-}
-
-fn format_json(processed_logs: &TreeProcessed) -> Vec<u8> {
-    fn fmt_rec<'a>(
-        tree: &TreeProcessed,
-        spans: &'a mut Vec<&'static str>,
-        uuid: Option<&'a str>,
-        mut writer: &mut Vec<u8>,
-    ) -> io::Result<()> {
-        match tree {
-            TreeProcessed::Event(event) => {
-                struct SerializeFields<'a> {
-                    values: &'a Vec<(&'static str, String)>,
-                }
-
-                impl<'a> Serialize for SerializeFields<'a> {
-                    fn serialize<S>(&self, serializer: S) -> Result<S::Ok, S::Error>
-                    where
-                        S: serde::Serializer,
-                    {
-                        let mut model = serializer.serialize_map(Some(self.values.len()))?;
-                        for (key, value) in self.values.iter() {
-                            model.serialize_entry(key, value)?;
-                        }
-                        model.end()
-                    }
-                }
-
-                struct SerializeEvent<'a> {
-                    event: &'a TreeEvent,
-                    uuid: &'a str,
-                    spans: &'a mut Vec<&'static str>,
-                }
-
-                impl<'a> Serialize for SerializeEvent<'a> {
-                    fn serialize<S>(&self, serializer: S) -> Result<S::Ok, S::Error>
-                    where
-                        S: serde::Serializer,
-                    {
-                        let mut model = serializer.serialize_struct("event", 8)?;
-                        model.serialize_field("uuid", self.uuid)?;
-                        model.serialize_field("timestamp", &self.event.timestamp.to_rfc3339())?;
-                        model.serialize_field("level", &self.event.level.as_serde())?;
-                        model.serialize_field("message", &self.event.message)?;
-                        model.serialize_field("log-type", "event")?;
-                        model.serialize_field("tag", &self.event.tag.map(EventTag::pretty))?;
-                        model.serialize_field(
-                            "fields",
-                            &SerializeFields {
-                                values: &self.event.values,
-                            },
-                        )?;
-                        model.serialize_field("spans", self.spans)?;
-                        model.end()
-                    }
-                }
-
-                let serialize_event = SerializeEvent {
-                    event,
-                    uuid: uuid.unwrap_or(EVENT_UUID),
-                    spans,
-                };
-
-                serde_json::to_writer(&mut writer, &serialize_event).map_err(io::Error::from)?;
-                writeln!(writer)
-            }
-            TreeProcessed::Span(span) => {
-                struct SerializeSpan<'a> {
-                    span: &'a TreeSpanProcessed,
-                    uuid: &'a str,
-                }
-
-                impl<'a> Serialize for SerializeSpan<'a> {
-                    fn serialize<S>(&self, serializer: S) -> Result<S::Ok, S::Error>
-                    where
-                        S: serde::Serializer,
-                    {
-                        let mut model = serializer.serialize_struct("event", 7)?;
-                        model.serialize_field("uuid", self.uuid)?;
-                        model.serialize_field("timestamp", &self.span.timestamp.to_rfc3339())?;
-                        model.serialize_field("level", "TRACE")?;
-                        model.serialize_field("message", &self.span.name)?;
-                        model.serialize_field("log-type", "span")?;
-                        model.serialize_field("nanos-nested", &self.span.nested_duration)?;
-                        model.serialize_field("nanos-total", &self.span.total_duration)?;
-                        model.end()
-                    }
-                }
-
-                #[allow(clippy::expect_used)]
-                let uuid = span
-                    .uuid
-                    .as_deref()
-                    .or(uuid)
-                    .expect("Span has no associated UUID, this is a bug");
-
-                let serialize_span = SerializeSpan { span, uuid };
-
-                serde_json::to_writer(&mut writer, &serialize_span).map_err(io::Error::from)?;
-                writeln!(writer)?;
-
-                // format stuff in child spans
-                spans.push(span.name);
-                for logs in span.processed_buf.iter() {
-                    fmt_rec(logs, spans, Some(uuid), writer)?;
-                }
-                spans.pop();
-                Ok(())
-            }
-        }
-    }
-
-    let mut writer = vec![];
-    let mut spans = vec![];
-    #[allow(clippy::expect_used)]
-    fmt_rec(processed_logs, &mut spans, None, &mut writer).expect("Write failed");
-    writer
-}
-
-fn format_pretty(processed_logs: &TreeProcessed) -> Vec<u8> {
-    #[derive(Clone, Copy)]
-    enum Fill {
-        Void,
-        Line,
-        Fork,
-        Turn,
-    }
-
-    impl fmt::Display for Fill {
-        fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
-            use Fill::*;
-            f.write_str(match self {
-                Void => "   ",
-                Line => "│  ",
-                Fork => "┝━ ",
-                Turn => "┕━ ",
-            })
-        }
-    }
-
-    fn fmt_rec(
-        tree: &TreeProcessed,
-        indent: &mut Vec<Fill>,
-        uuid: Option<&str>,
-        root_duration: Option<f64>,
-        writer: &mut Vec<u8>,
-    ) -> io::Result<()> {
-        use Fill::*;
-        match tree {
-            TreeProcessed::Event(event) => {
-                let uuid = uuid.unwrap_or(EVENT_UUID);
-
-                let timestamp_fmt = event.timestamp.to_rfc3339();
-
-                write!(writer, "{} {} {:<8} ", uuid, timestamp_fmt, event.level)?;
-
-                for fill in indent.iter() {
-                    write!(writer, "{}", fill)?;
-                }
-
-                write!(
-                    writer,
-                    "{} [{}]: {}",
-                    event.emoji(),
-                    event.tag(),
-                    event.message
-                )?;
-
-                for (field, value) in event.values.iter() {
-                    write!(writer, " | {}: {}", field, value)?;
-                }
-
-                writeln!(writer)
-            }
-            TreeProcessed::Span(span) => {
-                #[allow(clippy::expect_used)]
-                let uuid = span
-                    .uuid
-                    .as_deref()
-                    .or(uuid)
-                    .expect("Span has no associated UUID, this is a bug");
-
-                let timestamp_fmt = span.timestamp.to_rfc3339();
-
-                let total_duration = span.total_duration as f64;
-
-                let root_duration = root_duration.unwrap_or(total_duration);
-
-                let total_load = 100.0 * total_duration / root_duration;
-
-                struct DurationDisplay(f64);
-
-                // This is straight up stolen from chrono
-                impl fmt::Display for DurationDisplay {
-                    fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
-                        let mut t = self.0;
-                        for unit in ["ns", "µs", "ms", "s"].iter() {
-                            if t < 10.0 {
-                                return write!(f, "{:.2}{}", t, unit);
-                            } else if t < 100.0 {
-                                return write!(f, "{:.1}{}", t, unit);
-                            } else if t < 1000.0 {
-                                return write!(f, "{:.0}{}", t, unit);
-                            }
-                            t /= 1000.0;
-                        }
-                        write!(f, "{:.0}s", t * 1000.0)
-                    }
-                }
-
-                write!(writer, "{} {} TRACE    ", uuid, timestamp_fmt)?;
-
-                for fill in indent.iter() {
-                    write!(writer, "{}", fill)?;
-                }
-
-                write!(
-                    writer,
-                    "{} [ {} | ",
-                    span.name,
-                    DurationDisplay(total_duration)
-                )?;
-
-                if span.nested_duration > 0 {
-                    let direct_load =
-                        100.0 * (total_duration - span.nested_duration as f64) / root_duration;
-                    write!(writer, "{:.3}% / ", direct_load)?;
-                }
-
-                writeln!(writer, "{:.3}% ]", total_load)?;
-
-                if let Some((last, remaining)) = span.processed_buf.split_last() {
-                    // This span has children
-                    // This is for what wraps the left of this span
-                    match indent.last_mut() {
-                        Some(f @ Turn) => *f = Void,
-                        Some(f @ Fork) => *f = Line,
-                        _ => {}
-                    }
-
-                    // Need to extend by one
-                    indent.push(Fork);
-                    for logs in remaining {
-                        // Reset to Fork
-                        if let Some(fill) = indent.last_mut() {
-                            *fill = Fork;
-                        }
-                        fmt_rec(logs, indent, Some(uuid), Some(root_duration), writer)?;
-                    }
-
-                    // Last child, set to Turn
-                    if let Some(fill) = indent.last_mut() {
-                        *fill = Turn;
-                    }
-                    fmt_rec(last, indent, Some(uuid), Some(root_duration), writer)?;
-
-                    indent.pop();
-                } else {
-                    // this span has no children
-                }
-
-                Ok(())
-            }
-        }
-    }
-
-    let mut writer = vec![];
-    let mut indent = vec![];
-    #[allow(clippy::expect_used)]
-    fmt_rec(processed_logs, &mut indent, None, None, &mut writer).expect("Write failed");
-    writer
-}
-
-pub(super) fn format_immediate_event(
-    event: &TreeEvent,
-    maybe_scope: Option<ScopeFromRoot<Registry>>,
-) -> Result<String, fmt::Error> {
-    let mut writer = String::new();
-
-    write!(
-        writer,
-        "{} {em} [{}] {em}",
-        event.timestamp.to_rfc3339(),
-        event.level,
-        em = event.emoji()
-    )?;
-
-    if let Some(scope) = maybe_scope {
-        for span in scope {
-            write!(writer, "🔹{}", span.name())?;
-        }
-    }
-
-    write!(writer, ": {}", event.message)?;
-
-    for (key, value) in event.values.iter() {
-        write!(writer, " | {}: {}", key, value)?;
-    }
-
-    Ok(writer)
-}

kanidmd/idm/src/tracing_tree/mod.rs

@@ -1,13 +0,0 @@
-mod event_tag;
-mod formatter;
-mod macros;
-mod middleware;
-mod processor;
-mod subscriber;
-mod timings;
-
-pub use event_tag::EventTag;
-pub use middleware::TreeMiddleware;
-pub use subscriber::{
-    main_init, operation_id, test_init, test_level, TreePreProcessed, TreeSubscriber,
-};

kanidmd/idm/src/tracing_tree/processor.rs

@@ -1,34 +0,0 @@
-use super::TreePreProcessed;
-use tokio::sync::mpsc::UnboundedSender;
-
-pub trait Processor: 'static {
-    fn process(&self, preprocessed: TreePreProcessed);
-}
-
-pub struct ExportProcessor {
-    sender: UnboundedSender<TreePreProcessed>,
-}
-
-pub struct TestProcessor {}
-
-impl ExportProcessor {
-    pub fn with_sender(sender: UnboundedSender<TreePreProcessed>) -> Self {
-        ExportProcessor { sender }
-    }
-}
-
-impl Processor for ExportProcessor {
-    fn process(&self, preprocessed: TreePreProcessed) {
-        #[allow(clippy::expect_used)]
-        self.sender
-            .send(preprocessed)
-            .expect("Processing channel has been closed, cannot log events.");
-    }
-}
-
-impl Processor for TestProcessor {
-    fn process(&self, preprocessed: TreePreProcessed) {
-        #[allow(clippy::expect_used)]
-        preprocessed.process().expect("Failed to write logs");
-    }
-}

kanidmd/idm/src/tracing_tree/subscriber.rs

@@ -1,583 +0,0 @@
-use std::any::TypeId;
-use std::convert::TryFrom;
-use std::fmt;
-use std::fs::OpenOptions;
-use std::io::{self, Write as _};
-use std::path::PathBuf;
-use std::time::Duration;
-
-use chrono::{DateTime, Utc};
-use futures::Future;
-use tokio::sync::mpsc::unbounded_channel;
-use tokio::sync::mpsc::UnboundedSender;
-use tokio::task::JoinHandle;
-use tracing::dispatcher::SetGlobalDefaultError;
-use tracing::field::{Field, Visit};
-use tracing::span::{Attributes, Record};
-use tracing::{Event, Id, Level, Metadata, Subscriber};
-use tracing_subscriber::filter::EnvFilter;
-use tracing_subscriber::layer::{Context, Layered, SubscriberExt};
-use tracing_subscriber::registry::{LookupSpan, Registry, Scope, SpanRef};
-use tracing_subscriber::Layer;
-use uuid::Uuid;
-
-use crate::tracing_tree::processor::TestProcessor;
-
-use super::formatter::LogFmt;
-use super::processor::{ExportProcessor, Processor};
-use super::timings::Timer;
-use super::EventTag;
-
-pub struct TreeSubscriber<P> {
-    inner: Layered<TreeLayer<P>, Registry>,
-}
-
-struct TreeLayer<P> {
-    fmt: LogFmt,
-    processor: P,
-}
-
-#[derive(Debug)]
-pub(crate) struct TreeEvent {
-    pub timestamp: DateTime<Utc>,
-    pub message: String,
-    pub level: Level,
-    pub tag: Option<EventTag>,
-    pub values: Vec<(&'static str, String)>,
-}
-
-#[derive(Debug)]
-struct TreeSpan {
-    pub timestamp: DateTime<Utc>,
-    pub name: &'static str,
-    pub buf: Vec<Tree>,
-    pub uuid: Option<String>,
-    pub out: TreeIo,
-}
-
-#[derive(Debug)]
-enum Tree {
-    Event(TreeEvent),
-    Span(TreeSpan, Duration),
-}
-
-#[derive(Debug)]
-pub struct TreePreProcessed {
-    fmt: LogFmt,
-    logs: Tree,
-}
-
-#[derive(Debug)]
-pub enum TreeIo {
-    Stdout,
-    Stderr,
-    File(PathBuf),
-}
-
-pub(crate) struct TreeSpanProcessed {
-    pub timestamp: DateTime<Utc>,
-    pub name: &'static str,
-    pub processed_buf: Vec<TreeProcessed>,
-    pub uuid: Option<String>,
-    pub out: TreeIo,
-    pub nested_duration: u64,
-    pub total_duration: u64,
-}
-
-pub(crate) enum TreeProcessed {
-    Event(TreeEvent),
-    Span(TreeSpanProcessed),
-}
-
-impl TreeSubscriber<ExportProcessor> {
-    fn new_with(fmt: LogFmt, sender: UnboundedSender<TreePreProcessed>) -> Self {
-        let layer = TreeLayer {
-            fmt,
-            processor: ExportProcessor::with_sender(sender),
-        };
-
-        TreeSubscriber {
-            inner: Registry::default().with(layer),
-        }
-    }
-
-    pub fn new(fmt: LogFmt) -> (Self, impl Future<Output = ()>) {
-        let (log_tx, mut log_rx) = unbounded_channel();
-        let subscriber = TreeSubscriber::new_with(fmt, log_tx);
-        let logger = async move {
-            while let Some(processor) = log_rx.recv().await {
-                #[allow(clippy::expect_used)]
-                processor.process().expect("Failed to write logs");
-            }
-        };
-
-        (subscriber, logger)
-    }
-
-    // These are the preferred constructors.
-    #[allow(dead_code)]
-    pub fn json() -> (Self, impl Future<Output = ()>) {
-        TreeSubscriber::new(LogFmt::Json)
-    }
-
-    #[allow(dead_code)]
-    pub fn pretty() -> (Self, impl Future<Output = ()>) {
-        TreeSubscriber::new(LogFmt::Pretty)
-    }
-}
-
-impl<P: Processor> TreeSubscriber<P> {
-    #[allow(dead_code)]
-    pub fn thread_operation_id(&self) -> Option<Uuid> {
-        let current = self.inner.current_span();
-        // If there's no current span, we short-circuit.
-        let id = current.id()?;
-        #[allow(clippy::expect_used)]
-        let span = self
-            .inner
-            .span(id)
-            .expect("The subscriber doesn't have data for an existing span, this is a bug");
-
-        span.scope().into_iter().find_map(|span| {
-            let extensions = span.extensions();
-            // If `uuid` is `None`, then we keep searching.
-            #[allow(clippy::expect_used)]
-            let uuid = extensions
-                .get::<TreeSpan>()
-                .expect("Span buffer not found, this is a bug")
-                .uuid
-                .as_ref()?;
-            // TODO: make spans store UUID's as a u128 or 2 u64's
-            #[allow(clippy::expect_used)]
-            Some(Uuid::parse_str(uuid.as_str()).expect("Unable to parse UUID, this is a bug"))
-        })
-    }
-}
-
-impl<P: Processor> Subscriber for TreeSubscriber<P> {
-    fn enabled(&self, metadata: &Metadata) -> bool {
-        self.inner.enabled(metadata)
-    }
-
-    fn max_level_hint(&self) -> Option<tracing::metadata::LevelFilter> {
-        self.inner.max_level_hint()
-    }
-
-    fn new_span(&self, span: &Attributes) -> Id {
-        self.inner.new_span(span)
-    }
-
-    fn record(&self, span: &Id, values: &Record) {
-        self.inner.record(span, values)
-    }
-
-    fn record_follows_from(&self, span: &Id, follows: &Id) {
-        self.inner.record_follows_from(span, follows)
-    }
-
-    fn event(&self, event: &Event) {
-        self.inner.event(event)
-    }
-
-    fn enter(&self, span: &Id) {
-        self.inner.enter(span)
-    }
-
-    fn exit(&self, span: &Id) {
-        self.inner.exit(span)
-    }
-
-    fn clone_span(&self, id: &Id) -> Id {
-        self.inner.clone_span(id)
-    }
-
-    fn try_close(&self, id: Id) -> bool {
-        self.inner.try_close(id)
-    }
-
-    unsafe fn downcast_raw(&self, id: TypeId) -> Option<*const ()> {
-        // Allows us to access this or nested subscribers from dispatch
-        if id == TypeId::of::<Self>() {
-            Some(self as *const Self as *const ())
-        } else {
-            self.inner.downcast_raw(id)
-        }
-    }
-}
-
-impl<P: Processor> TreeLayer<P> {
-    fn log_to_parent(&self, logs: Tree, parent: Option<SpanRef<Registry>>) {
-        match parent {
-            // The parent exists- write to them
-            #[allow(clippy::expect_used)]
-            Some(span) => span
-                .extensions_mut()
-                .get_mut::<TreeSpan>()
-                .expect("Log buffer not found, this is a bug")
-                .log(logs),
-            // The parent doesn't exist- send to formatter
-            None => self.processor.process(TreePreProcessed {
-                fmt: self.fmt,
-                logs,
-            }),
-        }
-    }
-}
-
-impl<P: Processor> Layer<Registry> for TreeLayer<P> {
-    fn on_new_span(&self, attrs: &Attributes, id: &Id, ctx: Context<Registry>) {
-        #[allow(clippy::expect_used)]
-        let span = ctx.span(id).expect("Span not found, this is a bug");
-
-        let name = attrs.metadata().name();
-        let mut uuid = None;
-        let mut out = TreeIo::Stdout;
-
-        attrs.record(
-            &mut |field: &Field, value: &dyn fmt::Debug| match field.name() {
-                "uuid" => {
-                    uuid = Some(format!("{:?}", value));
-                }
-                "output" if ctx.lookup_current().is_none() => {
-                    out = match format!("{:?}", value).as_str() {
-                        "console stdout" => TreeIo::Stdout,
-                        "console stderr" => TreeIo::Stderr,
-                        path => TreeIo::File(PathBuf::from(path)),
-                    };
-                }
-                _ => {}
-            },
-        );
-
-        // Take provided ID, or make a fresh one if there's no parent span.
-        let uuid = uuid.or_else(|| {
-            ctx.lookup_current()
-                .is_none()
-                .then(|| Uuid::new_v4().to_string())
-        });
-
-        let mut extensions = span.extensions_mut();
-
-        extensions.insert(TreeSpan::new(name, uuid, out));
-        extensions.insert(Timer::new());
-    }
-
-    fn on_event(&self, event: &Event, ctx: Context<Registry>) {
-        let (tree_event, immediate) = TreeEvent::parse(event);
-
-        if immediate {
-            use super::formatter::format_immediate_event;
-            let maybe_scope = ctx.event_scope(event).map(Scope::from_root);
-            #[allow(clippy::expect_used)]
-            let formatted_event = format_immediate_event(&tree_event, maybe_scope)
-                .expect("Formatting immediate event failed");
-            eprintln!("{}", formatted_event);
-        }
-
-        self.log_to_parent(Tree::Event(tree_event), ctx.event_span(event));
-    }
-
-    fn on_enter(&self, id: &Id, ctx: Context<Registry>) {
-        #[allow(clippy::expect_used)]
-        ctx.span(id)
-            .expect("Span not found, this is a bug")
-            .extensions_mut()
-            .get_mut::<Timer>()
-            .expect("Timer not found, this is a bug")
-            .unpause();
-    }
-
-    fn on_exit(&self, id: &Id, ctx: Context<Registry>) {
-        #[allow(clippy::expect_used)]
-        ctx.span(id)
-            .expect("Span not found, this is a bug")
-            .extensions_mut()
-            .get_mut::<Timer>()
-            .expect("Timer not found, this is a bug")
-            .pause();
-    }
-
-    fn on_close(&self, id: Id, ctx: Context<Registry>) {
-        #[allow(clippy::expect_used)]
-        let span = ctx.span(&id).expect("Span not found, this is a bug");
-
-        let mut extensions = span.extensions_mut();
-
-        #[allow(clippy::expect_used)]
-        let span_buf = extensions
-            .remove::<TreeSpan>()
-            .expect("Span buffer not found, this is a bug");
-
-        #[allow(clippy::expect_used)]
-        let duration = extensions
-            .remove::<Timer>()
-            .expect("Timer not found, this is a bug")
-            .duration();
-
-        let logs = Tree::Span(span_buf, duration);
-
-        self.log_to_parent(logs, span.parent());
-    }
-}
-
-impl TreeEvent {
-    fn parse(event: &Event) -> (Self, bool) {
-        let timestamp = Utc::now();
-        let level = *event.metadata().level();
-
-        struct Visitor {
-            message: String,
-            tag: Option<EventTag>,
-            values: Vec<(&'static str, String)>,
-            immediate: bool,
-        }
-
-        impl Visit for Visitor {
-            fn record_u64(&mut self, field: &Field, value: u64) {
-                if field.name() == "event_tag_id" {
-                    let tag = EventTag::try_from(value).unwrap_or_else(|_| {
-                        error!("Invalid `event_tag_id`: {}, this is a bug", value);
-                        std::process::exit(1)
-                    });
-                    self.tag = Some(tag);
-                } else {
-                    self.record_debug(field, &value)
-                }
-            }
-
-            fn record_bool(&mut self, field: &Field, value: bool) {
-                if field.name() == "immediate" {
-                    self.immediate = value;
-                } else {
-                    self.record_debug(field, &value)
-                }
-            }
-
-            fn record_debug(&mut self, field: &Field, value: &dyn fmt::Debug) {
-                if field.name() == "message" {
-                    use fmt::Write;
-                    #[allow(clippy::expect_used)]
-                    write!(self.message, "{:?}", value).expect("Write failed");
-                } else {
-                    self.values.push((field.name(), format!("{:?}", value)));
-                }
-            }
-        }
-
-        let mut v = Visitor {
-            message: String::new(),
-            tag: None,
-            values: vec![],
-            immediate: false,
-        };
-
-        event.record(&mut v);
-
-        let Visitor {
-            message,
-            tag,
-            values,
-            immediate,
-        } = v;
-
-        (
-            TreeEvent {
-                timestamp,
-                message,
-                level,
-                tag,
-                values,
-            },
-            immediate,
-        )
-    }
-
-    pub(super) fn emoji(&self) -> &'static str {
-        self.tag
-            .map(EventTag::emoji)
-            .unwrap_or_else(|| match self.level {
-                Level::ERROR => "🚨",
-                Level::WARN => "⚠️ ",
-                Level::INFO => "  ",
-                Level::DEBUG => "🐛",
-                Level::TRACE => "📍",
-            })
-    }
-
-    pub(super) fn tag(&self) -> &'static str {
-        self.tag
-            .map(EventTag::pretty)
-            .unwrap_or_else(|| match self.level {
-                Level::ERROR => "error",
-                Level::WARN => "warn",
-                Level::INFO => "info",
-                Level::DEBUG => "debug",
-                Level::TRACE => "trace",
-            })
-    }
-}
-
-impl TreeSpan {
-    fn new(name: &'static str, uuid: Option<String>, out: TreeIo) -> Self {
-        TreeSpan {
-            timestamp: Utc::now(),
-            name,
-            buf: vec![],
-            uuid,
-            out,
-        }
-    }
-
-    fn log(&mut self, logs: Tree) {
-        self.buf.push(logs)
-    }
-}
-
-impl Tree {
-    pub fn process(self) -> TreeProcessed {
-        match self {
-            Tree::Event(event) => TreeProcessed::Event(event),
-            Tree::Span(span_buf, duration) => {
-                let mut processed_buf = vec![];
-
-                let nested_duration = span_buf
-                    .buf
-                    .into_iter()
-                    .map(|logs| {
-                        let processed = logs.process();
-
-                        let duration = match processed {
-                            TreeProcessed::Span(ref span) => span.total_duration,
-                            _ => 0,
-                        };
-
-                        // Side effect: Push processed logs to processed_buf
-                        processed_buf.push(processed);
-
-                        duration
-                    })
-                    .sum::<u64>();
-
-                TreeProcessed::Span(TreeSpanProcessed {
-                    timestamp: span_buf.timestamp,
-                    name: span_buf.name,
-                    processed_buf,
-                    uuid: span_buf.uuid,
-                    out: span_buf.out,
-                    nested_duration,
-                    total_duration: duration.as_nanos() as u64,
-                })
-            }
-        }
-    }
-}
-
-impl TreePreProcessed {
-    pub fn process(self) -> io::Result<()> {
-        let processed_logs = self.logs.process();
-        let formatted_logs = self.fmt.format(&processed_logs);
-
-        let buf = &formatted_logs[..];
-
-        match processed_logs.tree_io() {
-            TreeIo::Stdout => {
-                // BUG - we can't write to stdout/err directly because this breaks
-                // cargo test capturing of io.
-                // io::stdout().write_all(buf)
-
-                match std::str::from_utf8(buf) {
-                    Ok(s) => print!("{}", s),
-                    Err(e) => eprintln!("CRITICAL - UNABLE TO PRINT BUFFER -> {:?}", e),
-                }
-                Ok(())
-            }
-            TreeIo::Stderr => {
-                // io::stderr().write_all(buf)
-
-                match std::str::from_utf8(buf) {
-                    Ok(s) => eprint!("{}", s),
-                    Err(e) => eprintln!("CRITICAL - UNABLE TO PRINT BUFFER -> {:?}", e),
-                }
-                Ok(())
-            }
-            TreeIo::File(ref path) => OpenOptions::new()
-                .create(true)
-                .append(true)
-                .write(true)
-                .open(path)?
-                .write_all(buf),
-        }
-    }
-}
-
-impl TreeProcessed {
-    fn tree_io(self) -> TreeIo {
-        match self {
-            TreeProcessed::Event(_) => TreeIo::Stdout,
-            TreeProcessed::Span(TreeSpanProcessed { out, .. }) => out,
-        }
-    }
-}
-
-// Returns the UUID of the threads current span operation, or None if not in any spans.
-#[allow(dead_code)]
-pub fn operation_id() -> Option<Uuid> {
-    tracing::dispatcher::get_default(|dispatch| {
-        // Try to find the release subscriber
-        #[allow(clippy::expect_used)]
-        dispatch
-            .downcast_ref::<TreeSubscriber<ExportProcessor>>()
-            .map(TreeSubscriber::<ExportProcessor>::thread_operation_id)
-            .or_else(|| {
-                // Try to find the testing subscriber
-                dispatch
-                    .downcast_ref::<TreeSubscriber<TestProcessor>>()
-                    .map(TreeSubscriber::<TestProcessor>::thread_operation_id)
-            })
-            .expect("operation_id only works for `TreeSubscriber`'s!")
-    })
-}
-
-pub fn main_init() -> JoinHandle<()> {
-    let (subscriber, logger) = TreeSubscriber::pretty();
-    #[allow(clippy::expect_used)]
-    let subscriber = EnvFilter::try_from_default_env()
-        .or_else(|_| EnvFilter::try_new("info"))
-        .expect("Failed to init envfilter")
-        .with_subscriber(subscriber);
-    #[allow(clippy::expect_used)]
-    tracing::subscriber::set_global_default(subscriber)
-        .expect("🚨🚨🚨 Global subscriber already set, this is a bug 🚨🚨🚨");
-    tokio::spawn(logger)
-}
-
-// This should be used in testing only, because it processes logs on the working thread.
-// The main benefit is that this makes testing much easier, since it can be called in
-// every test without worring about a processing thread in a test holding an `UnboundedReceiver`
-// and then getting dropped, making the global subscriber panic on further attempts to send logs.
-#[allow(dead_code)]
-pub fn test_init() -> Result<(), SetGlobalDefaultError> {
-    let subscriber = TreeSubscriber {
-        inner: Registry::default().with(TreeLayer {
-            fmt: LogFmt::Pretty,
-            processor: TestProcessor {},
-        }),
-    };
-
-    tracing::subscriber::set_global_default(subscriber)
-}
-
-#[allow(dead_code)]
-pub fn test_level(level: tracing::Level) -> Result<(), SetGlobalDefaultError> {
-    let subscriber = TreeSubscriber {
-        inner: Registry::default().with(TreeLayer {
-            fmt: LogFmt::Pretty,
-            processor: TestProcessor {},
-        }),
-    };
-
-    let subscriber =
-        tracing_subscriber::filter::LevelFilter::from_level(level).with_subscriber(subscriber);
-
-    tracing::subscriber::set_global_default(subscriber)
-}

kanidmd/idm/src/tracing_tree/timings.rs

@@ -1,28 +0,0 @@
-use std::time::{Duration, Instant};
-
-pub struct Timer {
-    duration: Duration,
-    start: Instant,
-}
-
-impl Timer {
-    pub fn new() -> Self {
-        Timer {
-            duration: Duration::default(),
-            start: Instant::now(),
-        }
-    }
-
-    pub fn pause(&mut self) {
-        let stop = Instant::now();
-        self.duration += stop - self.start;
-    }
-
-    pub fn unpause(&mut self) {
-        self.start = Instant::now();
-    }
-
-    pub fn duration(self) -> Duration {
-        self.duration
-    }
-}

kanidmd/score/Cargo.toml

@@ -19,7 +19,6 @@ compact_jwt = "^0.2.3"
 futures-util = "^0.3.21"
 http-types = "^2.12.0"
 kanidm = { path = "../idm" }
-kanidm_client = { path = "../../kanidm_client" }
 kanidm_proto = { path = "../../kanidm_proto" }
 ldap3_proto = "^0.2.3"
 libc = "^0.2.126"
@@ -27,6 +26,7 @@ openssl = "^0.10.41"
 regex = "1.5.6"
 serde = { version = "^1.0.142", features = ["derive"] }
 serde_json = "^1.0.83"
+sketching = { path = "../../sketching" }
 tide = "^0.16.0"
 # I tried including brotli and it didn't work, including "default" pulls a mime-type list from the internet on build
 tide-compress = { version = "0.10.6", default-features = false, features = [ "deflate", "gzip", "regex-check" ] }
@@ -41,12 +41,8 @@ uuid = { version = "^1.1.2", features = ["serde", "v4" ] }
 profiles = { path = "../../profiles" }
 
 [dev-dependencies]
-tracing-subscriber = "^0.3.14"
+kanidm_client = { path = "../../kanidm_client" }
-# tokio = { version = "1", features = ["rt", "net", "time", "macros", "sync", "signal"] }
-# kanidm = { path = "../kanidmd" }
-# score = { path = "../kanidmd/score" }
 futures = "^0.3.21"
-# async-std = { version = "1.6", features = ["tokio1"] }
 
 webauthn-authenticator-rs = "0.4.2-beta.3"
 oauth2_ext = { package = "oauth2", version = "^4.1.0", default-features = false }

kanidmd/score/src/https/mod.rs

@@ -16,7 +16,6 @@ use kanidm::actors::v1_write::QueryServerWriteV1;
 use kanidm::config::{ServerRole, TlsConfiguration};
 use kanidm::prelude::*;
 use kanidm::status::StatusActor;
-use kanidm::tracing_tree::TreeMiddleware;
 use serde::Serialize;
 use std::fs::canonicalize;
 use std::path::PathBuf;
@@ -135,7 +134,7 @@ impl RequestExtensions for tide::Request<AppState> {
     }
 
     fn new_eventid(&self) -> (Uuid, String) {
-        let eventid = kanidm::tracing_tree::operation_id().unwrap();
+        let eventid = sketching::tracing_forest::id();
         let hv = eventid.as_hyphenated().to_string();
         (eventid, hv)
     }
@@ -349,7 +348,7 @@ pub fn create_https_server(
     });
 
     // Add middleware?
-    tserver.with(TreeMiddleware::with_stdout());
+    tserver.with(sketching::middleware::TreeMiddleware::default());
     // tserver.with(tide::log::LogMiddleware::new());
     // We do not force a session ttl, because we validate this elsewhere in usage.
     tserver.with(

kanidmd/score/src/ldaps.rs

@@ -35,7 +35,7 @@ async fn client_process_msg(
     protomsg: LdapMsg,
     qe_r_ref: &'static QueryServerReadV1,
 ) -> Option<LdapResponseState> {
-    let eventid = kanidm::tracing_tree::operation_id().unwrap();
+    let eventid = sketching::tracing_forest::id();
     security_info!(
         client_ip = %client_address.ip(),
         client_port = %client_address.port(),

kanidmd/score/tests/common.rs

@@ -3,7 +3,6 @@ use std::sync::atomic::{AtomicU16, Ordering};
 
 use kanidm::audit::LogLevel;
 use kanidm::config::{Configuration, IntegrationTestConfig, ServerRole};
-use kanidm::tracing_tree;
 use kanidm_client::{KanidmClient, KanidmClientBuilder};
 use score::create_server_core;
 use tokio::task;
@@ -25,7 +24,7 @@ pub fn is_free_port(port: u16) -> bool {
 // allowed because the use of this function is behind a test gate
 #[allow(dead_code)]
 pub async fn setup_async_test() -> KanidmClient {
-    let _ = tracing_tree::test_init();
+    let _ = sketching::test_init();
 
     let mut counter = 0;
     let port = loop {

kanidmd/score/tests/https_middleware.rs

@@ -5,7 +5,6 @@ use crate::common::{ADMIN_TEST_PASSWORD, ADMIN_TEST_USER, PORT_ALLOC};
 
 use kanidm::audit::LogLevel;
 use kanidm::config::{Configuration, IntegrationTestConfig, ServerRole};
-use kanidm::tracing_tree;
 use score::create_server_core;
 use tokio::task;
 
@@ -14,7 +13,7 @@ use crate::common::is_free_port;
 #[tokio::test]
 async fn test_https_middleware_headers() {
     // tests stuff
-    let _ = tracing_tree::test_init();
+    let _ = sketching::test_init();
 
     let mut counter = 0;
     let port = loop {

sketching/Cargo.toml

@@ -0,0 +1,18 @@
+[package]
+name = "sketching"
+version = "0.1.0"
+edition = "2021"
+
+# See more keys and their definitions at https://doc.rust-lang.org/cargo/reference/manifest.html
+
+[dependencies]
+async-trait = "^0.1.57"
+tide = "^0.16.0"
+num_enum = "^0.5.7"
+
+tracing = { version = "^0.1.35", features = ["attributes", "max_level_trace", "release_max_level_debug"] }
+tracing-subscriber = { version = "^0.3.14", features = ["env-filter"] }
+
+# tracing-forest = { version = "0.1.4", features = ["uuid", "smallvec", "tokio", "env-filter"] }
+tracing-forest = { git = "https://github.com/Firstyear/tracing-forest.git", rev = "18d242a4dde060c4946ade0a2c4d5be1df048aea", features = ["uuid", "smallvec", "tokio", "env-filter"] }
+

sketching/src/lib.rs

@@ -1,4 +1,31 @@
+#![deny(warnings)]
+#![warn(unused_extern_crates)]
+
 use num_enum::{IntoPrimitive, TryFromPrimitive};
+use tracing_forest::{util::*, Tag};
+
+pub mod macros;
+pub mod middleware;
+
+pub use tracing;
+pub use tracing_forest;
+pub use tracing_subscriber;
+
+pub fn test_init() -> () {
+    // tracing_subscriber::fmt::try_init()
+    let _ = tracing_forest::test_init();
+    /*
+    let _ = Registry::default().with(ForestLayer::new(
+        TestCapturePrinter::new(),
+        NoTag,
+    )).try_init();
+    */
+}
+
+/// This is for tagging events. Currently not wired in.
+pub fn event_tagger(_event: &Event) -> Option<Tag> {
+    None
+}
 
 #[derive(Debug, Clone, Copy, IntoPrimitive, TryFromPrimitive)]
 #[repr(u64)]

sketching/src/macros.rs

@@ -2,14 +2,14 @@
 macro_rules! spanned {
     ($name:expr, $code:block) => {{
         // Block: can short circuit outer function
-        use tracing::trace_span;
+        use tracing::debug_span;
-        let _entered_span = trace_span!($name).entered();
+        let _entered_span = debug_span!($name).entered();
         $code
     }};
     ($name:expr, || $code:block) => {{
         // Closure: cannot short circuit outer function
-        use tracing::trace_span;
+        use tracing::debug_span;
-        let _entered_span = trace_span!($name).entered();
+        let _entered_span = debug_span!($name).entered();
         (|| $code)()
     }};
 }
@@ -100,6 +100,11 @@ macro_rules! filter_info {
     ($($arg:tt)*) => { tagged_event!(INFO, EventTag::FilterInfo, $($arg)*) }
 }
 
+#[macro_export]
+macro_rules! filter_debug {
+    ($($arg:tt)*) => { tagged_event!(DEBUG, EventTag::FilterTrace, $($arg)*) }
+}
+
 #[macro_export]
 macro_rules! filter_trace {
     ($($arg:tt)*) => { tagged_event!(TRACE, EventTag::FilterTrace, $($arg)*) }

sketching/src/middleware.rs

@@ -1,45 +1,23 @@
-use std::path::PathBuf;
+use crate::{request_error, request_info, request_warn, security_info};
-
-use super::subscriber::TreeIo;
-use crate::prelude::*;
 use tide::{self, Middleware, Next, Request};
 use tracing::{self, instrument};
 
-// Modeled after:
+use crate::*;
-// https://docs.rs/tide/0.16.0/src/tide/log/middleware.rs.html#23-96
 
-pub struct TreeMiddleware {
+pub struct TreeMiddleware {}
-    output: TreeIo,
+
+impl Default for TreeMiddleware {
+    fn default() -> Self {
+        TreeMiddleware {}
+    }
 }
 
 impl TreeMiddleware {
-    #[allow(dead_code)]
+    #[instrument(name = "tide-request", skip(self, req, next))]
-    pub fn with_stdout() -> Self {
-        TreeMiddleware {
-            output: TreeIo::Stdout,
-        }
-    }
-
-    #[allow(dead_code)]
-    pub fn with_stderr() -> Self {
-        TreeMiddleware {
-            output: TreeIo::Stderr,
-        }
-    }
-
-    #[allow(dead_code)]
-    pub fn with_file(path: &str) -> Self {
-        TreeMiddleware {
-            output: TreeIo::File(PathBuf::from(path)),
-        }
-    }
-
-    #[instrument(name = "tide-request", skip(self, req, next, output), fields(%output))]
     async fn log<'a, State: Clone + Send + Sync + 'static>(
         &'a self,
         mut req: Request<State>,
         next: Next<'a, State>,
-        output: &str,
     ) -> tide::Result {
         struct TreeMiddlewareFinished;
 
@@ -111,20 +89,6 @@ impl TreeMiddleware {
 #[async_trait::async_trait]
 impl<State: Clone + Send + Sync + 'static> Middleware<State> for TreeMiddleware {
     async fn handle(&self, req: Request<State>, next: Next<'_, State>) -> tide::Result {
-        let output = match self.output {
+        self.log(req, next).await
-            TreeIo::Stdout => "console stdout",
-            TreeIo::Stderr => "console stderr",
-            TreeIo::File(ref path) => path.to_str().unwrap_or_else(|| {
-                eprintln!("File path isn't UTF-8, cannot write logs to: {:#?}", path);
-                std::process::exit(1);
-                // warn!(
-                //     "File path isn't UTF-8, logging to stderr instead: {:#?}",
-                //     path
-                // );
-                // "console stderr"
-            }),
-        };
-
-        self.log(req, next, output).await
     }
 }