Strange exception in HTTP-Session replication

[pflapf]

Hi,

I found the following lines in my debug output, I'm wondering if this is a deadlock? Version is 4.0.3SP1. We have two JBoss nodes (192.168.130.62:7850, 192.168.130.63:7850), this log is from 192.168.130.63:7850.

09:29:07,215 INFO [STDOUT] org.jboss.cache.lock.TimeoutException: read lock for /JSESSION/localhost/ROOT/TbFhducYwMPVAK3ONtUM7A** could not
be acquired by Thread[TP-Processor8,5,jboss] after 15000 ms. Locks: Read lock owners: []
Write lock owner: <192.168.130.63:7850>:2
, lock info: write owner=<192.168.130.63:7850>:2 (activeReaders=0, activeWriter=Thread[TP-Processor8,5,jboss], waitingReaders=0, waitingWrit
ers=0, waitingUpgrader=0)


The write lock owner 192.168.130.63:7850 is the machine itself, even the same thread, and it can't acquire a read lock? Is this usual? Is this a misconfiguration?

Thanks in advance,
Dirk

[ben.wang]

This is unusual. Should not happen. Can you reproduce it?

-Ben

[pflapf]

Yes, without problems, just need to start both nodes:

12:44:50,211 ERROR [IdentityLock] read lock for /JSESSION/localhost/ROOT/gcTJP89MyXji07wLwJgkGA** could not be acquired by Thread[TP-Process
or2,5,jboss] after 15000 ms. Locks: Read lock owners: []
Write lock owner: <192.168.130.63:7850>:2
, lock info: write owner=<192.168.130.63:7850>:2 (activeReaders=0, activeWriter=Thread[TP-Processor2,5,jboss], waitingReaders=0, waitingWrit
ers=0, waitingUpgrader=0)

Dirk

[pflapf]

Hi!
Has anyone an idea on that problem?


I also found the following exception and I'm wondering if both belong together in any way ...

09:39:18,926 INFO [STDOUT] java.util.ConcurrentModificationException
09:39:18,928 INFO [STDOUT] at java.util.HashMap$HashIterator.nextEntry(HashMap.java:782)
09:39:18,928 INFO [STDOUT] at java.util.HashMap$EntryIterator.next(HashMap.java:824)
09:39:18,928 INFO [STDOUT] at java.util.HashMap.writeObject(HashMap.java:978)
09:39:18,928 INFO [STDOUT] at sun.reflect.GeneratedMethodAccessor73.invoke(Unknown Source)
09:39:18,929 INFO [STDOUT] at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
09:39:18,929 INFO [STDOUT] at java.lang.reflect.Method.invoke(Method.java:324)
09:39:18,929 INFO [STDOUT] at java.io.ObjectStreamClass.invokeWriteObject(ObjectStreamClass.java:809)
09:39:18,929 INFO [STDOUT] at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1296)
09:39:18,929 INFO [STDOUT] at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1247)
09:39:18,930 INFO [STDOUT] at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1052)
09:39:18,930 INFO [STDOUT] at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:278)
09:39:18,930 INFO [STDOUT] at org.jboss.web.tomcat.tc5.session.SessionBasedClusteredSession.writeExternal(SessionBasedClusteredSession.
java:288)
09:39:18,930 INFO [STDOUT] at org.jboss.web.tomcat.tc5.session.JBossCacheService.externalizeSession(JBossCacheService.java:771)
09:39:18,930 INFO [STDOUT] at org.jboss.web.tomcat.tc5.session.JBossCacheService.putSession(JBossCacheService.java:229)
09:39:18,930 INFO [STDOUT] at org.jboss.web.tomcat.tc5.session.SessionBasedClusteredSession.processSessionRepl(SessionBasedClusteredSes
sion.java:165)
09:39:18,931 INFO [STDOUT] at org.jboss.web.tomcat.tc5.session.JBossCacheManager.processSessionRepl(JBossCacheManager.java:606)
09:39:18,931 INFO [STDOUT] at org.jboss.web.tomcat.tc5.session.JBossCacheManager.storeSession(JBossCacheManager.java:375)
09:39:18,931 INFO [STDOUT] at org.jboss.web.tomcat.tc5.session.InstantSnapshotManager.snapshot(InstantSnapshotManager.java:38)
09:39:18,931 INFO [STDOUT] at org.jboss.web.tomcat.tc5.session.ClusteredSessionValve.invoke(ClusteredSessionValve.java:91)
09:39:18,931 INFO [STDOUT] at org.jboss.web.tomcat.tc5.session.JvmRouteValve.invoke(JvmRouteValve.java:73)
09:39:18,931 INFO [STDOUT] at org.jboss.web.tomcat.security.JaccContextValve.invoke(JaccContextValve.java:59)
09:39:18,932 INFO [STDOUT] at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:126)
09:39:18,932 INFO [STDOUT] at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:105)
09:39:18,932 INFO [STDOUT] at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:107)
09:39:18,932 INFO [STDOUT] at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:148)
09:39:18,932 INFO [STDOUT] at org.apache.jk.server.JkCoyoteHandler.invoke(JkCoyoteHandler.java:307)
09:39:18,933 INFO [STDOUT] at org.apache.jk.common.HandlerRequest.invoke(HandlerRequest.java:385)
09:39:18,933 INFO [STDOUT] at org.apache.jk.common.ChannelSocket.invoke(ChannelSocket.java:748)
09:39:18,933 INFO [STDOUT] at org.apache.jk.common.ChannelSocket.processConnection(ChannelSocket.java:678)
09:39:18,933 INFO [STDOUT] at org.apache.jk.common.SocketConnection.runIt(ChannelSocket.java:871)
09:39:18,933 INFO [STDOUT] at org.apache.tomcat.util.threads.ThreadPool$ControlRunnable.run(ThreadPool.java:684)
09:39:18,933 INFO [STDOUT] at java.lang.Thread.run(Thread.java:534)


Maybe this happens if I try to modify a HashMap that is stored in the ClusteredSession object while it is replicated?!

Thanks in advance,

Dirk :)

p.s. this exception occured running only ONE node

[brian.stansberry]

Maybe this happens if I try to modify a HashMap that is stored in the ClusteredSession object while it is replicated?!

There was no synchronization on the attribute Map itself while it was being serialized for replication, so concurrently adding/removing an attribute could raise an exception. This is a bug in 4.0.3 and 4.0.3SP1, see http://jira.jboss.com/jira/browse/JBAS-2571. This is fixed in CVS.