[Date Prev][Date Next] [Chronological] [Thread] [Top]

ppolicy and ACLs of pwdAccountLockedTime?


Hi all,

I have exactly the same issue.

My repro config is within the .tgz attached to this email.
admin user is cn=admin,dc=example,dc=com and test user is uid=chantra,ou=users,dc=example,dc=com
password for both of them is "foobarcode".

To reproduce, on Debian Lenny,
* untar the archive
* cd ldaps
* ./install.sh (WARNING: ONLY DO THIS ON A TEST MACHINE, current setup/db will be ERASED).

That will stop slapd, override the config with the repro config, erase the current database, inject the testing one with slapadd, give credential to /var/lib/ldap to openldap user, start slapd

Then, run:
for i in {1..10}; do ./ldapauth.sh $i; sleep 2; done; ./ldaps.sh

which will perform 10 failed authentication, with a pause of 2 seconds.
Finally, ldaps.sh will output the details of user uid=chantra,ou=users,dc=example,dc=com

@Jiri, have you found a solution yet?

In my repro, here is the result after the 10 failed auth:

# chantra, users, example.com
dn: uid=chantra,ou=users,dc=example,dc=com
structuralObjectClass: inetOrgPerson
entryUUID: 2e93af32-2d8d-102e-8fab-21ae2aafa5d0
creatorsName:
createTimestamp: 20090904105519Z
entryCSN: 20090904105519.875933Z#000000#000#000000
modifiersName:
modifyTimestamp: 20090904105519Z
pwdFailureTime: 20090904105614Z
pwdFailureTime: 20090904105616Z
pwdFailureTime: 20090904105618Z
pwdFailureTime: 20090904105620Z
entryDN: uid=chantra,ou=users,dc=example,dc=com
subschemaSubentry: cn=Subschema
hasSubordinates: FALSE

Again, here, we see only 4 pwdFailureTime (the 5th should have locked user ). Output of syslog is in the attached file called: pwdaccountlockout.txt
but, the main part might be:
Sep  4 12:53:11 lenny32-tpl slapd[4079]: bdb_modify_internal: 0x00000004: uid=chantra,ou=users,dc=example,dc=com
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => access_allowed: delete access to "uid=chantra,ou=users,dc=example,dc=com" "pwdAccountLockedTime" requested
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => dn: [2]
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => acl_get: [3] attr pwdAccountLockedTime
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => slap_access_allowed: result not in cache (pwdAccountLockedTime)
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => acl_mask: access to entry "uid=chantra,ou=users,dc=example,dc=com", attr "pwdAccountLockedTime" requested
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => acl_mask: to all values by "", (=0)
Sep  4 12:53:11 lenny32-tpl slapd[4079]: <= check a_dn_pat: cn=admin,dc=example,dc=com
Sep  4 12:53:11 lenny32-tpl slapd[4079]: <= check a_dn_pat: *
Sep  4 12:53:11 lenny32-tpl slapd[4079]: <= acl_mask: [2] applying read(=rscxd) (stop)
Sep  4 12:53:11 lenny32-tpl slapd[4079]: <= acl_mask: [2] mask: read(=rscxd)
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => slap_access_allowed: delete access denied by read(=rscxd)
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => access_allowed: no more rules
Sep  4 12:53:11 lenny32-tpl slapd[4079]: hdb_modify: modify failed (50)
Same here,
changing:
access to *
        by dn="cn=admin,dc=example,dc=com" write
        by * read

to
access to *
        by dn="cn=admin,dc=example,dc=com" write
        by * write

will write pwdAccountLockedtime, but then, users or even anonymous will get far too much credentials :s

I also tried with the settings of openldap-2.4.17/tests/data/slapd-ppolicy.conf, e.g:
access to attrs=userpassword
  by self write
  by * auth

access to *
  by self write
  by * read

to no avail.

Michael mentioned to try 2.4.17 which as changes that might affect pwdLockout (actually, ITS#6168 was because users where locked out while pwdLockout was set to FALSE, AFAICS), to no avail

Then, I tried the setting from the archive on Fedora11, and Debian Etch, same issue... There is surely something that I am missing here, but shouldn't pwdAccountLockedTime being handled by the daemon? no access rule should be set ( except the for the fact that the admin user can write/delete it).

What rule am I missing here?

If needed, I can provide a VMDK of the repro, let me know and I will upload it somewhere.

Cheers,

chantra

> Hi,
>
> I am having troubles making the ppolicy overlay to prevent password
> guessing attacks with pwdLockout with slapd-2.4.11-1 in Debian Lenny.
>
> I set pwdMaxFailure to 3. In the user object I am testing with, I never get
> more than two entries for pwdFailureTime and pwdAccountLockedTime is never
> added at all.
>
> I tracked the problem down to the ACL settings in slapd.conf. With my default
>   access to *
>     by dn="cn=admin,dc=example,dc=net" write
>     by * read
> , I get the above result. When I rewrite the last line to "by * write", it works.
>
> The pwdFailureTime is updated, because it is defined as
> NO-USER-MODIFICATION, which bypasses te ACL checks for write.
> The problem happens when pwdMaxFailure failed logins are reached,
> and ppolicy.c tries to update pwdFailureTime and pwdAccountLockedTime 
> in a single request.
>
> How is this supposed to work?
> - Shouldn't pwdAccountLockedTime also be defined with NO-USER-MODIFICATION?
>
> - couldn't the update request in ppolicy.c be executed with higher
>   privileges? I tried to set up an non-anonymous bind in
>   pam_ldap but this did not help.
>
> - is there some recommended ACL setting to  grant the necessary privileges so that
>   ppolicy.c can update pwdAccountLockedTime, but users can't?
>   I am a splapd newbie, so maybe I don't see something obvious, but in
>   the log below, I see: "acl_mask: to all values by "", (=0)" -- that
>   looks like an anonymous bind, right? Allowing write for the
>   pwdAccountLockedTime attribute to anyone does not seem a good idea ;-)
>
>
>
> Thanks for any insight!
>
>
> Jiri
>
>
>
> P.S.: some detailed notes from my debugging are attached below:
>
> I am authenticating with pam-ldap. When I mis-type the password
> of a user and do a search on the user object (with a +, to see
> the operational attributes), the pwdFailureTime is created.  This
> is good.
>
> When I preform the bad login again, I get a second value for
> pwdFailureTime. Still good.
>
> But on the next login, instead of getting a third value for
> pwdFailureTime and an updated value for pwdAccountLockedTime, nothing
> happens. I put some more debug info into ppolicy_bind_response() like
> this:
>
> -----
>    * We only count those failures
>    * which are not due to expire.
>    */
>   Debug(LDAP_DEBUG_ANY, "xxx: counting pwdFailureTime %i/%d\n", i, fc, 0);
>  }
> }
> if ((ppb->pp.pwdMaxFailure > 0) &&
>   (fc >= ppb->pp.pwdMaxFailure - 1)) {
>   Debug(LDAP_DEBUG_ANY, "xxx: trying to insert pwdAccountLockedTime\n", 0, 0, 0);
> -----
>
> ... in the logs (with loglevel 65535), I really see:
>
> ------
> Aug  8 00:05:42 localhost slapd[15416]: xxx: counting pwdFailureTime 0/1
> Aug  8 00:05:42 localhost slapd[15416]: xxx: counting pwdFailureTime 1/2
> Aug  8 00:05:42 localhost slapd[15416]: xxx: trying to insert pwdAccountLockedTime
> [snip]
> Aug  8 00:05:42 localhost slapd[15416]: => access_allowed: delete access to "uid=j.bohac,ou=users,dc=example,dc=net" "pwdAccountLockedTime" requested
> Aug  8 00:05:42 localhost slapd[15416]: => acl_get: [2] attr pwdAccountLockedTime
> Aug  8 00:05:42 localhost slapd[15416]: => slap_access_allowed: result not in cache (pwdAccountLockedTime)
> Aug  8 00:05:42 localhost slapd[15416]: => acl_mask: access to entry "uid=j.bohac,ou=users,dc=example,dc=net", attr "pwdAccountLockedTime" requested
> Aug  8 00:05:42 localhost slapd[15416]: => acl_mask: to all values by "", (=0)
> Aug  8 00:05:42 localhost slapd[15416]: <= check a_dn_pat: cn=admin,dc=example,dc=net
> Aug  8 00:05:42 localhost slapd[15416]: <= check a_dn_pat: *
> Aug  8 00:05:42 localhost slapd[15416]: <= acl_mask: [2] applying read(=rscxd) (stop)
> Aug  8 00:05:42 localhost slapd[15416]: <= acl_mask: [2] mask: read(=rscxd)
> Aug  8 00:05:42 localhost slapd[15416]: => slap_access_allowed: delete access denied by read(=rscxd)
> Aug  8 00:05:42 localhost slapd[15416]: => access_allowed: no more rules
> ------
>
!DSPAM:4aa1064790404668414040! 
Sep  4 12:52:02 lenny32-tpl slapd[4079]: connection_closing: readying conn=9 sd=14 for close
Sep  4 12:52:02 lenny32-tpl slapd[4079]: connection_resched: attempting closing conn=9 sd=14
Sep  4 12:52:02 lenny32-tpl slapd[4079]: connection_close: conn=9 sd=14
Sep  4 12:52:02 lenny32-tpl slapd[4079]: daemon: removing 14
Sep  4 12:52:02 lenny32-tpl slapd[4079]: conn=9 fd=14 closed
Sep  4 12:52:02 lenny32-tpl slapd[4079]: daemon: activity on 1 descriptor
Sep  4 12:52:02 lenny32-tpl slapd[4079]: daemon: activity on:
Sep  4 12:52:02 lenny32-tpl slapd[4079]: 
Sep  4 12:52:02 lenny32-tpl slapd[4079]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Sep  4 12:52:02 lenny32-tpl slapd[4079]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: activity on 1 descriptor
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: activity on:
Sep  4 12:53:11 lenny32-tpl slapd[4079]: 
Sep  4 12:53:11 lenny32-tpl slapd[4079]: slap_listener_activate(9): 
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: epoll: listen=9 busy
Sep  4 12:53:11 lenny32-tpl slapd[4079]: >>> slap_listener(ldap:///)
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: listen=9, new connection on 14
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: added 14r (active) listener=(nil)
Sep  4 12:53:11 lenny32-tpl slapd[4079]: conn=10 fd=14 ACCEPT from IP=127.0.0.1:51486 (IP=0.0.0.0:389)
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: activity on 1 descriptor
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: activity on:
Sep  4 12:53:11 lenny32-tpl slapd[4079]: 
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: activity on 1 descriptor
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: activity on:
Sep  4 12:53:11 lenny32-tpl slapd[4079]:  14r
Sep  4 12:53:11 lenny32-tpl slapd[4079]: 
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: read active on 14
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Sep  4 12:53:11 lenny32-tpl slapd[4079]: connection_get(14)
Sep  4 12:53:11 lenny32-tpl slapd[4079]: connection_get(14): got connid=10
Sep  4 12:53:11 lenny32-tpl slapd[4079]: connection_read(14): checking for input on id=10
Sep  4 12:53:11 lenny32-tpl slapd[4079]: conn=10 op=0 do_bind
Sep  4 12:53:11 lenny32-tpl slapd[4079]: >>> dnPrettyNormal: <uid=chantra,ou=users,dc=example,dc=com>
Sep  4 12:53:11 lenny32-tpl slapd[4079]: <<< dnPrettyNormal: <uid=chantra,ou=users,dc=example,dc=com>, <uid=chantra,ou=users,dc=example,dc=com>
Sep  4 12:53:11 lenny32-tpl slapd[4079]: conn=10 op=0 BIND dn="uid=chantra,ou=users,dc=example,dc=com" method=128
Sep  4 12:53:11 lenny32-tpl slapd[4079]: do_bind: version=3 dn="uid=chantra,ou=users,dc=example,dc=com" method=128
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => bdb_entry_get: ndn: "uid=chantra,ou=users,dc=example,dc=com"
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => bdb_entry_get: oc: "(null)", at: "(null)"
Sep  4 12:53:11 lenny32-tpl slapd[4079]: bdb_dn2entry("uid=chantra,ou=users,dc=example,dc=com")
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => bdb_entry_get: found entry: "uid=chantra,ou=users,dc=example,dc=com"
Sep  4 12:53:11 lenny32-tpl slapd[4079]: bdb_entry_get: rc=0
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => bdb_entry_get: ndn: "cn=default,ou=policies,dc=example,dc=com"
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => bdb_entry_get: oc: "(null)", at: "(null)"
Sep  4 12:53:11 lenny32-tpl slapd[4079]: bdb_dn2entry("cn=default,ou=policies,dc=example,dc=com")
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => bdb_entry_get: found entry: "cn=default,ou=policies,dc=example,dc=com"
Sep  4 12:53:11 lenny32-tpl slapd[4079]: bdb_entry_get: rc=0
Sep  4 12:53:11 lenny32-tpl slapd[4079]: ==> hdb_bind: dn: uid=chantra,ou=users,dc=example,dc=com
Sep  4 12:53:11 lenny32-tpl slapd[4079]: bdb_dn2entry("uid=chantra,ou=users,dc=example,dc=com")
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => access_allowed: auth access to "uid=chantra,ou=users,dc=example,dc=com" "userPassword" requested
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => acl_get: [1] attr userPassword
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => slap_access_allowed: result not in cache (userPassword)
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => acl_mask: access to entry "uid=chantra,ou=users,dc=example,dc=com", attr "userPassword" requested
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => acl_mask: to value by "", (=0) 
Sep  4 12:53:11 lenny32-tpl slapd[4079]: <= check a_dn_pat: cn=admin,dc=example,dc=com
Sep  4 12:53:11 lenny32-tpl slapd[4079]: <= check a_dn_pat: anonymous
Sep  4 12:53:11 lenny32-tpl slapd[4079]: <= acl_mask: [2] applying auth(=xd) (stop)
Sep  4 12:53:11 lenny32-tpl slapd[4079]: <= acl_mask: [2] mask: auth(=xd)
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => slap_access_allowed: auth access granted by auth(=xd)
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => access_allowed: auth access granted by auth(=xd)
Sep  4 12:53:11 lenny32-tpl slapd[4079]: send_ldap_result: conn=10 op=0 p=3
Sep  4 12:53:11 lenny32-tpl slapd[4079]: send_ldap_result: err=49 matched="" text=""
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => bdb_entry_get: ndn: "uid=chantra,ou=users,dc=example,dc=com"
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => bdb_entry_get: oc: "(null)", at: "(null)"
Sep  4 12:53:11 lenny32-tpl slapd[4079]: bdb_dn2entry("uid=chantra,ou=users,dc=example,dc=com")
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => bdb_entry_get: found entry: "uid=chantra,ou=users,dc=example,dc=com"
Sep  4 12:53:11 lenny32-tpl slapd[4079]: bdb_entry_get: rc=0
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => bdb_entry_get: ndn: "uid=chantra,ou=users,dc=example,dc=com"
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => bdb_entry_get: oc: "(null)", at: "(null)"
Sep  4 12:53:11 lenny32-tpl slapd[4079]: bdb_dn2entry("uid=chantra,ou=users,dc=example,dc=com")
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => bdb_entry_get: found entry: "uid=chantra,ou=users,dc=example,dc=com"
Sep  4 12:53:11 lenny32-tpl slapd[4079]: bdb_entry_get: rc=0
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => bdb_entry_get: ndn: "cn=default,ou=policies,dc=example,dc=com"
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => bdb_entry_get: oc: "(null)", at: "(null)"
Sep  4 12:53:11 lenny32-tpl slapd[4079]: bdb_dn2entry("cn=default,ou=policies,dc=example,dc=com")
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => bdb_entry_get: found entry: "cn=default,ou=policies,dc=example,dc=com"
Sep  4 12:53:11 lenny32-tpl slapd[4079]: bdb_entry_get: rc=0
Sep  4 12:53:11 lenny32-tpl slapd[4079]: hdb_modify: uid=chantra,ou=users,dc=example,dc=com
Sep  4 12:53:11 lenny32-tpl slapd[4079]: bdb_dn2entry("uid=chantra,ou=users,dc=example,dc=com")
Sep  4 12:53:11 lenny32-tpl slapd[4079]: bdb_modify_internal: 0x00000004: uid=chantra,ou=users,dc=example,dc=com
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => access_allowed: delete access to "uid=chantra,ou=users,dc=example,dc=com" "pwdAccountLockedTime" requested
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => dn: [2] 
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => acl_get: [3] attr pwdAccountLockedTime
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => slap_access_allowed: result not in cache (pwdAccountLockedTime)
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => acl_mask: access to entry "uid=chantra,ou=users,dc=example,dc=com", attr "pwdAccountLockedTime" requested
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => acl_mask: to all values by "", (=0) 
Sep  4 12:53:11 lenny32-tpl slapd[4079]: <= check a_dn_pat: cn=admin,dc=example,dc=com
Sep  4 12:53:11 lenny32-tpl slapd[4079]: <= check a_dn_pat: *
Sep  4 12:53:11 lenny32-tpl slapd[4079]: <= acl_mask: [2] applying read(=rscxd) (stop)
Sep  4 12:53:11 lenny32-tpl slapd[4079]: <= acl_mask: [2] mask: read(=rscxd)
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => slap_access_allowed: delete access denied by read(=rscxd)
Sep  4 12:53:11 lenny32-tpl slapd[4079]: => access_allowed: no more rules
Sep  4 12:53:11 lenny32-tpl slapd[4079]: hdb_modify: modify failed (50)
Sep  4 12:53:11 lenny32-tpl slapd[4079]: send_ldap_result: conn=10 op=0 p=3
Sep  4 12:53:11 lenny32-tpl slapd[4079]: send_ldap_result: err=50 matched="" text=""
Sep  4 12:53:11 lenny32-tpl slapd[4079]: send_ldap_response: msgid=1 tag=97 err=49
Sep  4 12:53:11 lenny32-tpl slapd[4079]: conn=10 op=0 RESULT tag=97 err=49 text=
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: activity on 1 descriptor
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: activity on:
Sep  4 12:53:11 lenny32-tpl slapd[4079]: 
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: activity on 1 descriptor
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: activity on:
Sep  4 12:53:11 lenny32-tpl slapd[4079]:  14r
Sep  4 12:53:11 lenny32-tpl slapd[4079]: 
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: read active on 14
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: epoll: listen=9 active_threads=0 tvp=zero
Sep  4 12:53:11 lenny32-tpl slapd[4079]: connection_get(14)
Sep  4 12:53:11 lenny32-tpl slapd[4079]: connection_get(14): got connid=10
Sep  4 12:53:11 lenny32-tpl slapd[4079]: connection_read(14): checking for input on id=10
Sep  4 12:53:11 lenny32-tpl slapd[4079]: ber_get_next on fd 14 failed errno=0 (Success)
Sep  4 12:53:11 lenny32-tpl slapd[4079]: connection_read(14): input error=-2 id=10, closing.
Sep  4 12:53:11 lenny32-tpl slapd[4079]: connection_closing: readying conn=10 sd=14 for close
Sep  4 12:53:11 lenny32-tpl slapd[4079]: connection_close: conn=10 sd=14
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: removing 14
Sep  4 12:53:11 lenny32-tpl slapd[4079]: conn=10 fd=14 closed (connection lost)
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: activity on 1 descriptor
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: activity on:
Sep  4 12:53:11 lenny32-tpl slapd[4079]: 
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: epoll: listen=8 active_threads=0 tvp=zero
Sep  4 12:53:11 lenny32-tpl slapd[4079]: daemon: epoll: listen=9 active_threads=0 tvp=zero

Attachment: ldaps.tgz
Description: application/compressed-tar