After redeployment jndi lookup gets ClassCastException

[ithehorrible]

I've got a mbean service that is a part of a sar package inside ear archive. The service simply calls a stateless session bean in 10 seconds interval. To start jboss 3.2.2 server with deployed package works fine. Problem comes after I recompile and redeploy updated ear file -- and keep getting class cast exception on the service mbean at following:

Object homeObj = jndiContext.lookup( "workerHome" );
WorkerHome home = (WorkerHome)PortableRemoteObject.narrow(
homeObj, WorkerHome.class );

If I stop/start Jboss the "WorkerHome" is not getting "ClassCastException" and application works fine!??

I would be very please to get any help or this issue.

[jae77]

this is b/c the classloader has an "stale" reference to the "WorkerHome" object.

are the interfaces for the ejb externalized from the ear?

[jae77]

i had this same problem yesterday w/ local interfaces (for an entity bean). we have a "servicelocator" class (which implements the pattern of the same name) which we use to do all our lookups.

we ask the service locator for the EJBLocalHome object, and then downcast it in the code that make the initial "getLocalHome" call. in this case, an ear that was hot deployed made the call to the servicelocator for the EJBLocalHome object, and then did the cast. i haven't figured out why the casting exception occurs in this case.

[ithehorrible]

Thanks jae77 for your reply!

All EJB interfaces/beans are packed in its "ejb.jar" and the service mbean is a "scheduler.sar" with only a jboss-service.xml

Still haven't found the solution...

[jae77]

are you deploying the scheduler.sar and the ejb.jar together in a single ear?

[ithehorrible]

Yes the scheduler.sar & ejb.jar are in the same ear. Also I tried to separate scheduler into single deployed file -- but same result...

[ithehorrible]

It looks that my "enemy" is class-loader so I've added into jboss-app.xml following:

<loader-repository>dummy:loader=dummy.ear</loader-repository>

However it does not solving the redeployment issue at all...

[jae77]

hrm - i'm not really sure. you shouldn't be getting casting exceptions if both archives are being deployed as one unit. the classloader that deploys the ear should be the same one that is being used to look up class references.

i haven't experienced this problem when deploying everything in one ear.

adding the loader repository isn't going to do you much good in this instance b/c you're not trying to prevent the classes inside the ear from being accessed outside of the ear.

assuming you have a mbean in the sar, is it being shutdown and destroyed properly on the hot-deployment? the only other thing that comes to mind is that somehow it's not being completely destoryed and somehow as an incorrect reference.

at this point, i'd recommend turing on classloader debugging and posting back the relevant portions here.

[ithehorrible]

Thanks for your time to help on this issue.

"DummyService" MBEAN implements schedulable interface and calls the "Worker" session bean. As I said in my original post, this works fine if you restart the jboss appserver.

Here is the jboss log and you can see that "dummyService" MBEAN actually gets unloaded when redeployment occurs -- very strange indeed...


16:08:41,812 INFO [EjbModule] Stopping jboss.j2ee:module=ejb_test.jar,service=E
jbModule
16:08:41,843 INFO [StatelessSessionContainer] Stopping jboss.j2ee:jndiName=dumm
y/fileFetcherHome,service=EJB
16:08:41,843 INFO [StatelessSessionInstancePool] Stopping jboss.j2ee:jndiName=d
ummy/fileFetcherHome,plugin=pool,service=EJB
16:08:41,859 INFO [Scheduler] Stopping dummy:service=dummyService
16:08:41,859 INFO [StatelessSessionContainer] Stopping jboss.j2ee:jndiName=work
erHome,service=EJB
16:08:41,859 INFO [StatelessSessionInstancePool] Stopping jboss.j2ee:jndiName=w
orkerHome,plugin=pool,service=EJB
16:08:41,859 INFO [StatelessSessionContainer] Stopping jboss.j2ee:jndiName=dumm
yManager,service=EJB
16:08:41,859 INFO [StatelessSessionInstancePool] Stopping jboss.j2ee:jndiName=d
ummyManager,plugin=pool,service=EJB
16:08:41,859 INFO [EntityContainer] Stopping jboss.j2ee:jndiName=dummyLocalHome
,service=EJB
16:08:41,875 INFO [EntityInstancePool] Stopping jboss.j2ee:jndiName=dummyLocalH
ome,plugin=pool,service=EJB
16:08:41,875 INFO [TxConnectionManager] Stopping jboss.jca:service=LocalTxCM,na
me=datasource/dummy
16:08:41,875 INFO [JBossManagedConnectionPool] Stopping jboss.jca:service=Manag
edConnectionPool,name=datasource/dummy
16:08:41,875 INFO [RARDeployment] Stopping jboss.jca:service=ManagedConnectionF
actory,name=datasource/dummy
16:08:41,875 INFO [EARDeployer] Undeploying J2EE application, destroy step: fil
e:/C:/temp/local/jboss-3.2.2/server/default/deploy/dummy.ear
16:08:41,906 INFO [EJBModule] destroy(), remove EJB-Module: jboss.management.lo
cal:J2EEApplication=dummy.ear,J2EEServer=Local,j2eeType=EJBModule,name=ejb_test.
jar
16:08:41,953 WARN [DeploymentInfo] Could not delete file:/C:/temp/local/jboss-3
.2.2/server/default/tmp/deploy/tmp42655dummy.ear restart will delete it
16:08:42,000 INFO [MainDeployer] Starting deployment of package: file:/C:/temp/
local/jboss-3.2.2/server/default/deploy/dummy.ear
16:08:42,015 INFO [EARDeployer] Init J2EE application: file:/C:/temp/local/jbos
s-3.2.2/server/default/deploy/dummy.ear
16:08:42,671 INFO [EJBDeployer] nested deployment: file:/C:/temp/local/jboss-3.
2.2/server/default/tmp/deploy/tmp42656dummy.ear-contents/ejb_test.jar-contents/M
ETA-INF/mysql-ds.xml
16:08:46,453 INFO [EjbModule] Deploying DummyEJB
16:08:46,484 INFO [EjbModule] Deploying DummyManager
16:08:46,500 INFO [EjbModule] Deploying Worker
16:08:46,531 INFO [EjbModule] Deploying FileFetcher
16:08:46,765 INFO [RARDeployment] Started jboss.jca:service=ManagedConnectionFa
ctory,name=datasource/dummy
16:08:46,765 INFO [JBossManagedConnectionPool] Started jboss.jca:service=Manage
dConnectionPool,name=datasource/dummy
16:08:46,765 INFO [datasource/dummy] Bound connection factory for resource adap
ter for ConnectionManager 'jboss.jca:service=LocalTxCM,name=datasource/dummy to
JNDI name 'java:/datasource/dummy'
16:08:46,765 INFO [TxConnectionManager] Started jboss.jca:service=LocalTxCM,nam
e=datasource/dummy
16:08:47,281 INFO [DummyEJB] Table 'Test' already exists
16:08:47,281 INFO [EntityInstancePool] Started jboss.j2ee:jndiName=dummyLocalHo
me,plugin=pool,service=EJB
16:08:47,296 INFO [EntityContainer] Started jboss.j2ee:jndiName=dummyLocalHome,
service=EJB
16:08:47,359 INFO [StatelessSessionInstancePool] Started jboss.j2ee:jndiName=du
mmyManager,plugin=pool,service=EJB
16:08:47,359 INFO [StatelessSessionContainer] Started jboss.j2ee:jndiName=dummy
Manager,service=EJB
16:08:47,406 INFO [StatelessSessionInstancePool] Started jboss.j2ee:jndiName=wo
rkerHome,plugin=pool,service=EJB
16:08:47,406 INFO [StatelessSessionContainer] Started jboss.j2ee:jndiName=worke
rHome,service=EJB
16:08:47,406 INFO [STDOUT] DummyService has been initialized()
16:08:47,421 INFO [Scheduler] Started dummy:service=dummyService
16:08:47,421 INFO [StatelessSessionInstancePool] Started jboss.j2ee:jndiName=du
mmy/fileFetcherHome,plugin=pool,service=EJB
16:08:47,421 INFO [StatelessSessionContainer] Started jboss.j2ee:jndiName=dummy
/fileFetcherHome,service=EJB
16:08:47,421 INFO [EjbModule] Started jboss.j2ee:module=ejb_test.jar,service=Ej
bModule
16:08:47,421 INFO [EJBDeployer] Deployed: file:/C:/temp/local/jboss-3.2.2/serve
r/default/tmp/deploy/tmp42656dummy.ear-contents/ejb_test.jar
16:08:47,531 INFO [EARDeployer] Started J2EE application: file:/C:/temp/local/j
boss-3.2.2/server/default/deploy/dummy.ear
16:08:47,531 INFO [MainDeployer] Deployed package: file:/C:/temp/local/jboss-3.
2.2/server/default/deploy/dummy.ear
16:08:48,453 INFO [STDOUT] DummyService dummyTest() invoked...
16:08:48,484 INFO [STDOUT] $Proxy30
16:08:48,484 ERROR [STDERR] NPE
16:08:48,484 ERROR [STDERR] java.lang.ClassCastException
16:08:48,484 ERROR [STDERR] at com.sun.corba.se.internal.javax.rmi.PortableR
emoteObject.narrow(PortableRemoteObject.java:293)
16:08:48,500 ERROR [STDERR] at javax.rmi.PortableRemoteObject.narrow(Portabl
eRemoteObject.java:134)
16:08:48,500 ERROR [STDERR] at mbean.DummyService.dummyTest(DummyService.jav
a:54)
16:08:48,500 ERROR [STDERR] at mbean.DummyService.perform(DummyService.java:
40)
16:08:48,500 ERROR [STDERR] at org.jboss.varia.scheduler.Scheduler$Listener.
handleNotification(Scheduler.java:1263)
16:08:48,500 ERROR [STDERR] at org.jboss.mx.server.NotificationListenerProxy
.handleNotification(NotificationListenerProxy.java:69)
16:08:48,500 ERROR [STDERR] at javax.management.NotificationBroadcasterSuppo
rt.sendNotification(NotificationBroadcasterSupport.java:95)
16:08:48,500 ERROR [STDERR] at javax.management.timer.Timer.sendNotification
s(Timer.java:441)
16:08:48,500 ERROR [STDERR] at javax.management.timer.Timer.access$000(Timer
.java:31)
16:08:48,500 ERROR [STDERR] at javax.management.timer.Timer$RegisteredNotifi
cation.doRun(Timer.java:612)
16:08:48,500 ERROR [STDERR] at org.jboss.mx.util.SchedulableRunnable.run(Sch
edulableRunnable.java:164)
16:08:48,500 ERROR [STDERR] at org.jboss.mx.util.ThreadPool$Worker.run(Threa
dPool.java:225)

[jae77]

turn on classloader debugging (insert the following into your log4j.xml file)

<appender name="UCL" class="org.apache.log4j.FileAppender">
<param name="File" value="${jboss.server.home.dir}/log/ucl.log"/>
<param name="Append" value="false"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="[%r,%c{1},%t] %m%n"/>
</layout>
</appender>
<category name="org.jboss.mx.loading" additivity="false">
<priority value="TRACE" class="org.jboss.logging.XLevel"/>
<appender-ref ref="UCL"/>
</category>

if you have the jboss admin book, this is talked about in chapter 2 and it explains how to use the jmx console to provide some additional information (not sure if any of this is on a wiki page or not).

[ithehorrible]

Still battling with this issue, the classloader debug didn't gave me more clue so I decided to put a simple mbean service that call stateless session bean with complete package including ant build file.

Please download it from:
http://www.yourweb.co.za/download/service-calling-ejb.zip

Find '/deploy/worker.ear' package and after deployment you should get a answer from 'WorkerBean' that doWork() has been called. However if you just 'touch' the deployed ear or rebuild it from ant you will get the ClassCastException.

Also I tried to isolate both interfaces from ejb.jar into separate client.jar file but with the same results...

[ithehorrible]

The full deployment log is posted in this thread as well...


11:58:43,812 INFO [STDOUT] mbean.WorkerService callWorker() invoked
11:58:43,906 INFO [STDOUT] $Proxy31
11:58:43,906 ERROR [STDERR] NPE
11:58:43,906 ERROR [STDERR] java.lang.ClassCastException
11:58:43,906 ERROR [STDERR] at com.sun.corba.se.internal.javax.rmi.PortableR
emoteObject.narrow(PortableRemoteObject.java:293)
11:58:43,906 ERROR [STDERR] at javax.rmi.PortableRemoteObject.narrow(Portabl
eRemoteObject.java:134)
11:58:43,906 ERROR [STDERR] at mbean.WorkerService.callWorker(WorkerService.
java:46)
11:58:43,906 ERROR [STDERR] at mbean.WorkerService.perform(WorkerService.jav
a:32)
11:58:43,906 ERROR [STDERR] at org.jboss.varia.scheduler.Scheduler$Listener.
handleNotification(Scheduler.java:1263)
11:58:43,921 ERROR [STDERR] at org.jboss.mx.server.NotificationListenerProxy
.handleNotification(NotificationListenerProxy.java:69)
11:58:43,921 ERROR [STDERR] at javax.management.NotificationBroadcasterSuppo
rt.sendNotification(NotificationBroadcasterSupport.java:95)
11:58:43,937 ERROR [STDERR] at javax.management.timer.Timer.sendNotification
s(Timer.java:441)
11:58:43,953 ERROR [STDERR] at javax.management.timer.Timer.access$000(Timer
.java:31)
11:58:43,953 ERROR [STDERR] at javax.management.timer.Timer$RegisteredNotifi
cation.doRun(Timer.java:612)
11:58:43,968 ERROR [STDERR] at org.jboss.mx.util.SchedulableRunnable.run(Sch
edulableRunnable.java:164)
11:58:43,968 ERROR [STDERR] at org.jboss.mx.util.ThreadPool$Worker.run(Threa
dPool.java:225)

[ithehorrible]

I wonder if anyone in the WORLD have a working example...

[starksm64]

Its a bad interaction between the RMI marshalling's use of Class.forName that causes caching of classes due to your use of the java.naming.provider.url in your InitialContext properties. If I comment out this line from the ejb.jar:

java.naming.factory.initial = org.jnp.interfaces.NamingContextFactory
#java.naming.provider.url = localhost:1099
java.naming.factory.url.pkgs = org.jboss.naming:org.jnp.interfaces
jnp.socketFactory = org.jnp.interfaces.TimedSocketFactory

I can redeploy to by heart's content:

08:58:17,515 INFO [Server] JBoss (MX MicroKernel) [3.2.3 (build: CVSTag=JBoss_3
_2_3 date=200311301445)] Started in 23s:515ms
08:58:18,343 INFO [STDOUT] mbean.WorkerService callWorker() invoked
08:58:18,343 INFO [STDOUT] $Proxy36
08:58:18,359 INFO [STDOUT] ejb.WorkerBean has been instantiated!
08:58:18,359 INFO [STDOUT] ejb.WorkerBean doWork() has been called
08:58:27,390 INFO [EjbModule] Stopping jboss.j2ee:module=ejb.jar,service=EjbMod
ule
08:58:27,390 INFO [Scheduler] Stopping dummy:service=workerService
08:58:27,390 INFO [StatelessSessionContainer] Stopping jboss.j2ee:jndiName=work
erHome,service=EJB
08:58:27,390 INFO [StatelessSessionInstancePool] Stopping jboss.j2ee:jndiName=w
orkerHome,plugin=pool,service=EJB
08:58:27,390 INFO [EARDeployer] Undeploying J2EE application, destroy step: fil
e:/C:/cvs/Releases/jboss-3.2.3/server/redeploy/deploy/worker.ear
08:58:27,406 INFO [EJBModule] destroy(), remove EJB-Module: jboss.management.lo
cal:J2EEApplication=worker.ear,J2EEServer=Local,j2eeType=EJBModule,name=ejb.jar
08:58:27,421 WARN [DeploymentInfo] Could not delete file:/C:/cvs/Releases/jboss
-3.2.3/server/redeploy/tmp/deploy/tmp53149worker.ear restart will delete it
08:58:27,421 INFO [MainDeployer] Starting deployment of package: file:/C:/cvs/R
eleases/jboss-3.2.3/server/redeploy/deploy/worker.ear
08:58:27,421 INFO [EARDeployer] Init J2EE application: file:/C:/cvs/Releases/jb
oss-3.2.3/server/redeploy/deploy/worker.ear
08:58:28,421 INFO [EjbModule] Deploying Worker
08:58:28,500 INFO [StatelessSessionInstancePool] Started jboss.j2ee:jndiName=wo
rkerHome,plugin=pool,service=EJB
08:58:28,500 INFO [StatelessSessionContainer] Started jboss.j2ee:jndiName=worke
rHome,service=EJB
08:58:28,531 INFO [STDOUT] mbean.WorkerService has been initialized!
08:58:28,531 INFO [Scheduler] Started dummy:service=workerService
08:58:28,531 INFO [EjbModule] Started jboss.j2ee:module=ejb.jar,service=EjbModu
le
08:58:28,531 INFO [EJBDeployer] Deployed: file:/C:/cvs/Releases/jboss-3.2.3/ser
ver/redeploy/tmp/deploy/tmp53150worker.ear-contents/ejb.jar
08:58:28,546 INFO [EARDeployer] Started J2EE application: file:/C:/cvs/Releases
/jboss-3.2.3/server/redeploy/deploy/worker.ear
08:58:28,546 INFO [MainDeployer] Deployed package: file:/C:/cvs/Releases/jboss-
3.2.3/server/redeploy/deploy/worker.ear
08:58:29,531 INFO [STDOUT] mbean.WorkerService callWorker() invoked
08:58:29,531 INFO [STDOUT] $Proxy42
08:58:29,531 INFO [STDOUT] ejb.WorkerBean has been instantiated!
08:58:29,531 INFO [STDOUT] ejb.WorkerBean doWork() has been called
09:01:33,546 INFO [EjbModule] Stopping jboss.j2ee:module=ejb.jar,service=EjbMod
ule
09:01:33,546 INFO [Scheduler] Stopping dummy:service=workerService
09:01:33,546 INFO [StatelessSessionContainer] Stopping jboss.j2ee:jndiName=work
erHome,service=EJB
09:01:33,546 INFO [StatelessSessionInstancePool] Stopping jboss.j2ee:jndiName=w
orkerHome,plugin=pool,service=EJB
09:01:33,546 INFO [EARDeployer] Undeploying J2EE application, destroy step: fil
e:/C:/cvs/Releases/jboss-3.2.3/server/redeploy/deploy/worker.ear
09:01:33,562 INFO [EJBModule] destroy(), remove EJB-Module: jboss.management.lo
cal:J2EEApplication=worker.ear,J2EEServer=Local,j2eeType=EJBModule,name=ejb.jar
09:01:33,562 WARN [DeploymentInfo] Could not delete file:/C:/cvs/Releases/jboss
-3.2.3/server/redeploy/tmp/deploy/tmp53150worker.ear restart will delete it
09:01:33,562 INFO [MainDeployer] Starting deployment of package: file:/C:/cvs/R
eleases/jboss-3.2.3/server/redeploy/deploy/worker.ear
09:01:33,578 INFO [EARDeployer] Init J2EE application: file:/C:/cvs/Releases/jb
oss-3.2.3/server/redeploy/deploy/worker.ear
09:01:34,140 INFO [EjbModule] Deploying Worker
09:01:34,203 INFO [StatelessSessionInstancePool] Started jboss.j2ee:jndiName=wo
rkerHome,plugin=pool,service=EJB
09:01:34,203 INFO [StatelessSessionContainer] Started jboss.j2ee:jndiName=worke
rHome,service=EJB
09:01:34,203 INFO [STDOUT] mbean.WorkerService has been initialized!
09:01:34,203 INFO [Scheduler] Started dummy:service=workerService
09:01:34,203 INFO [EjbModule] Started jboss.j2ee:module=ejb.jar,service=EjbModu
le
09:01:34,203 INFO [EJBDeployer] Deployed: file:/C:/cvs/Releases/jboss-3.2.3/ser
ver/redeploy/tmp/deploy/tmp53151worker.ear-contents/ejb.jar
09:01:34,218 INFO [EARDeployer] Started J2EE application: file:/C:/cvs/Releases
/jboss-3.2.3/server/redeploy/deploy/worker.ear
09:01:34,218 INFO [MainDeployer] Deployed package: file:/C:/cvs/Releases/jboss-
3.2.3/server/redeploy/deploy/worker.ear
09:01:35,203 INFO [STDOUT] mbean.WorkerService callWorker() invoked
09:01:35,203 INFO [STDOUT] $Proxy47
09:01:35,203 INFO [STDOUT] ejb.WorkerBean has been instantiated!
09:01:35,203 INFO [STDOUT] ejb.WorkerBean doWork() has been called

[ithehorrible]

Thanks Scott for your help -- its working here as well... Is this a bug in sun's code?

The commenting out the "java.naming.provider.url" makes me wonder what to do if I need to call a session bean on the remote jboss instance, obviously I haven't tried it yet -- but will this problem appear if I leave it uncommented?