I've been banging my head against a wall for some time to figure out why my MDB fails to insantiate properly.

I have a web application sending an xml jms message into a queue and then consumed by a message driven bean.

THis is the trace from the web application sending the message, which appears to work ok.

12:31:01,124 DEBUG [org.springframework.jms.core.JmsTemplate] Executing callback on JMS session [SpySession@15552470[tx=false ack=AUTO txid=null RUNNING connection=Connection@1339313[token=ConnectionToken:ID:15/8c38468d5cf55299b6ceae67be418297 rcvstate=STOPPED]]] from connection [Connection@1339313[token=ConnectionToken:ID:15/8c38468d5cf55299b6ceae67be418297 rcvstate=STOPPED]]
12:31:01,126 DEBUG [org.springframework.jms.core.JmsTemplate] Sending created message [SpyTextMessage {
Header {
 jmsDestination : null
 jmsDeliveryMode : -1
 jmsExpiration : 0
 jmsPriority : -1
 jmsMessageID : null
 jmsTimeStamp : 0
 jmsCorrelationID: null
 jmsReplyTo : null
 jmsType : null
 jmsRedelivered : false
 jmsProperties : {}
 jmsPropReadWrite: true
 msgReadOnly : false
 producerClientId: ID:15
}
Body {
 text :<?xml version="1.0" encoding="UTF-8" standalone="yes"?>
<AuthorizationEvent xmlns="http://www.ccfone.com/AuthorizationEvent">

......

</AuthorizationEvent>


}
}]
12:31:01,134 DEBUG [org.springframework.web.context.support.XmlWebApplicationContext] Publishing event in context [WebApplicationContext for namespace 'transact-servlet']: RequestHandledEvent: url=[/transact/controller]; time=[5366ms]; client=[127.0.0.1]; method=[POST]; servlet=[transact]; session=[null]; user=[null]; status=[OK]
12:31:01,134 DEBUG [org.springframework.web.context.support.XmlWebApplicationContext] Publishing event in context [Root WebApplicationContext]: RequestHandledEvent: url=[/transact/controller]; time=[5366ms]; client=[127.0.0.1]; method=[POST]; servlet=[transact]; session=[null]; user=[null]; status=[OK]
12:31:01,134 DEBUG [org.springframework.transaction.support.TransactionSynchronizationManager] Removed value [org.springframework.orm.hibernate3.SessionHolder@3bb52a] for key [org.hibernate.impl.SessionFactoryImpl@f2dc9f] from thread [http-0.0.0.0-8080-1]

12:31:01,361 DEBUG [org.springframework.jndi.JndiTemplate] Looking up JNDI object with name [instance/properties/key]
12:31:01,362 DEBUG [org.springframework.jndi.JndiObjectFactoryBean] Located object with JNDI name [instance/properties/key]
12:31:01,363 DEBUG [org.springframework.jndi.JndiTemplate] Looking up JNDI object with name [instance/properties/mail]
12:31:01,363 DEBUG [org.springframework.jndi.JndiObjectFactoryBean] Located object with JNDI name [instance/properties/mail]
12:31:01,364 DEBUG [org.springframework.jndi.JndiTemplate] Looking up JNDI object with name [instance/properties/greylock]
12:31:01,364 DEBUG [org.springframework.jndi.JndiObjectFactoryBean] Located object with JNDI name [instance/properties/greylock]
12:31:01,365 DEBUG [org.springframework.jndi.JndiTemplate] Looking up JNDI object with name [instance/properties/sms]
12:31:01,366 DEBUG [org.springframework.jndi.JndiObjectFactoryBean] Located object with JNDI name [instance/properties/sms]
12:31:01,752 INFO [org.springframework.orm.hibernate3.LocalSessionFactoryBean] Building new Hibernate SessionFactory
12:31:01,830 DEBUG [com.opensymphony.oscache.base.Config] Config() called
12:31:01,830 DEBUG [com.opensymphony.oscache.base.AbstractCacheAdministrator] Constructed AbstractCacheAdministrator()
12:31:01,830 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Constructed GeneralCacheAdministrator()
12:31:01,830 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Creating new cache
12:31:02,004 DEBUG [com.opensymphony.oscache.base.Config] Config() called
12:31:02,004 DEBUG [com.opensymphony.oscache.base.AbstractCacheAdministrator] Constructed AbstractCacheAdministrator()
12:31:02,004 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Constructed GeneralCacheAdministrator()
12:31:02,004 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Creating new cache
12:31:02,039 DEBUG [com.opensymphony.oscache.base.Config] Config() called
12:31:02,039 DEBUG [com.opensymphony.oscache.base.AbstractCacheAdministrator] Constructed AbstractCacheAdministrator()
12:31:02,039 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Constructed GeneralCacheAdministrator()
12:31:02,039 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Creating new cache
12:31:02,158 DEBUG [com.opensymphony.oscache.base.Config] Config() called
12:31:02,158 DEBUG [com.opensymphony.oscache.base.AbstractCacheAdministrator] Constructed AbstractCacheAdministrator()
12:31:02,158 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Constructed GeneralCacheAdministrator()
12:31:02,158 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Creating new cache
12:31:02,216 DEBUG [com.opensymphony.oscache.base.Config] Config() called
12:31:02,216 DEBUG [com.opensymphony.oscache.base.AbstractCacheAdministrator] Constructed AbstractCacheAdministrator()
12:31:02,219 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Constructed GeneralCacheAdministrator()
12:31:02,219 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Creating new cache
12:31:02,255 DEBUG [com.opensymphony.oscache.base.Config] Config() called
12:31:02,258 DEBUG [com.opensymphony.oscache.base.AbstractCacheAdministrator] Constructed AbstractCacheAdministrator()
12:31:02,258 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Constructed GeneralCacheAdministrator()
12:31:02,258 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Creating new cache
12:31:02,299 DEBUG [com.opensymphony.oscache.base.Config] Config() called
12:31:02,299 DEBUG [com.opensymphony.oscache.base.AbstractCacheAdministrator] Constructed AbstractCacheAdministrator()
12:31:02,299 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Constructed GeneralCacheAdministrator()
12:31:02,299 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Creating new cache
12:31:02,336 DEBUG [com.opensymphony.oscache.base.Config] Config() called
12:31:02,336 DEBUG [com.opensymphony.oscache.base.AbstractCacheAdministrator] Constructed AbstractCacheAdministrator()
12:31:02,336 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Constructed GeneralCacheAdministrator()
12:31:02,336 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Creating new cache
12:31:02,640 DEBUG [com.opensymphony.oscache.base.Config] Config() called
12:31:02,641 DEBUG [com.opensymphony.oscache.base.AbstractCacheAdministrator] Constructed AbstractCacheAdministrator()
12:31:02,641 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Constructed GeneralCacheAdministrator()
12:31:02,641 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Creating new cache
12:31:02,674 DEBUG [com.opensymphony.oscache.base.Config] Config() called
12:31:02,674 DEBUG [com.opensymphony.oscache.base.AbstractCacheAdministrator] Constructed AbstractCacheAdministrator()
12:31:02,674 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Constructed GeneralCacheAdministrator()
12:31:02,674 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Creating new cache
12:31:02,707 DEBUG [com.opensymphony.oscache.base.Config] Config() called
12:31:02,707 DEBUG [com.opensymphony.oscache.base.AbstractCacheAdministrator] Constructed AbstractCacheAdministrator()
12:31:02,707 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Constructed GeneralCacheAdministrator()
12:31:02,707 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Creating new cache
12:31:02,751 DEBUG [com.opensymphony.oscache.base.Config] Config() called
12:31:02,751 DEBUG [com.opensymphony.oscache.base.AbstractCacheAdministrator] Constructed AbstractCacheAdministrator()
12:31:02,751 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Constructed GeneralCacheAdministrator()
12:31:02,753 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Creating new cache
12:31:02,790 DEBUG [com.opensymphony.oscache.base.Config] Config() called
12:31:02,790 DEBUG [com.opensymphony.oscache.base.AbstractCacheAdministrator] Constructed AbstractCacheAdministrator()
12:31:02,791 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Constructed GeneralCacheAdministrator()
12:31:02,791 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Creating new cache
12:31:02,828 DEBUG [com.opensymphony.oscache.base.Config] Config() called
12:31:02,828 DEBUG [com.opensymphony.oscache.base.AbstractCacheAdministrator] Constructed AbstractCacheAdministrator()
12:31:02,828 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Constructed GeneralCacheAdministrator()
12:31:02,828 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Creating new cache
12:31:02,922 DEBUG [com.opensymphony.oscache.base.Config] Config() called
12:31:02,922 DEBUG [com.opensymphony.oscache.base.AbstractCacheAdministrator] Constructed AbstractCacheAdministrator()
12:31:02,922 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Constructed GeneralCacheAdministrator()
12:31:02,922 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Creating new cache
12:31:03,052 DEBUG [com.opensymphony.oscache.base.Config] Config() called
12:31:03,054 DEBUG [com.opensymphony.oscache.base.AbstractCacheAdministrator] Constructed AbstractCacheAdministrator()
12:31:03,054 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Constructed GeneralCacheAdministrator()
12:31:03,054 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Creating new cache
12:31:03,056 DEBUG [com.opensymphony.oscache.base.Config] Config() called
12:31:03,056 DEBUG [com.opensymphony.oscache.base.AbstractCacheAdministrator] Constructed AbstractCacheAdministrator()
12:31:03,056 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Constructed GeneralCacheAdministrator()
12:31:03,056 INFO [com.opensymphony.oscache.general.GeneralCacheAdministrator] Creating new cache
12:31:03,364 INFO [org.apache.velocity.app.VelocityEngine] **************************************************************
12:31:03,364 INFO [org.apache.velocity.app.VelocityEngine] Starting Jakarta Velocity v1.4
12:31:03,364 INFO [org.apache.velocity.app.VelocityEngine] RuntimeInstance initializing.
12:31:03,364 INFO [org.apache.velocity.app.VelocityEngine] Default Properties File: org/apache/velocity/runtime/defaults/velocity.properties
12:31:03,364 INFO [org.apache.velocity.app.VelocityEngine] Default ResourceManager initializing. (class org.apache.velocity.runtime.resource.ResourceManagerImpl)
12:31:03,364 INFO [org.apache.velocity.app.VelocityEngine] Resource Loader Instantiated: org.apache.velocity.runtime.resource.loader.DataSourceResourceLoader
12:31:03,365 INFO [org.apache.velocity.app.VelocityEngine] ResourceCache : initialized. (class org.apache.velocity.runtime.resource.ResourceCacheImpl)
12:31:03,365 INFO [org.apache.velocity.app.VelocityEngine] Default ResourceManager initialization complete.
12:31:03,367 INFO [org.apache.velocity.app.VelocityEngine] Loaded System Directive: org.apache.velocity.runtime.directive.Literal
12:31:03,367 INFO [org.apache.velocity.app.VelocityEngine] Loaded System Directive: org.apache.velocity.runtime.directive.Macro
12:31:03,367 INFO [org.apache.velocity.app.VelocityEngine] Loaded System Directive: org.apache.velocity.runtime.directive.Parse
12:31:03,368 INFO [org.apache.velocity.app.VelocityEngine] Loaded System Directive: org.apache.velocity.runtime.directive.Include
12:31:03,368 INFO [org.apache.velocity.app.VelocityEngine] Loaded System Directive: org.apache.velocity.runtime.directive.Foreach
12:31:03,376 INFO [org.apache.velocity.app.VelocityEngine] Created: 20 parsers.
12:31:03,376 INFO [org.apache.velocity.app.VelocityEngine] Velocimacro : initialization starting.
12:31:03,377 INFO [org.apache.velocity.app.VelocityEngine] Velocimacro : adding VMs from VM library template : VM_global_library.vm
12:31:03,385 ERROR [org.apache.velocity.app.VelocityEngine] ResourceManager : unable to find resource 'VM_global_library.vm' in any resource loader.
12:31:03,386 INFO [org.apache.velocity.app.VelocityEngine] Velocimacro : error using VM library template VM_global_library.vm : org.apache.velocity.exception.ResourceNotFoundException: Unable to find resource 'VM_global_library.vm'
12:31:03,386 INFO [org.apache.velocity.app.VelocityEngine] Velocimacro : VM library template macro registration complete.
12:31:03,386 INFO [org.apache.velocity.app.VelocityEngine] Velocimacro : allowInline = true : VMs can be defined inline in templates
12:31:03,386 INFO [org.apache.velocity.app.VelocityEngine] Velocimacro : allowInlineToOverride = false : VMs defined inline may NOT replace previous VM definitions
12:31:03,386 INFO [org.apache.velocity.app.VelocityEngine] Velocimacro : allowInlineLocal = false : VMs defined inline will be global in scope if allowed.
12:31:03,386 INFO [org.apache.velocity.app.VelocityEngine] Velocimacro : messages on : VM system will output logging messages
12:31:03,387 INFO [org.apache.velocity.app.VelocityEngine] Velocimacro : autoload off : VM system will not automatically reload global library macros
12:31:03,387 INFO [org.apache.velocity.app.VelocityEngine] Velocimacro : initialization complete.
12:31:03,387 INFO [org.apache.velocity.app.VelocityEngine] Velocity successfully started.
12:31:03,387 DEBUG [org.springframework.jndi.JndiTemplate] Looking up JNDI object with name [queue/EmailMessage]
12:31:03,388 DEBUG [org.jboss.mq.referenceable.SpyDestinationObjectFactory] SpyDestinationObjectFactory->getObjectInstance()
12:31:03,388 DEBUG [org.springframework.jndi.JndiObjectFactoryBean] Located object with JNDI name [queue/EmailMessage]
12:31:03,389 DEBUG [org.springframework.jndi.JndiTemplate] Looking up JNDI object with name [java:/ConnectionFactory]
12:31:03,390 DEBUG [org.springframework.jndi.JndiObjectFactoryBean] Located object with JNDI name [java:/ConnectionFactory]
12:31:03,408 DEBUG [org.springframework.transaction.jta.JtaTransactionManager] Retrieving JTA UserTransaction from JNDI location [java:comp/UserTransaction]
12:31:03,409 DEBUG [org.springframework.jndi.JndiTemplate] Looking up JNDI object with name [java:comp/UserTransaction]
12:31:03,410 INFO [org.springframework.orm.hibernate3.LocalSessionFactoryBean] Closing Hibernate SessionFactory
12:31:03,411 ERROR [org.jboss.ejb.plugins.LogInterceptor] TransactionRolledbackLocalException in method: public abstract void javax.jms.MessageListener.onMessage(javax.jms.Message), causedBy:
javax.ejb.EJBException: Could not instantiate bean
 at org.jboss.ejb.plugins.AbstractInstancePool.get(AbstractInstancePool.java:180)
 at org.jboss.ejb.plugins.MessageDrivenInstanceInterceptor.invoke(MessageDrivenInstanceInterceptor.java:67)
 at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:48)
 at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:105)
 at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:335)
 at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:166)
 at org.jboss.ejb.plugins.RunAsSecurityInterceptor.invoke(RunAsSecurityInterceptor.java:94)
 at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:192)
 at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:122)
 at org.jboss.ejb.MessageDrivenContainer.internalInvoke(MessageDrivenContainer.java:389)
 at org.jboss.ejb.Container.invoke(Container.java:873)
 at org.jboss.ejb.plugins.jms.JMSContainerInvoker.invoke(JMSContainerInvoker.java:1090)
 at org.jboss.ejb.plugins.jms.JMSContainerInvoker$MessageListenerImpl.onMessage(JMSContainerInvoker.java:1392)
 at org.jboss.jms.asf.StdServerSession.onMessage(StdServerSession.java:256)
 at org.jboss.mq.SpyMessageConsumer.sessionConsumerProcessMessage(SpyMessageConsumer.java:904)
 at org.jboss.mq.SpyMessageConsumer.addMessage(SpyMessageConsumer.java:160)
 at org.jboss.mq.SpySession.run(SpySession.java:333)
 at org.jboss.jms.asf.StdServerSession.run(StdServerSession.java:180)
 at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:748)
 at java.lang.Thread.run(Thread.java:552)
12:31:03,413 ERROR [org.jboss.ejb.plugins.jms.JMSContainerInvoker] Exception in JMSCI message listener
javax.ejb.TransactionRolledbackLocalException: Could not instantiate bean; CausedByException is:
 Could not instantiate bean
 at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:232)
 at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:335)
 at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:166)
 at org.jboss.ejb.plugins.RunAsSecurityInterceptor.invoke(RunAsSecurityInterceptor.java:94)
 at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:192)
 at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:122)
 at org.jboss.ejb.MessageDrivenContainer.internalInvoke(MessageDrivenContainer.java:389)
 at org.jboss.ejb.Container.invoke(Container.java:873)
 at org.jboss.ejb.plugins.jms.JMSContainerInvoker.invoke(JMSContainerInvoker.java:1090)
 at org.jboss.ejb.plugins.jms.JMSContainerInvoker$MessageListenerImpl.onMessage(JMSContainerInvoker.java:1392)
 at org.jboss.jms.asf.StdServerSession.onMessage(StdServerSession.java:256)
 at org.jboss.mq.SpyMessageConsumer.sessionConsumerProcessMessage(SpyMessageConsumer.java:904)
 at org.jboss.mq.SpyMessageConsumer.addMessage(SpyMessageConsumer.java:160)
 at org.jboss.mq.SpySession.run(SpySession.java:333)
 at org.jboss.jms.asf.StdServerSession.run(StdServerSession.java:180)
 at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:748)
 at java.lang.Thread.run(Thread.java:552)
javax.ejb.EJBException: Could not instantiate bean
 at org.jboss.ejb.plugins.AbstractInstancePool.get(AbstractInstancePool.java:180)
 at org.jboss.ejb.plugins.MessageDrivenInstanceInterceptor.invoke(MessageDrivenInstanceInterceptor.java:67)
 at org.jboss.ejb.plugins.CallValidationInterceptor.invoke(CallValidationInterceptor.java:48)
 at org.jboss.ejb.plugins.AbstractTxInterceptor.invokeNext(AbstractTxInterceptor.java:105)
 at org.jboss.ejb.plugins.TxInterceptorCMT.runWithTransactions(TxInterceptorCMT.java:335)
 at org.jboss.ejb.plugins.TxInterceptorCMT.invoke(TxInterceptorCMT.java:166)
 at org.jboss.ejb.plugins.RunAsSecurityInterceptor.invoke(RunAsSecurityInterceptor.java:94)
 at org.jboss.ejb.plugins.LogInterceptor.invoke(LogInterceptor.java:192)
 at org.jboss.ejb.plugins.ProxyFactoryFinderInterceptor.invoke(ProxyFactoryFinderInterceptor.java:122)
 at org.jboss.ejb.MessageDrivenContainer.internalInvoke(MessageDrivenContainer.java:389)
 at org.jboss.ejb.Container.invoke(Container.java:873)
 at org.jboss.ejb.plugins.jms.JMSContainerInvoker.invoke(JMSContainerInvoker.java:1090)
 at org.jboss.ejb.plugins.jms.JMSContainerInvoker$MessageListenerImpl.onMessage(JMSContainerInvoker.java:1392)
 at org.jboss.jms.asf.StdServerSession.onMessage(StdServerSession.java:256)
 at org.jboss.mq.SpyMessageConsumer.sessionConsumerProcessMessage(SpyMessageConsumer.java:904)
 at org.jboss.mq.SpyMessageConsumer.addMessage(SpyMessageConsumer.java:160)
 at org.jboss.mq.SpySession.run(SpySession.java:333)
 at org.jboss.jms.asf.StdServerSession.run(StdServerSession.java:180)
 at EDU.oswego.cs.dl.util.concurrent.PooledExecutor$Worker.run(PooledExecutor.java:748)
 at java.lang.Thread.run(Thread.java:552)

My question is, why is this bean failing to instantiate?

This trace is with the following categories set in log4j.xml

 <category name="org.jboss.mq">
 <priority value="TRACE"/>
 </category>


 <category name="org.jboss.jms">
 <priority value="TRACE"/>
 </category>


 <category name="org.jboss.ejb">
 <priority value="TRACE"/>
 </category>

I am using the connection factory located at: java:/ConnectionFactory which i believe is the JVMIL

Any insite would be much appreciated, thanks....and I if you see any info that i've left out please let me know!