1 Reply Latest reply on Dec 5, 2005 10:26 PM by Adrian Brock

    Unknown exception in JMSCI message listener

    Ben Poweski Newbie

      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!