Unknown exception in JMSCI message listener
bpoweski Dec 1, 2005 1:34 PMI'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!