False negative result of enforcer.enforce()

[damienmiheev]

What's your scenario? What do you want to achieve? I'm using SyncedEnforcer in my app. There is only one instance of app, so redis watcher is disabled. Inside the app i'm using multiple write operations which may be called asynchronously in a different modules:

• removeNamedGroupingPolicies(..)
• addNamedGroupingPolicies(..)
• addPolicies(..)
• removePolicies(..)

Most of the time application works fine, but periodically something wrong is happening:

1. enforce(..) returns false, when true is expected
2. getRolesForUser(..) returns empty list, when the list of valid roles is expected

We started our investigation by checking what is the data is currently loaded to casbin model (to verify that the actual policies are valid, and it is not related to business logic of the app). To achieve that immediately after issue happened we fetched the data by:

• policies - getPolicy()
• g - enforcer.getNamedGroupingPolicy("g")
• g2 - enforcer.getNamedGroupingPolicy("g2")

By doing that we verified that the data currently loaded to enforcer model is valid. Also the correctness of data was confirmed in db.

We also replaced getRolesForUser(..) to enforcer.getNamedGroupingPolicy("g") and after that issue №2 has been disappeared. But this was only workaround, we still don't know the root cause of the problem nor the steps to reproduce it.

Definitely something wrong with getRolesForUser(..). It is synchronised by readLock(), but if you will take a look on the implementation of this method there is some write operations on the roleManager inner map which is not thread safe. So my assumption it is definitely need to be revisioned. As i said before we just replaced it with enforcer.getNamedGroupingPolicy("g") which is totally thread safe because produce only read operations.

But now we still have an issue with enforcer.enforce(..). I don't know are they (№1 and №2) connected. The main problem we don't have any steps to reproduce it. But the issue is still there and I only can make an assumption it is somehow related to multithreading.

Your model:

[request_definition]
r = sub, obj, act, type

[policy_definition]
p = sub, obj, act

[role_definition]
g = _, _
g2 = _, _, _

[policy_effect]
e = some(where (p.eft == allow))

[matchers]
m = g(r.sub, p.sub) && g2(r.obj, p.obj, r.type) && r.act == p.act

Your policy:

p, users, book1, read
p, admins, magazine1, write

g, alice, users
g, bob, admins

g2, article1, book1, book
g2, article2, magazine1, magazine

Your request(s):

alice, article1, read, book ---> false (expected: true)

I'm using latest version of jcasbin. Please help me to resolve this issue.

[imp2002]

Thanks for your detailed feedback😊. I will try fix it.

[damienmiheev]

@imp2002 any idea what may be the reason here?

[imp2002]

https://github.com/casbin/jcasbin/pull/310 try to fix it. You can try the lastest after the PR be merged. And the issue maybe close once the PR be merged, feel free to reopen it. Glad to see your feedback.

[damienmiheev]

@imp2002 oh, unfortunately problem is somewhere else. I replaced all the usage of getRole and getUser with getGroupingNamedFilteredPolicy.

Making getRole synchronised by write lock is also not correct i believe, because the performance of this method may be slightly decreased for my case. But that's not the main topic.

Something wrong with enforcer.enforce. Maybe some kind of deadlock under the hood, i don't know. Unfortunately i was not able to catch the issue due to small amount of debug logs.

[imp2002]

Something wrong with enforcer.enforce. Maybe some kind of deadlock under the hood, i don't know.

I'm still not sure if there's a problem here.

[damienmiheev]

@imp2002 I'll try to explain my guess. This is a list of methods used in our app:

• enforce(Object... rvals) - R?
• removeNamedGroupingPolicy(String ptype, String... params) - W
• getFilteredNamedGroupingPolicy(String ptype, int fieldIndex, String... fieldValues) - R*
• addNamedGroupingPolicy(String ptype, String... params) - W
• addPolicies(List<List> rules) - W
• addPolicy(List params) - W
• removePolicies(List<List> rules) - W
• removePolicy(List params) - W
• getFilteredPolicy(int fieldIndex, String... fieldValues) - R*
• addNamedGroupingPolicy(String ptype, List params) - W
• addNamedGroupingPolicies(String ptype, List<List> rules) - W

Methods marked with W are thread safe due to ReentrantReadWriteLock. Methods with R* are also thread safe because they are immutable.

So the only candidate is enforce(Object... rvals). And i remember there were already some concurrency issues with it: https://github.com/casbin/jcasbin/issues/292

I also noticed that enforce starts returning 403 on a high traffic (in my case it is integration tests run). Unfortunately my knowledge of casbin source code is not enough to find the reason of bug, and because the issue is randomly happening it was impossible for me to catch it in debug mode.

[hsluoyz]

@imp2002

[imp2002]

Can you roughly show some code to reproduce it? I can't reproduce this problem with the previous multi-threaded test code.

returning 403 on a high traffic

And What does your mean to return 403? Doesn't enforce only return true or false?

[damienmiheev]

That's the problem. We don't have scenario to reproduce it. The issue is happening randomly.

Sorry for confusing with 403. It's because we use spring permission evaluator with enforcer inside. And it means enforcer.enforce returns false where true is expected.

To fix it we just re-deploy the app. So basically enforcer load correct policies from db by loadPolicy. The data stored in db is always correct and something wrong with indexed in-memory data.

[hsluoyz]

Closed for now, feel free to open if you have more clues