LDAP connections not closing consistently during JSS authentication

sbrosnihan
New Contributor III

We are preparing to upgrade our JSS to 9.21 from 8.71 and have encountered problems with LDAP authentication. Pre-existing JSS LDAP users fail to authenticate - the UI hangs at login. We have tried deleting and re-adding users. Re-added users can authenticate once, but then fail after a logout. These users can login after waiting several minutes, but fail again after a logout. LDAP connections appear to be held beyond the LDAP timeout settings on the JSS. LDAP tests conducted in the JSS GUI succeed consistently in .03 seconds. We use stunnel to manage encryption on both the 8.71(production) JSS and the test 9.21 JSS.

This is what a failed login looks like in the JSS log:

2013-11-19 13:02:10,622 [DEBUG] [443-exec-49] [AccountHelper ] - Authenticating sbrosn via specific LDAP server...
2013-11-19 13:02:10,622 [DEBUG] [443-exec-49] [LDAPLookupHelper ] - Open LDAP Connection to Artic LDAP (ldap.artic.edu via stunnel 127.0.0.1)
2013-11-19 13:02:10,622 [DEBUG] [443-exec-49] [LDAPServer ] - ldap connection pooling enabled
2013-11-19 13:02:10,654 [DEBUG] [443-exec-49] [LDAPLookupHelper ] - LDAP parse User
2013-11-19 13:02:10,654 [DEBUG] [443-exec-49] [LDAPLookupHelper ] - Parse LDAP extension attributes
2013-11-19 13:02:10,654 [DEBUG] [443-exec-49] [LDAPLookupHelper ] - Done parsing LDAP extension attributes
2013-11-19 13:02:10,654 [DEBUG] [443-exec-49] [LDAPLookupHelper ] - Closing LDAP Connect

and a successful login:

2013-11-19 13:15:18,666 [DEBUG] [443-exec-70] [AccountHelper ] - Authenticating sbrosn via specific LDAP server...
2013-11-19 13:15:18,666 [DEBUG] [443-exec-70] [LDAPLookupHelper ] - Open LDAP Connection to Artic LDAP (ldap.artic.edu via stunnel 127.0.0.1)
2013-11-19 13:15:18,666 [DEBUG] [443-exec-70] [LDAPServer ] - ldap connection pooling enabled
2013-11-19 13:15:18,698 [DEBUG] [443-exec-70] [LDAPLookupHelper ] - LDAP parse User
2013-11-19 13:15:18,698 [DEBUG] [443-exec-70] [LDAPLookupHelper ] - Parse LDAP extension attributes
2013-11-19 13:15:18,698 [DEBUG] [443-exec-70] [LDAPLookupHelper ] - Done parsing LDAP extension attributes
2013-11-19 13:15:18,698 [DEBUG] [443-exec-70] [LDAPLookupHelper ] - Closing LDAP Connect
2013-11-19 13:15:18,710 [DEBUG] [443-exec-70] [LDAPLookupHelper ] - Closing LDAP Connect
2013-11-19 13:15:18,710 [DEBUG] [443-exec-70] [Account ] - Adding site: -1
2013-11-19 13:15:18,713 [DEBUG] [443-exec-70] [Account ] - Adding site: -1
2013-11-19 13:15:18,782 [DEBUG] [443-exec-71] [HTMLController ] - Requested URI: index.html
2013-11-19 13:15:18,782 [DEBUG] [443-exec-71] [HTMLController ] - Executing HTMLResponse: DashboardAction
2013-11-19 13:15:18,782 [DEBUG] [443-exec-71] [HTMLResponse ] - Requested URI: /index.html
2013-11-19 13:15:18,782 [DEBUG] [443-exec-71] [DashboardAction ] - Preparing dashboard for sbrosn

logout as seen by the log:

2013-11-19 13:17:00,087 [DEBUG] [443-exec-79] [HTMLController ] - Requested URI: logout.html
2013-11-19 13:17:00,087 [DEBUG] [443-exec-79] [HTMLController ] - Executing HTMLResponse: LogoutHTMLResponse
2013-11-19 13:17:00,088 [DEBUG] [443-exec-79] [HTMLResponse ] - Requested URI: /logout.html
2013-11-19 13:17:00,133 [DEBUG] [443-exec-79] [HTMLController ] - Drawing login page.

Here's the same interaction viewed from the ldap server - both servers are synced to the same ntp server:

Failure:

slapd.log:

Nov 19 13:02:10 turvy slapd[18047]: conn=8769 op=10 SRCH base="ou=people,dc=artic,dc=edu" scope=2 filter="(&(objectClass=AICPerson)(preferredUid=sbrosn))"
Nov 19 13:02:10 turvy slapd[18047]: conn=8769 op=10 SEARCH RESULT tag=101 err=0 text=
Nov 19 13:02:10 turvy slapd[18037]: daemon: conn=9292 fd=401 connection from IP=10.72.19.185:38811 (IP=0.0.0.0:636) accepted.

- Conn=8769 bound as jss searches for sbrosn and finds the record (err=0).

- New conn=9292 fd=401 is opened, but nothing ever comes of it. There's no record of a bind or of fd=401 closing.

- JSS is keeping the connection open but not using it.

netstat as of 5:50PM:

[root@turvy root]# netstat -an | fgrep 10.72.19.185 | fgrep 38811
tcp 0 0 198.40.30.137:636 10.72.19.185:38811 ESTABLISHED

Success:

slapd.log:

Nov 19 13:15:18 turvy slapd[18041]: conn=8769 op=13 SRCH base="ou=people,dc=artic,dc=edu" scope=2 filter="(&(objectClass=AICPerson)(preferredUid=sbrosn))"
Nov 19 13:15:18 turvy slapd[18041]: conn=8769 op=13 SEARCH RESULT tag=101 err=0 text=
Nov 19 13:15:18 turvy slapd[18037]: daemon: conn=9603 fd=463 connection from IP=10.72.19.185:38827 (IP=0.0.0.0:636) accepted.
Nov 19 13:15:18 turvy slapd[18044]: conn=9603 op=0 BIND dn="UID=SBROSN,OU=PEOPLE,DC=ARTIC,DC=EDU" method=128
Nov 19 13:15:18 turvy slapd[18044]: conn=9603 op=0 RESULT tag=97 err=0 text=
Nov 19 13:15:18 turvy slapd[18045]: conn=9603 op=1 UNBIND
Nov 19 13:15:18 turvy slapd[18045]: conn=-1 fd=463 closed

- Conn=8769 bound as jss searches for sbrosn and finds the record (err=0).

- New conn=9603 fd=401 is opened, binds as sbrosn, succeeds (err=0), unbinds, and closes.

0 REPLIES 0