From 9cb4fbd980c8e9448a47351939cd4fc80f59e23d Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 2 Feb 2026 02:25:58 +0000 Subject: [PATCH 1/5] Initial plan From 5808193c1c31744215639e8e0487ad841ebe221b Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 2 Feb 2026 02:31:14 +0000 Subject: [PATCH 2/5] Optimize logging in enforce_ex to avoid unnecessary str() calls Co-authored-by: hsluoyz <3787410+hsluoyz@users.noreply.github.com> --- casbin/core_enforcer.py | 21 ++++++----- tests/test_enforcer.py | 77 +++++++++++++++++++++++++++++++++++++++++ 2 files changed, 89 insertions(+), 9 deletions(-) diff --git a/casbin/core_enforcer.py b/casbin/core_enforcer.py index 4ffcef2..986bbfb 100644 --- a/casbin/core_enforcer.py +++ b/casbin/core_enforcer.py @@ -508,17 +508,20 @@ def enforce_ex(self, *rvals): result = effect_to_bool(final_effect) # Log request. - - req_str = "Request: " - req_str = req_str + ", ".join([str(v) for v in rvals]) - - req_str = req_str + " ---> %s" % result if result: - self.logger.info(req_str) + if self.logger.isEnabledFor(logging.INFO): + req_str = "Request: " + req_str = req_str + ", ".join([str(v) for v in rvals]) + req_str = req_str + " ---> %s" % result + self.logger.info(req_str) else: - # leaving this in warning for now, if it's very noise this can be changed to info or debug, - # or change the log level - self.logger.warning(req_str) + if self.logger.isEnabledFor(logging.WARNING): + req_str = "Request: " + req_str = req_str + ", ".join([str(v) for v in rvals]) + req_str = req_str + " ---> %s" % result + # leaving this in warning for now, if it's very noise this can be changed to info or debug, + # or change the log level + self.logger.warning(req_str) explain_rule = [] if explain_index != -1 and explain_index < policy_len: diff --git a/tests/test_enforcer.py b/tests/test_enforcer.py index 5ad0626..d431a78 100644 --- a/tests/test_enforcer.py +++ b/tests/test_enforcer.py @@ -575,6 +575,83 @@ def test_link_condition_function(self): self.assertFalse(e.enforce("alice", "domain5", "data5", "read")) self.assertFalse(e.enforce("alice", "domain5", "data5", "write")) + def test_enforce_ex_no_str_call_when_logging_disabled(self): + """Test that str() is not called on rvals when logging is disabled.""" + import logging + + # Create a custom class that tracks str() calls + class TrackedObject(str): + """A string subclass that tracks when str() is called.""" + str_call_count = 0 + + def __new__(cls, value): + instance = super().__new__(cls, value) + return instance + + def __str__(self): + TrackedObject.str_call_count += 1 + return super().__str__() + + e = self.get_enforcer( + get_examples("basic_model.conf"), + get_examples("basic_policy.csv"), + ) + + # Get the actual enforcer (for SyncedEnforcer, it's wrapped in _e) + actual_enforcer = e._e if hasattr(e, '_e') else e + + # Set logger to ERROR level (above INFO and WARNING) + actual_enforcer.logger.disabled = False + actual_enforcer.logger.setLevel(logging.ERROR) + + # Reset counter + TrackedObject.str_call_count = 0 + + # Call enforce_ex with TrackedObject instances + obj1 = TrackedObject("alice") + obj2 = TrackedObject("data1") + obj3 = TrackedObject("read") + + result, explain = e.enforce_ex(obj1, obj2, obj3) + + # str() should not be called when logging is disabled + self.assertEqual(TrackedObject.str_call_count, 0, "str() should not be called when logging is disabled") + self.assertTrue(result) + + # Now enable INFO level logging + actual_enforcer.logger.setLevel(logging.INFO) + TrackedObject.str_call_count = 0 + + result, explain = e.enforce_ex(obj1, obj2, obj3) + + # str() should be called when logging is enabled + self.assertGreater(TrackedObject.str_call_count, 0, "str() should be called when logging is enabled") + self.assertTrue(result) + + # Test with WARNING level (for failed enforce) + actual_enforcer.logger.setLevel(logging.WARNING) + TrackedObject.str_call_count = 0 + + obj4 = TrackedObject("alice") + obj5 = TrackedObject("data2") + obj6 = TrackedObject("read") + + result, explain = e.enforce_ex(obj4, obj5, obj6) + + # str() should be called for WARNING level + self.assertGreater(TrackedObject.str_call_count, 0, "str() should be called for WARNING level") + self.assertFalse(result) + + # Test with ERROR level (logging disabled for WARNING) + actual_enforcer.logger.setLevel(logging.ERROR) + TrackedObject.str_call_count = 0 + + result, explain = e.enforce_ex(obj4, obj5, obj6) + + # str() should not be called when logging is disabled + self.assertEqual(TrackedObject.str_call_count, 0, "str() should not be called when WARNING logging is disabled") + self.assertFalse(result) + class TestConfigSynced(TestConfig): def get_enforcer(self, model=None, adapter=None): From 651a35242dd80936de0049595684f93fcc92d8dd Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 2 Feb 2026 02:32:56 +0000 Subject: [PATCH 3/5] Refactor logging code to eliminate duplication Co-authored-by: hsluoyz <3787410+hsluoyz@users.noreply.github.com> --- casbin/core_enforcer.py | 18 ++++++++---------- 1 file changed, 8 insertions(+), 10 deletions(-) diff --git a/casbin/core_enforcer.py b/casbin/core_enforcer.py index 986bbfb..5b5e0e5 100644 --- a/casbin/core_enforcer.py +++ b/casbin/core_enforcer.py @@ -508,17 +508,15 @@ def enforce_ex(self, *rvals): result = effect_to_bool(final_effect) # Log request. - if result: - if self.logger.isEnabledFor(logging.INFO): - req_str = "Request: " - req_str = req_str + ", ".join([str(v) for v in rvals]) - req_str = req_str + " ---> %s" % result + if (result and self.logger.isEnabledFor(logging.INFO)) or ( + not result and self.logger.isEnabledFor(logging.WARNING) + ): + req_str = "Request: " + req_str = req_str + ", ".join([str(v) for v in rvals]) + req_str = req_str + " ---> %s" % result + if result: self.logger.info(req_str) - else: - if self.logger.isEnabledFor(logging.WARNING): - req_str = "Request: " - req_str = req_str + ", ".join([str(v) for v in rvals]) - req_str = req_str + " ---> %s" % result + else: # leaving this in warning for now, if it's very noise this can be changed to info or debug, # or change the log level self.logger.warning(req_str) From 48abb7f5ad09f0be0b5ce9d8767d5ff45bca3dfb Mon Sep 17 00:00:00 2001 From: "copilot-swe-agent[bot]" <198982749+Copilot@users.noreply.github.com> Date: Mon, 2 Feb 2026 02:54:30 +0000 Subject: [PATCH 4/5] Fix: apply Black formatting to test file Co-authored-by: hsluoyz <3787410+hsluoyz@users.noreply.github.com> --- tests/test_enforcer.py | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-) diff --git a/tests/test_enforcer.py b/tests/test_enforcer.py index d431a78..c21a0e1 100644 --- a/tests/test_enforcer.py +++ b/tests/test_enforcer.py @@ -582,6 +582,7 @@ def test_enforce_ex_no_str_call_when_logging_disabled(self): # Create a custom class that tracks str() calls class TrackedObject(str): """A string subclass that tracks when str() is called.""" + str_call_count = 0 def __new__(cls, value): @@ -598,7 +599,7 @@ def __str__(self): ) # Get the actual enforcer (for SyncedEnforcer, it's wrapped in _e) - actual_enforcer = e._e if hasattr(e, '_e') else e + actual_enforcer = e._e if hasattr(e, "_e") else e # Set logger to ERROR level (above INFO and WARNING) actual_enforcer.logger.disabled = False From 3d899441ff1cdab9bd2511daf1f32fbc600e601c Mon Sep 17 00:00:00 2001 From: Yang Luo Date: Mon, 2 Feb 2026 11:00:43 +0800 Subject: [PATCH 5/5] Update test_enforcer.py --- tests/test_enforcer.py | 78 ------------------------------------------ 1 file changed, 78 deletions(-) diff --git a/tests/test_enforcer.py b/tests/test_enforcer.py index c21a0e1..5ad0626 100644 --- a/tests/test_enforcer.py +++ b/tests/test_enforcer.py @@ -575,84 +575,6 @@ def test_link_condition_function(self): self.assertFalse(e.enforce("alice", "domain5", "data5", "read")) self.assertFalse(e.enforce("alice", "domain5", "data5", "write")) - def test_enforce_ex_no_str_call_when_logging_disabled(self): - """Test that str() is not called on rvals when logging is disabled.""" - import logging - - # Create a custom class that tracks str() calls - class TrackedObject(str): - """A string subclass that tracks when str() is called.""" - - str_call_count = 0 - - def __new__(cls, value): - instance = super().__new__(cls, value) - return instance - - def __str__(self): - TrackedObject.str_call_count += 1 - return super().__str__() - - e = self.get_enforcer( - get_examples("basic_model.conf"), - get_examples("basic_policy.csv"), - ) - - # Get the actual enforcer (for SyncedEnforcer, it's wrapped in _e) - actual_enforcer = e._e if hasattr(e, "_e") else e - - # Set logger to ERROR level (above INFO and WARNING) - actual_enforcer.logger.disabled = False - actual_enforcer.logger.setLevel(logging.ERROR) - - # Reset counter - TrackedObject.str_call_count = 0 - - # Call enforce_ex with TrackedObject instances - obj1 = TrackedObject("alice") - obj2 = TrackedObject("data1") - obj3 = TrackedObject("read") - - result, explain = e.enforce_ex(obj1, obj2, obj3) - - # str() should not be called when logging is disabled - self.assertEqual(TrackedObject.str_call_count, 0, "str() should not be called when logging is disabled") - self.assertTrue(result) - - # Now enable INFO level logging - actual_enforcer.logger.setLevel(logging.INFO) - TrackedObject.str_call_count = 0 - - result, explain = e.enforce_ex(obj1, obj2, obj3) - - # str() should be called when logging is enabled - self.assertGreater(TrackedObject.str_call_count, 0, "str() should be called when logging is enabled") - self.assertTrue(result) - - # Test with WARNING level (for failed enforce) - actual_enforcer.logger.setLevel(logging.WARNING) - TrackedObject.str_call_count = 0 - - obj4 = TrackedObject("alice") - obj5 = TrackedObject("data2") - obj6 = TrackedObject("read") - - result, explain = e.enforce_ex(obj4, obj5, obj6) - - # str() should be called for WARNING level - self.assertGreater(TrackedObject.str_call_count, 0, "str() should be called for WARNING level") - self.assertFalse(result) - - # Test with ERROR level (logging disabled for WARNING) - actual_enforcer.logger.setLevel(logging.ERROR) - TrackedObject.str_call_count = 0 - - result, explain = e.enforce_ex(obj4, obj5, obj6) - - # str() should not be called when logging is disabled - self.assertEqual(TrackedObject.str_call_count, 0, "str() should not be called when WARNING logging is disabled") - self.assertFalse(result) - class TestConfigSynced(TestConfig): def get_enforcer(self, model=None, adapter=None):