pam_ldap doesn't bind SIMPLE for anonymous auth?

[Jo Rhett]

I'm seeing a problem where I can authenticate as a user using the ldap tools (ie ldapsearch) but I am unable to login using PAM.

Comparing debug on the server shows that ldapsearch is doing a new BIND, where's PAM is not:

Jun 4 14:58:52 ldap-server slapd[5158]: => dn: [1]
Jun 4 14:58:52 ldap-server slapd[5158]: => acl_get: [2] attr userPassword
Jun 4 14:58:52 ldap-server slapd[5158]: access_allowed: no res from state (userPassword)
Jun 4 14:58:52 ldap-server slapd[5158]: => acl_mask: access to entry "uid=jrhett,ou=Users,dc=equinix,dc=com", attr "userPassword" requested
Jun 4 14:58:52 ldap-server slapd[5158]: => acl_mask: to value by "", (=0)
Jun 4 14:58:52 ldap-server slapd[5158]: <= check a_dn_pat: anonymous
Jun 4 14:58:52 ldap-server slapd[5158]: <= acl_mask: [1] applying auth(=xd) (stop)
Jun 4 14:58:52 ldap-server slapd[5158]: <= acl_mask: [1] mask: auth(=xd)
Jun 4 14:58:52 ldap-server slapd[5158]: => access_allowed: auth access granted by auth(=xd)
Jun 4 14:58:52 ldap-server slapd[5158]: send_ldap_result: conn=75 op=2 p=3
Jun 4 14:58:52 ldap-server slapd[5158]: send_ldap_result: err=49 matched="" text=""
Jun 4 14:58:52 ldap-server slapd[5158]: send_ldap_response: msgid=3 tag=97 err=49
Jun 4 14:58:52 ldap-server slapd[5158]: conn=75 op=2 RESULT tag=97 err=49 text=

Now ldapsearch has identical debug output down until just below the access_allowed line.

Jun 4 15:02:54 ldap-server slapd[5158]: => acl_get: [2] attr userPassword
Jun 4 15:02:54 ldap-server slapd[5158]: access_allowed: no res from state (userPassword)
Jun 4 15:02:54 ldap-server slapd[5158]: => acl_mask: access to entry "uid=jrhett,ou=Users,dc=equinix,dc=com", attr "userPassword" requested
Jun 4 15:02:54 ldap-server slapd[5158]: => acl_mask: to value by "", (=0)
Jun 4 15:02:54 ldap-server slapd[5158]: <= check a_dn_pat: anonymous
Jun 4 15:02:54 ldap-server slapd[5158]: <= acl_mask: [1] applying auth(=xd) (stop)
Jun 4 15:02:54 ldap-server slapd[5158]: <= acl_mask: [1] mask: auth(=xd)
Jun 4 15:02:54 ldap-server slapd[5158]: => access_allowed: auth access granted by auth(=xd)
Jun 4 15:02:54 ldap-server slapd[5158]: conn=83 op=0 BIND dn="uid=jrhett,ou=Users,dc=equinix,dc=com" mech=SIMPLE ssf=0
Jun 4 15:02:54 ldap-server slapd[5158]: do_bind: v3 bind: "uid=jrhett,ou=Users,dc=equinix,dc=com" to "uid=jrhett,ou=Users,dc=equinix,dc=com"
Jun 4 15:02:54 ldap-server slapd[5158]: send_ldap_result: conn=83 op=0 p=3
Jun 4 15:02:54 ldap-server slapd[5158]: send_ldap_result: err=0 matched="" text=""
Jun 4 15:02:54 ldap-server slapd[5158]: send_ldap_response: msgid=1 tag=97 err=0
Jun 4 15:02:54 ldap-server slapd[5158]: conn=83 op=0 RESULT tag=97 err=0 text=
Jun 4 15:02:54 ldap-server slapd[5158]: daemon: activity on 1 descriptor
Jun 4 15:02:54 ldap-server slapd[5158]: daemon: activity on:

Can someone give me a clue what's going wrong here?

The key to this problem is that I'm trying to avoid putting system logins, rootbinddns on each server, and just do anonymous bind's for authentication. No configuration file on this client has a valid Manager or any other authentication password, and I'm trying to keep it that way. In theory, this should work ;-) I mean, ldapsearch works fine ...

[Buchan Milne]

Post by Jo Rhett
I'm seeing a problem where I can authenticate as a user using the ldap
tools (ie ldapsearch) but I am unable to login using PAM.
Comparing debug on the server shows that ldapsearch is doing a new BIND,
Jun 4 14:58:52 ldap-server slapd[5158]: => dn: [1]
Jun 4 14:58:52 ldap-server slapd[5158]: => acl_get: [2] attr userPassword
Jun 4 14:58:52 ldap-server slapd[5158]: access_allowed: no res from state
access to entry "uid=jrhett,ou=Users,dc=equinix,dc=com", attr
"userPassword" requested Jun 4 14:58:52 ldap-server slapd[5158]: =>
acl_mask: to value by "", (=0) Jun 4 14:58:52 ldap-server slapd[5158]: <=
check a_dn_pat: anonymous Jun 4 14:58:52 ldap-server slapd[5158]: <=
acl_mask: [1] applying auth(=xd) (stop) Jun 4 14:58:52 ldap-server
slapd[5158]: <= acl_mask: [1] mask: auth(=xd) Jun 4 14:58:52 ldap-server
slapd[5158]: => access_allowed: auth access granted by auth(=xd) Jun 4
14:58:52 ldap-server slapd[5158]: send_ldap_result: conn=75 op=2 p=3 Jun
4 14:58:52 ldap-server slapd[5158]: send_ldap_result: err=49 matched=""
msgid=3 tag=97 err=49 Jun 4 14:58:52 ldap-server slapd[5158]: conn=75
op=2 RESULT tag=97 err=49 text=
Now ldapsearch has identical debug output down until just below the access_allowed line.
Jun 4 15:02:54 ldap-server slapd[5158]: => acl_get: [2] attr userPassword
Jun 4 15:02:54 ldap-server slapd[5158]: access_allowed: no res from state
access to entry "uid=jrhett,ou=Users,dc=equinix,dc=com", attr
"userPassword" requested Jun 4 15:02:54 ldap-server slapd[5158]: =>
acl_mask: to value by "", (=0) Jun 4 15:02:54 ldap-server slapd[5158]: <=
check a_dn_pat: anonymous Jun 4 15:02:54 ldap-server slapd[5158]: <=
acl_mask: [1] applying auth(=xd) (stop) Jun 4 15:02:54 ldap-server
slapd[5158]: <= acl_mask: [1] mask: auth(=xd) Jun 4 15:02:54 ldap-server
slapd[5158]: => access_allowed: auth access granted by auth(=xd) Jun 4
15:02:54 ldap-server slapd[5158]: conn=83 op=0 BIND
dn="uid=jrhett,ou=Users,dc=equinix,dc=com" mech=SIMPLE ssf=0 Jun 4
"uid=jrhett,ou=Users,dc=equinix,dc=com" to
"uid=jrhett,ou=Users,dc=equinix,dc=com" Jun 4 15:02:54 ldap-server
slapd[5158]: send_ldap_result: conn=83 op=0 p=3 Jun 4 15:02:54
ldap-server slapd[5158]: send_ldap_result: err=0 matched="" text="" Jun 4
15:02:54 ldap-server slapd[5158]: send_ldap_response: msgid=1 tag=97 err=0
Jun 4 15:02:54 ldap-server slapd[5158]: conn=83 op=0 RESULT tag=97 err=0
text= Jun 4 15:02:54 ldap-server slapd[5158]: daemon: activity on 1
Can someone give me a clue what's going wrong here?

err=49 is invalid credentials, thus one or more of:
1)Wrong DN
2)Wrong password
3)ACLs don't allow simple auth

Your successful authentication with the same DN with ldapsearch rules out (1)
and (also indicated in the acl logging for the pam_ldap case) (3).

That leaves on more cause ...

Post by Jo Rhett
The key to this problem is that I'm trying to avoid putting system logins,
rootbinddns on each server, and just do anonymous bind's for
authentication.

Well, it needn't be "rootbinddns", in the sense that you should be just as
happy to lose a binddn or rootbinddn as with providing anonymous access (these
users should be least-privilege, only with access to similar data you are
already exposing to all users who would have access to the credentials - via
'getent passwd'), but you could consider using Kerberos keytab's or
certificates, or per-host credentials.

Either way, I have used anonymous for nss_ldap/pam_ldap before, without
problems.

Post by Jo Rhett
No configuration file on this client has a valid Manager
or any other authentication password, and I'm trying to keep it that way.
In theory, this should work ;-) I mean, ldapsearch works fine ...

Sure, but are you sure ldapsearch and pam_ldap are using the same password? If
you *think* so, maybe you should check with a packet capture ...

Regards,
Buchan

[Jo Rhett]

Post by Buchan Milne
Sure, but are you sure ldapsearch and pam_ldap are using the same password? If
you *think* so, maybe you should check with a packet capture ...

I did, and found that pam_ldap had altered the password prior to submittal. It turns out that for what it perceives as invalid user ids, it changes the password hash to 'INCORECT', mis-spelling and all. There was a problem with nsswitch/nscd which when resolved, the userid was valid and ldap worked fine.

This is hardly useful behavior. I fail to understand why this particular approach is taken.

Also on the other hand, comparing the logs I showed indicates that more logging would really help identify the problem. The failed BIND attempt is not logged, even at debug level 9, which is part of what confuses a person trying to understand the problem.

[Russ Allbery]

Post by Jo Rhett
I did, and found that pam_ldap had altered the password prior to
submittal. It turns out that for what it perceives as invalid user ids,
it changes the password hash to 'INCORECT', mis-spelling and all. There
was a problem with nsswitch/nscd which when resolved, the userid was
valid and ldap worked fine.
This is hardly useful behavior. I fail to understand why this
particular approach is taken.

I can tell you in general why a PAM module would do that. One of the
security concerns discovered a while back in PAM-style systems is that one
could tell from timing measurements whether or not the username one
attempted was valid but you had the wrong password or whether the username
was entirely invalid. That's because the second case would be rejected
much faster than the first. This information disclosure vulnerability
could then be used to further target brute-force password attacks and
sometimes even to deduce e-mail addresses for spam targets and other
purposes.

Many PAM modules and PAM-using applications were therefore modified to
never reject invalid users up-front. Instead, they would mangle the
password into something that would (hopefully) never authenticate and then
go through the authentication process, hopefully thereby causing the
failure to take roughly the same length of time in both cases.

[Jo Rhett]

Post by Russ Allbery
I can tell you in general why a PAM module would do that. One of the
....
much faster than the first. This information disclosure vulnerability
could then be used to further target brute-force password attacks and

I understand that. I believe that my complaint about the logging problem is valid. If you look at the log excepts below, it appears that in one scenario no BIND attempt occurred. Logging it for success but not for failure in the logs (see where it skips right to send-ldap_result without logging the BIND attempt) tends to lead someone down the wrong road when debugging the problem.

Post by Russ Allbery
Jun 4 14:58:52 ldap-server slapd[5158]: => dn: [1]
Jun 4 14:58:52 ldap-server slapd[5158]: => acl_get: [2] attr userPassword
Jun 4 14:58:52 ldap-server slapd[5158]: access_allowed: no res from state (userPassword)
Jun 4 14:58:52 ldap-server slapd[5158]: => acl_mask: access to entry "uid=jrhett,ou=Users,dc=equinix,dc=com", attr "userPassword" requested
Jun 4 14:58:52 ldap-server slapd[5158]: => acl_mask: to value by "", (=0)
Jun 4 14:58:52 ldap-server slapd[5158]: <= check a_dn_pat: anonymous
Jun 4 14:58:52 ldap-server slapd[5158]: <= acl_mask: [1] applying auth(=xd) (stop)
Jun 4 14:58:52 ldap-server slapd[5158]: <= acl_mask: [1] mask: auth(=xd)
Jun 4 14:58:52 ldap-server slapd[5158]: => access_allowed: auth access granted by auth(=xd)
Jun 4 14:58:52 ldap-server slapd[5158]: send_ldap_result: conn=75 op=2 p=3
Jun 4 14:58:52 ldap-server slapd[5158]: send_ldap_result: err=49 matched="" text=""
Jun 4 14:58:52 ldap-server slapd[5158]: send_ldap_response: msgid=3 tag=97 err=49
Jun 4 14:58:52 ldap-server slapd[5158]: conn=75 op=2 RESULT tag=97 err=49 text=
Jun 4 15:02:54 ldap-server slapd[5158]: => acl_get: [2] attr userPassword
Jun 4 15:02:54 ldap-server slapd[5158]: access_allowed: no res from state (userPassword)
Jun 4 15:02:54 ldap-server slapd[5158]: => acl_mask: access to entry "uid=jrhett,ou=Users,dc=equinix,dc=com", attr "userPassword" requested
Jun 4 15:02:54 ldap-server slapd[5158]: => acl_mask: to value by "", (=0)
Jun 4 15:02:54 ldap-server slapd[5158]: <= check a_dn_pat: anonymous
Jun 4 15:02:54 ldap-server slapd[5158]: <= acl_mask: [1] applying auth(=xd) (stop)
Jun 4 15:02:54 ldap-server slapd[5158]: <= acl_mask: [1] mask: auth(=xd)
Jun 4 15:02:54 ldap-server slapd[5158]: => access_allowed: auth access granted by auth(=xd)
Jun 4 15:02:54 ldap-server slapd[5158]: conn=83 op=0 BIND dn="uid=jrhett,ou=Users,dc=equinix,dc=com" mech=SIMPLE ssf=0
Jun 4 15:02:54 ldap-server slapd[5158]: do_bind: v3 bind: "uid=jrhett,ou=Users,dc=equinix,dc=com" to "uid=jrhett,ou=Users,dc=equinix,dc=com"
Jun 4 15:02:54 ldap-server slapd[5158]: send_ldap_result: conn=83 op=0 p=3
Jun 4 15:02:54 ldap-server slapd[5158]: send_ldap_result: err=0 matched="" text=""
Jun 4 15:02:54 ldap-server slapd[5158]: send_ldap_response: msgid=1 tag=97 err=0
Jun 4 15:02:54 ldap-server slapd[5158]: conn=83 op=0 RESULT tag=97 err=0 text=
Jun 4 15:02:54 ldap-server slapd[5158]: daemon: activity on 1 descriptor

[Howard Chu]

Post by Russ Allbery
I can tell you in general why a PAM module would do that. One of the
....
much faster than the first. This information disclosure vulnerability
could then be used to further target brute-force password attacks and

I understand that. I believe that my complaint about the logging problem
is

valid. If you look at the log excepts below, it appears that in one scenario
no BIND attempt occurred. Logging it for success but not for failure in the
logs (see where it skips right to send-ldap_result without logging the BIND
attempt) tends to lead someone down the wrong road when debugging the problem.

You're overlooking the obvious fact, which we repeat on these lists far too
many times, that syslog is lossy and cannot be relied on as a debugging aid.
There's a reason slapd has an explicit -d debug flag, distinct from the syslog
flags.

Your log excerpt here clearly shows that it's sending a reply to an operation
with id op=2, so obviously some other operations have already occurred on this
connection. (Since operation counters always start from 0.) Either they're
missing from your log or you just didn't snip the right portion of the log.
Either way, the fact that there's no Bind request in this snippet doesn't mean
that the Bind request didn't occur, or that slapd didn't attempt to send it to
syslog.

Post by Russ Allbery
Jun 4 14:58:52 ldap-server slapd[5158]: => dn: [1]
Jun 4 14:58:52 ldap-server slapd[5158]: => acl_get: [2] attr userPassword
Jun 4 14:58:52 ldap-server slapd[5158]: access_allowed: no res from state (userPassword)
Jun 4 14:58:52 ldap-server slapd[5158]: => acl_mask: access to entry "uid=jrhett,ou=Users,dc=equinix,dc=com", attr "userPassword" requested
Jun 4 14:58:52 ldap-server slapd[5158]: => acl_mask: to value by "", (=0)
Jun 4 14:58:52 ldap-server slapd[5158]:<= check a_dn_pat: anonymous
Jun 4 14:58:52 ldap-server slapd[5158]:<= acl_mask: [1] applying auth(=xd) (stop)
Jun 4 14:58:52 ldap-server slapd[5158]:<= acl_mask: [1] mask: auth(=xd)
Jun 4 14:58:52 ldap-server slapd[5158]: => access_allowed: auth access granted by auth(=xd)
Jun 4 14:58:52 ldap-server slapd[5158]: send_ldap_result: conn=75 op=2 p=3
Jun 4 14:58:52 ldap-server slapd[5158]: send_ldap_result: err=49 matched="" text=""
Jun 4 14:58:52 ldap-server slapd[5158]: send_ldap_response: msgid=3 tag=97 err=49
Jun 4 14:58:52 ldap-server slapd[5158]: conn=75 op=2 RESULT tag=97 err=49 text=
Jun 4 15:02:54 ldap-server slapd[5158]: => acl_get: [2] attr userPassword
Jun 4 15:02:54 ldap-server slapd[5158]: access_allowed: no res from state (userPassword)
Jun 4 15:02:54 ldap-server slapd[5158]: => acl_mask: access to entry "uid=jrhett,ou=Users,dc=equinix,dc=com", attr "userPassword" requested
Jun 4 15:02:54 ldap-server slapd[5158]: => acl_mask: to value by "", (=0)
Jun 4 15:02:54 ldap-server slapd[5158]:<= check a_dn_pat: anonymous
Jun 4 15:02:54 ldap-server slapd[5158]:<= acl_mask: [1] applying auth(=xd) (stop)
Jun 4 15:02:54 ldap-server slapd[5158]:<= acl_mask: [1] mask: auth(=xd)
Jun 4 15:02:54 ldap-server slapd[5158]: => access_allowed: auth access granted by auth(=xd)
Jun 4 15:02:54 ldap-server slapd[5158]: conn=83 op=0 BIND dn="uid=jrhett,ou=Users,dc=equinix,dc=com" mech=SIMPLE ssf=0
Jun 4 15:02:54 ldap-server slapd[5158]: do_bind: v3 bind: "uid=jrhett,ou=Users,dc=equinix,dc=com" to "uid=jrhett,ou=Users,dc=equinix,dc=com"
Jun 4 15:02:54 ldap-server slapd[5158]: send_ldap_result: conn=83 op=0 p=3
Jun 4 15:02:54 ldap-server slapd[5158]: send_ldap_result: err=0 matched="" text=""
Jun 4 15:02:54 ldap-server slapd[5158]: send_ldap_response: msgid=1 tag=97 err=0
Jun 4 15:02:54 ldap-server slapd[5158]: conn=83 op=0 RESULT tag=97 err=0 text=
Jun 4 15:02:54 ldap-server slapd[5158]: daemon: activity on 1 descriptor