unbound ldap library (Sakai 12.4)

165 views
Skip to first unread message

Austin

unread,
Oct 1, 2018, 8:26:13 PM10/1/18
to sakai-dev
Hello All,

I've been trying to test the 'unboundid' library with Sakai 12.4.  I've applied patches for:

https://jira.sakaiproject.org/browse/SAK-23630 Move to supported LDAP library
https://jira.sakaiproject.org/browse/SAK-40572 Additional configuration options for unboundid LDAP provider
https://jira.sakaiproject.org/browse/SAK-40716 Unboundid ldap sdk: Upgrade from 4.0.7 to 4.0.8

however, I'm running an intermittent exception (see below).  It seems like it happens most often just after starting up the Sakai server.  But if I try to login again or after a few tries, it works.  But then if I leave the system idle for a few minutes (user cache expires?), it will fail again.  

I asked our system admin to check the ldap server's logs and he mentioned that he,

"noticed a pattern where the server doesn't get any connections for 3-5 seconds, which is a bit unusual.  I wonder if there's a difference in lifetime of connections between one and the other (jldap vs unboundid).  Maybe the firewall is causing a timeout on idle connections that weren't noticed with the other library"

we've never seen this error using the regular jldap library.  So I don't think it's our ldap server?  Has anyone seen anything similar?  Have I misconfigured something?

Thanks,

Austin


01-Oct-2018 13:55:28.630 SEVERE [http-nio-8980-exec-1] org.apache.catalina.core.ApplicationDispatcher.invoke Servlet.service() for servlet [sakai.login] threw exception
 java.lang.RuntimeException: searchDirectory(): RuntimeException while executing search [baseDN = null][filter = uid=MYUSERNAME][return attribs = null][max results = 1]
at org.sakaiproject.unboundid.UnboundidDirectoryProvider.searchDirectory(UnboundidDirectoryProvider.java:918)
at org.sakaiproject.unboundid.UnboundidDirectoryProvider.searchDirectoryForSingleEntry(UnboundidDirectoryProvider.java:810)
at org.sakaiproject.unboundid.UnboundidDirectoryProvider.getUserByEid(UnboundidDirectoryProvider.java:736)
at org.sakaiproject.unboundid.UnboundidDirectoryProvider.getUserByEid(UnboundidDirectoryProvider.java:699)
at org.sakaiproject.unboundid.UnboundidDirectoryProvider.getUser(UnboundidDirectoryProvider.java:526)
at org.sakaiproject.user.impl.BaseUserDirectoryService.getProvidedUserByEid(BaseUserDirectoryService.java:752)
at org.sakaiproject.user.impl.BaseUserDirectoryService.getUserByEid(BaseUserDirectoryService.java:882)
at org.sakaiproject.user.impl.BaseUserDirectoryService.getInternallyAuthenticatedUser(BaseUserDirectoryService.java:1680)
at org.sakaiproject.user.impl.BaseUserDirectoryService.authenticate(BaseUserDirectoryService.java:1665)
at org.sakaiproject.user.impl.UserAuthnComponent.authenticate(UserAuthnComponent.java:107)
at edu.gatech.sakai.user.impl.GaTechUserAuthnComponent.authenticate(GaTechUserAuthnComponent.java:36)
at org.sakaiproject.login.impl.LoginServiceComponent.authenticate(LoginServiceComponent.java:90)
at org.sakaiproject.login.tool.SkinnableLogin.doPost(SkinnableLogin.java:350)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:661)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.sakaiproject.util.RequestFilter.doFilter(RequestFilter.java:418)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.catalina.core.ApplicationDispatcher.invoke(ApplicationDispatcher.java:728)
at org.apache.catalina.core.ApplicationDispatcher.processRequest(ApplicationDispatcher.java:470)
at org.apache.catalina.core.ApplicationDispatcher.doForward(ApplicationDispatcher.java:356)
at org.apache.catalina.core.ApplicationDispatcher.forward(ApplicationDispatcher.java:316)
at org.sakaiproject.tool.impl.ActiveToolComponent$MyActiveTool.help(ActiveToolComponent.java:583)
at org.sakaiproject.portal.charon.SkinnableCharonPortal.doLogin(SkinnableCharonPortal.java:966)
at org.sakaiproject.portal.charon.handlers.XLoginHandler.doGet(XLoginHandler.java:61)
at org.sakaiproject.portal.charon.handlers.XLoginHandler.doPost(XLoginHandler.java:50)
at org.sakaiproject.portal.charon.SkinnableCharonPortal.doPost(SkinnableCharonPortal.java:1171)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:661)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.sakaiproject.util.RequestFilter.doFilter(RequestFilter.java:467)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:496)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:650)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:803)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:790)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1468)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:748)
Caused by: LDAPException(resultCode=81 (server down), numEntries=0, numReferences=0, diagnosticMessage='The connection to server MYTESTSERVER:MYPORT was closed while waiting for a response to search request SearchRequest(baseDN='MYBASEDN', scope=SUB, deref=NEVER, sizeLimit=1, timeLimit=9000, filter='uid=MYUSERNAME', attrs={uid, givenName, sn, mail}):  An I/O error occurred while trying to read the response from the server:  SocketException(Connection reset), ldapSDKVersion=4.0.8, revision=28812'')
at com.unboundid.ldap.sdk.SearchRequest.process(SearchRequest.java:1234)
at com.unboundid.ldap.sdk.LDAPConnection.search(LDAPConnection.java:3757)
at com.unboundid.ldap.sdk.AbstractConnectionPool.search(AbstractConnectionPool.java:2056)
at com.unboundid.ldap.sdk.AbstractConnectionPool.search(AbstractConnectionPool.java:1789)
at org.sakaiproject.unboundid.UnboundidDirectoryProvider.searchDirectory(UnboundidDirectoryProvider.java:877)
... 55 more

Austin

unread,
Oct 10, 2018, 5:06:52 PM10/10/18
to sakai-dev
Hello Sakai-Devs,

Sorry to trouble you all again, but I was hoping someone might have an idea about the error I'm seeing with the unboundid library vs jldap?

Sam Ottenhoff

unread,
Oct 10, 2018, 6:19:55 PM10/10/18
to Austin, sakai-dev
Maybe something is destroying your pooled connections. Try changing size of pool or removing use of pool?

--
You received this message because you are subscribed to the Google Groups "Sakai Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to sakai-dev+...@apereo.org.
To post to this group, send email to saka...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/sakai-dev/.

Austin

unread,
Oct 11, 2018, 9:02:24 PM10/11/18
to Sam Ottenhoff, sakai-dev
Hello Sam,

Thanks for the reply.  Our Systems Admin suspects that the connection might be getting destroyed by some server between our Sakai server and our ldap server, perhaps the firewall, because of an idle connection.

I tried setting the pool to 20, 40, and even tried 1, but I'm still seeing the same error.  As far as disabling the pool, it doesn't look like the Sakai's unboundid implementation supports disabling pooling.  It's the only option.  I think I'd have to rework a bunch of things in UnboundidDirectoryProvider.java to make that work.  But besides isn't pooling supposed to be safer?  I believe the unboundid sdk even does health checks on the pool's connections every minute or so.... although, I found an article saying that connections checked out of the pool aren't health checked (https://sourceforge.net/p/ldap-sdk/discussion/1001257/thread/d97de2ed/)

I was also thinking of switching to CAS instead of ldap... actually 'in addition' to jldap.  I believe we can run both, right?  I think we'd still need ldap for WebDav connections.  However, do you know if we run both, is there anyway to configure jldap to only be used for WebDav?  e.g. we don't want the normal login page to allow ldap logins.

Thanks,

Austin

To unsubscribe from this group and stop receiving emails from it, send an email to sakai-dev+unsubscribe@apereo.org.

Earle Nietzel

unread,
Oct 15, 2018, 1:24:46 PM10/15/18
to Austin, Sam Ottenhoff, sakai-dev
Hi Austin,

I suspect your right something on the network could be killing these connections after a specific amount of time, in such cases its best to enable keep alive.

As for your CAS question, CAS is for authentication only (supports SSO), you will still need to configure sakai to fetch user information where ever you have it stored. 

Its a typical configuration to have Sakai configured to use CAS for SSO (which is configured to use ldap), and also configure sakai's ldap provider to access the same user information.

                +---------+
     +----------|  Sakai  |
     |          +---------+
     |               |
     v               v
+---------+     +---------+     +---------+
|   CAS   |---->|  LDAP   |<----|   SIS   |
+---------+     +---------+     +---------+

Another slight variation is,
To load user information into the sakai database via an SIS load (sometimes the same process that would load the same info to LDAP), then you wouldn't need to configure sakai to use ldap, you can still use CAS for authentication so that passwords are not stale which is probably the most important piece here.

                +---------+
     +----------|  Sakai  |<---------+
     |          +---------+          |
     |                               |
     v                               |
+---------+     +---------+     +---------+
|   CAS   |---->|  LDAP   |<----|   SIS   |
+---------+     +---------+     +---------+

To unsubscribe from this group and stop receiving emails from it, send an email to sakai-dev+...@apereo.org.

To post to this group, send email to saka...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/sakai-dev/.

--
You received this message because you are subscribed to the Google Groups "Sakai Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to sakai-dev+...@apereo.org.

Austin

unread,
Oct 18, 2018, 5:02:42 PM10/18/18
to Earle Nietzel, Sam Ottenhoff, sakai-dev
Thanks Earle,

I believe unboundid sets keep alive = true by default.  Also, our system admin corrected himself and said that there isn't a firewall between me and the ldap server, so I don't think I'm losing the connection there.

Taking a look at our ldap server logs, it seems as though it successfully does a bind, but it never receives a 'search' message.  I'm thinking that after sakai sends the bind, it thinks / detects that the connection is closed (LDAPException(resultCode=81 (server down)), so it never sends the search?

[16/Oct/2018:08:57:07 -1000] conn=819089 fd=147 slot=147 SSL connection from x.x.x.x to x.x.x.x
[16/Oct/2018:08:57:07 -1000] conn=819089 TLS1.2 128-bit AES-GCM
[16/Oct/2018:08:57:07 -1000] conn=819089 op=0 BIND dn="<MyDN>" method=128 version=3
[16/Oct/2018:08:57:07 -1000] conn=819089 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="<MyDN>"
[16/Oct/2018:09:18:22 -1000] conn=819089 op=-1 fd=147 closed - B1

-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

when I connect using the old jldap library, I can see BIND, SRCH, UNBIND

[17/Oct/2018:11:30:13 -1000] conn=367663 fd=235 slot=235 SSL connection from x.x.x.x to x.x.x.x
[17/Oct/2018:11:30:13 -1000] conn=367663 TLS1.2 128-bit AES-GCM
[17/Oct/2018:11:30:13 -1000] conn=367663 op=0 BIND dn="<MyDN>" method=128 version=3
[17/Oct/2018:11:30:13 -1000] conn=367663 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="<MyDN>"
[17/Oct/2018:11:30:13 -1000] conn=367663 op=1 SRCH base="<MyBaseDN>" scope=2 filter="(uid=<MyUid>)" attrs="uid givenName sn mail"
[17/Oct/2018:11:30:13 -1000] conn=367663 op=1 RESULT err=0 tag=101 nentries=1 etime=0
[17/Oct/2018:11:30:13 -1000] conn=367663 op=2 UNBIND
[17/Oct/2018:11:30:13 -1000] conn=367663 op=2 fd=235 closed - U1

-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

But what's strange when using the unboundid library, is that if I try to login and get the server down error, but then I refresh the browser page quickly to resend the login, it appears to do the search (but doesn't UNBIND?)

[18/Oct/2018:08:51:52 -1000] conn=436090 fd=85 slot=85 SSL connection from x.x.x.x to x.x.x.x
[18/Oct/2018:08:51:52 -1000] conn=436090 TLS1.2 128-bit AES-GCM
[18/Oct/2018:08:51:52 -1000] conn=436090 op=0 BIND dn="<MyDN>" method=128 version=3
[18/Oct/2018:08:51:52 -1000] conn=436090 op=0 RESULT err=0 tag=97 nentries=0 etime=0 dn="<MyDN>"
[18/Oct/2018:08:51:55 -1000] conn=436090 op=1 SRCH base="<MyBaseDN>" scope=2 filter="(uid=<MyUid>)" attrs="uid givenName sn mail"
[18/Oct/2018:08:51:55 -1000] conn=436090 op=1 RESULT err=0 tag=101 nentries=1 etime=0

but... I get a different error in the tomcat logs:

18-Oct-2018 08:59:34.354 WARN [http-nio-8580-exec-7] org.sakaiproject.portal.util.ErrorReporter.logAndMail Bug Report bug-id: 9872ee20-2d08-4394-8578-31926de35f76 user: null usage-session: null time: Oct 18, 2018 08:59:34 user comment: null stack trace
org.sakaiproject.portal.api.PortalHandlerException: java.lang.NullPointerException
    at org.sakaiproject.portal.charon.handlers.XLoginHandler.doPost(XLoginHandler.java:50)
caused by: java.lang.NullPointerException
    at org.sakaiproject.unboundid.UnboundidDirectoryProvider.authenticateUser(UnboundidDirectoryProvider.java:388)
    at org.sakaiproject.user.impl.BaseUserDirectoryService.getProviderAuthenticatedUser(BaseUserDirectoryService.java:1727)
    at org.sakaiproject.user.impl.BaseUserDirectoryService.authenticate(BaseUserDirectoryService.java:1670)
    at org.sakaiproject.user.impl.UserAuthnComponent.authenticate(UserAuthnComponent.java:107)
    at org.sakaiproject.login.impl.LoginServiceComponent.authenticate(LoginServiceComponent.java:90)
    at org.sakaiproject.login.tool.SkinnableLogin.doPost(SkinnableLogin.java:350)
    at javax.servlet.http.HttpServlet.service(HttpServlet.java:661)
    .
    .
    .

Where the null pointer is failing on a null securityService object in the UnboundidDirectoryProvider.

Also, while attempting to debug with eclipse (the original failure, not the nullpointer), it would get into

sun.security.ssl.AppInputStream

then fail with an exception

java.net.SocketTimeoutException: Read timed out

However, I don't know if that's the real cause or if my debugging takes too long and it times out.

To unsubscribe from this group and stop receiving emails from it, send an email to sakai-dev+unsubscribe@apereo.org.

To post to this group, send email to saka...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/sakai-dev/.

--
You received this message because you are subscribed to the Google Groups "Sakai Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to sakai-dev+unsubscribe@apereo.org.

To post to this group, send email to saka...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/sakai-dev/.

--
You received this message because you are subscribed to the Google Groups "Sakai Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to sakai-dev+unsubscribe@apereo.org.

Sam Ottenhoff

unread,
Oct 18, 2018, 8:49:01 PM10/18/18
to Austin, Earle Nietzel, sakai-dev
My approach here would be to comment out the three lines where you hit the NPE. And then I would look to see if any of the Unboundid connection options make sense for your situation:


These would be added in the init() method.

To unsubscribe from this group and stop receiving emails from it, send an email to sakai-dev+...@apereo.org.

To post to this group, send email to saka...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/sakai-dev/.

--
You received this message because you are subscribed to the Google Groups "Sakai Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to sakai-dev+...@apereo.org.

To post to this group, send email to saka...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/sakai-dev/.

--
You received this message because you are subscribed to the Google Groups "Sakai Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to sakai-dev+...@apereo.org.

Austin

unread,
Oct 23, 2018, 8:42:44 PM10/23/18
to Sam Ottenhoff, Earle Nietzel, sakai-dev
These are the 3 lines that are causing the NPE

if ( !allowAuthenticationAdmin && securityService.isSuperUser(edit.getId())) {
log.debug("authenticateUser(): returning false, not authenticating for superuser (admin) {}", edit.getEid());
return false;
}

where securityService is null.  I don't see how anyone else could not be hitting this NPE... unless they've added custom code to set allowAuthenticationAdmin = true (the default is false).  Or added some custom code to inject the securityService (since it doesn't appear to be injected?)

Also, as far as the connection options, I found several unboundid forums that suggested using:

LDAPConnectionPool.setRetryFailedOperationsDueToInvalidConnections(true)


from the first article above:

"if an operation performed directly against the pool (i.e., using one of the pool's add, bind, search, etc. methods, rather than checking a connection out and doing something with it) does not complete successfully, then the default health check will determine whether that failure may indicate that the connection is no longer valid. If the health check indicates that the connection may no longer be valid, then it will throw away that connection and create another one to take its place. If automatic retry is enabled, then the pool will automatically retry that failed operation on the newly-established connection."

That option does seem to fix our "server down" issue, so we'll probably add that option to our code.  It's pretty strange though, that somewhere in our network, something is timing us out after only ~60s.  I'm not sure if that would be common in anyone else's set ups, maybe not if no one else is hitting the resultCode=81 (server down) issue?  Should I start a JIRA to make that a configurable option?

To unsubscribe from this group and stop receiving emails from it, send an email to sakai-dev+unsubscribe@apereo.org.

To post to this group, send email to saka...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/sakai-dev/.

--
You received this message because you are subscribed to the Google Groups "Sakai Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to sakai-dev+unsubscribe@apereo.org.

To post to this group, send email to saka...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/sakai-dev/.

--
You received this message because you are subscribed to the Google Groups "Sakai Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to sakai-dev+unsubscribe@apereo.org.

Sam Ottenhoff

unread,
Oct 23, 2018, 8:54:03 PM10/23/18
to Austin, Earle Nietzel, saka...@apereo.org
Yes, a JIRA would be great for the new option to RetryFailedOperationsDueToInvalidConnections.

Thanks,
Sam

To unsubscribe from this group and stop receiving emails from it, send an email to sakai-dev+...@apereo.org.

To post to this group, send email to saka...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/sakai-dev/.

--
You received this message because you are subscribed to the Google Groups "Sakai Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to sakai-dev+...@apereo.org.

To post to this group, send email to saka...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/sakai-dev/.

--
You received this message because you are subscribed to the Google Groups "Sakai Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to sakai-dev+...@apereo.org.

Austin

unread,
Oct 23, 2018, 9:40:10 PM10/23/18
to Sam Ottenhoff, Earle Nietzel, sakai-dev
https://jira.sakaiproject.org/browse/SAK-40833 Add unboundid configurable option RetryFailedOperationsDueToInvalidConnections
https://jira.sakaiproject.org/browse/SAK-40834 NPE logging in with unboundid ldap sdk

To unsubscribe from this group and stop receiving emails from it, send an email to sakai-dev+unsubscribe@apereo.org.

To post to this group, send email to saka...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/sakai-dev/.

--
You received this message because you are subscribed to the Google Groups "Sakai Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to sakai-dev+unsubscribe@apereo.org.

To post to this group, send email to saka...@apereo.org.
Visit this group at https://groups.google.com/a/apereo.org/group/sakai-dev/.

--
You received this message because you are subscribed to the Google Groups "Sakai Development" group.
To unsubscribe from this group and stop receiving emails from it, send an email to sakai-dev+unsubscribe@apereo.org.
Reply all
Reply to author
Forward
0 new messages