Hi,
We've encountered a strange problem while running some automated tests on
our system. It consists of two servers, both running Glassfish 3.0.1, where
one of them has a WAR file with a JSF2 application, and the other has a
bunch of EJBs (deployed as a WAR). Below are some examples from our logs, I
hope someone can help us shed light on the problem:
After an hour or two with a few requests (somewhere around 100 requests an
hour), we get the following error on the front-end server:
[#|2011-01-05T01:53:41.335+0100|WARNING|glassfish3.0.1|javax.enterprise.resource.corba.ee._CORBA_.rpc.protocol|_ThreadID=451;_ThreadName=Thread-1;|"IOP00710220:
(INTERNAL) Error in GIOP magic"
org.omg.CORBA.INTERNAL: vmcid: SUN minor code: 220 completed: Maybe
at
com.sun.corba.ee.impl.logging.ORBUtilSystemException.giopMagicError(ORBUtilSystemException.java:5970)
at
com.sun.corba.ee.impl.logging.ORBUtilSystemException.giopMagicError(ORBUtilSystemException.java:5984)
at
com.sun.corba.ee.impl.protocol.giopmsgheaders.MessageBase.parseGiopHeader(MessageBase.java:196)
at
com.sun.corba.ee.impl.protocol.MessageParserImpl.parseBytes(MessageParserImpl.java:181)
at
com.sun.corba.ee.impl.transport.SocketOrChannelConnectionImpl.parseBytesAndDispatchMessages(SocketOrChannelConnectionImpl.java:1829)
at
com.sun.corba.ee.impl.transport.SocketOrChannelConnectionImpl.blockingRead(SocketOrChannelConnectionImpl.java:1775)
at
com.sun.corba.ee.impl.transport.SocketOrChannelConnectionImpl.doOptimizedReadStrategy(SocketOrChannelConnectionImpl.java:1671)
at
com.sun.corba.ee.impl.transport.SocketOrChannelConnectionImpl.doWork(SocketOrChannelConnectionImpl.java:1216)
at
com.sun.corba.ee.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.performWork(ThreadPoolImpl.java:492)
at
com.sun.corba.ee.impl.orbutil.threadpool.ThreadPoolImpl$WorkerThread.run(ThreadPoolImpl.java:528)
|#]
#|2011-01-05T01:53:41.339+0100|WARNING|glassfish3.0.1|javax.enterprise.resource.corba.ee.S1AS-ORB.rpc.encoding|_ThreadID=448;_ThreadName=Thread-1;|"IOP00810211:
(MARSHAL) Exception from readValue on ValueHandler in CDRInputStream"
org.omg.CORBA.MARSHAL: vmcid: SUN minor code: 211 completed: Maybe
at
com.sun.corba.ee.impl.logging.ORBUtilSystemException.valuehandlerReadException(ORBUtilSystemException.java:8888)
at
com.sun.corba.ee.impl.encoding.CDRInputStream_1_0.readRMIIIOPValueType(CDRInputStream_1_0.java:1076)
at
com.sun.corba.ee.impl.encoding.CDRInputStream_1_0.read_value(CDRInputStream_1_0.java:1175)
at
com.sun.corba.ee.impl.encoding.CDRInputObject.read_value(CDRInputObject.java:655)
at
com.sun.corba.ee.impl.io.IIOPInputStream.inputObjectField(IIOPInputStream.java:2298)
at
com.sun.corba.ee.impl.io.IIOPInputStream.inputClassFields(IIOPInputStream.java:2552)
at
com.sun.corba.ee.impl.io.IIOPInputStream.inputObject(IIOPInputStream.java:1310)
at
com.sun.corba.ee.impl.io.IIOPInputStream.simpleReadObject(IIOPInputStream.java:449)
at
com.sun.corba.ee.impl.io.ValueHandlerImpl.readValueInternal(ValueHandlerImpl.java:364)
at
com.sun.corba.ee.impl.io.ValueHandlerImpl.readValue(ValueHandlerImpl.java:320)
at
com.sun.corba.ee.impl.encoding.CDRInputStream_1_0.readRMIIIOPValueType(CDRInputStream_1_0.java:1066)
at
com.sun.corba.ee.impl.encoding.CDRInputStream_1_0.read_value(CDRInputStream_1_0.java:1175)
at
com.sun.corba.ee.impl.encoding.CDRInputStream_1_0.read_value(CDRInputStream_1_0.java:986)
at
com.sun.corba.ee.impl.encoding.CDRInputStream_1_0.read_abstract_interface(CDRInputStream_1_0.java:978)
at
com.sun.corba.ee.impl.encoding.CDRInputStream_1_0.read_abstract_interface(CDRInputStream_1_0.java:968)
at
com.sun.corba.ee.impl.encoding.CDRInputObject.read_abstract_interface(CDRInputObject.java:691)
at
com.sun.corba.ee.impl.io.IIOPInputStream.readObjectDelegate(IIOPInputStream.java:402)
at
com.sun.corba.ee.impl.io.IIOPInputStream.readObjectOverride(IIOPInputStream.java:577)
at java.io.ObjectInputStream.readObject(ObjectInputStream.java:344)
at java.util.ArrayList.readObject(ArrayList.java:593)
at sun.reflect.GeneratedMethodAccessor7824.invoke(Unknown Source)
at
sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
at java.lang.reflect.Method.invoke(Method.java:597)
at
com.sun.corba.ee.impl.io.IIOPInputStream.invokeObjectReader(IIOPInputStream.java:1965)
at
com.sun.corba.ee.impl.io.IIOPInputStream.inputObject(IIOPInputStream.java:1300)
at
com.sun.corba.ee.impl.io.IIOPInputStream.simpleReadObject(IIOPInputStream.java:449)
at
com.sun.corba.ee.impl.io.ValueHandlerImpl.readValueInternal(ValueHandlerImpl.java:364)
at
com.sun.corba.ee.impl.io.ValueHandlerImpl.readValue(ValueHandlerImpl.java:320)
at
com.sun.corba.ee.impl.encoding.CDRInputStream_1_0.readRMIIIOPValueType(CDRInputStream_1_0.java:1066)
at
com.sun.corba.ee.impl.encoding.CDRInputStream_1_0.read_value(CDRInputStream_1_0.java:1175)
at
com.sun.corba.ee.impl.encoding.CDRInputObject.read_value(CDRInputObject.java:655)
at
com.sun.corba.ee.impl.presentation.rmi.DynamicMethodMarshallerImpl$14.read(DynamicMethodMarshallerImpl.java:383)
at
com.sun.corba.ee.impl.presentation.rmi.DynamicMethodMarshallerImpl.readResult(DynamicMethodMarshallerImpl.java:484)
at
com.sun.corba.ee.impl.presentation.rmi.StubInvocationHandlerImpl.privateInvoke(StubInvocationHandlerImpl.java:190)
at
com.sun.corba.ee.impl.presentation.rmi.StubInvocationHandlerImpl.invoke(StubInvocationHandlerImpl.java:147)
at
com.sun.corba.ee.impl.presentation.rmi.codegen.CodegenStubBase.invoke(CodegenStubBase.java:225)
And the following on the back-end server:
[#|2011-01-05T01:51:22.383+0100|WARNING|glassfish3.0.1|javax.enterprise.resource.corba.ee.S1AS-ORB.rpc.encoding|_ThreadID=4575;_ThreadName=Thread-1;|"IOP00410237:
(COMM_FAILURE) Timeout while reading data in buffer manager"
[#|2011-01-05T01:51:23.699+0100|WARNING|glassfish3.0.1|javax.enterprise.resource.corba.ee.S1AS-ORB.rpc.transport|_ThreadID=4413;_ThreadName=Thread-1;|"IOP00410229:
(COMM_FAILURE) Blocking read failed, expected to read additional bytes: max
wait time = 6,000ms total time spent waiting = 7,280ms"
[#|2011-01-05T01:53:38.599+0100|WARNING|glassfish3.0.1|javax.enterprise.resource.corba.ee.S1AS-ORB.rpc.transport|_ThreadID=4545;_ThreadName=Thread-1;|"IOP00410225:
(COMM_FAILURE) Write of message exceeded TCP timeout : max wait time = 6,000
ms, total time spent blocked, waiting to write = 7,280 ms."
[#|2011-01-05T01:53:41.337+0100|WARNING|glassfish3.0.1|javax.enterprise.resource.corba.ee._INITIALIZING_.rpc.protocol|_ThreadID=4548;_ThreadName=Thread-1;|"IOP00410210:
(COMM_FAILURE) Received a GIOP MessageError, indicating header corruption or
version mismatch"
After a while, we get the following on the front-end (omitted full stack
traces for now):
[#|2011-01-05T02:28:25.520+0100|SEVERE|glassfish3.0.1|javax.enterprise.resource.corba.ee.S1AS-ORB.rpc.transport|_ThreadID=456;_ThreadName=Thread-1;|"IOP00410227:
(COMM_FAILURE) Unexpected exception when writing with a temporary selector:
bytes written = 3,640, total bytes requested to write = 4,096, time spent
waiting = 2,000 ms, max time to wait = 6,000."
org.omg.CORBA.COMM_FAILURE: vmcid: SUN minor code: 227 completed: No
[#|2011-01-05T02:28:55.800+0100|WARNING|glassfish3.0.1|javax.enterprise.resource.corba.ee.S1AS-ORB.rpc.protocol|_ThreadID=456;_ThreadName=Thread-1;|"IOP00410801:
(COMM_FAILURE) IOException during cancel request"
org.omg.CORBA.COMM_FAILURE: vmcid: SUN minor code: 801 completed: Maybe
[#|2011-01-05T02:33:47.631+0100|WARNING|glassfish3.0.1|javax.enterprise.resource.corba.ee.S1AS-ORB.rpc.transport|_ThreadID=457;_ThreadName=Thread-1;|"IOP00410229:
(COMM_FAILURE) Blocking read failed, expected to read additional bytes: max
wait time = 6,000ms total time spent waiting = 7,280ms"
org.omg.CORBA.COMM_FAILURE: vmcid: SUN minor code: 229 completed: No
[#|2011-01-05T02:37:56.540+0100|WARNING|glassfish3.0.1|javax.enterprise.resource.corba.ee.S1AS-ORB.rpc.encoding|_ThreadID=33;_ThreadName=Thread-1;|"IOP00410237:
(COMM_FAILURE) Timeout while reading data in buffer manager"
org.omg.CORBA.COMM_FAILURE: vmcid: SUN minor code: 237 completed: No
And finally:
[#|2011-01-05T03:10:33.182+0100|WARNING|glassfish3.0.1|com.sun.grizzly.config.GrizzlyServiceListener|_ThreadID=13;_ThreadName=Thread-1;|Interrupting
idle Thread: http-thread-pool-8080-(515)|#]
[#|2011-01-05T03:15:25.479+0100|WARNING|glassfish3.0.1|javax.enterprise.system.container.web.com.sun.enterprise.web|_ThreadID=458;_ThreadName=Thread-1;|StandardWrapperValve[Faces
Servlet]: PWC1406: Servlet.service() for servlet Faces Servlet threw
exception
java.lang.IllegalStateException: Application was not properly initialized at
startup, could not find Factory: javax.faces.render.RenderKitFactory
...
[#|2011-01-05T08:02:04.889+0100|SEVERE|glassfish3.0.1|javax.enterprise.system.core.security.com.sun.enterprise.iiop.security|_ThreadID=29;_ThreadName=Thread-1;|iiop.principal_error|#]
Regards,
Vetle