Also I noted this additional information about my problem. By looking at the glassfish logs I noted that Http Session data being lost on the node is highly correlated with:
1. A session replication broadcast log occurs within moments of the servlet request
2. The thread used for the last session replication broadcast log is the same thread that serves the servlet request.
--- BEGIN LOG ---
[#|2008-02-08T23:46:17.009-0500|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=26;_ThreadName=httpSSLWorkerThread-38080-1;|<mprt> DEBUG [httpSSLWorkerThread-38080-1] com.assurz.common.web.stripes.AssurzSecurityManager - ***Begin Session Attributes***
|#]
[#|2008-02-08T23:46:17.010-0500|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=26;_ThreadName=httpSSLWorkerThread-38080-1;|<mprt> DEBUG [httpSSLWorkerThread-38080-1] com.assurz.common.web.stripes.AssurzSecurityManager - com.assurz.common.model.AppUser: com.assurz.mprt.dao.MerchantAccount_at_36794d7c has class: com.assurz.mprt.dao.MerchantAccount
|#]
[#|2008-02-08T23:46:17.012-0500|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=26;_ThreadName=httpSSLWorkerThread-38080-1;|<mprt> DEBUG [httpSSLWorkerThread-38080-1] com.assurz.common.web.stripes.AssurzSecurityManager - __stripes_secret_key: javax.crypto.spec.SecretKeySpec_at_fffe82d9 has class: javax.crypto.spec.SecretKeySpec
|#]
[#|2008-02-08T23:46:17.013-0500|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=26;_ThreadName=httpSSLWorkerThread-38080-1;|<mprt> DEBUG [httpSSLWorkerThread-38080-1] com.assurz.common.web.stripes.AssurzSecurityManager - ***End Session Attributes***
|#]
[b]End of good request[/b]
[b]
Beginning of replication broadcast log[/b]
[#|2008-02-08T23:46:17.320-0500|INFO|sun-appserver9.1|com.sun.enterprise.ee.web.sessmgmt|_ThreadID=25;_ThreadName=httpSSLWorkerThread-38080-3;|transferFromReplicationCache for id: c82f5129382aab803d1d67e53985 took: 0 ms|#]
[#|2008-02-08T23:46:17.321-0500|INFO|sun-appserver9.1|com.sun.enterprise.ee.web.sessmgmt|_ThreadID=25;_ThreadName=httpSSLWorkerThread-38080-3;|ReplicationStore>>load:localCachedState=null|#]
[#|2008-02-08T23:46:17.333-0500|INFO|sun-appserver9.1|com.sun.enterprise.ee.web.sessmgmt|_ThreadID=25;_ThreadName=httpSSLWorkerThread-38080-3;|findSessionViaBroadcast for id: c82f5129382aab803d1d67e53985 took: 12 ms|#]
[#|2008-02-08T23:46:17.449-0500|INFO|sun-appserver9.1|com.sun.enterprise.ee.web.sessmgmt|_ThreadID=26;_ThreadName=httpSSLWorkerThread-38080-1;|transferFromReplicationCache for id: c82f5129382aab803d1d67e53985 took: 0 ms|#]
[#|2008-02-08T23:46:17.450-0500|INFO|sun-appserver9.1|com.sun.enterprise.ee.web.sessmgmt|_ThreadID=26;_ThreadName=httpSSLWorkerThread-38080-1;|ReplicationStore>>load:localCachedState=null|#]
[#|2008-02-08T23:46:17.462-0500|INFO|sun-appserver9.1|com.sun.enterprise.ee.web.sessmgmt|_ThreadID=26;_ThreadName=httpSSLWorkerThread-38080-1;|findSessionViaBroadcast for id: c82f5129382aab803d1d67e53985 took: 12 ms|#]
[#|2008-02-08T23:46:17.474-0500|INFO|sun-appserver9.1|com.sun.enterprise.ee.web.sessmgmt|_ThreadID=27;_ThreadName=httpSSLWorkerThread-38080-0;|transferFromReplicationCache for id: c82f5129382aab803d1d67e53985 took: 0 ms|#]
[#|2008-02-08T23:46:17.474-0500|INFO|sun-appserver9.1|com.sun.enterprise.ee.web.sessmgmt|_ThreadID=27;_ThreadName=httpSSLWorkerThread-38080-0;|ReplicationStore>>load:localCachedState=null|#]
[#|2008-02-08T23:46:17.496-0500|INFO|sun-appserver9.1|com.sun.enterprise.ee.web.sessmgmt|_ThreadID=27;_ThreadName=httpSSLWorkerThread-38080-0;|findSessionViaBroadcast for id: c82f5129382aab803d1d67e53985 took: 21 ms|#]
[#|2008-02-08T23:46:17.550-0500|INFO|sun-appserver9.1|com.sun.enterprise.ee.web.sessmgmt|_ThreadID=24;_ThreadName=httpSSLWorkerThread-38080-2;|transferFromReplicationCache for id: c82f5129382aab803d1d67e53985 took: 0 ms|#]
[#|2008-02-08T23:46:17.550-0500|INFO|sun-appserver9.1|com.sun.enterprise.ee.web.sessmgmt|_ThreadID=24;_ThreadName=httpSSLWorkerThread-38080-2;|ReplicationStore>>load:localCachedState=null|#]
[#|2008-02-08T23:46:17.560-0500|INFO|sun-appserver9.1|com.sun.enterprise.ee.web.sessmgmt|_ThreadID=24;_ThreadName=httpSSLWorkerThread-38080-2;|findSessionViaBroadcast for id: c82f5129382aab803d1d67e53985 took: 9 ms|#]
[#|2008-02-08T23:46:17.588-0500|INFO|sun-appserver9.1|com.sun.enterprise.ee.web.sessmgmt|_ThreadID=25;_ThreadName=httpSSLWorkerThread-38080-3;|transferFromReplicationCache for id: c82f5129382aab803d1d67e53985 took: 0 ms|#]
[#|2008-02-08T23:46:17.589-0500|INFO|sun-appserver9.1|com.sun.enterprise.ee.web.sessmgmt|_ThreadID=25;_ThreadName=httpSSLWorkerThread-38080-3;|ReplicationStore>>load:localCachedState=null|#]
[#|2008-02-08T23:46:17.641-0500|INFO|sun-appserver9.1|com.sun.enterprise.ee.web.sessmgmt|_ThreadID=25;_ThreadName=httpSSLWorkerThread-38080-3;|findSessionViaBroadcast for id: c82f5129382aab803d1d67e53985 took: 52 ms|#]
[#|2008-02-08T23:46:17.653-0500|INFO|sun-appserver9.1|com.sun.enterprise.ee.web.sessmgmt|_ThreadID=23;_ThreadName=httpSSLWorkerThread-38080-4;|transferFromReplicationCache for id: c82f5129382aab803d1d67e53985 took: 0 ms|#]
[#|2008-02-08T23:46:17.654-0500|INFO|sun-appserver9.1|com.sun.enterprise.ee.web.sessmgmt|_ThreadID=23;_ThreadName=httpSSLWorkerThread-38080-4;|ReplicationStore>>load:localCachedState=null|#]
[#|2008-02-08T23:46:17.669-0500|INFO|sun-appserver9.1|com.sun.enterprise.ee.web.sessmgmt|_ThreadID=23;_ThreadName=httpSSLWorkerThread-38080-4;|findSessionViaBroadcast for id: c82f5129382aab803d1d67e53985 took: 15 ms|#]
[#|2008-02-08T23:46:46.347-0500|INFO|sun-appserver9.1|com.sun.enterprise.ee.web.sessmgmt|_ThreadID=26;_ThreadName=httpSSLWorkerThread-38080-1;|transferFromReplicationCache for id: c82f5129382aab803d1d67e53985 took: 0 ms|#]
[#|2008-02-08T23:46:46.348-0500|INFO|sun-appserver9.1|com.sun.enterprise.ee.web.sessmgmt|_ThreadID=26;_ThreadName=httpSSLWorkerThread-38080-1;|ReplicationStore>>load:localCachedState=null|#]
[#|2008-02-08T23:46:46.359-0500|INFO|sun-appserver9.1|com.sun.enterprise.ee.web.sessmgmt|_ThreadID=26;_ThreadName=httpSSLWorkerThread-38080-1;|findSessionViaBroadcast for id: c82f5129382aab803d1d67e53985 took: 10 ms|#]
[b]
End of replication broadcast log[/b]
[b]Beginning of bad request[/b]
[#|2008-02-08T23:46:46.367-0500|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=26;_ThreadName=httpSSLWorkerThread-38080-1;|<mprt> DEBUG [httpSSLWorkerThread-38080-1] com.assurz.common.web.stripes.AssurzSecurityManager - ***Begin Request Headers***
|#]
[b]I only included the cookie id in the header to summarize[/b]
[#|2008-02-08T23:46:46.373-0500|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=26;_ThreadName=httpSSLWorkerThread-38080-1;|<mprt> DEBUG [httpSSLWorkerThread-38080-1] com.assurz.common.web.stripes.AssurzSecurityManager - cookie: JSESSIONID=c82f5129382aab803d1d67e53985; JSESSIONIDVERSION=/mprt:9
|#]
[#|2008-02-08T23:46:46.373-0500|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=26;_ThreadName=httpSSLWorkerThread-38080-1;|<mprt> DEBUG [httpSSLWorkerThread-38080-1] com.assurz.common.web.stripes.AssurzSecurityManager - ***End Request Headers***
[#|2008-02-08T23:46:46.399-0500|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=26;_ThreadName=httpSSLWorkerThread-38080-1;|<mprt> DEBUG [httpSSLWorkerThread-38080-1] com.assurz.common.web.stripes.AssurzSecurityManager - ***Begin Session Attributes***
|#]
[b]Notice the session data is gone!!![/b]
[#|2008-02-08T23:46:46.400-0500|INFO|sun-appserver9.1|javax.enterprise.system.stream.out|_ThreadID=26;_ThreadName=httpSSLWorkerThread-38080-1;|<mprt> DEBUG [httpSSLWorkerThread-38080-1] com.assurz.common.web.stripes.AssurzSecurityManager - ***End Session Attributes***
--- END LOG ---
It may be that session data loss correlates individually to events 1 and 2 simply because events 1 and 2 are correlated between themselves. Therefore if either event 1 or 2 is actually causing the problem, it is hard for me to say whether the loss of session data is related to a servlet request coinciding closely in time with a session replication broadcast event or a servlet request being served by the same thread that is performing the session replication broadcast. Of course it is possible that both events 1 and 2 are coincidental and not the cause at all, but since the loss of session data does not occur on every request, it does seem fishy.
Any thoughts? Should I report a bug?
Thanks,
-J
[Message sent by forum member 'jmetcalf' (jmetcalf)]
http://forums.java.net/jive/thread.jspa?messageID=258186