[jbosscache-dev] Cache bean deployment via MC failing when TRACE enabled on org.jboss.kernel

[Brian Stansberry]

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 at lists.jboss.org
> https://lists.jboss.org/mailman/listinfo/jbosscache-dev


-- 
Brian Stansberry
Lead, AS Clustering
JBoss, a division of Red Hat
brian.stansberry at redhat.com