Cannot load from BACKUPSTORE issue

Advertisement
Hi,
Hopefully, someone can help with this. I'm in the process of developing a J2EE application. At present it contains one very small stateful session bean. The issue I have regards passivation and removal of this bean. For testing purposes I have set the passivation and removal timeouts to small values as follows:
<bean-cache>
<victim-selection-policy>FIFO</victim-selection-policy>
<cache-idle-timeout-in-seconds>60</cache-idle-timeout-in-seconds>
<removal-timeout-in-seconds>60</removal-timeout-in-seconds>
</bean-cache>
My understanding is that using the above settings will passivate the bean after 1 minute and remove the bean after a further minute.
Passivation appears to be occuring as a message contained within the ejbPassivate method is being written to the server log. However, the problem I'm having is when I then try to access the bean once passivated. I get the following stack trace:
[08/Sep/2004:15:56:16] SEVERE (23316): FIFO-com.syntegra.neg.ejbtesterejb.EJBTesterBean: Cannot load from BACKUPSTORE FOR Key: <de899dfc12>
[08/Sep/2004:15:56:16] WARNING (23316): [FIFO-com.syntegra.neg.ejbtesterejb.EJBTesterBean.1]: Invalid sessionID: de899dfc12
[08/Sep/2004:15:56:16] SEVERE (23316): IOP5011: Exception getting the servant: [javax.ejb.NoSuchObjectLocalException: Invalid Session Key ( de899dfc12)]
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr: Exception in thread "service-j2ee-9" org.omg.CORBA.OBJECT_NOT_EXIST: vmcid: 0x2000 minor code: 1807 completed: No
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.enterprise.iiop.POAProtocolMgr.preinvoke(POAProtocolMgr.java:381)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.corba.ee.internal.POA.POAImpl.internalGetServant(POAImpl.java:388)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.corba.ee.internal.POA.POAImpl.getServant(POAImpl.java:309)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.corba.ee.internal.POA.GenericPOAServerSC.preinvoke(GenericPOAServerSC.java:348)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.corba.ee.internal.POA.ServantCachePOAClientSC.initServant(ServantCachePOAClientSC.java:112)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.corba.ee.internal.POA.ServantCachePOAClientSC.setOrb(ServantCachePOAClientSC.java:95)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.corba.ee.internal.iiop.CDRInputStream_1_0.createDelegate(CDRInputStream_1_0.java:760)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.corba.ee.internal.iiop.CDRInputStream_1_0.internalIORToObject(CDRInputStream_1_0.java:750)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.corba.ee.internal.iiop.CDRInputStream_1_0.read_Object(CDRInputStream_1_0.java:669)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.corba.ee.internal.iiop.CDRInputStream_1_0.read_abstract_interface(CDRInputStream_1_0.java:890)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.corba.ee.internal.iiop.CDRInputStream_1_0.read_abstract_interface(CDRInputStream_1_0.java:884)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.corba.ee.internal.iiop.CDRInputStream.read_abstract_interface(CDRInputStream.java:307)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.corba.se.internal.io.IIOPInputStream.readObjectDelegate(IIOPInputStream.java:228)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.corba.se.internal.io.IIOPInputStream.readObjectOverride(IIOPInputStream.java:381)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at java.io.ObjectInputStream.readObject(ObjectInputStream.java:318)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.enterprise.iiop.IIOPHandleDelegate.getStub(IIOPHandleDelegate.java:64)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.enterprise.iiop.IIOPHandleDelegate.readEJBObject(IIOPHandleDelegate.java:39)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.ejb.portable.HandleImpl.readObject(HandleImpl.java:91)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.corba.se.internal.io.IIOPInputStream.readObject(Native Method)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.corba.se.internal.io.IIOPInputStream.invokeObjectReader(IIOPInputStream.java:1298)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.corba.se.internal.io.IIOPInputStream.inputObject(IIOPInputStream.java:908)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.corba.se.internal.io.IIOPInputStream.simpleReadObject(IIOPInputStream.java:261)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.corba.se.internal.io.ValueHandlerImpl.readValueInternal(ValueHandlerImpl.java:247)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.corba.se.internal.io.ValueHandlerImpl.readValue(ValueHandlerImpl.java:209)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.corba.ee.internal.iiop.CDRInputStream_1_0.read_value(CDRInputStream_1_0.java:981)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.corba.ee.internal.iiop.CDRInputStream.read_value(CDRInputStream.java:287)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.sun.corba.ee.internal.javax.rmi.CORBA.Util.copyObject(Util.java:598)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at javax.rmi.CORBA.Util.copyObject(Util.java:314)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.syntegra.neg.ejbtesterejb._EJBTester_Stub.getHandle(Unknown Source)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.syntegra.neg.web.ModelManager.getExistingEJBTester(ModelManager.java:178)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.syntegra.neg.web.ModelManager.getTesterEJB(ModelManager.java:121)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.syntegra.neg.web.WebTisRequestProcessor.processRequest(WebTisRequestProcessor.java:191)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.syntegra.neg.web.RoutingControl.doPostOrGet(RoutingControl.java:134)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.syntegra.neg.web.RoutingControl.doGet(RoutingControl.java:91)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at javax.servlet.http.HttpServlet.service(HttpServlet.java:740)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at org.apache.catalina.core.StandardWrapperValve.invokeServletService(StandardWrapperValve.java:720)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at org.apache.catalina.core.StandardWrapperValve.access$000(StandardWrapperValve.java:118)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at org.apache.catalina.core.StandardWrapperValve$1.run(StandardWrapperValve.java:278)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at java.security.AccessController.doPrivileged(Native Method)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:274)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:505)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:212)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:505)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:203)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:505)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.iplanet.ias.web.connector.nsapi.NSAPIProcessor.process(NSAPIProcessor.java:158)
[08/Sep/2004:15:56:16] WARNING (23316): CORE3283: stderr:      at com.iplanet.ias.web.WebContainer.service(WebContainer.java:850)
[08/Sep/2004:15:56:16] WARNING (23316):java.io.IOException: Serializable readObject method failed internally
     at com.sun.corba.se.internal.io.IIOPInputStream.throwExceptionType(Native Method)
     at com.sun.corba.se.internal.io.IIOPInputStream.simpleReadObject(IIOPInputStream.java:274)
     at com.sun.corba.se.internal.io.ValueHandlerImpl.readValueInternal(ValueHandlerImpl.java:247)
     at com.sun.corba.se.internal.io.ValueHandlerImpl.readValue(ValueHandlerImpl.java:209)
     at com.sun.corba.ee.internal.iiop.CDRInputStream_1_0.read_value(CDRInputStream_1_0.java:981)
     at com.sun.corba.ee.internal.iiop.CDRInputStream.read_value(CDRInputStream.java:287)
     at com.sun.corba.ee.internal.javax.rmi.CORBA.Util.copyObject(Util.java:598)
     at javax.rmi.CORBA.Util.copyObject(Util.java:314)
     at com.syntegra.neg.ejbtesterejb._EJBTester_Stub.getHandle(Unknown Source)
     at com.syntegra.neg.web.ModelManager.getExistingEJBTester(ModelManager.java:178)
     at com.syntegra.neg.web.ModelManager.getTesterEJB(ModelManager.java:121)
     at com.syntegra.neg.web.WebTisRequestProcessor.processRequest(WebTisRequestProcessor.java:191)
     at com.syntegra.neg.web.RoutingControl.doPostOrGet(RoutingControl.java:134)
     at com.syntegra.neg.web.RoutingControl.doGet(RoutingControl.java:91)
     at javax.servlet.http.HttpServlet.service(HttpServlet.java:740)
     at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)
     at org.apache.catalina.core.StandardWrapperValve.invokeServletService(StandardWrapperValve.java:720)
     at org.apache.catalina.core.StandardWrapperValve.access$000(StandardWrapperValve.java:118)
     at org.apache.catalina.core.StandardWrapperValve$1.run(StandardWrapperValve.java:278)
     at java.security.AccessController.doPrivileged(Native Method)
     at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:274)
     at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:505)
     at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:212)
     at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:505)
     at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:203)
     at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:505)
     at com.iplanet.ias.web.connector.nsapi.NSAPIProcessor.process(NSAPIProcessor.java:158)
     at com.iplanet.ias.web.WebContainer.service(WebContainer.java:850)
[08/Sep/2004:15:56:16] WARNING (23316):
org.omg.CORBA.MARSHAL: Unable to read value from underlying bridge : Serializable readObject method failed internally vmcid: SUN minor code: 211 completed: Maybe
     at com.sun.corba.ee.internal.iiop.CDRInputStream_1_0.read_value(CDRInputStream_1_0.java:989)
     at com.sun.corba.ee.internal.iiop.CDRInputStream.read_value(CDRInputStream.java:287)
     at com.sun.corba.ee.internal.javax.rmi.CORBA.Util.copyObject(Util.java:598)
     at javax.rmi.CORBA.Util.copyObject(Util.java:314)
     at com.syntegra.neg.ejbtesterejb._EJBTester_Stub.getHandle(Unknown Source)
     at com.syntegra.neg.web.ModelManager.getExistingEJBTester(ModelManager.java:178)
     at com.syntegra.neg.web.ModelManager.getTesterEJB(ModelManager.java:121)
     at com.syntegra.neg.web.WebTisRequestProcessor.processRequest(WebTisRequestProcessor.java:191)
     at com.syntegra.neg.web.RoutingControl.doPostOrGet(RoutingControl.java:134)
     at com.syntegra.neg.web.RoutingControl.doGet(RoutingControl.java:91)
     at javax.servlet.http.HttpServlet.service(HttpServlet.java:740)
     at javax.servlet.http.HttpServlet.service(HttpServlet.java:853)
     at org.apache.catalina.core.StandardWrapperValve.invokeServletService(StandardWrapperValve.java:720)
     at org.apache.catalina.core.StandardWrapperValve.access$000(StandardWrapperValve.java:118)
     at org.apache.catalina.core.StandardWrapperValve$1.run(StandardWrapperValve.java:278)
     at java.security.AccessController.doPrivileged(Native Method)
     at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:274)
     at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:505)
     at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:212)
     at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:505)
     at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:203)
     at org.apache.catalina.core.StandardPipeline.invoke(StandardPipeline.java:505)
     at com.iplanet.ias.web.connector.nsapi.NSAPIProcessor.process(NSAPIProcessor.java:158)
     at com.iplanet.ias.web.WebContainer.service(WebContainer.java:850)
Previously using IPlanet 6 we did not receive such a stack trace. Is this simply because we are now using a later JVM and this stack trace is to be expected?
Thanks,
Emma.
Advertisement

Replay

I have finally discovered the cause of this problem. A class file is available to the EJB's client, but not to the EJB.
It seems we have decided to use pass-by-reference with our EJB (in sun-application.xml). So when an EJB method is called with such an object for an argument, no copy needs to be created, and we do not get any class loading errors.
The EJB can hold and use the object, and even passivate it without problem. However, when the EJB container needs to restore the passivated EJB a java.lang.ClassNotFoundException is thrown if the class file is not available. Oddly this exception is only seen in the log if logging is set to FINIEST, but this leads to the "Cannot load from BACKUPSTORE" message, the javax.ejb.NoSuchObjectLocalException, the org.omg.CORBA.OBJECT_NOT_EXIST, and the java.rmi.NoSuchObjectException.