[Date Prev][Date Next] [Chronological] [Thread] [Top]
slapd locks up on modify op (ITS#3365)

To: openldap-its@OpenLDAP.org
Subject: slapd locks up on modify op (ITS#3365)
From: kuenne@rentec.com
Date: Mon, 11 Oct 2004 22:30:58 GMT
Full_Name: Karsten Kuenne
Version: 2.2.17
OS: Solaris 8
URL: ftp://ftp.openldap.org/incoming/slapdlog.lockup
Submission from: (NULL) (65.213.85.247)


I have frequent problems with slapd locking up if I try to modify an entry which
is part of a group ACL. Today I was able to find a reproducible case and get
some more information. In slapd.conf I have the following ACL's:

access to dn="dc=rentec,dc=com"
        by ssf=56 group/groupofurls/memberurl="cn=admins,dc=rentec,dc=com"
write
        by * read
access to dn.subtree="ou=profile,dc=rentec,dc=com"
        by ssf=56 group/groupofurls/memberurl="cn=admins,dc=rentec,dc=com"
write
        by * read
access to dn.subtree="ou=People,dc=rentec,dc=com"
        by ssf=56 group/groupofurls/memberurl="cn=admins,dc=rentec,dc=com"
write
        by * read
access to dn.subtree="ou=Webaccess,dc=rentec,dc=com"
        by ssf=56 group/groupofurls/memberurl="cn=admins,dc=rentec,dc=com"
write
        by * read
access to dn.subtree="ou=Group,dc=rentec,dc=com"
        by ssf=56 group/groupofurls/memberurl="cn=admins,dc=rentec,dc=com"
write
        by * read
access to dn.subtree="ou=Services,dc=rentec,dc=com"
        by ssf=56 group/groupofurls/memberurl="cn=admins,dc=rentec,dc=com"
write
        by * read
access to dn.subtree="ou=Protocols,dc=rentec,dc=com"
        by ssf=56 group/groupofurls/memberurl="cn=admins,dc=rentec,dc=com"
write
        by * read
.... (and so on)

The group "admins" looks like the following:

dn: cn=admins,dc=rentec,dc=com
objectClass: top
objectClass: groupOfURLs
cn: admins
memberURL: ldap:///ou=People,dc=rentec,dc=com??one?(gidNumber=14)
memberURL: ldap:///ou=People,dc=rentec,dc=com??one?(uidNumber=0)
description: LDAP server administrators

One of the dynamic members of the group is:

dn: uid=root,ou=People,dc=rentec,dc=com
objectClass: inetOrgPerson
objectClass: posixAccount
objectClass: shadowAccount
objectClass: top
objectClass: krb5Principal
sn: Account for root
cn: Account for root
uid: root
uidNumber: 0
gidNumber: 1
homeDirectory: /root
krb5PrincipalName: root@RENTEC.COM

The steps to reproduce the hang are the following. We're using Heimdal-Kerberos
with the LDAP backend. So I connected with "kadmin -l" to the ldapi:/// "port",
which uses SASL/EXTERNAL and authenticates as the above "uid=root,..." via a
sasl-regexp and did some lookup. At the same time I used gq on a different host
and connected with TLS and SASL/GSSAPI authentication as "uid=kuenne,..." (don't
know whether this matters) and modified the "uid=root,..." entry. The modify
operation never finished. Following are stacktraces from all the slapd threads
and BDB lock stats:

(dbx) threads
      t@1      ?()   sleep on 0xff07ee10  in  _reap_wait_cancel()
      t@2  b  l@2   ?()   running          in  _signotifywait()
      t@3      ?()   sleep on 0xff0829e0  in  _reap_wait()
      t@4      reg_thread()   sleep on 0x4c4e30  in 
_cond_reltimedwait_cancel()
      t@5  b  l@5   _co_timerset()   running          in  _lwp_sema_wait()
      t@7  a  l@4   slapd_daemon_task()   running          in  _libc_poll()
 >    t@8  a  l@1   ldap_int_thread_pool_wrapper()   running          in 
___lwp_cond_wait()
      t@9  a  l@6   ldap_int_thread_pool_wrapper()   sleep on 0x4d3af8  in 
_lwp_sema_wait()
(dbx) where -v t@1
current thread: t@1
=>[1] _reap_wait_cancel(0xff07ee10, 0xff07e000, 0xe0, 0xff085930, 0xf9c01d70,
0x1), at 0xff05de14
  [2] _thrp_join(0xff07ee10, 0x7, 0x0, 0xff07e000, 0x0, 0x7), at 0xff0600a0
  [3] ldap_pvt_thread_join(thread = 7U, thread_return = (nil)), line 165 in
"thr_posix.c"
  [4] slapd_daemon(), line 2037 in "daemon.c"
  [5] main(argc = 5, argv = 0xffbefa9c), line 710 in "main.c"
(dbx) where -v t@2
current thread: t@2
=>[1] _signotifywait(0xff08b240, 0xff07e000, 0x0, 0xff07e000, 0x0,
0xfef1f854),at 0xfef1eb08
  [2] _dynamiclwps(0xff07e000, 0x0, 0xff3e7200, 0xff3d39d4, 0xff3e9b28,
0xff3e7760), at 0xff05ed54
(dbx) where -v t@3
current thread: t@3
=>[1] _reap_wait(0xff0829e0, 0xff07e000, 0x0, 0xff07e000, 0x0, 0x0), at
0xff05ddbc
  [2] _reaper(0xff07ee30, 0xff084740, 0xff0829e0, 0xff07ee08, 0x1,
0xfe400000),at 0xff05db14
(dbx) where -v t@4
current thread: t@4
=>[1] _cond_reltimedwait_cancel(0x0, 0x0, 0x0, 0x1, 0x0, 0x0), at 0xff057e10
  [2] _cond_timedwait_cancel(0x4c4e30, 0x4c6008, 0xfea0bd08, 0x4c4e30, 0x0,
0x0), at 0xff057c08
  [3] slp_dequeue_timed(0xfea0bd04, 0xfea0bd08, 0xfea0bd04, 0x4c6028,
0xff390000, 0x1), at 0xff3882f4
  [4] reg_thread(0x0, 0xfee73d10, 0x1, 0xff39273c, 0xff392740, 0x2), at
0xff386404
(dbx) where -v t@5
current thread: t@5
=>[1] _lwp_sema_wait(0xff07fa08, 0xff07f9f8, 0x0, 0x4, 0xe, 0xfe909cd8), at
0xfef1f1b8
  [2] _co_timerset(0xff07ed30, 0xff07e000, 0x1, 0x3, 0xff07e000, 0x0), at
0xff058d04
(dbx) where -v t@7
current thread: t@7
=>[1] _libc_poll(0xf9c01548, 0x7, 0x1d4c, 0x0, 0x1d4c, 0x0), at 0xfef1d344
  [2] _libc_select(0x10, 0x0, 0x0, 0xf9c01580, 0xf9c01be4, 0xf9c01548), at
0xfeecd2c8
  [3] _ti_select(0xf9c0169a, 0xfee73d10, 0x0, 0x5, 0x1, 0xfe400000), at
0xff06b150
(dbx) where -v t@8
current thread: t@8
  [1] ___lwp_cond_wait(0xfe0d4eb0, 0xfe0d4e98, 0x0, 0xffffffffffffffff,
0xfffffffffffffff8, 0x72eb69), at 0xfef1f16c
  [2] _lwp_cond_wait(0xfe0d4eb0, 0xfe0d4e98, 0x736320, 0x33, 0x0, 0x1ecce8),
at0xfef166b0
  [3] __db_pthread_mutex_lock(0x5345a0, 0xfe0d4e98, 0xfe0d4eb0, 0x722780, 0x1,
0x0), at 0xff24efb8
  [4] __lock_get_internal(0x534e68, 0x80000035, 0x0, 0x0, 0x2, 0xfe0d4e98), at
0xff2f2da4
  [5] __lock_vec(0xf94014d0, 0xfe0f3f40, 0xffffffff, 0xff2f0f04, 0x1, 0x0), at
0xff2f1058
=>[6] bdb_cache_entry_db_relock(env = 0x5345a0, locker = 2147483701U, ei =
0x61d248, rw = 1, tryOnly = 0, lock = 0xf9401630), line 89 in "cache.c"
  [7] bdb_cache_modify(e = 0x7252d0, newAttrs = 0x723828, env = 0x5345a0, locker
= 2147483701U, lock = 0xf9401630), line 875 in "cache.c"
  [8] bdb_modify(op = 0x728390, rs = 0xf9401ac8), line 700 in "modify.c"
  [9] do_modify(op = 0x728390, rs = 0xf9401ac8), line 506 in "modify.c"
  [10] connection_operation(ctx = 0xf9401b84, arg_v = 0x728390), line 1069 in
"connection.c"
  [11] ldap_int_thread_pool_wrapper(xpool = 0x4d3ad8), line 467 in "tpool.c"
(dbx) where -v t@9
current thread: t@9
=>[1] _lwp_sema_wait(0xf8c01e30, 0x0, 0x0, 0x0, 0x0, 0x2), at 0xfef1f1b8
  [2] _park(0xf8c01e30, 0xff07e000, 0x0, 0xf8c01d70, 0x24d84, 0xf9401d70), at
0xff059ac4
  [3] _swtch(0xf8c01d70, 0x0, 0xff07e000, 0x5, 0x1000, 0x0), at 0xff05978c
  [4] _cond_wait_cancel(0xf8c01d70, 0x0, 0x0, 0xff07e000, 0x0, 0x4d3ae0), at
0xff05826c
  [5] pthread_cond_wait(0x4d3af8, 0x4d3ae0, 0xf8c01ab4, 0x4d3ae0, 0x0, 0x0),
at0xff058110
  [6] ldap_pvt_thread_cond_wait(cond = 0x4d3af8, mutex = 0x4d3ae0), line 261
in"thr_posix.c"
  [7] ldap_int_thread_pool_wrapper(xpool = 0x4d3ad8), line 456 in "tpool.c"
(dbx) quit
detaching from process 8780
jaguar:/opt/ldap/libexec # cd ..
jaguar:/opt/ldap # cd db/nis
jaguar:/opt/ldap/db/nis # /usr/local/products/BerkeleyDB/4.2.52/bin/db_stat -C
c

=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
Conflict matrix
0       0       0       0       0       0       0       0       0
0       0       1       0       1       0       1       0       1
0       1       1       1       1       1       1       1       1
0       0       0       0       0       0       0       0       0
0       1       1       0       0       0       0       1       1
0       0       1       0       0       0       0       0       1
0       1       1       0       0       0       0       1       1
0       0       1       0       1       0       1       0       0
0       1       1       0       1       1       1       0       1
jaguar:/opt/ldap/db/nis # /usr/local/products/BerkeleyDB/4.2.52/bin/db_stat -C
p
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
Lock region parameters
locker table size: 1031, object table size: 1031, obj_off: 401064,
osynch_off: 0, locker_off: 392808, lsynch_off: 0, need_dd: 0
jaguar:/opt/ldap/db/nis # /usr/local/products/BerkeleyDB/4.2.52/bin/db_stat -C
A
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
Lock region parameters
locker table size: 1031, object table size: 1031, obj_off: 401064,
osynch_off: 0, locker_off: 392808, lsynch_off: 0, need_dd: 0

=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
Conflict matrix
0       0       0       0       0       0       0       0       0
0       0       1       0       1       0       1       0       1
0       1       1       1       1       1       1       1       1
0       0       0       0       0       0       0       0       0
0       1       1       0       0       0       0       1       1
0       0       1       0       0       0       0       0       1
0       1       1       0       0       0       0       1       1
0       0       1       0       1       0       1       0       0
0       1       1       0       1       1       1       0       1
=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
Locks grouped by lockers
Locker   Mode      Count Status  ----------------- Object ---------------
      1a dd=30 locks held 1    write locks 0
      1a READ          1 HELD    id2entry.bdb             handle        0

      1b dd=29 locks held 0    write locks 0
      1c dd=28 locks held 1    write locks 0
      1c READ          1 HELD    dn2id.bdb                handle        0

      1d dd=27 locks held 0    write locks 0
      1e dd=26 locks held 0    write locks 0
      1f dd=25 locks held 0    write locks 0
      20 dd=24 locks held 1    write locks 0
      20 READ          6 HELD    0x332c0 len:   5 data: 0x000x000x1ec0x00


      21 dd=22 locks held 1    write locks 0
      21 READ          1 HELD    objectClass.bdb          handle        0

      22 dd=21 locks held 0    write locks 0
      23 dd=20 locks held 0    write locks 0
      24 dd=19 locks held 1    write locks 0
      24 READ          1 HELD    uid.bdb                  handle        0

      25 dd=18 locks held 0    write locks 0
      26 dd=17 locks held 0    write locks 0
      27 dd=16 locks held 1    write locks 0
      27 READ          1 HELD    ou.bdb                   handle        0

      28 dd=15 locks held 0    write locks 0
      29 dd=14 locks held 0    write locks 0
      2a dd=13 locks held 0    write locks 0
      2b dd=12 locks held 0    write locks 0
      2c dd=11 locks held 2    write locks 0
      2c READ          1 HELD    0x331e8 len:   5 data: 0x000x000x00x0x00

      2c READ          1 HELD    0x332c0 len:   5 data: 0x000x000x1ec0x00


      2d dd= 9 locks held 0    write locks 0
      2e dd= 8 locks held 0    write locks 0
      2f dd= 7 locks held 1    write locks 0
      2f READ          1 HELD    uidNumber.bdb            handle        0

      30 dd= 6 locks held 0    write locks 0
      31 dd= 5 locks held 0    write locks 0
      32 dd= 4 locks held 1    write locks 0
      32 READ          1 HELD    gidNumber.bdb            handle        0

      33 dd= 3 locks held 0    write locks 0
      34 dd= 2 locks held 0    write locks 0
      35 dd= 1 locks held 0    write locks 0
80000008 dd=23 locks held 0    write locks 0
80000030 dd=10 locks held 0    write locks 0
80000035 dd= 0 locks held 5    write locks 3
80000035 WRITE         1 WAIT    0x332c0 len:   5 data: 0x000x000x1ec0x00

80000035 WRITE         1 HELD    0x33398 len:   5 data: 0x000x000x1e0xec0x00

80000035 WRITE         1 HELD    id2entry.bdb             page        424
80000035 WRITE         1 HELD    id2entry.bdb             page        409
80000035 READ          1 HELD    0x331e8 len:   5 data: 0x000x000x00x0x00

80000035 READ          1 HELD    0x33308 len:   5 data: 0x000x000x1e0xeb0x00


=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
Locks grouped by object
Locker   Mode      Count Status  ----------------- Object ---------------
      2c READ          1 HELD    0x331e8 len:   5 data: 0x000x000x00x0x00

80000035 READ          1 HELD    0x331e8 len:   5 data: 0x000x000x00x0x00


80000035 READ          1 HELD    0x33308 len:   5 data: 0x000x000x1e0xeb0x00


80000035 WRITE         1 HELD    id2entry.bdb             page        409

80000035 WRITE         1 HELD    id2entry.bdb             page        424

      20 READ          6 HELD    0x332c0 len:   5 data: 0x000x000x1ec0x00

      2c READ          1 HELD    0x332c0 len:   5 data: 0x000x000x1ec0x00

80000035 WRITE         1 WAIT    0x332c0 len:   5 data: 0x000x000x1ec0x00


      1a READ          1 HELD    id2entry.bdb             handle        0

      1c READ          1 HELD    dn2id.bdb                handle        0

      21 READ          1 HELD    objectClass.bdb          handle        0

      27 READ          1 HELD    ou.bdb                   handle        0

      24 READ          1 HELD    uid.bdb                  handle        0

      2f READ          1 HELD    uidNumber.bdb            handle        0

      32 READ          1 HELD    gidNumber.bdb            handle        0

80000035 WRITE         1 HELD    0x33398 len:   5 data: 0x000x000x1e0xec0x00


=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=
Memory free list
0xfef90004: 120796


I uploaded the slapd log as slapdlog.lockup because of it's size.
Prev by Date: (ITS#3365)
Next by Date: Re: SyncREPL Behaves Inconsistently (ITS#3262)
Index(es):
- Chronological
- Thread