Marshalling problem w/ 2.2.0.CR5
brian.stansberry Jun 27, 2008 5:16 PMWell, maybe not CR5, since I haven't tested this. But, as briefly discussed on the dev list I'm seeing a failure in a AS testsuite test w/ a snapshot built earlier in the week against the head of 2.2.X branch. I assume it's still there in CR5
Problem is remote call comes in to delete a node that's previously been passivated to disk. As part of handling that call the node is read from disk; this fails due to not using the correct classloader. Region-based marshalling is used, buddy replication, FileCacheLoader.
Following is some analysis; not complete but as far as I can go for now. To reproduce, checkout the head of the AS, change the JBC version in component-matrix/pom.xml to CR5, build AS and testsuite, and from testsuite dir
./build.sh tests-clustering-field-br
OK, what I' seeing. First the failure:
2008-06-27 12:53:50,846 TRACE [org.jboss.cache.interceptors.ActivationInterceptor] (Incoming-1,192.168.1.145:43241) loadNode /_BUDDY_BACKUP_/127.0.0.1_43238/JSESSION/localhost/http-field-pass/giGN4tImzJAMCoFaHg-gZw__/__JBossInternal__/ATTRIBUTE/TEST_DESER/_ID_/5c4o141-i7090w-fhz2z6jb-1-fhz323cn-2k 2008-06-27 12:53:50,846 TRACE [org.jboss.cache.RegionManager] (Incoming-1,192.168.1.145:43241) Contents of RegionsRegistry: {/_BUDDY_BACKUP_/127.0.0.1_43238=RegionImpl{fqn=/_BUDDY_BACKUP_/127.0.0.1_43238; classloader=null; status=INACTIVE; eviction=true; timerThreadRegistered=true}, /=RegionImpl{fqn=/; classloader=null; status=INACTIVE; eviction=true; timerThreadRegistered=true}, /JSESSION/localhost/http-field-pass=RegionImpl{fqn=/JSESSION/localhost/http-field-pass; classloader=org.jboss.web.tomcat.service.WebCtxLoader$ENCLoader@41fc8c; status=ACTIVE; eviction=false; timerThreadRegistered=false}} 2008-06-27 12:53:50,847 TRACE [org.jboss.cache.RegionManager] (Incoming-1,192.168.1.145:43241) Trying next region /_BUDDY_BACKUP_/127.0.0.1_43238 and got RegionImpl{fqn=/_BUDDY_BACKUP_/127.0.0.1_43238; classloader=null; status=INACTIVE; eviction=true; timerThreadRegistered=true} 2008-06-27 12:53:50,847 TRACE [org.jboss.cache.RegionManager] (Incoming-1,192.168.1.145:43241) Trying next region / and got RegionImpl{fqn=/; classloader=null; status=INACTIVE; eviction=true; timerThreadRegistered=true} 2008-06-27 12:53:50,847 TRACE [org.jboss.cache.marshall.CacheMarshaller210] (Incoming-1,192.168.1.145:43241) Unmarshalled region as null. Not using a context class loader to unmarshall. 2008-06-27 12:53:50,847 TRACE [org.jboss.cache.marshall.CacheMarshaller210] (Incoming-1,192.168.1.145:43241) Unmarshalled regionFqn null from stream 2008-06-27 12:53:50,847 DEBUG [org.jboss.cache.marshall.CacheMarshaller210] (Incoming-1,192.168.1.145:43241) Region does not exist for Fqn null - not using a context classloader. 2008-06-27 12:53:50,851 ERROR [org.jboss.cache.interceptors.TxInterceptor] (Incoming-1,192.168.1.145:43241) prepare failed! java.lang.ClassNotFoundException: org.jboss.test.cluster.web.DeserializationSensor at java.net.URLClassLoader$1.run(URLClassLoader.java:200) at java.security.AccessController.doPrivileged(Native Method) at java.net.URLClassLoader.findClass(URLClassLoader.java:188) at java.lang.ClassLoader.loadClass(ClassLoader.java:306) at sun.misc.Launcher$AppClassLoader.loadClass(Launcher.java:268) at java.lang.ClassLoader.loadClass(ClassLoader.java:251) at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:319) at java.lang.Class.forName0(Native Method) at java.lang.Class.forName(Class.java:242) at org.jboss.classloader.spi.base.BaseClassLoaderDomain.loadClass(BaseClassLoaderDomain.java:207) at org.jboss.classloader.spi.base.BaseClassLoaderDomain.loadClass(BaseClassLoaderDomain.java:1009) at org.jboss.classloader.spi.base.BaseClassLoader.loadClassFromDomain(BaseClassLoader.java:728) at org.jboss.classloader.spi.base.BaseClassLoader.loadClass(BaseClassLoader.java:372) at java.lang.ClassLoader.loadClass(ClassLoader.java:251) at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:319) at java.lang.Class.forName0(Native Method) at java.lang.Class.forName(Class.java:242) at org.jboss.util.stream.MarshalledValueInputStream.resolveClass(MarshalledValueInputStream.java:62) at java.io.ObjectInputStream.readNonProxyDesc(ObjectInputStream.java:1544) at java.io.ObjectInputStream.readClassDesc(ObjectInputStream.java:1466) at java.io.ObjectInputStream.readOrdinaryObject(ObjectInputStream.java:1699) at java.io.ObjectInputStream.readObject0(ObjectInputStream.java:1305) at java.io.ObjectInputStream.readObject(ObjectInputStream.java:348) at org.jboss.cache.marshall.CacheMarshaller200.unmarshallObject(CacheMarshaller200.java:540) at org.jboss.cache.marshall.CacheMarshaller200.populateFromStream(CacheMarshaller200.java:750) at org.jboss.cache.marshall.CacheMarshaller200.unmarshallHashMap(CacheMarshaller200.java:713) at org.jboss.cache.marshall.CacheMarshaller200.unmarshallObject(CacheMarshaller200.java:571) at org.jboss.cache.marshall.CacheMarshaller200.unmarshallObject(CacheMarshaller200.java:513) at org.jboss.cache.marshall.CacheMarshaller200.objectFromObjectStreamRegionBased(CacheMarshaller200.java:202) at org.jboss.cache.marshall.CacheMarshaller200.objectFromObjectStream(CacheMarshaller200.java:126) at org.jboss.cache.marshall.VersionAwareMarshaller.objectFromObjectStream(VersionAwareMarshaller.java:326) at org.jboss.cache.loader.FileCacheLoader.doUnmarshall(FileCacheLoader.java:481) at org.jboss.cache.loader.AbstractCacheLoader.regionAwareUnmarshall(AbstractCacheLoader.java:214) at org.jboss.cache.loader.FileCacheLoader.loadAttributes(FileCacheLoader.java:434) at org.jboss.cache.loader.FileCacheLoader.get(FileCacheLoader.java:201) at org.jboss.cache.interceptors.CacheLoaderInterceptor.loadData(CacheLoaderInterceptor.java:564) at org.jboss.cache.interceptors.CacheLoaderInterceptor.loadNode(CacheLoaderInterceptor.java:491) at org.jboss.cache.interceptors.CacheLoaderInterceptor.loadIfNeeded(CacheLoaderInterceptor.java:305) at org.jboss.cache.interceptors.CacheLoaderInterceptor.visitPutKeyValueCommand(CacheLoaderInterceptor.java:106) at org.jboss.cache.interceptors.ActivationInterceptor.visitPutKeyValueCommand(ActivationInterceptor.java:135) at org.jboss.cache.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:92) at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:142) at org.jboss.cache.interceptors.PessimisticLockInterceptor.handlePutCommand(PessimisticLockInterceptor.java:118) at org.jboss.cache.interceptors.PessimisticLockInterceptor.handlePutKeyValueCommand(PessimisticLockInterceptor.java:86) at org.jboss.cache.interceptors.base.PostProcessingCommandInterceptor.visitPutKeyValueCommand(PostProcessingCommandInterceptor.java:56) at org.jboss.cache.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:92) at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:142) at org.jboss.cache.interceptors.ReplicationInterceptor.handleCrudMethod(ReplicationInterceptor.java:129) at org.jboss.cache.interceptors.ReplicationInterceptor.visitPutKeyValueCommand(ReplicationInterceptor.java:86) at org.jboss.cache.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:92) at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:142) at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:157) at org.jboss.cache.commands.AbstractVisitor.visitPutKeyValueCommand(AbstractVisitor.java:35) at org.jboss.cache.commands.write.PutKeyValueCommand.acceptVisitor(PutKeyValueCommand.java:92) at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:142) at org.jboss.cache.interceptors.TxInterceptor.replayModifications(TxInterceptor.java:502) at org.jboss.cache.interceptors.TxInterceptor.handleRemotePrepare(TxInterceptor.java:382) at org.jboss.cache.interceptors.TxInterceptor.visitPrepareCommand(TxInterceptor.java:105) at org.jboss.cache.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:46) at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:142) at org.jboss.cache.interceptors.base.CommandInterceptor.handleDefault(CommandInterceptor.java:157) at org.jboss.cache.commands.AbstractVisitor.visitPrepareCommand(AbstractVisitor.java:110) at org.jboss.cache.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:46) at org.jboss.cache.interceptors.base.CommandInterceptor.invokeNextInterceptor(CommandInterceptor.java:142) at org.jboss.cache.interceptors.InvocationContextInterceptor.handleAll(InvocationContextInterceptor.java:158) at org.jboss.cache.interceptors.InvocationContextInterceptor.visitPrepareCommand(InvocationContextInterceptor.java:84) at org.jboss.cache.commands.tx.PrepareCommand.acceptVisitor(PrepareCommand.java:46) at org.jboss.cache.interceptors.InterceptorChain.invokeRemote(InterceptorChain.java:239) at org.jboss.cache.commands.remote.ReplicateCommand.processSingleCommand(ReplicateCommand.java:116) at org.jboss.cache.commands.remote.ReplicateCommand.perform(ReplicateCommand.java:92) at org.jboss.cache.marshall.CommandAwareRpcDispatcher.executeCommand(CommandAwareRpcDispatcher.java:173) at org.jboss.cache.marshall.InactiveRegionAwareRpcDispatcher.handle(InactiveRegionAwareRpcDispatcher.java:73) at org.jgroups.blocks.RequestCorrelator.handleRequest(RequestCorrelator.java:624) at org.jgroups.blocks.RequestCorrelator.receiveMessage(RequestCorrelator.java:533) at org.jgroups.blocks.RequestCorrelator.receive(RequestCorrelator.java:365) at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:764) at org.jgroups.JChannel.up(JChannel.java:1265) at org.jgroups.stack.ProtocolStack.up(ProtocolStack.java:441) at org.jgroups.protocols.pbcast.FLUSH.up(FLUSH.java:373) at org.jgroups.protocols.pbcast.STATE_TRANSFER.up(STATE_TRANSFER.java:144) at org.jgroups.protocols.FRAG2.up(FRAG2.java:205) at org.jgroups.protocols.FC.up(FC.java:411) at org.jgroups.protocols.pbcast.GMS.up(GMS.java:772) at org.jgroups.protocols.pbcast.STABLE.up(STABLE.java:233) at org.jgroups.protocols.UNICAST.handleDataReceived(UNICAST.java:627) at org.jgroups.protocols.UNICAST.up(UNICAST.java:286) at org.jgroups.protocols.pbcast.NAKACK.up(NAKACK.java:729) at org.jgroups.protocols.VERIFY_SUSPECT.up(VERIFY_SUSPECT.java:167) at org.jgroups.protocols.FD.up(FD.java:284) at org.jgroups.protocols.FD_SOCK.up(FD_SOCK.java:309) at org.jgroups.protocols.MERGE2.up(MERGE2.java:144) at org.jgroups.protocols.Discovery.up(Discovery.java:244) at org.jgroups.protocols.TP$ProtocolAdapter.up(TP.java:2191) at org.jgroups.protocols.TP.passMessageUp(TP.java:1235) at org.jgroups.protocols.TP.access$100(TP.java:49) at org.jgroups.protocols.TP$IncomingPacket.handleMyMessage(TP.java:1802) at org.jgroups.protocols.TP$IncomingPacket.run(TP.java:1776) at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:650) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:675) at java.lang.Thread.run(Thread.java:595)
The earlier logging from RegionManager is due to calls from AbstractCacheLoader.regionAwareUnmarshall(), which is trying to find an appropriate classloader to set and fails. I think this comes down to a problem in AbstractCacheLoader.regionAwareMarshall() and regionAwareUnmarshall():
Region r = regionManager == null ? null : regionManager.getRegion(fqn, Region.Type.MARSHALLING, false);
That call won't convert from a BR FQN to a main tree FQN, so it doesn't find the region. Better would be to call a method that does that, a la AbstractMarshaller.getRegion(Fqn):
protected Region getRegion(Fqn fqn) { if (fqn == null) return null; if (buddyFqnTransformer.isBackupFqn(fqn)) { // Strip out the buddy group portion fqn = buddyFqnTransformer.getActualFqn(fqn); } return regionManager.getRegion(fqn, Region.Type.MARSHALLING, false); }
That should wrap it up, yes? Problem is I look at the code in 2.1.1.GA and it looks the same, so I don't understand why the test is failing now and not w/ 2.1.1.GA. So I'm missing something important.
Could it be that 2.1.1.GA wouldn't try to load the node from disk when doing the remove, i.e. the problem's been there all along but a behavior change has exposed it?