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

[josey]

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 **************

[jaikiran]

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).

[jaikiran]

"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?

[josey]

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]

[triumphthepup]

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>