feat: log expression compilation errors and replace single quotes in ExpressionHandler (#397)

* Initial plan

* Log expression compilation errors and replace single quotes in expressions

Co-authored-by: hsluoyz <3787410+hsluoyz@users.noreply.github.com>

* Propagate logger via property setters instead of per-call in InternalEnforce

Co-authored-by: sagilio <42855245+sagilio@users.noreply.github.com>

* fix: pass exception to log formatter in MockLogger

Co-authored-by: sagilio <42855245+sagilio@users.noreply.github.com>

* refactor: move single-quote normalization to EnforceView.CreateWithMatcher

Co-authored-by: sagilio <42855245+sagilio@users.noreply.github.com>

---------

Co-authored-by: copilot-swe-agent[bot] <198982749+Copilot@users.noreply.github.com>
Co-authored-by: hsluoyz <3787410+hsluoyz@users.noreply.github.com>
Co-authored-by: sagilio <42855245+sagilio@users.noreply.github.com>

Author: 3 people

Casbin.UnitTests/Mock/MockLogger.cs

@@ -1,5 +1,6 @@
 #if !NET452
 using System;
+using System.Collections.Generic;
 using Microsoft.Extensions.Logging;
 using Xunit.Abstractions;
 
@@ -11,11 +12,14 @@ public class MockLogger<T> : ILogger<T>
 
         public MockLogger(ITestOutputHelper testOutputHelper) => _testOutputHelper = testOutputHelper;
 
+        public List<(LogLevel Level, Exception Exception, string Message)> Logs { get; } = new();
+
         public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception exception,
             Func<TState, Exception, string> formatter)
         {
-            string outPut = formatter(state, null);
+            string outPut = formatter(state, exception);
             _testOutputHelper.WriteLine(outPut);
+            Logs.Add((logLevel, exception, outPut));
         }
 
         public bool IsEnabled(LogLevel logLevel) => true;

Casbin.UnitTests/ModelTests/EnforcerTest.cs

@@ -1290,4 +1290,33 @@ public async Task TestEnforceExWithMatcherAsync()
     }
 
     #endregion
+
+#if !NET452
+    #region ExpressionHandler Tests
+
+    [Fact]
+    public void TestExpressionHandlerSingleQuoteReplacement()
+    {
+        Enforcer e = new(TestModelFixture.GetBasicTestModel());
+        // Single quotes should be replaced with double quotes to handle DynamicExpresso limitations
+        string matcherWithSingleQuotes = "r.sub == 'alice' && r.obj == p.obj && r.act == p.act";
+
+        Assert.True(e.EnforceWithMatcher(matcherWithSingleQuotes, "alice", "data1", "read"));
+        Assert.False(e.EnforceWithMatcher(matcherWithSingleQuotes, "alice", "data1", "write"));
+        Assert.False(e.EnforceWithMatcher(matcherWithSingleQuotes, "bob", "data1", "read"));
+    }
+
+    [Fact]
+    public void TestExpressionHandlerLogsWarningOnInvalidExpression()
+    {
+        var logger = new MockLogger<Enforcer>(_testOutputHelper);
+        Enforcer e = new(TestModelFixture.GetBasicTestModel()) { Logger = logger };
+
+        // An invalid expression should return false and log a warning
+        Assert.False(e.EnforceWithMatcher("this_is_not_valid!!!", "alice", "data1", "read"));
+        Assert.Contains(logger.Logs, log => log.Level == Microsoft.Extensions.Logging.LogLevel.Warning);
+    }
+
+    #endregion
+#endif
 }

Casbin/EnforceView.cs

@@ -59,6 +59,7 @@ public static EnforceView CreateWithMatcher(
             string policyType = PermConstants.DefaultPolicyType,
             string effectType = PermConstants.DefaultPolicyEffectType)
         {
+            matcher = matcher.Replace('\'', '"');
             IReadOnlyAssertion requestAssertion = model.Sections.GetRequestAssertion(requestType);
             PolicyAssertion policyAssertion = model.Sections.GetPolicyAssertion(policyType);
             IReadOnlyAssertion effectAssertion = model.Sections.GetPolicyEffectAssertion(effectType);

Casbin/Enforcer.cs

@@ -2,6 +2,7 @@
 using System.Threading.Tasks;
 using Casbin.Caching;
 using Casbin.Effect;
+using Casbin.Evaluation;
 using Casbin.Model;
 using Casbin.Persist;
 using Casbin.Persist.Adapter.File;
@@ -84,7 +85,22 @@ public IReadOnlyWatcher Watcher
             set => Model.WatcherHolder.Watcher = value;
         }
 
-        public IModel Model { get; set; }
+        private IModel _model;
+
+        public IModel Model
+        {
+            get => _model;
+            set
+            {
+                _model = value;
+#if !NET452
+                if (value?.ExpressionHandler is ExpressionHandler exprHandler)
+                {
+                    exprHandler.Logger = _logger;
+                }
+#endif
+            }
+        }
 
         public IReadOnlyAdapter Adapter
         {
@@ -99,7 +115,20 @@ public IEnforceCache EnforceCache
         }
 
 #if !NET452
-        public ILogger Logger { get; set; }
+        private ILogger _logger;
+
+        public ILogger Logger
+        {
+            get => _logger;
+            set
+            {
+                _logger = value;
+                if (_model?.ExpressionHandler is ExpressionHandler exprHandler)
+                {
+                    exprHandler.Logger = value;
+                }
+            }
+        }
 #endif
 
         #endregion

Casbin/Evaluation/ExpressionHandler.cs

@@ -5,6 +5,9 @@
 using Casbin.Functions;
 using Casbin.Model;
 using DynamicExpresso;
+#if !NET452
+using Microsoft.Extensions.Logging;
+#endif
 
 namespace Casbin.Evaluation;
 
@@ -20,6 +23,10 @@ internal class ExpressionHandler : IExpressionHandler
 
     private bool TryCompile { get; set; } = true;
 
+#if !NET452
+    internal ILogger Logger { get; set; }
+#endif
+
     public ExpressionHandler()
     {
         _interpreter = CreateInterpreter();
@@ -117,9 +124,12 @@ private bool TryCompileExpression<TRequest, TPolicy>(in EnforceContext context,
         {
             func = CompileExpression<TRequest, TPolicy>(in context, expressionString);
         }
-        catch (Exception)
+        catch (Exception e)
         {
             func = null;
+#if !NET452
+            Logger?.LogWarning(e, "Failed to compile the expression \"{ExpressionString}\".", expressionString);
+#endif
             return false;
         }
         return true;