OID Stops Responding Intermittently For New Connections. OID Debug Log Shows Plugin Exception / Timeout While Executing Java Plug-in
(Doc ID 1339674.1)
Last updated on APRIL 26, 2023
Applies to:
Oracle Internet Directory - Version 10.1.4 to 11.1.1.9.0 [Release 10gR3 to 11g]Information in this document applies to any platform.
Symptoms
Oracle Internet Directory (OID) integrated with WebCenter and other applications.
Intermittently OID stops responding.
Existing connections may continue to work.
New connections from any application fail. The users cannot login, and get either a timeout and/or hangs, or authentication failures.
Ldapbind tests at the time the problem is happening from any client, remote host, or from the OID server's command prompt itself, all fail to an OID instance and ports that most applications use, with error:
Can't contact LDAP server
Ldapbind tests at the time the problem is happening to the other OID instance/ports continue to work fine.
The workaround is to recycle / restart OID server with opmnctl or, sometimes, if able to wait long enough OID can suddenly start working again on its own.
Initial OID debugged logs did not show much information, such as the following example:
...<snip>...
2011/05/27:08:04:43 * ServerController:0 * SynchCheck: Aquiring the shm lock
2011/05/27:08:04:43 * ServerController:0 * SynchCheck : Releasing the SHM lock
2011/05/27:08:04:43 * ServerController:0 * SynchCheck : Recvd refEvent 5, Loc version = 2, ShmVersion = 3
2011/05/27:08:04:43 * ServerController:0 * gslusshaUpdtCount: Aquiring the lock
2011/05/27:08:04:43 * ServerController:0 * gslusshaUpdtCount: releasing the lock
2011/05/27:08:04:43 * ServerController:0 * ServerController: recvd refresh events 128
2011/05/27:08:04:43 * ServerController:0 * Entry gslirrdrRefreshDSE
2011/05/27:08:04:43 * ServerController:0 * Base Search Sql: SELECT /*+ USE_NL(store) USE_NL(dn) INDEX(store EI_ATTRSTORE) INDEX(dn RP_DN) ORDERED */ store.entryid,AttrName,NVL(AttrVal,' '),attrkind,NVL(attrstype, ' '),NVL(AttrVer,' ') FROM CT_DN dn, ds_attrStore store WHERE (dn.rdn = :szCommonName AND dn.parentdn = :szBaseDomain) AND store.entryid = dn.entryid AND (attrkind = 'u' OR attrkind = 't')
2011/05/27:08:04:43 * ServerController:0 * szCommonName = * *, szBaseDomain = * ,*
2011/05/27:08:04:43 * ServerController:0 * Base Search Completed with: 100
2011/05/27:09:29:00 * ServerDispatcher :1 * sgslufread: Hard error on read, OS error = 104
2011/05/27:09:41:03 * ServerController:0 * WARNING : ServerController : Processing shutdown notification
2011/05/27:09:41:03 * ServerWorker (SPW):15 * FATAL * ServerWorker * Processing shutdown notification
2011/05/27:09:41:03 * ServerWorker (SPW):13 * FATAL * ServerWorker * Processing shutdown notification
2011/05/27:09:41:03 * ServerWorker (SPW):16 * FATAL * ServerWorker * Processing shutdown notification
2011/05/27:09:41:03 * ServerWorker (SPW):17 * FATAL * ServerWorker * Processing shutdown notification
2011/05/27:09:41:03 * ServerWorker (SPW):14 * FATAL * ServerWorker * Processing shutdown notification
...<end>...
2011/05/27:08:04:43 * ServerController:0 * SynchCheck: Aquiring the shm lock
2011/05/27:08:04:43 * ServerController:0 * SynchCheck : Releasing the SHM lock
2011/05/27:08:04:43 * ServerController:0 * SynchCheck : Recvd refEvent 5, Loc version = 2, ShmVersion = 3
2011/05/27:08:04:43 * ServerController:0 * gslusshaUpdtCount: Aquiring the lock
2011/05/27:08:04:43 * ServerController:0 * gslusshaUpdtCount: releasing the lock
2011/05/27:08:04:43 * ServerController:0 * ServerController: recvd refresh events 128
2011/05/27:08:04:43 * ServerController:0 * Entry gslirrdrRefreshDSE
2011/05/27:08:04:43 * ServerController:0 * Base Search Sql: SELECT /*+ USE_NL(store) USE_NL(dn) INDEX(store EI_ATTRSTORE) INDEX(dn RP_DN) ORDERED */ store.entryid,AttrName,NVL(AttrVal,' '),attrkind,NVL(attrstype, ' '),NVL(AttrVer,' ') FROM CT_DN dn, ds_attrStore store WHERE (dn.rdn = :szCommonName AND dn.parentdn = :szBaseDomain) AND store.entryid = dn.entryid AND (attrkind = 'u' OR attrkind = 't')
2011/05/27:08:04:43 * ServerController:0 * szCommonName = * *, szBaseDomain = * ,*
2011/05/27:08:04:43 * ServerController:0 * Base Search Completed with: 100
2011/05/27:09:29:00 * ServerDispatcher :1 * sgslufread: Hard error on read, OS error = 104
2011/05/27:09:41:03 * ServerController:0 * WARNING : ServerController : Processing shutdown notification
2011/05/27:09:41:03 * ServerWorker (SPW):15 * FATAL * ServerWorker * Processing shutdown notification
2011/05/27:09:41:03 * ServerWorker (SPW):13 * FATAL * ServerWorker * Processing shutdown notification
2011/05/27:09:41:03 * ServerWorker (SPW):16 * FATAL * ServerWorker * Processing shutdown notification
2011/05/27:09:41:03 * ServerWorker (SPW):17 * FATAL * ServerWorker * Processing shutdown notification
2011/05/27:09:41:03 * ServerWorker (SPW):14 * FATAL * ServerWorker * Processing shutdown notification
...<end>...
Eventually OID debugged logs showed the following regarding plugins, for example:
...<snip>...
2011/05/31:08:04:48 * ServerController:0 * gslduudSetDBparams * DB parameters optimizer_features_enable and _hash_join_enabled are set to 10.2.0.4 and false respectively.
2011/05/31:08:04:48 * ServerController:0 * gslduudSetDBparams * DB parameters optimizer_features_enable and _hash_join_enabled are set to 10.2.0.4 and false respectively.
2011/05/31:08:04:48 * ServerController:0 * sgsluschcHandShake : Establishing conn to disp process=12746, pno=12791
2011/05/31:08:04:48 * ServerController:0 * sgsluschcHandShake: Rcvd CONN ACK from dispatcher process
2011/05/31:08:04:48 * ServerController:0 * sgsluschcHandShake : Successfully established connection with dispatcher
2011/05/31:08:04:48 * ServerListener :2 * OS thread id 1163447200 Started
2011/05/31:08:04:48 * ServerDispatcher :1 * OS thread id 1162394528 Started
2011/05/31:08:04:48 * ServerWorker (REG):3 * OS thread id 1165548448 Started
2011/05/31:08:04:48 * ServerWorker (REG):4 * OS thread id 1167649696 Started
2011/05/31:08:04:48 * ServerWorker (REG):8 * OS thread id 1176054688 Started
2011/05/31:08:04:48 * ServerWorker (REG):10 * OS thread id 1180257184 Started
2011/05/31:08:04:48 * ServerWorker (REG):7 * OS thread id 1173953440 Started
2011/05/31:08:04:48 * ServerWorker (REG):9 * OS thread id 1178155936 Started
2011/05/31:08:04:48 * ServerWorker (SPW):16 * OS thread id 1192864672 Started
2011/05/31:08:04:48 * ServerWorker (SPW):17 * OS thread id 1194965920 Started
2011/05/31:08:04:48 * ServerWorker (REG):11 * OS thread id 1182358432 Started
2011/05/31:08:04:48 * ServerWorker (REG):12 * OS thread id 1184459680 Started
2011/05/31:08:04:48 * ServerWorker (REG):5 * OS thread id 1169750944 Started
2011/05/31:08:04:48 * ServerWorker (SPW):13 * OS thread id 1186560928 Started
2011/05/31:08:04:48 * ServerWorker (SPW):14 * OS thread id 1188662176 Started
2011/05/31:08:04:48 * ServerWorker (SPW):15 * OS thread id 1190763424 Started
2011/05/31:08:04:48 * ServerWorker (REG):6 * OS thread id 1171852192 Started
BEGIN
2011/05/31:08:05:06 * ServerWorker (REG):8
ConnID:50 * mesgID:4 * OpID:3 * OpName:modify
ConnIP:<IP Address> ConnDN: cn=<USERNAME>,cn=users,dc=<COMPANY NAME>,dc=com
ERROR * sgslpip_invokeJPlg * Exception thrown while executing Java Plug-in MyGroups_Modify
END
BEGIN
2011/05/31:08:05:06 * ServerWorker (REG):8
ConnID:50 * mesgID:4 * OpID:3 * OpName:modify
ConnIP:<IP Address> ConnDN: cn=<USERNAME>,cn=users,dc=<COMPANY NAME>,dc=com
ERROR * sgslpex_exceptionHndlr * Exception Message : returnInitialLdapContext() times out after 10000 ms - JNDI initialization method not returning
ERROR * sgslpex_exceptionHndlr * The Exception Stack Trace :
javax.naming.CommunicationException
oracle.ldap.util.jndi.ConnectionUtil.returnInitialLdapContext(ConnectionUtil.java:483)
oracle.ldap.util.jndi.ConnectionUtil.getDefaultDirCtx(ConnectionUtil.java:134)
oracle.ldap.util.jndi.ConnectionUtil.getDefaultDirCtx(ConnectionUtil.java:156)
oracle.ldap.ospf.Server.getLdapContextFromServerPlugin(Server.java:126)
SNILdapUtil.getServerContext(SNILdapUtil.java:138)
MyGroups.pre_modify(MyGroups.java:164)
MyGroups_Modify.pre_modify(MyGroups_Modify.java:16)
END
BEGIN
2011/05/31:08:05:11 * ServerWorker (REG):7
ConnID:5 * mesgID:4 * OpID:3 * OpName:modify
ConnIP:<IP Address> ConnDN: cn=<USERNAME>,cn=users,dc=<COMPANY NAME>,dc=com
ERROR * sgslpip_invokeJPlg * Exception thrown while executing Java Plug-in MyGroups_Modify
END
BEGIN
2011/05/31:08:05:11 * ServerWorker (REG):7
ConnID:5 * mesgID:4 * OpID:3 * OpName:modify
ConnIP:<IP Address> ConnDN: ccn=<USERNAME>,cn=users,dc=<COMPANY NAME>,dc=com
ERROR * sgslpex_exceptionHndlr * Exception Message : Error in resolving Oracle Context: cn=OracleContext <OIDHOST>:636; socket closed
ERROR * sgslpex_exceptionHndlr * The Exception Stack Trace :
oracle.ldap.util.UtilException
oracle.ldap.util.OracleContext.resolve(OracleContext.java:209)
oracle.ldap.util.RootOracleContext.getSubscriber(RootOracleContext.java:337)
SNILdapUtil.getSubscriber(SNILdapUtil.java:353)
SNILdapUtil.getAttributeValues_DirectLdapCall_DN(SNILdapUtil.java:172)
SNILdapUtil.isMyGroupDN(SNILdapUtil.java:383)
MyGroups.pre_modify(MyGroups.java:177)
MyGroups_Modify.pre_modify(MyGroups_Modify.java:16)
END
2011/05/31:08:13:39 * ServerController:0 * WARNING : ServerController : Processing shutdown notification
2011/05/31:08:13:39 * ServerWorker (SPW):14 * FATAL * ServerWorker * Processing shutdown notification
2011/05/31:08:13:39 * ServerWorker (SPW):16 * FATAL * ServerWorker * Processing shutdown notification
2011/05/31:08:13:39 * ServerWorker (SPW):13 * FATAL * ServerWorker * Processing shutdown notification
2011/05/31:08:13:39 * ServerWorker (SPW):17 * FATAL * ServerWorker * Processing shutdown notification
2011/05/31:08:13:39 * ServerWorker (SPW):15 * FATAL * ServerWorker * Processing shutdown notification
...<end>...
2011/05/31:08:04:48 * ServerController:0 * gslduudSetDBparams * DB parameters optimizer_features_enable and _hash_join_enabled are set to 10.2.0.4 and false respectively.
2011/05/31:08:04:48 * ServerController:0 * gslduudSetDBparams * DB parameters optimizer_features_enable and _hash_join_enabled are set to 10.2.0.4 and false respectively.
2011/05/31:08:04:48 * ServerController:0 * sgsluschcHandShake : Establishing conn to disp process=12746, pno=12791
2011/05/31:08:04:48 * ServerController:0 * sgsluschcHandShake: Rcvd CONN ACK from dispatcher process
2011/05/31:08:04:48 * ServerController:0 * sgsluschcHandShake : Successfully established connection with dispatcher
2011/05/31:08:04:48 * ServerListener :2 * OS thread id 1163447200 Started
2011/05/31:08:04:48 * ServerDispatcher :1 * OS thread id 1162394528 Started
2011/05/31:08:04:48 * ServerWorker (REG):3 * OS thread id 1165548448 Started
2011/05/31:08:04:48 * ServerWorker (REG):4 * OS thread id 1167649696 Started
2011/05/31:08:04:48 * ServerWorker (REG):8 * OS thread id 1176054688 Started
2011/05/31:08:04:48 * ServerWorker (REG):10 * OS thread id 1180257184 Started
2011/05/31:08:04:48 * ServerWorker (REG):7 * OS thread id 1173953440 Started
2011/05/31:08:04:48 * ServerWorker (REG):9 * OS thread id 1178155936 Started
2011/05/31:08:04:48 * ServerWorker (SPW):16 * OS thread id 1192864672 Started
2011/05/31:08:04:48 * ServerWorker (SPW):17 * OS thread id 1194965920 Started
2011/05/31:08:04:48 * ServerWorker (REG):11 * OS thread id 1182358432 Started
2011/05/31:08:04:48 * ServerWorker (REG):12 * OS thread id 1184459680 Started
2011/05/31:08:04:48 * ServerWorker (REG):5 * OS thread id 1169750944 Started
2011/05/31:08:04:48 * ServerWorker (SPW):13 * OS thread id 1186560928 Started
2011/05/31:08:04:48 * ServerWorker (SPW):14 * OS thread id 1188662176 Started
2011/05/31:08:04:48 * ServerWorker (SPW):15 * OS thread id 1190763424 Started
2011/05/31:08:04:48 * ServerWorker (REG):6 * OS thread id 1171852192 Started
BEGIN
2011/05/31:08:05:06 * ServerWorker (REG):8
ConnID:50 * mesgID:4 * OpID:3 * OpName:modify
ConnIP:<IP Address> ConnDN: cn=<USERNAME>,cn=users,dc=<COMPANY NAME>,dc=com
ERROR * sgslpip_invokeJPlg * Exception thrown while executing Java Plug-in MyGroups_Modify
END
BEGIN
2011/05/31:08:05:06 * ServerWorker (REG):8
ConnID:50 * mesgID:4 * OpID:3 * OpName:modify
ConnIP:<IP Address> ConnDN: cn=<USERNAME>,cn=users,dc=<COMPANY NAME>,dc=com
ERROR * sgslpex_exceptionHndlr * Exception Message : returnInitialLdapContext() times out after 10000 ms - JNDI initialization method not returning
ERROR * sgslpex_exceptionHndlr * The Exception Stack Trace :
javax.naming.CommunicationException
oracle.ldap.util.jndi.ConnectionUtil.returnInitialLdapContext(ConnectionUtil.java:483)
oracle.ldap.util.jndi.ConnectionUtil.getDefaultDirCtx(ConnectionUtil.java:134)
oracle.ldap.util.jndi.ConnectionUtil.getDefaultDirCtx(ConnectionUtil.java:156)
oracle.ldap.ospf.Server.getLdapContextFromServerPlugin(Server.java:126)
SNILdapUtil.getServerContext(SNILdapUtil.java:138)
MyGroups.pre_modify(MyGroups.java:164)
MyGroups_Modify.pre_modify(MyGroups_Modify.java:16)
END
BEGIN
2011/05/31:08:05:11 * ServerWorker (REG):7
ConnID:5 * mesgID:4 * OpID:3 * OpName:modify
ConnIP:<IP Address> ConnDN: cn=<USERNAME>,cn=users,dc=<COMPANY NAME>,dc=com
ERROR * sgslpip_invokeJPlg * Exception thrown while executing Java Plug-in MyGroups_Modify
END
BEGIN
2011/05/31:08:05:11 * ServerWorker (REG):7
ConnID:5 * mesgID:4 * OpID:3 * OpName:modify
ConnIP:<IP Address> ConnDN: ccn=<USERNAME>,cn=users,dc=<COMPANY NAME>,dc=com
ERROR * sgslpex_exceptionHndlr * Exception Message : Error in resolving Oracle Context: cn=OracleContext <OIDHOST>:636; socket closed
ERROR * sgslpex_exceptionHndlr * The Exception Stack Trace :
oracle.ldap.util.UtilException
oracle.ldap.util.OracleContext.resolve(OracleContext.java:209)
oracle.ldap.util.RootOracleContext.getSubscriber(RootOracleContext.java:337)
SNILdapUtil.getSubscriber(SNILdapUtil.java:353)
SNILdapUtil.getAttributeValues_DirectLdapCall_DN(SNILdapUtil.java:172)
SNILdapUtil.isMyGroupDN(SNILdapUtil.java:383)
MyGroups.pre_modify(MyGroups.java:177)
MyGroups_Modify.pre_modify(MyGroups_Modify.java:16)
END
2011/05/31:08:13:39 * ServerController:0 * WARNING : ServerController : Processing shutdown notification
2011/05/31:08:13:39 * ServerWorker (SPW):14 * FATAL * ServerWorker * Processing shutdown notification
2011/05/31:08:13:39 * ServerWorker (SPW):16 * FATAL * ServerWorker * Processing shutdown notification
2011/05/31:08:13:39 * ServerWorker (SPW):13 * FATAL * ServerWorker * Processing shutdown notification
2011/05/31:08:13:39 * ServerWorker (SPW):17 * FATAL * ServerWorker * Processing shutdown notification
2011/05/31:08:13:39 * ServerWorker (SPW):15 * FATAL * ServerWorker * Processing shutdown notification
...<end>...
Using custom plugins to integrate applications with OID, but the plugins and OID server had been working fine for well over a year, and no changes have been made.
In OID 11g, OID server debugged log may show:
BEGIN
ConnID:18261 mesgID:30 OpID:29 OpName:bind ConnIP:<IP Address> ConnDN:Anonymous
ERROR * sgslpex_exceptionHndlr * Exception Message : returnInitialLdapContext() times out after 10000 ms - JNDI initialization method not returning
ERROR * sgslpex_exceptionHndlr * The Exception Stack Trace :
javax.naming.CommunicationException
oracle.ldap.util.jndi.ConnectionUtil.returnInitialLdapContext(ConnectionUtil.java:497)
oracle.ldap.util.jndi.ConnectionUtil.getDefaultDirCtx(ConnectionUtil.java:135)
oracle.ldap.util.jndi.ConnectionUtil.getDefaultDirCtx(ConnectionUtil.java:157)
oracle.ldap.ospf.Server.getNonSSLLdapContextFromServerPlugin(Server.java:139)
qcLastBindDate.post_bind(qcLastBindDate.java:81)
END
ConnID:18261 mesgID:30 OpID:29 OpName:bind ConnIP:<IP Address> ConnDN:Anonymous
ERROR * sgslpex_exceptionHndlr * Exception Message : returnInitialLdapContext() times out after 10000 ms - JNDI initialization method not returning
ERROR * sgslpex_exceptionHndlr * The Exception Stack Trace :
javax.naming.CommunicationException
oracle.ldap.util.jndi.ConnectionUtil.returnInitialLdapContext(ConnectionUtil.java:497)
oracle.ldap.util.jndi.ConnectionUtil.getDefaultDirCtx(ConnectionUtil.java:135)
oracle.ldap.util.jndi.ConnectionUtil.getDefaultDirCtx(ConnectionUtil.java:157)
oracle.ldap.ospf.Server.getNonSSLLdapContextFromServerPlugin(Server.java:139)
qcLastBindDate.post_bind(qcLastBindDate.java:81)
END
Changes
Cause
To view full details, sign in with your My Oracle Support account. |
|
Don't have a My Oracle Support account? Click to get started! |
In this Document
| Symptoms |
| Changes |
| Cause |
| Solution |
| References |