Jo Rhett jrhett@netconsonance.com writes:

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 wrote:

On Jun 9, 2010, at 12:37 PM, Russ Allbery wrote:

...

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.

...

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 Jun 4 15:02:54 ldap-server slapd[5158]: daemon: activity on: