LogConfigurationException from commons-logging

[brian.stansberry]

I've been seeing this kind of thing quite a bit in logs from testsuite runs; seems to correspond to intermittent increase in clustering failures:

2008-04-10 13:58:28,949 ERROR [org.jboss.cache.remoting.jgroups.CacheMessageListener] (Multiplexer,udp,10.18.34.175:51700) Caught org.apache.commons.logging.LogConfigurationException while responding to state transfer request
org.apache.commons.logging.LogConfigurationException: User-specified log class 'org.apache.commons.logging.impl.Log4JLogger' cannot be found or is not useable.
 at org.apache.commons.logging.impl.LogFactoryImpl.discoverLogImplementation(LogFactoryImpl.java:798)
 at org.apache.commons.logging.impl.LogFactoryImpl.newInstance(LogFactoryImpl.java:601)
 at org.apache.commons.logging.impl.LogFactoryImpl.getInstance(LogFactoryImpl.java:333)
 at org.apache.commons.logging.LogFactory.getLog(LogFactory.java:664)
 at org.jboss.cache.statetransfer.DefaultStateTransferGenerator.<init>(DefaultStateTransferGenerator.java:32)
 at org.jboss.cache.statetransfer.StateTransferFactory.getStateTransferGenerator(StateTransferFactory.java:43)
 at org.jboss.cache.statetransfer.StateTransferManager.getStateTransferGenerator(StateTransferManager.java:297)
 at org.jboss.cache.statetransfer.StateTransferManager.getState(StateTransferManager.java:82)
 at org.jboss.cache.remoting.jgroups.CacheMessageListener.getState(CacheMessageListener.java:137)
 at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.handleUpEvent(MessageDispatcher.java:629)
 at org.jgroups.blocks.MessageDispatcher$ProtocolAdapter.up(MessageDispatcher.java:747)
 at org.jgroups.JChannel.up(JChannel.java:1154)
 at org.jgroups.mux.Multiplexer$Task.run(Multiplexer.java:1175)
 at org.jgroups.mux.Multiplexer$ExecuteTask.run(Multiplexer.java:1198)
 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)

I'm going to turn on commons-logging's diagnostic logging feature for the cluster-udp-0 and cluster-udp-1 configs; hopefully that will shed some light on what's causing this.

[adrian.brock]

What's the context classloader?

My guess is that before the multiplexer was introduced, the thread's classloader
was the same as jboss cache's when it started the JChannel and hence the thread.

Now it's just "random"?

[brian.stansberry]

Hmm, thought I'd replied before, but don't see the reply.

Anyway, pretty sure you were on the right track. Log from last night's run showed a similar problem, but root cause was an ISE from BaseClassLoader when trying to use it after it had been undeployed -- i.e. a CL leak to a JGroups thread pool thread.

I think this started intermittently popping up when I set "loopback=true" on the channel configs to correct the FLUSH issues you were seeing. All your fault. ;-) With loopback enabled, app threads with the app's TCCL not only push messages down the stack, they also handle carrying the message back up and passing it off to the multiplexer thread pool. If the pool allocates a new thread to handle that message, the app's TCCL leaks to the pool.

I replaced the mulitplexer with the shared transport this evening; I think that should take care of this. Posted on jgroups-dev to check for other similar scenarios:
http://www.nabble.com/Classloader-leaks-in-thread-pools-to16642502.html

I'm working to get it so the standard JEE distributed caches are lazy initialized. That means some user deployment's TCCL is going to be in effect when cache and associated channel are created. Your post makes me realize I need to be sure to set the TCCL to the default domain loader before creating any cache or channel.

Thanks. :)

[brian.stansberry]

For the record, my last post was wrong about app thread carrying a message back up the stack if loopback=true. Rather, it creates a task and hands it off to the transport protocol's thread pool. So, the app TCCL can leak to the transport protocol thread pool as well. Removing the multiplexer still left that problem.

I'm fixing this for the AS by having the AS channel factory inject specialized thread pools into the channel that properly control the TCCL on pool threads, like what I did for JBCOMMON-41.

http://jira.jboss.com/jira/browse/JBAS-5414