Hi, Bear with me on this one, it's a bit long :) I've been running some tests creating Cache instances via MC and I've noticed that when TRACE logging is enabled on org.jboss.kernel, my Cache beans are not deployed whereas when org.jboss.kernel is set to DEBUG or higher, Cache beans deploy fine. The error I'm getting is the following: 2009-03-03 21:40:51,505 ERROR [AbstractKernelController] (main) Error installing to Instantiated: name=CacheClusterA1 state=Described java.lang.UnsupportedOperationException: Not supported in UnversionedNode at org.jboss.cache.AbstractNode.getChildrenDirect(AbstractNode.java:277) at org.jboss.cache.mvcc.NodeReference.getChildrenDirect(NodeReference.java:272) at org.jboss.cache.invocation.NodeInvocationDelegate.getChildrenDirect(NodeInvocationDelegate.java:163) at org.jboss.cache.DataContainerImpl.numNodes(DataContainerImpl.java:461) at org.jboss.cache.DataContainerImpl.getNumberOfNodes(DataContainerImpl.java:438) at org.jboss.cache.DataContainerImpl.toString(DataContainerImpl.java:394) at org.jboss.cache.DataContainerImpl.toString(DataContainerImpl.java:372) at org.jboss.cache.invocation.CacheInvocationDelegate.toString(CacheInvocationDelegate.java:144) at java.lang.String.valueOf(String.java:2615) at org.jboss.util.JBossStringBuilder.append(JBossStringBuilder.java:114) at org.jboss.dependency.plugins.AbstractControllerContext.toString(AbstractControllerContext.java:362) Looks like in TRACE mode, MC is trying to print the Cache when this is not fully started. To try to understand this, let's look at what DataContainerImpl logs when org.jboss.kernel is set to DEBUG: log4j-jboss-kerneldebug.log:2894:2009-03-03 21:40:24,249 2198 TRACE [org.jboss.cache.DataContainerImpl] (main:) Starting data container. Using MVCC? false log4j-jboss-kerneldebug.log:2895:2009-03-03 21:40:24,274 2223 TRACE [org.jboss.cache.DataContainerImpl] (main:) Setting root node to an instance of class org.jboss.cache.mvcc.NodeReference ... log4j-jboss-kerneldebug.log:3038:2009-03-03 21:40:24,336 2285 TRACE [org.jboss.cache.DataContainerImpl] (main:) Starting data container. Using MVCC? true log4j-jboss-kerneldebug.log:3039:2009-03-03 21:40:24,338 2287 DEBUG [org.jboss.cache.DataContainerImpl] (main:) Setting rootInternal to NodeReference{delegate=UnversionedNode[ /]} After MVCC has been set to true, DataContainerImpl.getNumberOfNodes() is able to get the number of nodes successfully: if (!usingMvcc) return numNodes(root) - 1; return numNodesMvcc(rootInternal) - 1; However, if in between the two "Starting data container" messages, someone (i.e. MC), tries to get the number of nodes (via toString), then Cache tries to get number of nodes of a MVCC node as a non MVCC node failing with the exception above. This is exactly what happens when you enable TRACE on MC kernel. numNodesMvcc() calls getChildren(). numNodes calls getChildrenDirect(). With this TRACE enabled, log only show the first two lines: log4j-jboss-kerneltrace.log:6731:2009-03-03 21:40:51,468 2817 TRACE [org.jboss.cache.DataContainerImpl] (main:) Starting data container. Using MVCC? false log4j-jboss-kerneltrace.log:6732:2009-03-03 21:40:51,475 2824 TRACE [org.jboss.cache.DataContainerImpl] (main:) Setting root node to an instance of class org.jboss.cache.mvcc.NodeReference So, how do we solve this? I'm not sure I understand why DataContainerImpl.createRootNode() is called twice. The very first call, which seems to come from DataContainerImpl.injectDependencies() method (annotated with @Inject) looks suspicious. Why does it look suspicious? Because calls like this expect a config to be set. And when they're called initially from @Inject, the config object is not still set (when the call comes as part of the start operation, config is indeed set) usingMvcc = config != null && config.getNodeLockingScheme() == NodeLockingScheme.MVCC; And this returning false, when in fact the config is set to MVCC is what results of number of nodes being calculated incorrectly. Not sure on how to fix this though. Thoughts?

------------------------------------------------------------------------ _______________________________________________ jbosscache-dev mailing list jbosscache-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/jbosscache-dev

I kind of got lost in the details there, but I don't think that affects my opinion. ;) IMHO trying to do complex stuff in toString() is asking for trouble. Either DataContainerImpl.toString() or CacheInvocationDelegate.toString() should stop calling into arbitrarily complex code and just output basic info.

Galder Zamarreno wrote: > Hi, > Bear with me on this one, it's a bit long :) > I've been running some tests creating Cache instances via MC and > I've noticed that when TRACE logging is enabled on > org.jboss.kernel, my Cache beans are not deployed whereas when > org.jboss.kernel is set to DEBUG or higher, Cache beans deploy fine. > The error I'm getting is the following: > 2009-03-03 21:40:51,505 ERROR [AbstractKernelController] (main) > Error installing to Instantiated: name=CacheClusterA1 state=Described > java.lang.UnsupportedOperationException: Not supported in > UnversionedNode > at > org.jboss.cache.AbstractNode.getChildrenDirect(AbstractNode.java:277) > at > org > .jboss > .cache.mvcc.NodeReference.getChildrenDirect(NodeReference.java: > 272) at > org > .jboss > .cache > .invocation > .NodeInvocationDelegate > .getChildrenDirect(NodeInvocationDelegate.java:163) at > org.jboss.cache.DataContainerImpl.numNodes(DataContainerImpl.java: > 461) > at > org > .jboss > .cache.DataContainerImpl.getNumberOfNodes(DataContainerImpl.java: > 438) at > org.jboss.cache.DataContainerImpl.toString(DataContainerImpl.java: > 394) > at > org.jboss.cache.DataContainerImpl.toString(DataContainerImpl.java: > 372) > at > org > .jboss > .cache > .invocation > .CacheInvocationDelegate.toString(CacheInvocationDelegate.java: > 144) at java.lang.String.valueOf(String.java:2615) > at > org.jboss.util.JBossStringBuilder.append(JBossStringBuilder.java:114) > at > org > .jboss > .dependency > .plugins > .AbstractControllerContext.toString(AbstractControllerContext.java: > 362) Looks like in TRACE mode, MC is trying to print the Cache when > this is not fully started. > To try to understand this, let's look at what DataContainerImpl > logs when org.jboss.kernel is set to DEBUG: > log4j-jboss-kerneldebug.log:2894:2009-03-03 21:40:24,249 2198 > TRACE [org.jboss.cache.DataContainerImpl] (main:) Starting data > container. Using MVCC? false > log4j-jboss-kerneldebug.log:2895:2009-03-03 21:40:24,274 2223 > TRACE [org.jboss.cache.DataContainerImpl] (main:) Setting root node > to an instance of class org.jboss.cache.mvcc.NodeReference > ... > log4j-jboss-kerneldebug.log:3038:2009-03-03 21:40:24,336 2285 > TRACE [org.jboss.cache.DataContainerImpl] (main:) Starting data > container. Using MVCC? true > log4j-jboss-kerneldebug.log:3039:2009-03-03 21:40:24,338 2287 > DEBUG [org.jboss.cache.DataContainerImpl] (main:) Setting > rootInternal to NodeReference{delegate=UnversionedNode[ /]} > After MVCC has been set to true, > DataContainerImpl.getNumberOfNodes() is able to get the number of > nodes successfully: > if (!usingMvcc) return numNodes(root) - 1; > return numNodesMvcc(rootInternal) - 1; > However, if in between the two "Starting data container" messages, > someone (i.e. MC), tries to get the number of nodes (via toString), > then Cache tries to get number of nodes of a MVCC node as a non > MVCC node failing with the exception above. This is exactly what > happens when you enable TRACE on MC kernel. > numNodesMvcc() calls getChildren(). numNodes calls > getChildrenDirect(). > With this TRACE enabled, log only show the first two lines: > log4j-jboss-kerneltrace.log:6731:2009-03-03 21:40:51,468 2817 > TRACE [org.jboss.cache.DataContainerImpl] (main:) Starting data > container. Using MVCC? false > log4j-jboss-kerneltrace.log:6732:2009-03-03 21:40:51,475 2824 > TRACE [org.jboss.cache.DataContainerImpl] (main:) Setting root node > to an instance of class org.jboss.cache.mvcc.NodeReference > So, how do we solve this? > I'm not sure I understand why DataContainerImpl.createRootNode() is > called twice. The very first call, which seems to come from > DataContainerImpl.injectDependencies() method (annotated with > @Inject) looks suspicious. Why does it look suspicious? Because > calls like this expect a config to be set. And when they're called > initially from @Inject, the config object is not still set (when > the call comes as part of the start operation, config is indeed set) > usingMvcc = config != null && config.getNodeLockingScheme() == > NodeLockingScheme.MVCC; > And this returning false, when in fact the config is set to MVCC is > what results of number of nodes being calculated incorrectly. > Not sure on how to fix this though. > Thoughts? > ------------------------------------------------------------------------ > _______________________________________________ > jbosscache-dev mailing list > jbosscache-dev(a)lists.jboss.org > https://lists.jboss.org/mailman/listinfo/jbosscache-dev -- Brian Stansberry Lead, AS Clustering JBoss, a division of Red Hat brian.stansberry(a)redhat.com _______________________________________________ jbosscache-dev mailing list jbosscache-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/jbosscache-dev

Manik Surtani wrote: > On 3 Mar 2009, at 22:14, Brian Stansberry wrote: >> I kind of got lost in the details there, but I don't think that >> affects my opinion. ;) >> >> IMHO trying to do complex stuff in toString() is asking for >> trouble. Either DataContainerImpl.toString() or >> CacheInvocationDelegate.toString() should stop calling into >> arbitrarily complex code and just output basic info. > Yup. Also, this is a known issue and is fixed in 3.0.3.GA: > https://jira.jboss.org/jira/browse/JBCACHE-1478 I'm already using 3.0.3.GA...

>> Galder Zamarreno wrote: >>> Hi, >>> Bear with me on this one, it's a bit long :) >>> I've been running some tests creating Cache instances via MC and >>> I've noticed that when TRACE logging is enabled on >>> org.jboss.kernel, my Cache beans are not deployed whereas when >>> org.jboss.kernel is set to DEBUG or higher, Cache beans deploy >>> fine. >>> The error I'm getting is the following: >>> 2009-03-03 21:40:51,505 ERROR [AbstractKernelController] (main) >>> Error installing to Instantiated: name=CacheClusterA1 >>> state=Described >>> java.lang.UnsupportedOperationException: Not supported in >>> UnversionedNode >>> at >>> org.jboss.cache.AbstractNode.getChildrenDirect(AbstractNode.java: >>> 277) >>> at >>> org >>> .jboss >>> .cache.mvcc.NodeReference.getChildrenDirect(NodeReference.java: >>> 272) at >>> org >>> .jboss >>> .cache >>> .invocation >>> .NodeInvocationDelegate >>> .getChildrenDirect(NodeInvocationDelegate.java:163) at >>> org.jboss.cache.DataContainerImpl.numNodes(DataContainerImpl.java: >>> 461) >>> at >>> org >>> .jboss >>> .cache.DataContainerImpl.getNumberOfNodes(DataContainerImpl.java: >>> 438) at >>> org.jboss.cache.DataContainerImpl.toString(DataContainerImpl.java: >>> 394) >>> at >>> org.jboss.cache.DataContainerImpl.toString(DataContainerImpl.java: >>> 372) >>> at >>> org >>> .jboss >>> .cache >>> .invocation >>> .CacheInvocationDelegate.toString(CacheInvocationDelegate.java: >>> 144) at java.lang.String.valueOf(String.java:2615) >>> at >>> org.jboss.util.JBossStringBuilder.append(JBossStringBuilder.java: >>> 114) >>> at >>> org >>> .jboss >>> .dependency >>> .plugins >>> .AbstractControllerContext >>> .toString(AbstractControllerContext.java:362) Looks like in TRACE >>> mode, MC is trying to print the Cache when this is not fully >>> started. >>> To try to understand this, let's look at what DataContainerImpl >>> logs when org.jboss.kernel is set to DEBUG: >>> log4j-jboss-kerneldebug.log:2894:2009-03-03 21:40:24,249 2198 >>> TRACE [org.jboss.cache.DataContainerImpl] (main:) Starting data >>> container. Using MVCC? false >>> log4j-jboss-kerneldebug.log:2895:2009-03-03 21:40:24,274 2223 >>> TRACE [org.jboss.cache.DataContainerImpl] (main:) Setting root >>> node to an instance of class org.jboss.cache.mvcc.NodeReference >>> ... >>> log4j-jboss-kerneldebug.log:3038:2009-03-03 21:40:24,336 2285 >>> TRACE [org.jboss.cache.DataContainerImpl] (main:) Starting data >>> container. Using MVCC? true >>> log4j-jboss-kerneldebug.log:3039:2009-03-03 21:40:24,338 2287 >>> DEBUG [org.jboss.cache.DataContainerImpl] (main:) Setting >>> rootInternal to NodeReference{delegate=UnversionedNode[ /]} >>> After MVCC has been set to true, >>> DataContainerImpl.getNumberOfNodes() is able to get the number of >>> nodes successfully: >>> if (!usingMvcc) return numNodes(root) - 1; >>> return numNodesMvcc(rootInternal) - 1; >>> However, if in between the two "Starting data container" >>> messages, someone (i.e. MC), tries to get the number of nodes >>> (via toString), then Cache tries to get number of nodes of a MVCC >>> node as a non MVCC node failing with the exception above. This is >>> exactly what happens when you enable TRACE on MC kernel. >>> numNodesMvcc() calls getChildren(). numNodes calls >>> getChildrenDirect(). >>> With this TRACE enabled, log only show the first two lines: >>> log4j-jboss-kerneltrace.log:6731:2009-03-03 21:40:51,468 2817 >>> TRACE [org.jboss.cache.DataContainerImpl] (main:) Starting data >>> container. Using MVCC? false >>> log4j-jboss-kerneltrace.log:6732:2009-03-03 21:40:51,475 2824 >>> TRACE [org.jboss.cache.DataContainerImpl] (main:) Setting root >>> node to an instance of class org.jboss.cache.mvcc.NodeReference >>> So, how do we solve this? >>> I'm not sure I understand why DataContainerImpl.createRootNode() >>> is called twice. The very first call, which seems to come from >>> DataContainerImpl.injectDependencies() method (annotated with >>> @Inject) looks suspicious. Why does it look suspicious? Because >>> calls like this expect a config to be set. And when they're >>> called initially from @Inject, the config object is not still set >>> (when the call comes as part of the start operation, config is >>> indeed set) >>> usingMvcc = config != null && config.getNodeLockingScheme() == >>> NodeLockingScheme.MVCC; >>> And this returning false, when in fact the config is set to MVCC >>> is what results of number of nodes being calculated incorrectly. >>> Not sure on how to fix this though. >>> Thoughts? >>> ------------------------------------------------------------------------ >>> _______________________________________________ >>> jbosscache-dev mailing list >>> jbosscache-dev(a)lists.jboss.org >>> https://lists.jboss.org/mailman/listinfo/jbosscache-dev >> >> >> -- >> Brian Stansberry >> Lead, AS Clustering >> JBoss, a division of Red Hat >> brian.stansberry(a)redhat.com >> _______________________________________________ >> jbosscache-dev mailing list >> jbosscache-dev(a)lists.jboss.org >> https://lists.jboss.org/mailman/listinfo/jbosscache-dev > -- > Manik Surtani > Lead, JBoss Cache > http://www.jbosscache.org > manik(a)jboss.org > ------------------------------------------------------------------------ > _______________________________________________ > jbosscache-dev mailing list > jbosscache-dev(a)lists.jboss.org > https://lists.jboss.org/mailman/listinfo/jbosscache-dev -- Galder Zamarreño Sr. Software Maintenance Engineer JBoss, a division of Red Hat

Since 3.0.3.GA has already been released, I'll create a new JIRA and assign it to you. Otherwise we'll lose track of what JBCACHE-1478 fixed for 3.0.3.GA. It might be that they're different cases.

On 4 Mar 2009, at 00:24, Galder Zamarreno wrote: > > Long term, we need a place where we can add MC+Cache integration > tests. The obvious place looks to me AS unless we wanna bring in MC > into Cache. I reckon the AS.

Manik Surtani wrote: > > On 4 Mar 2009, at 00:24, Galder Zamarreno wrote: > >> >> Long term, we need a place where we can add MC+Cache integration >> tests. The obvious place looks to me AS unless we wanna bring in MC >> into Cache. > > I reckon the AS. > Sure, sounds good.

We just have to be sure that if such a test finds something that we try hard to reproduce the issue w/o using MC and add a test in the JBC testsuite.