4 Replies Latest reply on Jun 16, 2009 5:54 PM by Richard Taylor

    Quartz Job unable to access deployed EJB (JBoss AS 5.01)

    Joe W Newbie

      I am upgrading from JBoss AS 4.05 to JBoss 5.01. The code mentioned below works fine in JBoss 4.05.

      I have a quartz job that is unable to get a remote access to a deployed EJB. I know that the EJB is deployed because I see it in the JMX console. Additionally, I wrote a client program that uses the same code (as is used by the quartz job) to access the EJB remotely. The client program works fine.

      It seems to be a class loader issue (where quartz is running).

      Here is the relevant part of the stack trace:

      2009-05-07 17:30:00,101 INFO [com.squaretrade.locator.Locator] (DefaultQuartzScheduler_Worker-2) LOOKING UP SESSION: batch/QueueingEngineMessageSenderImpl/remote
      2009-05-07 17:30:00,101 INFO [com.squaretrade.locator.Locator] (DefaultQuartzScheduler_Worker-2) USING PROVIDER URL FOR REMOTE CONTEXT: jboss-batch-local-11:1100,jboss-batch-local-12:1100 2009-05-07 17:30:00,102 DEBUG [org.jboss.ejb3.proxy.objectfactory.ProxyObjectFactory] (DefaultQuartzScheduler_Worker-2) org.jboss.ejb3.proxy.objectfactory.ProxyObjectFactory servicing request for batch/QueueingEngineMessageSenderImpl/remote
      2009-05-07 17:30:00,140 DEBUG [org.jboss.remoting.InvokerRegistry] (DefaultQuartzScheduler_Worker-2) removed org.jboss.remoting.transport.local.LocalClientInvoker@1ac1a45 from registry
      2009-05-07 17:30:00,140 DEBUG [org.jboss.ejb3.proxy.objectfactory.session.SessionProxyObjectFactory] (DefaultQuartzScheduler_Worker-2) Created Proxy of type $Proxy271 for EJB3 Business Interface: com.squaretrade.queueing.QueueingEngineMessageSenderRemote
      2009-05-07 17:30:00,140 INFO [com.squaretrade.locator.Locator] (DefaultQuartzScheduler_Worker-2) CAUGHT NAMING EXCEPTION: Could not dereference object ATTEMPTING RETRY
      2009-05-07 17:30:00,201 ERROR [com.squaretrade.locator.Locator] (DefaultQuartzScheduler_Worker-2) CAUGHT NAMING EXCEPTION: Could not dereference object FINISHED RETRYING
      2009-05-07 17:30:00,201 ERROR [com.squaretrade.queueing.AbstractQueueingOperation] (DefaultQuartzScheduler_Worker-2) Exception caught in AbstractQueueingOperation.execute when executing queueing spec: com.squaretrade.queueing.spec.WarrantyOrderRequeueingOperation
      javax.naming.NamingException: Could not dereference object [Root exception is java.lang.RuntimeException: Can not find interface declared by Proxy in our CL + BaseClassLoader@16fde80{vfszip:/usr/local/jboss-5.0.1.GA/server/batch/deploy/quartz-ra.rar/}]
       at org.jnp.interfaces.NamingContext.getObjectInstanceWrapFailure(NamingContext.java:1472)
       at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:818)
       at org.jnp.interfaces.NamingContext.lookup(NamingContext.java:682)
       at javax.naming.InitialContext.lookup(InitialContext.java:392)
       at com.squaretrade.locator.Locator.getSession(Locator.java:196)
       at com.squaretrade.queueing.AbstractQueueingOperation.sendMessage(AbstractQueueingOperation.java:137)
       at com.squaretrade.queueing.AbstractQueueingOperation.execute(AbstractQueueingOperation.java:101)
       at com.squaretrade.semaphore.quartz.AbstractSerialQuartzJob.execute(AbstractSerialQuartzJob.java:56)
       at sun.reflect.GeneratedMethodAccessor436.invoke(Unknown Source)
       at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
       at java.lang.reflect.Method.invoke(Method.java:597)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeTarget(MethodInvocation.java:122)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:111)
       at org.jboss.ejb3.EJBContainerInvocationWrapper.invokeNext(EJBContainerInvocationWrapper.java:69)
       at org.jboss.ejb3.interceptors.aop.InterceptorSequencer.invoke(InterceptorSequencer.java:73)
       at org.jboss.ejb3.interceptors.aop.InterceptorSequencer.aroundInvoke(InterceptorSequencer.java:59)
       at sun.reflect.GeneratedMethodAccessor435.invoke(Unknown Source)
       at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
       at java.lang.reflect.Method.invoke(Method.java:597)
       at org.jboss.aop.advice.PerJoinpointAdvice.invoke(PerJoinpointAdvice.java:174)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
       at org.jboss.ejb3.interceptors.aop.InvocationContextInterceptor.fillMethod(InvocationContextInterceptor.java:72)
       at org.jboss.aop.advice.org.jboss.ejb3.interceptors.aop.InvocationContextInterceptor_z_fillMethod_11445709.invoke(InvocationContextInterceptor_z_fillMethod_11445709.java)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
       at org.jboss.ejb3.interceptors.aop.InvocationContextInterceptor.setup(InvocationContextInterceptor.java:88)
       at org.jboss.aop.advice.org.jboss.ejb3.interceptors.aop.InvocationContextInterceptor_z_setup_11445709.invoke(InvocationContextInterceptor_z_setup_11445709.java)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
       at org.jboss.ejb3.connectionmanager.CachedConnectionInterceptor.invoke(CachedConnectionInterceptor.java:62)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
       at org.jboss.ejb3.entity.TransactionScopedEntityManagerInterceptor.invoke(TransactionScopedEntityManagerInterceptor.java:56)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
       at org.jboss.ejb3.AllowedOperationsInterceptor.invoke(AllowedOperationsInterceptor.java:47)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
       at org.jboss.ejb3.tx.NullInterceptor.invoke(NullInterceptor.java:42)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
       at org.jboss.ejb3.stateless.StatelessInstanceInterceptor.invoke(StatelessInstanceInterceptor.java:68)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
       at org.jboss.aspects.tx.TxPolicy.invokeInCallerTx(TxPolicy.java:126)
       at org.jboss.aspects.tx.TxInterceptor$Required.invoke(TxInterceptor.java:194)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
       at org.jboss.ejb3.tx.NullInterceptor.invoke(NullInterceptor.java:42)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
       at org.jboss.ejb3.security.Ejb3AuthenticationInterceptorv2.invoke(Ejb3AuthenticationInterceptorv2.java:80)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
       at org.jboss.ejb3.BlockContainerShutdownInterceptor.invoke(BlockContainerShutdownInterceptor.java:67)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
       at org.jboss.aspects.currentinvocation.CurrentInvocationInterceptor.invoke(CurrentInvocationInterceptor.java:67)
       at org.jboss.aop.joinpoint.MethodInvocation.invokeNext(MethodInvocation.java:102)
       at org.jboss.ejb3.mdb.MessagingContainer.localInvoke(MessagingContainer.java:262)
       at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.delivery(MessageInflowLocalProxy.java:270)
       at org.jboss.ejb3.mdb.inflow.MessageInflowLocalProxy.invoke(MessageInflowLocalProxy.java:140)
       at $Proxy212.execute(Unknown Source)
       at org.jboss.resource.adapter.quartz.inflow.QuartzJob.execute(QuartzJob.java:57)
       at org.quartz.core.JobRunShell.run(JobRunShell.java:203)
       at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:520)
      Caused by: java.lang.RuntimeException: Can not find interface declared by Proxy in our CL + BaseClassLoader@16fde80{vfszip:/usr/local/jboss-5.0.1.GA/server/batch/deploy/quartz-ra.rar/}
       at org.jboss.ejb3.proxy.objectfactory.ProxyObjectFactory.redefineProxyInTcl(ProxyObjectFactory.java:341)
       at org.jboss.ejb3.proxy.objectfactory.session.SessionProxyObjectFactory.createProxy(SessionProxyObjectFactory.java:134)
       at org.jboss.ejb3.proxy.objectfactory.session.stateless.StatelessSessionProxyObjectFactory.getProxy(StatelessSessionProxyObjectFactory.java:79)
       at org.jboss.ejb3.proxy.objectfactory.ProxyObjectFactory.getObjectInstance(ProxyObjectFactory.java:156)
       at javax.naming.spi.NamingManager.getObjectInstance(NamingManager.java:304)
       at org.jnp.interfaces.NamingContext.getObjectInstance(NamingContext.java:1447)
       at org.jnp.interfaces.NamingContext.getObjectInstanceWrapFailure(NamingContext.java:1464)
       ... 54 more
      Caused by: java.lang.ClassNotFoundException: com.squaretrade.queueing.QueueingEngineMessageSenderRemote from BaseClassLoader@16fde80{VFSClassLoaderPolicy@178d35f{name=vfszip:/usr/local/jboss-5.0.1.GA/server/batch/deploy/quartz-ra.rar/ domain=ClassLoaderDomain@790192{name=DefaultDomain parentPolicy=BEFORE parent=org.jboss.system.NoAnnotationURLClassLoader@1c247a0} roots=[MemoryContextHandler@24978055[path= context=vfsmemory://4sg251y-ua7hys-fug1iydt-1-fug1kcb3-22 real=vfsmemory://4sg251y-ua7hys-fug1iydt-1-fug1kcb3-22], DelegatingHandler@6674454[path=quartz-ra.rar context=file:/usr/local/jboss-5.0.1.GA/server/batch/deploy/ real=file:/usr/local/jboss-5.0.1.GA/server/batch/deploy/quartz-ra.rar], DelegatingHandler@5091970[path=quartz-ra.rar/quartz-ra.jar context=file:/usr/local/jboss-5.0.1.GA/server/batch/deploy/ real=file:/usr/local/jboss-5.0.1.GA/server/batch/deploy/quartz-ra.rar/quartz-ra.jar]] delegates=null exported=[org.jboss.resource.adapter.quartz.inflow, META-INF] <IMPORT-ALL>NON_EMPTY}}
       at org.jboss.classloader.spi.base.BaseClassLoader.loadClass(BaseClassLoader.java:422)
       at java.lang.ClassLoader.loadClass(ClassLoader.java:251)
       at java.lang.ClassLoader.loadClassInternal(ClassLoader.java:319)
       at java.lang.Class.forName0(Native Method)
       at java.lang.Class.forName(Class.java:247)
       at org.jboss.ejb3.proxy.objectfactory.ProxyObjectFactory.redefineProxyInTcl(ProxyObjectFactory.java:337)
       ... 60 more
      2009-05-07 17:30:00,207 DEBUG [org.jboss.jpa.deployment.ManagedEntityManagerFactory] (DefaultQuartzScheduler_Worker-2) ************** closing entity managersession **************
      




        • 1. Re: Quartz Job unable to access deployed EJB (JBoss AS 5.01)
          jaikiran pai Master

          This has come up a couple of times before and i think a JIRA was raised. The issue is definitely with classloading. The quartz job gets triggered through a classloader (during server startup) which does not have visibility to the application's classloader(/classes).

          • 2. Re: Quartz Job unable to access deployed EJB (JBoss AS 5.01)
            jaikiran pai Master

             

            "jaikiran" wrote:
            This has come up a couple of times before and i think a JIRA was raised.


            Here https://jira.jboss.org/jira/browse/JBAS-6314. If you have a sample application which reproduces this issue, could you please attach it to that JIRA?

            • 3. Re: Quartz Job unable to access deployed EJB (JBoss AS 5.01)
              Joe W Newbie

              Yeah, I saw that jira issue and a posting http://www.jboss.org/index.html?module=bb&op=viewtopic&t=147180. I figured that it was likely the same issue but was not sure.

              Here is a simple example I made that runs in the server. It will be easier than posting all the related code pertaining to the log output above. Here goes:

              QueueingEngineMessageSenderI.java

              package com.squaretrade.queueing;
              
              public interface QueueingEngineMessageSenderI {
               public void displayMessage(String message);
              }
              



              QueueingEngineMessageSenderRemote.java (not really necessary for this exact example as I could have just used the interface above as the remote reference but displaying anyway)
              package com.squaretrade.queueing;
              
              public interface QueueingEngineMessageSenderRemote extends QueueingEngineMessageSenderI
              {
              }
              


              QueueingEngineMessageSenderImpl.java
              package com.squaretrade.queueing;
              
              import javax.ejb.Stateless;
              import javax.ejb.Remote;
              import org.apache.log4j.Logger;
              
              @Stateless
              @Remote(QueueingEngineMessageSenderRemote.class)
              public class QueueingEngineMessageSenderImpl
               implements QueueingEngineMessageSenderRemote
              {
               private static final Logger log =
               Logger.getLogger(QueueingEngineMessageSenderImpl.class);
              
               /**
               * Logs the message.
               * @param message the type of the message
               */
               public void displayMessage(String message) {
               log.info("Message: " + message);
               }
              }
              


              ejb-jar.xml
              <?xml version="1.0" encoding="UTF-8"?>
              <ejb-jar
               xmlns="http://java.sun.com/xml/ns/javaee"
               xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
               xsi:schemaLocation="http://java.sun.com/xml/ns/javaee
               http://java.sun.com/xml/ns/javaee/ejb-jar_3_0.xsd"
               version="3.0">
               <enterprise-beans>
               <message-driven>
               <ejb-name>RequeueingEngineMessageSenderTestMDB</ejb-name>
               <ejb-class>com.squaretrade.queueing.spec.RequeueingEngineMessageSenderTest</ejb-class>
               <transaction-type>Container</transaction-type>
               <activation-config>
               <activation-config-property>
               <activation-config-property-name>cronTrigger</activation-config-property-name>
               <activation-config-property-value>0 0/5 * * * ?</activation-config-property-value>
               </activation-config-property>
               <activation-config-property>
               <activation-config-property-name>jobName</activation-config-property-name>
               <activation-config-property-value>RequeueingEngineMessageSenderTest</activation-config-property-value>
               </activation-config-property>
               </activation-config>
               </message-driven>
               </enterprise-beans>
              </ejb-jar>
              




              The relevant server log output for the quartz job execution:
              2009-05-08 12:40:00,023 DEBUG [org.jboss.ejb3.interceptors.aop.InterceptorSequencer] (DefaultQuartzScheduler_Worker-4) aroundInvoke [advisedMethod=public void com.squaretrade.queueing.spec.RequeueingEngineMessageSenderTest.execute(org.quartz.JobExecutionContext) throws org.quartz.JobExecutionException, unadvisedMethod=public void com.squaretrade.queueing.spec.RequeueingEngineMessageSenderTest.execute(org.quartz.JobExecutionContext) throws org.quartz.JobExecutionException, metadata=null, targetObject=com.squaretrade.queueing.spec.RequeueingEngineMessageSenderTest@18697cd, arguments=[Ljava.lang.Object;@1aea098]
              2009-05-08 12:40:00,023 INFO [com.squaretrade.queueing.spec.RequeueingEngineMessageSenderTest] (DefaultQuartzScheduler_Worker-4) Get initial context for ejb
              2009-05-08 12:40:00,024 INFO [com.squaretrade.queueing.spec.RequeueingEngineMessageSenderTest] (DefaultQuartzScheduler_Worker-4) Look up jndi name:batch/QueueingEngineMessageSenderImpl/remote
              2009-05-08 12:40:00,025 DEBUG [org.jboss.ejb3.proxy.objectfactory.ProxyObjectFactory] (DefaultQuartzScheduler_Worker-4) org.jboss.ejb3.proxy.objectfactory.ProxyObjectFactory servicing request for batch/QueueingEngineMessageSenderImpl/remote
              2009-05-08 12:40:00,031 DEBUG [org.jboss.remoting.InvokerRegistry] (DefaultQuartzScheduler_Worker-4) removed org.jboss.remoting.transport.local.LocalClientInvoker@c7732a from registry
              2009-05-08 12:40:00,031 DEBUG [org.jboss.ejb3.proxy.objectfactory.session.SessionProxyObjectFactory] (DefaultQuartzScheduler_Worker-4) Created Proxy of type $Proxy345 for EJB3 Business Interface: com.squaretrade.queueing.QueueingEngineMessageSenderRemote
              2009-05-08 12:40:00,031 ERROR [com.squaretrade.queueing.spec.RequeueingEngineMessageSenderTest] (DefaultQuartzScheduler_Worker-4) javax.naming.NamingException: Could not dereference object [Root exception is java.lang.RuntimeException: Can not find interface declared by Proxy in our CL + BaseClassLoader@1f85f8c{vfszip:/usr/local/jboss-5.0.1.GA/server/batch/deploy/quartz-ra.rar/}]
              



              Other things to note:
              The session bean is deployed. I verified this in two ways:
              1. By looking at the jmx-console
              2. By running a client program from the command line that accesses the stateless session bean in the remote context

              Here is the relevant server log output that happened when calling session bean's remote context from a client program (command line). It shows that the sessions bean has a remote context that is accessible to clients.
              2009-05-08 12:43:27,161 DEBUG [org.jboss.remoting.transport.socket.ClientSocketWrapper] (WorkerThread#0[172.16.100.152:38162]) reset timeout: 60000
              2009-05-08 12:43:27,225 DEBUG [org.jboss.remoting.transport.socket.ServerSocketWrapper] (WorkerThread#0[172.16.100.152:38162]) ServerSocketWrapper[Socket[addr=/172.16.100.152,port=38162,localport=3873].1af594f] wrote CLOSING
              2009-05-08 12:43:27,225 DEBUG [org.jboss.remoting.transport.socket.SocketWrapper] (WorkerThread#0[172.16.100.152:38162]) ServerSocketWrapper[Socket[addr=/172.16.100.152,port=38162,localport=3873].1af594f] closing socketPreview
              2009-05-08 12:43:27,225 DEBUG [org.jboss.remoting.transport.socket.SocketWrapper] (WorkerThread#0[172.16.100.152:38162]) ServerSocketWrapper[Socket[addr=/172.16.100.152,port=38162,localport=3873].1af594f] closed socket
              2009-05-08 12:43:27,225 DEBUG [org.jboss.remoting.transport.socket.ServerThread] (WorkerThread#0[172.16.100.152:38162]) WorkerThread#0[172.16.100.152:38162] closed socketWrapper: ServerSocketWrapper[Socket[addr=/172.16.100.152,port=38162,localport=3873].1af594f]
              2009-05-08 12:43:27,286 DEBUG [org.jboss.remoting.transport.socket.ClientSocketWrapper] (WorkerThread#0[172.16.100.152:38163]) reset timeout: 60000
              2009-05-08 12:43:27,304 DEBUG [org.jboss.ejb3.stateless.StatelessContainer] (WorkerThread#0[172.16.100.152:38163]) Received dynamic invocation for method with hash: 278620747465739483
              2009-05-08 12:43:27,308 DEBUG [org.jboss.ejb3.interceptors.aop.InterceptorSequencer] (WorkerThread#0[172.16.100.152:38163]) aroundInvoke [advisedMethod=public void com.squaretrade.queueing.QueueingEngineMessageSenderImpl.displayMessage(java.lang.String), unadvisedMethod=public void com.squaretrade.queueing.QueueingEngineMessageSenderImpl.displayMessage(java.lang.String), metadata=[metaData={DISPATCHER={OID=[type=AS_ISvalue=jboss.j2ee:ear=batch.ear,jar=beans-batch.jar,name=QueueingEngineMessageSenderImpl,service=EJB3]}, REMOTING={SUBSYSTEM=[type=AS_ISvalue=AOP], INVOKER_LOCATOR=[type=AS_ISvalue=InvokerLocator [socket://172.16.77.70:3873/]]}, security={context=[type=MARSHALLEDvalue=[org.jboss.security.plugins.JBossSecurityContext()CLIENT)]]}, IS_LOCAL={GUID=[type=AS_ISvalue=jboss.j2ee:ear=batch.ear,jar=beans-batch.jar,name=QueueingEngineMessageSenderImpl,service=EJB3,VMID=9dc59e2c84f0ecd8:5cf1d0f4:12121b2911f:-7ff7]}, SessionInvocation={InvokedMethod=[type=AS_ISvalue=com.squaretrade.queueing.QueueingEngineMessageSenderRemote: com.squaretrade.queueing.QueueingEngineMessageSenderI.displayMessage(java.lang.String)]}}], targetObject=com.squaretrade.queueing.QueueingEngineMessageSenderImpl@1092239, arguments=[Ljava.lang.Object;@63db73]
              2009-05-08 12:43:27,308 INFO [com.squaretrade.queueing.QueueingEngineMessageSenderImpl] (WorkerThread#0[172.16.100.152:38163]) Message: Test quartz message
              2009-05-08 12:43:27,311 DEBUG [org.jboss.remoting.transport.socket.ServerSocketWrapper] (WorkerThread#0[172.16.100.152:38163]) ServerSocketWrapper[Socket[addr=/172.16.100.152,port=38163,localport=3873].8ee16c] wrote CLOSING
              2009-05-08 12:43:27,311 DEBUG [org.jboss.remoting.transport.socket.SocketWrapper] (WorkerThread#0[172.16.100.152:38163]) ServerSocketWrapper[Socket[addr=/172.16.100.152,port=38163,localport=3873].8ee16c] closing socket
              2009-05-08 12:43:27,311 DEBUG [org.jboss.remoting.transport.socket.SocketWrapper] (WorkerThread#0[172.16.100.152:38163]) ServerSocketWrapper[Socket[addr=/172.16.100.152,port=38163,localport=3873].8ee16c] closed socket
              2009-05-08 12:43:27,311 DEBUG [org.jboss.remoting.transport.socket.ServerThread] (WorkerThread#0[172.16.100.152:38163]) WorkerThread#0[172.16.100.152:38163] closed socketWrapper: ServerSocketWrapper[Socket[addr=/172.16.100.152,port=38163,localport=3873].8ee16c]
              



              • 4. Re: Quartz Job unable to access deployed EJB (JBoss AS 5.01)
                Richard Taylor Newbie

                May or may not work for others, but I was just able to work around this issue by turning off EAR classloading isolation (Jboss 5.1.0 JDK6). After setting the following property to false, the quartz resource adapter can now load my ejb and that ejb's dependencies are properly injected. There are obviously other classloading implications, but if it's an option...

                in jboss/server/all/deployers/ear-deployer-jboss.beans.xml:

                <bean name="EARClassLoaderDeployer" class="org.jboss.deployment.EarClassLoaderDeployer">
                 <property name="isolated">false</property>
                 </bean>