Simple logger (#134)

* define casbin's own rhai package

* remove transparent error to make casbin error explicit

* implement TryIntoAdapter for ()

* add simple logger

* improve format

* bump version

* add mgmt log

* disable logging by default for better performance

* fix clippy warnings

Author: 0x8f701

Cargo.toml

@@ -1,6 +1,6 @@
 [package]
 name = "casbin"
-version = "0.6.2"
+version = "0.7.0"
 authors = ["Joey <joey.xf@gmail.com>", "Cheng JIANG <jiang.cheng@vip.163.com>"]
 edition = "2018"
 license = "Apache-2.0"
@@ -27,7 +27,7 @@ globset = "0.4.5"
 thiserror = "1.0.14"
 
 [features]
-default = ["runtime-async-std", "logging"]
+default = ["runtime-async-std"]
 
 runtime-tokio = ["tokio/fs", "tokio/io-util", "tokio/stream", "tokio/rt-threaded", "tokio/blocking"]
 runtime-async-std = ["async-std"]

README.md

@@ -27,8 +27,9 @@ Add this package to `Cargo.toml` of your project. (Check https://crates.io/crate
 
 ```toml
 [dependencies]
-casbin = "0.6.2"
+casbin = { version = "0.7.0", default-features = false, features = ["runtime-async-std", "logging"] }
 async-std = { version = "1.5.0", features = ["attributes"] }
+env_logger = "0.7.1"
 ```
 
 ## Get started
@@ -41,7 +42,13 @@ use casbin::prelude::*;
 
 #[async_std::main]
 async fn main() -> Result<()> {
-    let mut e = Enforcer::new("path/to/model.conf", "path/to/policy.csv").await?;
+    ::std::env::set_var("RUST_LOG", "casbin=info");
+    env_logger::init();
+
+    let mut e = Enforcer::new("examples/rbac_with_domains_model.conf", "examples/rbac_with_domains_policy.csv").await?;
+    e.enable_log(true);
+
+    e.enforce(&["alice", "domain1", "data1", "read"]).await?;
     Ok(())
 }
 ```

benches/benchmark.rs

@@ -104,11 +104,7 @@ fn b_benchmark_cached_rbac_model(b: &mut Bencher) {
 
 #[bench]
 fn b_benchmark_rbac_model_small(b: &mut Bencher) {
-    let mut e = await_future(Enforcer::new(
-        "examples/rbac_model.conf",
-        None as Option<&str>,
-    ))
-    .unwrap();
+    let mut e = await_future(Enforcer::new("examples/rbac_model.conf", ())).unwrap();
 
     e.enable_auto_build_role_links(false);
 
@@ -145,11 +141,7 @@ fn b_benchmark_rbac_model_small(b: &mut Bencher) {
 
 #[bench]
 fn b_benchmark_cached_rbac_model_small(b: &mut Bencher) {
-    let mut e = await_future(CachedEnforcer::new(
-        "examples/rbac_model.conf",
-        None as Option<&str>,
-    ))
-    .unwrap();
+    let mut e = await_future(CachedEnforcer::new("examples/rbac_model.conf", ())).unwrap();
 
     e.enable_auto_build_role_links(false);
 
@@ -186,11 +178,7 @@ fn b_benchmark_cached_rbac_model_small(b: &mut Bencher) {
 
 #[bench]
 fn b_benchmark_rbac_model_medium(b: &mut Bencher) {
-    let mut e = await_future(Enforcer::new(
-        "examples/rbac_model.conf",
-        None as Option<&str>,
-    ))
-    .unwrap();
+    let mut e = await_future(Enforcer::new("examples/rbac_model.conf", ())).unwrap();
 
     e.enable_auto_build_role_links(false);
 
@@ -227,11 +215,7 @@ fn b_benchmark_rbac_model_medium(b: &mut Bencher) {
 
 #[bench]
 fn b_benchmark_cached_rbac_model_medium(b: &mut Bencher) {
-    let mut e = await_future(CachedEnforcer::new(
-        "examples/rbac_model.conf",
-        None as Option<&str>,
-    ))
-    .unwrap();
+    let mut e = await_future(CachedEnforcer::new("examples/rbac_model.conf", ())).unwrap();
 
     e.enable_auto_build_role_links(false);
 
@@ -268,11 +252,7 @@ fn b_benchmark_cached_rbac_model_medium(b: &mut Bencher) {
 
 #[bench]
 fn b_benchmark_rbac_model_large(b: &mut Bencher) {
-    let mut e = await_future(Enforcer::new(
-        "examples/rbac_model.conf",
-        None as Option<&str>,
-    ))
-    .unwrap();
+    let mut e = await_future(Enforcer::new("examples/rbac_model.conf", ())).unwrap();
 
     e.enable_auto_build_role_links(false);
 
@@ -309,11 +289,7 @@ fn b_benchmark_rbac_model_large(b: &mut Bencher) {
 
 #[bench]
 fn b_benchmark_cached_rbac_model_large(b: &mut Bencher) {
-    let mut e = await_future(CachedEnforcer::new(
-        "examples/rbac_model.conf",
-        None as Option<&str>,
-    ))
-    .unwrap();
+    let mut e = await_future(CachedEnforcer::new("examples/rbac_model.conf", ())).unwrap();
 
     e.enable_auto_build_role_links(false);
 
@@ -394,22 +370,14 @@ fn b_benchmark_cached_rbac_model_with_domains(b: &mut Bencher) {
 
 #[bench]
 fn b_benchmark_abac_model(b: &mut Bencher) {
-    let e = await_future(Enforcer::new(
-        "examples/abac_model.conf",
-        None as Option<&str>,
-    ))
-    .unwrap();
+    let e = await_future(Enforcer::new("examples/abac_model.conf", ())).unwrap();
 
     b.iter(|| await_future(e.enforce(&["alice", r#"{"Owner": "alice"}"#, "read"])).unwrap());
 }
 
 #[bench]
 fn b_benchmark_cached_abac_model(b: &mut Bencher) {
-    let mut e = await_future(CachedEnforcer::new(
-        "examples/abac_model.conf",
-        None as Option<&str>,
-    ))
-    .unwrap();
+    let mut e = await_future(CachedEnforcer::new("examples/abac_model.conf", ())).unwrap();
 
     b.iter(|| await_future(e.enforce_mut(&["alice", r#"{"Owner": "alice"}"#, "read"])).unwrap());
 }

src/cached_enforcer.rs

@@ -13,6 +13,9 @@ use crate::{
     Result,
 };
 
+#[cfg(feature = "logging")]
+use crate::Logger;
+
 use async_trait::async_trait;
 
 use std::{
@@ -21,7 +24,7 @@ use std::{
     time::Duration,
 };
 
-type EventCallback = fn(&mut CachedEnforcer, Option<EventData>);
+type EventCallback = fn(&mut CachedEnforcer, EventData);
 
 pub struct CachedEnforcer {
     pub(crate) enforcer: Enforcer,
@@ -30,15 +33,15 @@ pub struct CachedEnforcer {
 }
 
 impl EventEmitter<Event> for CachedEnforcer {
-    fn on(&mut self, e: Event, f: fn(&mut Self, Option<EventData>)) {
+    fn on(&mut self, e: Event, f: fn(&mut Self, EventData)) {
         self.events.entry(e).or_insert_with(Vec::new).push(f)
     }
 
     fn off(&mut self, e: Event) {
         self.events.remove(&e);
     }
 
-    fn emit(&mut self, e: Event, d: Option<EventData>) {
+    fn emit(&mut self, e: Event, d: EventData) {
         if let Some(cbs) = self.events.get(&e) {
             for cb in cbs.clone().iter() {
                 cb(self, d.clone())
@@ -59,7 +62,7 @@ impl CoreApi for CachedEnforcer {
             events: HashMap::new(),
         };
 
-        cached_enforcer.on(Event::PolicyChange, clear_cache);
+        cached_enforcer.on(Event::ClearCache, clear_cache);
 
         Ok(cached_enforcer)
     }
@@ -128,21 +131,61 @@ impl CoreApi for CachedEnforcer {
         self.enforcer.set_adapter(a).await
     }
 
+    #[cfg(feature = "logging")]
+    #[inline]
+    fn get_logger(&self) -> &dyn Logger {
+        self.enforcer.get_logger()
+    }
+
+    #[cfg(feature = "logging")]
+    #[inline]
+    fn set_logger(&mut self, l: Box<dyn Logger>) {
+        self.enforcer.set_logger(l);
+    }
+
     #[inline]
     fn set_effector(&mut self, e: Box<dyn Effector>) {
         self.enforcer.set_effector(e);
     }
 
     async fn enforce_mut<S: AsRef<str> + Send + Sync>(&mut self, rvals: &[S]) -> Result<bool> {
         let key: Vec<String> = rvals.iter().map(|x| String::from(x.as_ref())).collect();
+        #[allow(unused_variables)]
+        let log_enabled = {
+            #[cfg(feature = "logging")]
+            {
+                if self.enforcer.get_logger().is_enabled() {
+                    self.enforcer.enable_log(false);
+                    true
+                } else {
+                    false
+                }
+            }
 
-        if let Some(result) = self.cache.get(&key).await {
-            Ok(*result)
+            #[cfg(not(feature = "logging"))]
+            {
+                false
+            }
+        };
+
+        #[allow(unused_variables)]
+        let (res, is_cached) = if let Some(result) = self.cache.get(&key).await {
+            (*result, true)
         } else {
             let result = self.enforcer.enforce(rvals).await?;
-            self.cache.set(key, result).await;
-            Ok(result)
+            self.cache.set(key.clone(), result).await;
+            (result, false)
+        };
+
+        #[cfg(feature = "logging")]
+        {
+            self.enforcer.enable_log(log_enabled);
+            self.enforcer
+                .get_logger()
+                .print_enforce_log(key, res, is_cached);
         }
+
+        Ok(res)
     }
 
     /// CachedEnforcer should use `enforce_mut` instead so that
@@ -181,6 +224,12 @@ impl CoreApi for CachedEnforcer {
         self.enforcer.clear_policy();
     }
 
+    #[cfg(feature = "logging")]
+    #[inline]
+    fn enable_log(&mut self, enabled: bool) {
+        self.enforcer.enable_log(enabled);
+    }
+
     #[inline]
     fn enable_enforce(&mut self, enabled: bool) {
         self.enforcer.enable_enforce(enabled);

src/convert.rs

@@ -54,6 +54,14 @@ where
     }
 }
 
+#[allow(clippy::unit_arg)]
+#[async_trait]
+impl TryIntoAdapter for () {
+    async fn try_into_adapter(self) -> Result<Box<dyn Adapter>> {
+        Ok(Box::new(NullAdapter))
+    }
+}
+
 #[async_trait]
 impl<T> TryIntoModel for T
 where

src/core_api.rs

@@ -2,6 +2,9 @@ use crate::{
     Adapter, Effector, Filter, Model, Result, RoleManager, TryIntoAdapter, TryIntoModel, Watcher,
 };
 
+#[cfg(feature = "logging")]
+use crate::Logger;
+
 use async_trait::async_trait;
 
 use std::sync::{Arc, RwLock};
@@ -19,6 +22,10 @@ pub trait CoreApi: Sized + Send + Sync {
     fn get_mut_watcher(&mut self) -> Option<&mut dyn Watcher>;
     fn get_role_manager(&self) -> Arc<RwLock<dyn RoleManager>>;
     fn set_role_manager(&mut self, rm: Arc<RwLock<dyn RoleManager>>) -> Result<()>;
+    #[cfg(feature = "logging")]
+    fn get_logger(&self) -> &dyn Logger;
+    #[cfg(feature = "logging")]
+    fn set_logger(&mut self, logger: Box<dyn Logger>);
     fn add_matching_fn(&mut self, f: fn(String, String) -> bool) -> Result<()>;
     async fn set_model<M: TryIntoModel>(&mut self, m: M) -> Result<()>;
     async fn set_adapter<A: TryIntoAdapter>(&mut self, a: A) -> Result<()>;
@@ -31,6 +38,8 @@ pub trait CoreApi: Sized + Send + Sync {
     fn is_filtered(&self) -> bool;
     async fn save_policy(&mut self) -> Result<()>;
     fn clear_policy(&mut self);
+    #[cfg(feature = "logging")]
+    fn enable_log(&mut self, enabled: bool);
     fn enable_auto_save(&mut self, auto_save: bool);
     fn enable_enforce(&mut self, enabled: bool);
     fn enable_auto_build_role_links(&mut self, auto_build_role_links: bool);

src/emitter.rs

@@ -1,10 +1,11 @@
 use crate::{cached_api::CachedApi, core_api::CoreApi};
 
-use std::hash::Hash;
+use std::{fmt, hash::Hash};
 
 #[derive(Hash, PartialEq, Eq)]
 pub enum Event {
     PolicyChange,
+    ClearCache,
 }
 
 pub trait EventKey: Hash + PartialEq + Eq + Send + Sync {}
@@ -18,24 +19,47 @@ pub enum EventData {
     RemovePolicies(Vec<Vec<String>>),
     RemoveFilteredPolicy(Vec<Vec<String>>),
     SavePolicy(Vec<Vec<String>>),
+    ClearCache,
+}
+
+impl fmt::Display for EventData {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        use EventData::*;
+        match *self {
+            AddPolicy(ref p) => write!(f, "Event: AddPolicy, Data: {:?}", p.join(", ")),
+            AddPolicies(ref p) => write!(f, "Event: AddPolicies, Added: {}", p.len()),
+            RemovePolicy(ref p) => write!(f, "Event: RemovePolicy, Data: {:?}", p.join(", ")),
+            RemovePolicies(ref p) => write!(f, "Event: RemovePolicies, Removed: {}", p.len()),
+            RemoveFilteredPolicy(ref p) => {
+                write!(f, "Event: RemoveFilteredPolicy, Removed: {}", p.len())
+            }
+            SavePolicy(ref p) => write!(f, "Event: SavePolicy, Saved: {}", p.len()),
+            ClearCache => write!(f, "Event: ClearCache, Data: ClearCache"),
+        }
+    }
 }
 
 pub trait EventEmitter<K>
 where
     K: EventKey,
 {
-    fn on(&mut self, e: K, f: fn(&mut Self, Option<EventData>));
+    fn on(&mut self, e: K, f: fn(&mut Self, EventData));
     fn off(&mut self, e: K);
-    fn emit(&mut self, e: K, d: Option<EventData>);
+    fn emit(&mut self, e: K, d: EventData);
 }
 
-pub(crate) fn notify_watcher<T: CoreApi>(e: &mut T, d: Option<EventData>) {
+pub(crate) fn notify_watcher<T: CoreApi>(e: &mut T, d: EventData) {
+    #[cfg(feature = "logging")]
+    {
+        e.get_logger().print_mgmt_log(&d);
+    }
+
     if let Some(w) = e.get_mut_watcher() {
         w.update(d);
     }
 }
 
-pub(crate) fn clear_cache<T: CoreApi + CachedApi>(ce: &mut T, _d: Option<EventData>) {
+pub(crate) fn clear_cache<T: CoreApi + CachedApi>(ce: &mut T, _d: EventData) {
     #[cfg(feature = "runtime-tokio")]
     {
         tokio::runtime::Builder::new()