We’ve recently discovered a problem in our audit logging facility where Acegi returns a different user other than the actual user. It’s a little hard to replicate because it happens only when multiple users are accessing the system. In summary, audit logs were associated to other users because Acegi SecurityContextHolder is returning incorrect user reference when invoked within a Hibernate interceptor. Our tests showed that retrieving user within the service or DAO layer works correctly but retrieving user from an interceptor may potentially return a different user.
We discovered this problem during the Beta Test stage since there are multiple concurrent users testing the system. To prove that system is misbehaving, we’ve performed the following:
- Create a long running process for User A session. Let the process continue to execute with recording of audit logs.
- Create a new session for User B and do a couple of actions for the user.
- Check audit logs created for process of User A.
Our test results showed that some audit logs for User A process were recorded to User B, specifically during the time when User B performs an action. Apparently, this poses a serious hidden flaw in using Hibernate Interceptor and Acegi SecurityContextHolder for audit logging.
Hibernate Interceptor seems to create a separate thread to perform postFlush and other interceptor functions and Acegi SecurityContextHolder also has its own threading algorithm. In the end, a disconnect of user sessions.
To solve this problem, we resorted to adding a transient variable for the user id in the Auditable entity. The value of user id is populated on the service level because Acegi returns the correct user reference at this time. While this solution may not seem intrusive, I’m happy to say that it solves the concurrency issue.
Nevertheless, I posted this blog as reference to anyone attempting to implement Audit Logging or anyone who has already encountered the same problem. Please post other possible solutions.