We haven't seen this any more after increasing the timeout by adding the
following parameter:
-Dcom.sun.corba.ee.transport.ORBTCPTimeouts=500:30000:20
On Wed, Jan 5, 2011 at 12:58, Vetle Roeim <vetler_at_gmail.com> wrote:
> 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
>
--
Vetle Roeim