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: