[Sakai Jira] Created: (KERN-1233) 12.10.2010 16:03:35.854 *WARN* [Finalizer] org.apache.jackrabbit.core.SessionImpl Unclosed session detected. The session was opened here: java.lang.Exception: Stack Trace
Ian Boston (JIRA)
----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Key: KERN-1233
URL: http://jira.sakaiproject.org/browse/KERN-1233
Project: Nakamura
Issue Type: Bug
Components: System - other
Affects Versions: 0.8
Reporter: Ian Boston
Fix For: 0.9
12.10.2010 16:03:35.854 *WARN* [Finalizer] org.apache.jackrabbit.core.SessionImpl Unclosed session detected. The session was opened here: java.lang.Exception: Stack Trace
at org.apache.jackrabbit.core.SessionImpl.<init>(SessionImpl.java:237)
at org.apache.jackrabbit.core.SystemSession.<init>(SystemSession.java:76)
at org.apache.jackrabbit.core.SystemSession.create(SystemSession.java:64)
at org.apache.jackrabbit.core.DynamicSecurityManager.getAccessControlProvider(DynamicSecurityManager.java:564)
at org.apache.jackrabbit.core.DynamicSecurityManager.getAccessManager(DynamicSecurityManager.java:272)
at org.apache.jackrabbit.core.SessionImpl.createAccessManager(SessionImpl.java:373)
at org.apache.jackrabbit.core.SessionImpl.<init>(SessionImpl.java:290)
at org.apache.jackrabbit.core.SessionImpl.<init>(SessionImpl.java:259)
at org.apache.jackrabbit.core.XASessionImpl.<init>(XASessionImpl.java:107)
at org.apache.jackrabbit.core.RepositoryImpl.createSessionInstance(RepositoryImpl.java:1602)
at org.apache.jackrabbit.core.RepositoryImpl.createSession(RepositoryImpl.java:1010)
at org.apache.jackrabbit.core.RepositoryImpl.login(RepositoryImpl.java:1500)
at org.apache.sling.jcr.base.AbstractSlingRepository.login(AbstractSlingRepository.java:214)
at org.apache.sling.jcr.base.AbstractSlingRepository.loginAdministrative(AbstractSlingRepository.java:180)
at org.sakaiproject.nakamura.activity.ActivityListener.onMessage(ActivityListener.java:113)
at org.apache.activemq.ActiveMQMessageConsumer.dispatch(ActiveMQMessageConsumer.java:1088)
at org.apache.activemq.ActiveMQSessionExecutor.dispatch(ActiveMQSessionExecutor.java:127)
at org.apache.activemq.ActiveMQSessionExecutor.iterate(ActiveMQSessionExecutor.java:197)
at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122)
at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)
at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)
at java.lang.Thread.run(Thread.java:619)
--
This message is automatically generated by JIRA.
-
If you think it was sent incorrectly contact one of the administrators: http://jira.sakaiproject.org/secure/Administrators.jspa
-
For more information on JIRA, see: http://www.atlassian.com/software/jira
Ian Boston (JIRA)
[ http://jira.sakaiproject.org/browse/KERN-1233?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Ian Boston reassigned KERN-1233:
--------------------------------
Assignee: Ray Davis
> 12.10.2010 16:03:35.854 *WARN* [Finalizer] org.apache.jackrabbit.core.SessionImpl Unclosed session detected. The session was opened here: java.lang.Exception: Stack Trace
> ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: KERN-1233
> URL: http://jira.sakaiproject.org/browse/KERN-1233
> Project: Nakamura
> Issue Type: Bug
> Components: System - other
> Affects Versions: 0.8
> Reporter: Ian Boston
> Assignee: Ray Davis
Ray Davis (JIRA)
[ http://jira.sakaiproject.org/browse/KERN-1233?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Work on KERN-1233 started by Ray Davis.
> 12.10.2010 16:03:35.854 *WARN* [Finalizer] org.apache.jackrabbit.core.SessionImpl Unclosed session detected. The session was opened here: java.lang.Exception: Stack Trace
> ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: KERN-1233
> URL: http://jira.sakaiproject.org/browse/KERN-1233
> Project: Nakamura
> Issue Type: Bug
> Components: System - other
> Affects Versions: 0.8
> Reporter: Ian Boston
> Assignee: Ray Davis
Ray Davis (JIRA)
[ http://jira.sakaiproject.org/browse/KERN-1233?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Work on KERN-1233 stopped by Ray Davis.
> 12.10.2010 16:03:35.854 *WARN* [Finalizer] org.apache.jackrabbit.core.SessionImpl Unclosed session detected. The session was opened here: java.lang.Exception: Stack Trace
> ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: KERN-1233
> URL: http://jira.sakaiproject.org/browse/KERN-1233
> Project: Nakamura
> Issue Type: Bug
> Components: System - other
> Affects Versions: 0.8
> Reporter: Ian Boston
> Assignee: Ray Davis
Ray Davis (JIRA)
[ http://jira.sakaiproject.org/browse/KERN-1233?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Ray Davis reassigned KERN-1233:
-------------------------------
Assignee: (was: Ray Davis)
Based on the bugbash log, these exceptions happen in pairs. In each pair, one of the open sessions is the admin session that gets created at the top of the onMessage call. The other is created as a side-effect of the PersonalActivityRouter trying to get the UserManager from the node created for the new activity (with a path like "/_user/[USER_PATH]/public/authprofile/activity/[GENERATED_PATH]"). Nakamura's DynamicSecurityManager takes the getUserManager(Session) call. If the DynamicSecurityManager's stored "systemSession" has a different workspace name than the workspace name associated with the node-derived session, then DynamicSecurityManager creates a new session (without a corresponding session logout) to provide the UserManager. The logic is copied from Jackrabbit's DefaultSecurityManager, but I confess I don't yet understand how it normally expects to handle session cleanup.
There are a pair of these exceptions for about half of the POSTs to update a user's current activity status (29 POSTs, 34 exceptions).
I spent about four hours trying to reproduce the issue with various combinations of personal connections, multiple updates from different browsers, integration tests running, and explicit garbage collections. Although I hit a number of other problems, I was never able to generate this one.
Since I don't yet understand one of the key aspects of the code, I haven't been able to reproduce the issue, and I'm unavailable tomorrow, I'm going to declare defeat for now and open this bug to other takers.
Ray Davis (JIRA)
[ http://jira.sakaiproject.org/browse/KERN-1233?page=com.atlassian.jira.plugin.system.issuetabpanels:worklog-tabpanel#action_51666 ]
Ray Davis logged work on KERN-1233:
-----------------------------------
Author: Ray Davis
Created on: 13-Oct-2010 15:44
Start Date: 13-Oct-2010 15:44
Worklog Time Spent: 4 hours
Issue Time Tracking
-------------------
Remaining Estimate: 0 minutes
Time Spent: 4 hours
> 12.10.2010 16:03:35.854 *WARN* [Finalizer] org.apache.jackrabbit.core.SessionImpl Unclosed session detected. The session was opened here: java.lang.Exception: Stack Trace
> ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: KERN-1233
> URL: http://jira.sakaiproject.org/browse/KERN-1233
> Project: Nakamura
> Issue Type: Bug
> Components: System - other
> Affects Versions: 0.8
> Reporter: Ian Boston
> Fix For: 0.9
>
> Time Spent: 4 hours
> Remaining Estimate: 0 minutes
Ian Boston (JIRA)
[ http://jira.sakaiproject.org/browse/KERN-1233?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=111146#action_111146 ]
Ian Boston commented on KERN-1233:
----------------------------------
Sessions in the DynamicSecurityManager are bound to Workspaces and then Threads, stored in a SoftReference + Weak Keyed hashmap. If the thread goes, the session is closed as GC puts the AccessControlProvider that uses the session into a ReferenceQueue and closed (also closing the session). If the GC is under extreem pressure the Softreference is broken and the ACP goes into a RefenceQueue to be closed. Also if the ACP is old (time or overuse) its retired and closed.
Closing is a two stage process, the ACP is unbound, and then a fixed period of time later its closed. This is to allow any active threads that may be using the ACP to finish what they are doing and release any references to the session.
Why bother doing all this?
Standard Jackrabbit uses 1 session per Workspace for a single ACP. This does 2 things. Rapidly collects lots and lots of state, eventually containing ever ACL within the system for all users as Nodes in its ItemManager and 2, causes massive blocking when all threads try and get through the ItemManager and do things to the session local item state and 3. Deadlocks on write as some threads get blocked by a synchronization in the ItemManager of the session state and others that have that lock are waiting for a read lock in the SharedItemManager (blocked by the write lock of the first thread).
Some, but not all of this will be fixed in JR2.2. I have a feeling that the Deadlock will still be possible, and have submitted a patch.
> 12.10.2010 16:03:35.854 *WARN* [Finalizer] org.apache.jackrabbit.core.SessionImpl Unclosed session detected. The session was opened here: java.lang.Exception: Stack Trace
> ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: KERN-1233
> URL: http://jira.sakaiproject.org/browse/KERN-1233
> Project: Nakamura
> Issue Type: Bug
> Components: System - other
> Affects Versions: 0.8
> Reporter: Ian Boston
> Fix For: 0.9
>
> Time Spent: 4 hours
> Remaining Estimate: 0 minutes
>
Ian Boston (JIRA)
[ http://jira.sakaiproject.org/browse/KERN-1233?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Ian Boston reassigned KERN-1233:
--------------------------------
Assignee: Ian Boston
> 12.10.2010 16:03:35.854 *WARN* [Finalizer] org.apache.jackrabbit.core.SessionImpl Unclosed session detected. The session was opened here: java.lang.Exception: Stack Trace
> ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: KERN-1233
> URL: http://jira.sakaiproject.org/browse/KERN-1233
> Project: Nakamura
> Issue Type: Bug
> Components: System - other
> Affects Versions: 0.8
> Reporter: Ian Boston
> Assignee: Ian Boston
> Fix For: 0.9
>
> Time Spent: 4 hours
> Remaining Estimate: 0 minutes
>
Ian Boston (JIRA)
[ http://jira.sakaiproject.org/browse/KERN-1233?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Ian Boston resolved KERN-1233.
------------------------------
Resolution: Won't Fix
Since all AccessControlProviders are held by the AccessControlProviderHolders which are Softly Referenced, and the AccessControlProviderHolder holds a strong reference to the SystemSession (which is the session in this case) the system session cannot be GC'd before the AccessControlProvider's soft reference is broken. When the AccessControlProviders soft reference is broken it *should* be added to the ReferenceQueue which *will* cause it and the session be be closed before all references are released. Therefore, the AccessControlProviderHolder is not added to the ReferenceQueue by the GC operation. Since I cant fix the GC behaviour, I cant fix this problem and we will have to live with it. The check on the finaizer in the SessionImpl was placed there to identify programmer errors where the sessions were routinely left open rather than to report that JVMs dont always do what we would expect during GC operations under load.No harm is done by this, so I closing this as wont fix.
> 12.10.2010 16:03:35.854 *WARN* [Finalizer] org.apache.jackrabbit.core.SessionImpl Unclosed session detected. The session was opened here: java.lang.Exception: Stack Trace
> ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: KERN-1233
> URL: http://jira.sakaiproject.org/browse/KERN-1233
> Project: Nakamura
> Issue Type: Bug
> Components: System - other
> Affects Versions: 0.8
> Reporter: Ian Boston
> Assignee: Ian Boston
> Fix For: 0.9
>
> Time Spent: 4 hours
> Remaining Estimate: 0 minutes
>
Ray Davis (JIRA)
[ http://jira.sakaiproject.org/browse/KERN-1233?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=111337#action_111337 ]
Ray Davis commented on KERN-1233:
---------------------------------
Thank you for the detailed explanations, Ian. I find them hugely useful, and I'm sure others will as well.
> 12.10.2010 16:03:35.854 *WARN* [Finalizer] org.apache.jackrabbit.core.SessionImpl Unclosed session detected. The session was opened here: java.lang.Exception: Stack Trace
> ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>
> Key: KERN-1233
> URL: http://jira.sakaiproject.org/browse/KERN-1233
> Project: Nakamura
> Issue Type: Bug
> Components: System - other
> Affects Versions: 0.8
> Reporter: Ian Boston
> Assignee: Ian Boston
> Fix For: 0.9
>
> Time Spent: 4 hours
> Remaining Estimate: 0 minutes
>