APP Server is Unresponsive and Following Exception is Seen in Weblogic Logs: "weblogic.rmi.extensions.RequestTimeoutException"

(Doc ID 1933491.1)

Last updated on NOVEMBER 13, 2017

Applies to:

Oracle Transportation Management - Version 6.3.1 to 6.4.2 [Release 6.3 to 6.4]
Information in this document applies to any platform.

Symptoms

App server went unresponsive thread dumps were showing one thread blocking the others from processing.

INFO | 2017/04/25 11:53:18 | "agentPlanning - 16" id=176 idx=0x2cc tid=1600 prio=5 alive, in native, daemon
INFO | 2017/04/25 11:53:18 | at jrockit/net/SocketNativeIO.readBytesPinned(Ljava/io/FileDescriptor;[BIII)I(Native Method)
INFO | 2017/04/25 11:53:18 | at jrockit/net/SocketNativeIO.socketRead(SocketNativeIO.java:32)inlined
INFO | 2017/04/25 11:53:18 | at java/net/SocketInputStream.socketRead0(Ljava/io/FileDescriptor;[BIII)I(SocketInputStream.java)inlined
INFO | 2017/04/25 11:53:18 | at java/net/SocketInputStream.read(SocketInputStream.java:129)optimized
INFO | 2017/04/25 11:53:18 | at oracle/net/ns/Packet.receive(Packet.java:300)optimized
INFO | 2017/04/25 11:53:18 | at oracle/net/ns/DataPacket.receive(DataPacket.java:106)optimized
INFO | 2017/04/25 11:53:18 | at oracle/net/ns/NetInputStream.getNextPacket(NetInputStream.java:315)optimized
INFO | 2017/04/25 11:53:18 | at oracle/net/ns/NetInputStream.read(NetInputStream.java:260)optimized
INFO | 2017/04/25 11:53:18 | at oracle/net/ns/NetInputStream.read(NetInputStream.java:185)inlined
INFO | 2017/04/25 11:53:18 | at oracle/net/ns/NetInputStream.read(NetInputStream.java:102)optimized
INFO | 2017/04/25 11:53:18 | at oracle/jdbc/driver/T4CSocketInputStreamWrapper.readNextPacket(T4CSocketInputStreamWrapper.java:124)inlined
INFO | 2017/04/25 11:53:18 | at oracle/jdbc/driver/T4CSocketInputStreamWrapper.read(T4CSocketInputStreamWrapper.java:80)optimized
INFO | 2017/04/25 11:53:18 | at oracle/jdbc/driver/T4CMAREngine.unmarshalUB1(T4CMAREngine.java:1137)inlined
INFO | 2017/04/25 11:53:18 | at oracle/jdbc/driver/T4CTTIfun.receive(T4CTTIfun.java:290)optimized
INFO | 2017/04/25 11:53:18 | at oracle/jdbc/driver/T4CTTIfun.doRPC(T4CTTIfun.java:192)optimized
INFO | 2017/04/25 11:53:18 | at oracle/jdbc/driver/T4C8Oall.doOALL(T4C8Oall.java:531)inlined
INFO | 2017/04/25 11:53:18 | at oracle/jdbc/driver/T4CPreparedStatement.doOall8(T4CPreparedStatement.java:207)optimized
INFO | 2017/04/25 11:53:18 | at oracle/jdbc/driver/T4CPreparedStatement.executeForRows(T4CPreparedStatement.java:1044)optimized
INFO | 2017/04/25 11:53:18 | at oracle/jdbc/driver/OracleStatement.doExecuteWithTimeout(OracleStatement.java:1329)optimized
INFO | 2017/04/25 11:53:18 | at oracle/jdbc/driver/OraclePreparedStatement.executeInternal(OraclePreparedStatement.java:3584)inlined
INFO | 2017/04/25 11:53:18 | at oracle/jdbc/driver/OraclePreparedStatement.executeUpdate(OraclePreparedStatement.java:3665)optimized
INFO | 2017/04/25 11:53:18 | ^-- Holding lock: oracle/jdbc/driver/T4CConnection@0x10f62ca18thin lock
INFO | 2017/04/25 11:53:18 | at oracle/jdbc/driver/OraclePreparedStatementWrapper.executeUpdate(OraclePreparedStatementWrapper.java:1352)optimized
INFO | 2017/04/25 11:53:18 | at weblogic/jdbc/wrapper/PreparedStatement.executeUpdate(PreparedStatement.java:172)optimized
INFO | 2017/04/25 11:53:18 | at glog/util/jdbc/SqlUpdate.resetArguments(SqlUpdate.java:250)inlined
INFO | 2017/04/25 11:53:18 | at glog/util/jdbc/SqlUpdate.resetArguments(SqlUpdate.java:166)inlined
INFO | 2017/04/25 11:53:18 | at glog/util/jdbc/SqlUpdate.execute(SqlUpdate.java:91)inlined
INFO | 2017/04/25 11:53:18 | at glog/util/remote/BeanManagedEntityBean.executeUpdate(BeanManagedEntityBean.java:809)inlined
INFO | 2017/04/25 11:53:18 | at glog/util/remote/BeanManagedEntityBean$3.execute(BeanManagedEntityBean.java:279)optimized
INFO | 2017/04/25 11:53:18 | at glog/util/remote/BeanManagedEntityBean.dbModify(BeanManagedEntityBean.java:1082)optimized
INFO | 2017/04/25 11:53:18 | at glog/util/remote/BeanManagedEntityBean.doStore(BeanManagedEntityBean.java:276)inlined
INFO | 2017/04/25 11:53:18 | at glog/util/remote/BaseEntityBean$3.doIt(BaseEntityBean.java:521)inlined
INFO | 2017/04/25 11:53:18 | at glog/util/remote/BaseEntityBean.ejb(BaseEntityBean.java:802)inlined
INFO | 2017/04/25 11:53:18 | at glog/util/remote/BaseEntityBean.ejbStore(BaseEntityBean.java:519)inlined
INFO | 2017/04/25 11:53:18 | at glog/util/remote/BeanManagedEntityBean.ejbStore(BeanManagedEntityBean.java:524)optimized
INFO | 2017/04/25 11:53:18 | at glog/ejb/shipment/ShipmentStopStub.store(ShipmentStopStub.java:3277)
INFO | 2017/04/25 11:53:18 | at glog/ejb/shipment/ShipmentStopStub.setAppointmentPickup(ShipmentStopStub.java:963)
INFO | 2017/04/25 11:53:18 | at glog/ejb/location/AppointmentSync.updateShipmentAppointmentTime(AppointmentSync.java:109)
INFO | 2017/04/25 11:53:18 | at glog/ejb/location/AppointmentSync.execute(AppointmentSync.java:64)
INFO | 2017/04/25 11:53:18 | at glog/server/workflow/SimpleWorkflow.execute(SimpleWorkflow.java:23)optimized
INFO | 2017/04/25 11:53:18 | at glog/server/workflow/WorkflowSessionBean.execute(WorkflowSessionBean.java:64)optimized
INFO | 2017/04/25 11:53:18 | at glog/server/workflow/WorkflowSessionServerSideEJBWrapper.execute(WorkflowSessionServerSideEJBWrapper.java:38)optimized
INFO | 2017/04/25 11:53:18 | at glog/server/workflow/WorkflowSessionServerSideEJBWrapper_61kh96_EOImpl.__WL_invoke(Ljava/lang/Object;[Ljava/lang/Object;I)Ljava/lang/Object;(Unknown Source)inlined
INFO | 2017/04/25 11:53:18 | at weblogic/ejb/container/internal/SessionRemoteMethodInvoker.invoke(SessionRemoteMethodInvoker.java:40)inlined
INFO | 2017/04/25 11:53:18 | at glog/server/workflow/WorkflowSessionServerSideEJBWrapper_61kh96_EOImpl.execute(Lglog/server/workflow/WorkflowFactory;Lglog/server/workflow/Trigger;Lglog/server/workflow/Topic;)V(Unknown Source)optimized
INFO | 2017/04/25 11:53:18 | at glog/server/workflow/WorkflowManager.execute(WorkflowManager.java:352)optimized
INFO | 2017/04/25 11:53:18 | at glog/server/workflow/Trigger.trigger(Trigger.java:122)optimized
INFO | 2017/04/25 11:53:18 | at glog/util/event/EventHandler.triggerEvent(EventHandler.java:247)inlined
INFO | 2017/04/25 11:53:18 | at glog/server/workflow/TopicManager.execute(TopicManager.java:218)inlined
INFO | 2017/04/25 11:53:18 | at glog/server/workflow/ServerPublisher.execute(ServerPublisher.java:179)inlined
INFO | 2017/04/25 11:53:18 | at glog/server/workflow/ServerPublisher.execute(ServerPublisher.java:182)optimized
INFO | 2017/04/25 11:53:18 | at glog/server/workflow/Topic.execute(Topic.java:178)
INFO | 2017/04/25 11:53:18 | at glog/server/workflow/RecalcDataObjectSync.execute(RecalcDataObjectSync.java:32)
INFO | 2017/04/25 11:53:18 | at glog/server/workflow/RecalcDataObjectSync.afterCompletion(RecalcDataObjectSync.java:39)
INFO | 2017/04/25 11:53:18 | at glog/util/transaction/GLTransactionHelper.registerSynchronization(GLTransactionHelper.java:152)inlined
INFO | 2017/04/25 11:53:18 | at glog/util/transaction/GLTransactionHelper.registerSynchronization(GLTransactionHelper.java:43)optimized
INFO | 2017/04/25 11:53:18 | ^-- Holding lock: java/lang/Class@0x117de3108thin lock
INFO | 2017/04/25 11:53:18 | at glog/server/workflow/RecalcDataObjectSync.registerSynchronization(RecalcDataObjectSync.java:115)
INFO | 2017/04/25 11:53:18 | at glog/server/workflow/RecalcDataObjectSync.register(RecalcDataObjectSync.java:107)optimized
INFO | 2017/04/25 11:53:18 | at glog/ejb/location/AppointmentSync.register(AppointmentSync.java:45)
INFO | 2017/04/25 11:53:18 | at glog/server/appointment/AppointmentPersister.deleteAppointmentByShipmentStop(AppointmentPersister.java:439)
INFO | 2017/04/25 11:53:18 | at glog/server/appointment/scheduler/AppointmentActionSessionBean.removeAppointments(AppointmentActionSessionBean.java:332)
INFO | 2017/04/25 11:53:18 | at glog/server/appointment/scheduler/AppointmentActionSessionServerSideEJBWrapper.removeAppointments(AppointmentActionSessionServerSideEJBWrapper.java:288)
INFO | 2017/04/25 11:53:18 | at glog/server/appointment/scheduler/AppointmentActionSessionServerSideEJBWrapper_lmgt1r_EOImpl.__WL_invoke(Ljava/lang/Object;[Ljava/lang/Object;I)Ljava/lang/Object;(Unknown Source)
INFO | 2017/04/25 11:53:18 | at weblogic/ejb/container/internal/SessionRemoteMethodInvoker.invoke(SessionRemoteMethodInvoker.java:40)optimized
INFO | 2017/04/25 11:53:18 | at glog/server/appointment/scheduler/AppointmentActionSessionServerSideEJBWrapper_lmgt1r_EOImpl.removeAppointments(Ljava/lang/String;Ljava/lang/String;ILjava/lang/String;)V(Unknown Source)
INFO | 2017/04/25 11:53:18 | at glog/server/appointment/scheduler/AppointmentServiceAdaptor.removeAppointment(AppointmentServiceAdaptor.java:128)
INFO | 2017/04/25 11:53:18 | at glog/server/appointment/ShipmentAppointmentSessionBean.removeAppointment(ShipmentAppointmentSessionBean.java:20)
INFO | 2017/04/25 11:53:18 | at glog/server/appointment/ShipmentAppointmentSessionServerSideEJBWrapper.removeAppointment(ShipmentAppointmentSessionServerSideEJBWrapper.java:85)
INFO | 2017/04/25 11:53:18 | at glog/server/appointment/ShipmentAppointmentSessionServerSideEJBWrapper_mpj1u9_EOImpl.__WL_invoke(Ljava/lang/Object;[Ljava/lang/Object;I)Ljava/lang/Object;(Unknown Source)
INFO | 2017/04/25 11:53:18 | at weblogic/ejb/container/internal/SessionRemoteMethodInvoker.invoke(SessionRemoteMethodInvoker.java:40)optimized
INFO | 2017/04/25 11:53:18 | at glog/server/appointment/ShipmentAppointmentSessionServerSideEJBWrapper_mpj1u9_EOImpl.removeAppointment(Ljava/lang/String;Ljava/lang/String;I)V(Unknown Source)
INFO | 2017/04/25 11:53:18 | at glog/server/agent/business/shipment/RemoveAppointment.execute(RemoveAppointment.java:64)
INFO | 2017/04/25 11:53:18 | at glog/server/agent/ActionWorkflow.execute(ActionWorkflow.java:49)optimized
INFO | 2017/04/25 11:53:18 | at glog/server/workflow/WorkflowSessionBean.execute(WorkflowSessionBean.java:64)optimized
INFO | 2017/04/25 11:53:18 | at glog/server/workflow/WorkflowSessionServerSideEJBWrapper.execute(WorkflowSessionServerSideEJBWrapper.java:38)optimized
INFO | 2017/04/25 11:53:18 | at glog/server/workflow/WorkflowSessionServerSideEJBWrapper_61kh96_EOImpl.__WL_invoke(Ljava/lang/Object;[Ljava/lang/Object;I)Ljava/lang/Object;(Unknown Source)inlined
INFO | 2017/04/25 11:53:18 | at weblogic/ejb/container/internal/SessionRemoteMethodInvoker.invoke(SessionRemoteMethodInvoker.java:40)inlined
INFO | 2017/04/25 11:53:18 | at glog/server/workflow/WorkflowSessionServerSideEJBWrapper_61kh96_EOImpl.execute(Lglog/server/workflow/WorkflowFactory;Lglog/server/workflow/Trigger;Lglog/server/workflow/Topic;)V(Unknown Source)optimized
INFO | 2017/04/25 11:53:18 | at glog/server/workflow/WorkflowManager.execute(WorkflowManager.java:352)optimized
INFO | 2017/04/25 11:53:18 | at glog/server/workflow/Trigger.trigger(Trigger.java:122)optimized
INFO | 2017/04/25 11:53:18 | at glog/util/event/MemoryEventQueueRunnable.processEvent(MemoryEventQueueRunnable.java:145)optimized
INFO | 2017/04/25 11:53:18 | at glog/util/event/MemoryEventQueueRunnable.run(MemoryEventQueueRunnable.java:100)
INFO | 2017/04/25 11:53:18 | at glog/util/event/EventThread.run(EventThread.java:86)
INFO | 2017/04/25 11:53:18 | at java/lang/Thread.run(Thread.java:662)
INFO | 2017/04/25 11:53:18 | at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
INFO | 2017/04/25 11:53:18 | -- end of trace

Ex. Blocked Thread
INFO | 2017/04/25 11:53:18 | "STUCK ExecuteThread: '31' for queue: 'weblogic.kernel.Default (self-tuning)'" id=318 idx=0x344 tid=30087 prio=1 alive, blocked, native_blocked, daemon
INFO | 2017/04/25 11:53:18 | -- Blocked trying to get lock: java/lang/Class@0x117de3108thin lock
INFO | 2017/04/25 11:53:18 | at jrockit/vm/Threads.sleep(I)V(Native Method)
INFO | 2017/04/25 11:53:18 | at jrockit/vm/Locks.waitForThinRelease(Locks.java:955)optimized
INFO | 2017/04/25 11:53:18 | at jrockit/vm/Locks.monitorEnterSecondStageHard(Locks.java:1083)optimized
INFO | 2017/04/25 11:53:18 | at jrockit/vm/Locks.monitorEnterSecondStage(Locks.java:1005)optimized
INFO | 2017/04/25 11:53:18 | at jrockit/vm/Locks.monitorEnter(Locks.java:2179)optimized
INFO | 2017/04/25 11:53:18 | at glog/util/transaction/GLTransactionHelper.registerSynchronization(GLTransactionHelper.java:39)
INFO | 2017/04/25 11:53:18 | at glog/database/security/dbrealm/CachingRealm.broadcast(CachingRealm.java:2091)
INFO | 2017/04/25 11:53:18 | at glog/database/security/dbrealm/CachingRealm.assignUserRole(CachingRealm.java:262)
INFO | 2017/04/25 11:53:18 | at glog/database/security/SecurityUtil.resetCurrentUserRoleGid(SecurityUtil.java:430)
INFO | 2017/04/25 11:53:18 | at glog/database/security/SecurityUtil.resetCurrentUserRoleGid(SecurityUtil.java:421)
INFO | 2017/04/25 11:53:18 | at glog/database/security/SecuritySessionBean.resetCurrentUserRoleGid(SecuritySessionBean.java:1031)
INFO | 2017/04/25 11:53:18 | at glog/database/security/SecuritySessionServerSideEJBWrapper.resetCurrentUserRoleGid(SecuritySessionServerSideEJBWrapper.java:4966)
INFO | 2017/04/25 11:53:18 | at glog/database/security/SecuritySessionHome_snlvan_EOImpl.__WL_invoke_1(Ljava/lang/Object;[Ljava/lang/Object;I)Ljava/lang/Object;(Unknown Source)
INFO | 2017/04/25 11:53:18 | at glog/database/security/SecuritySessionHome_snlvan_EOImpl.__WL_invoke(Ljava/lang/Object;[Ljava/lang/Object;I)Ljava/lang/Object;(Unknown Source)optimized
INFO | 2017/04/25 11:53:18 | at weblogic/ejb/container/internal/SessionRemoteMethodInvoker.invoke(SessionRemoteMethodInvoker.java:40)optimized
INFO | 2017/04/25 11:53:18 | at glog/database/security/SecuritySessionHome_snlvan_EOImpl.resetCurrentUserRoleGid()Lglog/database/security/SecurityAuthenticatedUserRole;(Unknown Source)
INFO | 2017/04/25 11:53:18 | at glog/database/security/SecuritySessionHome_snlvan_EOImpl_WLSkel.internalInvoke1(ILweblogic/rmi/spi/InboundRequest;Lweblogic/rmi/spi/OutboundResponse;Ljava/lang/Object;)Lweblogic/rmi/spi/OutboundResponse;(Unknown Source)
INFO | 2017/04/25 11:53:18 | at glog/database/security/SecuritySessionHome_snlvan_EOImpl_WLSkel.invoke(ILweblogic/rmi/spi/InboundRequest;Lweblogic/rmi/spi/OutboundResponse;Ljava/lang/Object;)Lweblogic/rmi/spi/OutboundResponse;(Unknown Source)
INFO | 2017/04/25 11:53:18 | at weblogic/rmi/internal/BasicServerRef.invoke(BasicServerRef.java:667)optimized
INFO | 2017/04/25 11:53:18 | at weblogic/rmi/cluster/ClusterableServerRef.invoke(ClusterableServerRef.java:230)optimized
INFO | 2017/04/25 11:53:18 | at weblogic/rmi/internal/BasicServerRef$1.run(BasicServerRef.java:522)inlined
INFO | 2017/04/25 11:53:18 | at weblogic/security/acl/internal/AuthenticatedSubject.doAs(AuthenticatedSubject.java:363)inlined
INFO | 2017/04/25 11:53:18 | at weblogic/security/service/SecurityManager.runAs(SecurityManager.java:146)inlined
INFO | 2017/04/25 11:53:18 | at weblogic/rmi/internal/BasicServerRef.handleRequest(BasicServerRef.java:518)inlined
INFO | 2017/04/25 11:53:18 | at weblogic/rmi/internal/wls/WLSExecuteRequest.run(WLSExecuteRequest.java:118)optimized
INFO | 2017/04/25 11:53:18 | at weblogic/work/ExecuteThread.execute(ExecuteThread.java:256)inlined
INFO | 2017/04/25 11:53:18 | at weblogic/work/ExecuteThread.run(ExecuteThread.java:221)optimized
INFO | 2017/04/25 11:53:18 | at jrockit/vm/RNI.c2java(JJJJJ)V(Native Method)
INFO | 2017/04/25 11:53:18 | -- end of trace

Cause

Sign In with your My Oracle Support account

Don't have a My Oracle Support account? Click to get started

My Oracle Support provides customers with access to over a
Million Knowledge Articles and hundreds of Community platforms