PUBLIC - Liferay Portal Community Edition

Read timeout time short can lead to timeout error

Details

  • Type: Bug Bug
  • Status: Verified Verified
  • Priority: Minor Minor
  • Resolution: Unresolved
  • Affects Version/s: 6.0.X EE, 6.1.X EE, 6.2.0 CE M3
  • Fix Version/s: None
  • Component/s: Infrastructure, Infrastructure > LDAP
  • Labels:
    None
  • Environment:
  • Fix Priority:
    4
  • Similar Issues:
    Show 5 results 

Description

1. Include the following property in the portal-ext.properties file (The default value is 15 seconds):

ldap.connection.com.sun.jndi.ldap.read.timeout=500

2. Restart the portal and run a load test script that simply logs a user in and out repeatedly. Alternatively, configure the portal to do a LDAP import on start-up. Basically any action that will produce a large number of LDAP requests for data retrieved from LDAP.(Example: 5500 users)
3. Check the log files for any LDAP read-timeout errors.

Search user in LDAP throw error message in console:

05:13:08,835 ERROR [liferay/scheduler_dispatch-3][PortalLDAPImporterImpl:700] Unable to import user cn=qa2675,ou=users,dc=Name: null:null:{cn=cn: qa26
75}
javax.naming.NamingException: LDAP response read timed out, timeout used:500ms.; remaining name 'dc=example,dc=com'
        at com.sun.jndi.ldap.Connection.readReply(Connection.java:448)
        at com.sun.jndi.ldap.LdapClient.getSearchReply(LdapClient.java:611)
        at com.sun.jndi.ldap.LdapClient.search(LdapClient.java:534)
        at com.sun.jndi.ldap.LdapCtx.doSearch(LdapCtx.java:1962)
        at com.sun.jndi.ldap.LdapCtx.searchAux(LdapCtx.java:1824)
        at com.sun.jndi.ldap.LdapCtx.c_search(LdapCtx.java:1749)
        at com.sun.jndi.toolkit.ctx.ComponentDirContext.p_search(ComponentDirContext.java:368)
        at com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.search(PartialCompositeDirContext.java:338)
        at com.sun.jndi.toolkit.ctx.PartialCompositeDirContext.search(PartialCompositeDirContext.java:321)
        at javax.naming.directory.InitialDirContext.search(InitialDirContext.java:248)
        at com.liferay.portal.security.ldap.PortalLDAPUtil.getUser(PortalLDAPUtil.java:488)
        at com.liferay.portal.security.ldap.PortalLDAPImporterImpl.importGroups(PortalLDAPImporterImpl.java:790)
        at com.liferay.portal.security.ldap.PortalLDAPImporterImpl.importFromLDAPByUser(PortalLDAPImporterImpl.java:695)
        at com.liferay.portal.security.ldap.PortalLDAPImporterImpl.importFromLDAP(PortalLDAPImporterImpl.java:200)
        at com.liferay.portal.security.ldap.PortalLDAPImporterImpl.importFromLDAP(PortalLDAPImporterImpl.java:137)
        at com.liferay.portal.security.ldap.PortalLDAPImporterUtil.importFromLDAP(PortalLDAPImporterUtil.java:43)
        at com.liferay.portlet.admin.messaging.LDAPImportMessageListener.doImportOnStartup(LDAPImportMessageListener.java:38)
        at com.liferay.portlet.admin.messaging.LDAPImportMessageListener.doReceive(LDAPImportMessageListener.java:48)
        at com.liferay.portal.kernel.messaging.BaseMessageListener.receive(BaseMessageListener.java:25)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
        at java.lang.reflect.Method.invoke(Method.java:597)
        at com.liferay.portal.kernel.bean.ClassLoaderBeanHandler.invoke(ClassLoaderBeanHandler.java:67)
        at $Proxy283.receive(Unknown Source)
        at com.liferay.portal.kernel.scheduler.messaging.SchedulerEventMessageListenerWrapper.receive(SchedulerEventMessageListenerWrapper.java:75)
        at com.liferay.portal.kernel.messaging.InvokerMessageListener.receive(InvokerMessageListener.java:63)
        at com.liferay.portal.kernel.messaging.ParallelDestination$1.run(ParallelDestination.java:68)
        at com.liferay.portal.kernel.concurrent.ThreadPoolExecutor$WorkerTask._runTask(ThreadPoolExecutor.java:671)
        at com.liferay.portal.kernel.concurrent.ThreadPoolExecutor$WorkerTask.run(ThreadPoolExecutor.java:582)
        at java.lang.Thread.run(Thread.java:662)

Issue Links

relates

Bug - A problem which impairs or prevents the functions of the product. LPS-28638 LDAP failure to close NamingEnumeration causing thread locks

  • Major - Major loss of function.
  • Closed - The issue is considered finished, the resolution is correct. Issues which are not closed can be reopened.

Activity

Ascending order - Click to sort in descending order
Hide
Permalink
Juan G added a comment - - edited

Happens same to our Liferay 6.1.1. We have a 60s timeout in LDAP servers, and is always failing when importing massive users.

I guess this is caused by the reuse of the same connection for every LDAP queries, so is easy to get this timeout.

I tried using LDAP connection pool, but same error arises.

Show
Juan G added a comment - - edited Happens same to our Liferay 6.1.1. We have a 60s timeout in LDAP servers, and is always failing when importing massive users. I guess this is caused by the reuse of the same connection for every LDAP queries, so is easy to get this timeout. I tried using LDAP connection pool, but same error arises.
Hide
Permalink
Juan G added a comment -

Seems problem is bigger than initially guessed.

After some days, some PermGen exceptions appear, and happened just after log in using LDAP. Perhaps there is a memory leak here...

Show
Juan G added a comment - Seems problem is bigger than initially guessed. After some days, some PermGen exceptions appear, and happened just after log in using LDAP. Perhaps there is a memory leak here...
Hide
Permalink
Juan G added a comment -

Any updates on this issue?

Show
Juan G added a comment - Any updates on this issue?
Hide
Permalink
Graeme Steyn added a comment -

Hi Juan,

I had a breif response from our systems admininstrator about our LDAP performance and got the following as possible causes for the slow performance of our LDAP system ("The ldap query is taking 11 seconds to run on test, but it takes <1s to run on production").

  • "No I haven't had a chance to find out what it is. If I had to guess I'd say the hardware it's running on. The old sun hardware runs low on memory, as the queries that liferay does on the LDAP servers flog the hell out of it and it caches everything. This then causes it to go to swap so things swap out and in as needed."

The original investigation that I did resulted in the changes as outlined in LPS-28638, LPS-28639 and LPS-28640. I was still experiencing the following in our test environment.

I have finished going through the code and introduced 2 optimizations and some fixes for the returning of the connections to the LDAP pool.  The LDAP connection pool is now working correctly.  However, there are still very long response times involved in the test environment.  Here is an extract of some of the logging that I have introduced to get a better idea of where the time is being spent (last figure on logging line is time in ms from some custom timers inserted at specific points).
 
                1543       2012-07-18 03:21:47,005 [INFO ] [tomcat-http--34] [com.liferay.portal.security.auth.OpenSSOAutoLogin:?] 02 Get OpenSSO Attributes in OpenSSOAutoLogin 31
                1544       2012-07-18 03:21:47,006 [INFO ] [tomcat-http--34] [com.liferay.portal.security.auth.OpenSSOAutoLogin:?] 03 Check for existing user in OpenSSOAutoLogin 0
                1545       2012-07-18 03:21:47,020 [INFO ] [tomcat-http--34] [com.liferay.portal.security.ldap.PortalLDAPImporterImpl:?] 14 Search for User in importLDAPUser 2
                1588       2012-07-18 03:21:58,582 [INFO ] [tomcat-http--34] [com.liferay.portal.security.ldap.PortalLDAPImporterImpl:?] 15 Get user attibutes in importLDAPUser 11561
                1593       2012-07-18 03:21:58,598 [INFO ] [tomcat-http--34] [com.liferay.portal.security.ldap.PortalLDAPImporterImpl:?] 08 Import User in PortalLDAPImporterImpl 16
                1596       2012-07-18 03:21:58,648 [INFO ] [tomcat-http--34] [com.liferay.portal.security.ldap.PortalLDAPImporterImpl:?] (&(&(ou:dn:=groups)(objectClass=groupOfUniqueNames)(uniqueMember=*))(uniqueMember=uid=s0184076,ou=people,dc=cqu,dc=edu,dc=au))
                1653       2012-07-18 03:22:15,748 [INFO ] [tomcat-http--34] [com.liferay.portal.security.ldap.PortalLDAPImporterImpl:?] 11 PortalLDAPUtil.searchLDAP 17100
                1660       2012-07-18 03:22:17,225 [INFO ] [tomcat-http--34] [com.liferay.portal.security.ldap.PortalLDAPImporterImpl:?] 12 Add and delete useer from groups 1477
                1661       2012-07-18 03:22:17,230 [INFO ] [tomcat-http--34] [com.liferay.portal.security.ldap.PortalLDAPImporterImpl:?] 09 Import Groups in PortalLDAPImporterImpl 18631
                1662       2012-07-18 03:22:17,230 [INFO ] [tomcat-http--34] [com.liferay.portal.security.ldap.PortalLDAPImporterImpl:?] 10 importLDAPUser in PortalLDAPImporterImpl 30224
                1663       2012-07-18 03:22:17,230 [INFO ] [tomcat-http--34] [com.liferay.portal.security.auth.OpenSSOAutoLogin:?] 04 LDAP user import SN in OpenSSOAutoLogin 30224
                1664       2012-07-18 03:22:17,230 [INFO ] [tomcat-http--34] [com.liferay.portal.security.auth.OpenSSOAutoLogin:?] 07 User NULL check in OpenSSOAutoLogin 0   
 
From the section above and from thread dumps that I have being taking there appear to be two hot spots.
 
1.      (&(&(ou:dn:=groups)(objectClass=groupOfUniqueNames)(uniqueMember=*))(uniqueMember=uid=xxxx,ou=people,dc=xxx,dc=xxx,dc=xx)) = 17.1 seconds to return.
2.      Another query that gets the LDAP properties for a group using the groups FullDN, e.g. cn=all-students,ou=groups,dc=xxx,dc=xxx,dc=xx.  The LDAP properties that it retrieves are: cn, description, creatorsName, createTimestamp, modifiersName, modifyTimestamp  - this query often appears to have threads waiting for a lock.
3.      Retrieving the user’s attributes is also slow at about 11.561 seconds.  This is normally a query using the Full DN for the user and a list of specified attributes values to retrieve, e.g. uid, mail, givenName, sn, title, displayName, isMemberOf, creatorsName, createTimestamp, modifiersName, modifyTimeStamp.
 
I have done as much as I can in the current code.

Hope some of this helps.

Show
Graeme Steyn added a comment - Hi Juan, I had a breif response from our systems admininstrator about our LDAP performance and got the following as possible causes for the slow performance of our LDAP system ("The ldap query is taking 11 seconds to run on test, but it takes <1s to run on production"). "No I haven't had a chance to find out what it is. If I had to guess I'd say the hardware it's running on. The old sun hardware runs low on memory, as the queries that liferay does on the LDAP servers flog the hell out of it and it caches everything. This then causes it to go to swap so things swap out and in as needed." The original investigation that I did resulted in the changes as outlined in LPS-28638 , LPS-28639 and LPS-28640 . I was still experiencing the following in our test environment. I have finished going through the code and introduced 2 optimizations and some fixes for the returning of the connections to the LDAP pool. The LDAP connection pool is now working correctly. However, there are still very long response times involved in the test environment. Here is an extract of some of the logging that I have introduced to get a better idea of where the time is being spent (last figure on logging line is time in ms from some custom timers inserted at specific points). 1543 2012-07-18 03:21:47,005 [INFO ] [tomcat-http--34] [com.liferay.portal.security.auth.OpenSSOAutoLogin:?] 02 Get OpenSSO Attributes in OpenSSOAutoLogin 31 1544 2012-07-18 03:21:47,006 [INFO ] [tomcat-http--34] [com.liferay.portal.security.auth.OpenSSOAutoLogin:?] 03 Check for existing user in OpenSSOAutoLogin 0 1545 2012-07-18 03:21:47,020 [INFO ] [tomcat-http--34] [com.liferay.portal.security.ldap.PortalLDAPImporterImpl:?] 14 Search for User in importLDAPUser 2 1588 2012-07-18 03:21:58,582 [INFO ] [tomcat-http--34] [com.liferay.portal.security.ldap.PortalLDAPImporterImpl:?] 15 Get user attibutes in importLDAPUser 11561 1593 2012-07-18 03:21:58,598 [INFO ] [tomcat-http--34] [com.liferay.portal.security.ldap.PortalLDAPImporterImpl:?] 08 Import User in PortalLDAPImporterImpl 16 1596 2012-07-18 03:21:58,648 [INFO ] [tomcat-http--34] [com.liferay.portal.security.ldap.PortalLDAPImporterImpl:?] (&(&(ou:dn:=groups)(objectClass=groupOfUniqueNames)(uniqueMember=*))(uniqueMember=uid=s0184076,ou=people,dc=cqu,dc=edu,dc=au)) 1653 2012-07-18 03:22:15,748 [INFO ] [tomcat-http--34] [com.liferay.portal.security.ldap.PortalLDAPImporterImpl:?] 11 PortalLDAPUtil.searchLDAP 17100 1660 2012-07-18 03:22:17,225 [INFO ] [tomcat-http--34] [com.liferay.portal.security.ldap.PortalLDAPImporterImpl:?] 12 Add and delete useer from groups 1477 1661 2012-07-18 03:22:17,230 [INFO ] [tomcat-http--34] [com.liferay.portal.security.ldap.PortalLDAPImporterImpl:?] 09 Import Groups in PortalLDAPImporterImpl 18631 1662 2012-07-18 03:22:17,230 [INFO ] [tomcat-http--34] [com.liferay.portal.security.ldap.PortalLDAPImporterImpl:?] 10 importLDAPUser in PortalLDAPImporterImpl 30224 1663 2012-07-18 03:22:17,230 [INFO ] [tomcat-http--34] [com.liferay.portal.security.auth.OpenSSOAutoLogin:?] 04 LDAP user import SN in OpenSSOAutoLogin 30224 1664 2012-07-18 03:22:17,230 [INFO ] [tomcat-http--34] [com.liferay.portal.security.auth.OpenSSOAutoLogin:?] 07 User NULL check in OpenSSOAutoLogin 0 From the section above and from thread dumps that I have being taking there appear to be two hot spots. 1. (&(&(ou:dn:=groups)(objectClass=groupOfUniqueNames)(uniqueMember=*))(uniqueMember=uid=xxxx,ou=people,dc=xxx,dc=xxx,dc=xx)) = 17.1 seconds to return. 2. Another query that gets the LDAP properties for a group using the groups FullDN, e.g. cn=all-students,ou=groups,dc=xxx,dc=xxx,dc=xx. The LDAP properties that it retrieves are: cn, description, creatorsName, createTimestamp, modifiersName, modifyTimestamp - this query often appears to have threads waiting for a lock. 3. Retrieving the user’s attributes is also slow at about 11.561 seconds. This is normally a query using the Full DN for the user and a list of specified attributes values to retrieve, e.g. uid, mail, givenName, sn, title, displayName, isMemberOf, creatorsName, createTimestamp, modifiersName, modifyTimeStamp. I have done as much as I can in the current code. Hope some of this helps.

People

Vote (2)
Watch (5)

Dates

  • Created:
    Updated:
    Days since last comment:
    12 weeks ago