[Date Prev][Date Next]
[Chronological]
[Thread]
[Top]
help needed with LDAP update errors
We've been using OpenLDAP 1.2.x for more than a year to store
descriptions of document services. Today, while testing our code we
seem to have screwed up the database, or its indices, or both.
Current setup: Sleepycat db-2.7.7
OpenLDAP 1.2.9
The scenario that seems to have caused the problem is the following:
1. Application on client 1 is repeatedly listing all entries on a
subtree and then deleting and then immediately adding an entry on the
same subtree
2. Application on client 2 is doing the same but with a different
entry.
I did an ldbmcat and rebuilt indices (didn't seem to help, but maybe
I'm not doing it right).
Any suggestions on what's up and what to do are appreciated. My
hypotheses include
(1) threading problem with simultaneous updates from more
than 1 client
(2) some problem with DB2 database
(3) some problem with LDAP
Bill Anderson
Xerox Research & Technology
=====================
a portion of the log is:
13 11:21:37 monk slapd[325]: conn=82 op=22 DEL dn="CN=ORCH00008,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM"
Jun 13 11:21:37 monk slapd[325]: conn=82 op=22 RESULT err=0 tag=107 nentries=0
Jun 13 11:21:37 monk slapd[325]: conn=82 op=23 ADD dn="CN=ORCH00008,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM"
Jun 13 11:21:37 monk slapd[325]: ====> entry cn=Orch00008,ou=Citizens,dc=sifsola,dc=xerox,dc=com id 87 already in id cache
Jun 13 11:21:37 monk slapd[325]: cache_add_entry_lock failed
and a portion of the -d 255 debugging trace is:
=> id2entry_r( 83 )
=> ldbm_cache_open( "/usr/ldapdata/id2entry.dbb", 7, 600 )
<= ldbm_cache_open (cache 1)
=> str2entry
<= str2entry 0x1342e8
entry_rdwr_rlock: ID: 83
<= id2entry_r( 83 ) (disk)
=> test_filter
PRESENT
=> access_allowed: entry (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com) attr (objectclass)
=> acl_get: entry (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com) attr (objectclass)
<= acl_get: no acl applicable to database root
=> acl_access_allowed: search access to entry "cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com"
=> acl_access_allowed: search access to value "any" by "CN=ADMIN,DC=XEROX,DC=COM"
<= acl_access_allowed: granted to database root
=> access_allowed: exit (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com) attr (objectclass)
<= test_filter 0
<= checking for alias for dn cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com
=> send_search_entry (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com)
=> access_allowed: entry (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com) attr (entry)
=> acl_get: entry (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com) attr (entry)
<= acl_get: no acl applicable to database root
=> acl_access_allowed: read access to entry "cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com"
=> acl_access_allowed: read access to value "any" by "CN=ADMIN,DC=XEROX,DC=COM"
<= acl_access_allowed: granted to database root
=> access_allowed: exit (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com) attr (entry)
=> acl_get: entry (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com) attr (supportedservice)
<= acl_get: no acl applicable to database root
=> acl_access_allowed: read access to entry "cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com"
=> acl_access_allowed: read access to value "any" by "CN=ADMIN,DC=XEROX,DC=COM"
<= acl_access_allowed: granted to database root
=> acl_get: entry (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com) attr (sifcitizentype)
<= acl_get: no acl applicable to database root
=> acl_access_allowed: read access to entry "cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com"
=> acl_access_allowed: read access to value "any" by "CN=ADMIN,DC=XEROX,DC=COM"
<= acl_access_allowed: granted to database root
=> acl_get: entry (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com) attr (sifreference)
<= acl_get: no acl applicable to database root
=> acl_access_allowed: read access to entry "cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com"
=> acl_access_allowed: read access to value "any" by "CN=ADMIN,DC=XEROX,DC=COM"
<= acl_access_allowed: granted to database root
=> acl_get: entry (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com) attr (objectclass)
<= acl_get: no acl applicable to database root
=> acl_access_allowed: read access to entry "cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com"
=> acl_access_allowed: read access to value "any" by "CN=ADMIN,DC=XEROX,DC=COM"
<= acl_access_allowed: granted to database root
=> acl_get: entry (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com) attr (cn)
<= acl_get: no acl applicable to database root
=> acl_access_allowed: read access to entry "cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com"
=> acl_access_allowed: read access to value "any" by "CN=ADMIN,DC=XEROX,DC=COM"
<= acl_access_allowed: granted to database root
=> acl_get: entry (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com) attr (capabilitydescription)
<= acl_get: no acl applicable to database root
=> acl_access_allowed: read access to entry "cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com"
=> acl_access_allowed: read access to value "any" by "CN=ADMIN,DC=XEROX,DC=COM"
<= acl_access_allowed: granted to database root
ber_flush: 11380 bytes to sd 5
0 82 , p 02 01 04 d 82 , i 04 ; c n =
T e s t C i t i z e n 0 0 0 0 8
p , o u = C i t i z e n s , d c
= s i f s o l a , d c = x e r o
x , d c = c o m 0 82 , ( 0 " 04 10
s u p p o r t e d s e r v i c e
1 0e 04 0c S E R V I C E 0 0 0 0 8
0 1c 04 0e s i f c i t i z e n t y
p e 1 0a 04 08 p r o v i d e r 0 )
04 0c s i f r e f e r e n c e 1 19
04 17 H T T P : / / 1 3 . 0 . 3 2
. 1 0 0 : 1 8 9 2 0 1b 04 0b o b j
e c t c l a s s 1 0c 04 0a s i f c
i t i z e n 0 19 04 02 c n 1 13 04 11
T e s t C i t i z e n 0 0 0 0 8
p 0 82 + 7f 04 15 c a p a b i l i t
y d e s c r i p t i o n 1 82 + d
04 82 + ` P D 9 4 b W w g d m V y
... large base64 attribute value deleted
<= send_search_entry
====> cache_return_entry_r
entry_rdwr_runlock: ID: 83
send_ldap_result 0::
ber_flush: 14 bytes to sd 5
0 0c 02 01 04 e 07 0a 01 00 04 00 04 00
select activity on 1 descriptors
activity on: 5r
read activity on 5
ber_get_next
ber_get_next: tag 0x30 len 99 contents:
ber_dump: buf 0x131e00, ptr 0x131e00, end 0x131e63
current len 99, contents:
02 01 05 c ^ 04 > c n = T e s t C i
t i z e n 0 0 0 0 8 p , 20 o u =
C i t i z e n s , 20 d c = s i f
S O L A , 20 d c = x e r o x , d
c = c o m 0a 01 00 0a 01 03 02 01 00 02 01
00 01 01 00 87 0b o b j e c t C l a s
s 0 00
do_search
SRCH "CN=TESTCITIZEN00008P,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM" 0 3 0 0 0
begin get_filter
PRESENT
end get_filter 0
filter: (objectclass=*)
attrs:
=> ldbm_back_search
<= dereferencing dn: "CN=TESTCITIZEN00008P,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM"
dn2entry_r: dn: "CN=TESTCITIZEN00008P,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM"
=> dn2id( "CN=TESTCITIZEN00008P,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM" )
====> cache_find_entry_dn2id: found dn: CN=TESTCITIZEN00008P,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM
<= dn2id 83 (in cache)
=> id2entry_r( 83 )
====> cache_find_entry_dn2id: found id: 83 rw: 0
entry_rdwr_rtrylock: ID: 83
<= id2entry_r 0x1342e8 (cache)
====> cache_return_entry_r
entry_rdwr_runlock: ID: 83
dn2entry_r: dn: "CN=TESTCITIZEN00008P,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM"
=> dn2id( "CN=TESTCITIZEN00008P,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM" )
====> cache_find_entry_dn2id: found dn: CN=TESTCITIZEN00008P,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM
<= dn2id 83 (in cache)
=> id2entry_r( 83 )
====> cache_find_entry_dn2id: found id: 83 rw: 0
entry_rdwr_rtrylock: ID: 83
<= id2entry_r 0x1342e8 (cache)
<= checking for alias for dn cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com
====> cache_return_entry_r
entry_rdwr_runlock: ID: 83
====> cache_return_entry_r
entry_rdwr_runlock: ID: 83
<= returning deref DN of "cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com"
using base "CN=TESTCITIZEN00008P,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM"
base_candidates: base: "CN=TESTCITIZEN00008P,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM"
dn2entry_r: dn: "CN=TESTCITIZEN00008P,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM"
=> dn2id( "CN=TESTCITIZEN00008P,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM" )
====> cache_find_entry_dn2id: found dn: CN=TESTCITIZEN00008P,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM
<= dn2id 83 (in cache)
=> id2entry_r( 83 )
====> cache_find_entry_dn2id: found id: 83 rw: 0
entry_rdwr_rtrylock: ID: 83
<= id2entry_r 0x1342e8 (cache)
====> cache_return_entry_r
entry_rdwr_runlock: ID: 83
=> id2entry_r( 83 )
====> cache_find_entry_dn2id: found id: 83 rw: 0
entry_rdwr_rtrylock: ID: 83
<= id2entry_r 0x1342e8 (cache)
=> test_filter
PRESENT
=> access_allowed: entry (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com) attr (objectclass)
=> acl_get: entry (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com) attr (objectclass)
<= acl_get: no acl applicable to database root
=> acl_access_allowed: search access to entry "cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com"
=> acl_access_allowed: search access to value "any" by "CN=ADMIN,DC=XEROX,DC=COM"
<= acl_access_allowed: granted to database root
=> access_allowed: exit (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com) attr (objectclass)
<= test_filter 0
<= checking for alias for dn cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com
=> send_search_entry (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com)
=> access_allowed: entry (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com) attr (entry)
=> acl_get: entry (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com) attr (entry)
<= acl_get: no acl applicable to database root
=> acl_access_allowed: read access to entry "cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com"
=> acl_access_allowed: read access to value "any" by "CN=ADMIN,DC=XEROX,DC=COM"
<= acl_access_allowed: granted to database root
=> access_allowed: exit (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com) attr (entry)
=> acl_get: entry (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com) attr (supportedservice)
<= acl_get: no acl applicable to database root
=> acl_access_allowed: read access to entry "cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com"
=> acl_access_allowed: read access to value "any" by "CN=ADMIN,DC=XEROX,DC=COM"
<= acl_access_allowed: granted to database root
=> acl_get: entry (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com) attr (sifcitizentype)
<= acl_get: no acl applicable to database root
=> acl_access_allowed: read access to entry "cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com"
=> acl_access_allowed: read access to value "any" by "CN=ADMIN,DC=XEROX,DC=COM"
<= acl_access_allowed: granted to database root
=> acl_get: entry (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com) attr (sifreference)
<= acl_get: no acl applicable to database root
=> acl_access_allowed: read access to entry "cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com"
=> acl_access_allowed: read access to value "any" by "CN=ADMIN,DC=XEROX,DC=COM"
<= acl_access_allowed: granted to database root
=> acl_get: entry (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com) attr (objectclass)
<= acl_get: no acl applicable to database root
=> acl_access_allowed: read access to entry "cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com"
=> acl_access_allowed: read access to value "any" by "CN=ADMIN,DC=XEROX,DC=COM"
<= acl_access_allowed: granted to database root
=> acl_get: entry (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com) attr (cn)
<= acl_get: no acl applicable to database root
=> acl_access_allowed: read access to entry "cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com"
=> acl_access_allowed: read access to value "any" by "CN=ADMIN,DC=XEROX,DC=COM"
<= acl_access_allowed: granted to database root
=> acl_get: entry (cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com) attr (capabilitydescription)
<= acl_get: no acl applicable to database root
=> acl_access_allowed: read access to entry "cn=TestCitizen00008p,ou=Citizens,dc=sifsola,dc=xerox,dc=com"
=> acl_access_allowed: read access to value "any" by "CN=ADMIN,DC=XEROX,DC=COM"
<= acl_access_allowed: granted to database root
ber_flush: 11380 bytes to sd 5
0 82 , p 02 01 05 d 82 , i 04 ; c n =
T e s t C i t i z e n 0 0 0 0 8
p , o u = C i t i z e n s , d c
= s i f s o l a , d c = x e r o
x , d c = c o m 0 82 , ( 0 " 04 10
s u p p o r t e d s e r v i c e
1 0e 04 0c S E R V I C E 0 0 0 0 8
0 1c 04 0e s i f c i t i z e n t y
p e 1 0a 04 08 p r o v i d e r 0 )
04 0c s i f r e f e r e n c e 1 19
04 17 H T T P : / / 1 3 . 0 . 3 2
. 1 0 0 : 1 8 9 2 0 1b 04 0b o b j
e c t c l a s s 1 0c 04 0a s i f c
i t i z e n 0 19 04 02 c n 1 13 04 11
T e s t C i t i z e n 0 0 0 0 8
p 0 82 + 7f 04 15 c a p a b i l i t
y d e s c r i p t i o n 1 82 + d
... large base64 attribute value deleted
do_delete
do_delete: dn (cn=TestCitizen00008p, ou=Citizens, dc=sifSOLA, dc=xerox,dc=com)
==> ldbm_back_delete: CN=TESTCITIZEN00008P,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM
dn2entry_w: dn: "CN=TESTCITIZEN00008P,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM"
=> dn2id( "CN=TESTCITIZEN00008P,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM" )
====> cache_find_entry_dn2id: found dn: CN=TESTCITIZEN00008P,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM
<= dn2id 83 (in cache)
=> id2entry_w( 83 )
====> cache_find_entry_dn2id: found id: 83 rw: 1
entry_rdwr_wtrylock: ID: 83
<= id2entry_w 0x1342e8 (cache)
=> has_children( 83 )
=> ldbm_cache_open( "/usr/ldapdata/id2children.dbb", 7, 600 )
<= ldbm_cache_open (cache 2)
<= has_children( 83 ): yes
<=- ldbm_back_delete: non leaf CN=TESTCITIZEN00008P,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM
send_ldap_result 66::
ber_flush: 14 bytes to sd 5
0 0c 02 01 06 k 07 0a 01 B 04 00 04 00
====> cache_return_entry_w
entry_rdwr_wunlock: ID: 83
listening for connections on 3, activity on: 5r
before select active_threads 0
select activity on 1 descriptors
new connection on 11
activity on:
listening for connections on 3, activity on: 5r 11r
before select active_threads 0
select activity on 1 descriptors
activity on: 11r
read activity on 11
ber_get_next
ber_get_next: tag 0x30 len 44 contents:
ber_dump: buf 0x1343f8, ptr 0x1343f8, end 0x134424
current len 44, contents:
02 01 01 ` ' 02 01 02 04 18 c n = a d m
i n , d c = x e r o x , d c = c
o m 80 08 p a n d a . 1 2
do_bind
do_bind: version 2 dn (cn=admin,dc=xerox,dc=com) method 128
==> ldbm_back_bind: dn: CN=ADMIN,DC=XEROX,DC=COM
dn2entry_r: dn: "CN=ADMIN,DC=XEROX,DC=COM"
=> dn2id( "CN=ADMIN,DC=XEROX,DC=COM" )
=> ldbm_cache_open( "/usr/ldapdata/dn2id.dbb", 7, 600 )
<= ldbm_cache_open (cache 0)
<= dn2id NOID
dn2entry_r: dn: "DC=XEROX,DC=COM"
=> dn2id( "DC=XEROX,DC=COM" )
====> cache_find_entry_dn2id: found dn: DC=XEROX,DC=COM
<= dn2id 78 (in cache)
=> id2entry_r( 78 )
====> cache_find_entry_dn2id: found id: 78 rw: 0
entry_rdwr_rtrylock: ID: 78
<= id2entry_r 0xa4640 (cache)
====> cache_return_entry_r
entry_rdwr_runlock: ID: 78
do_bind: bound "cn=admin,dc=xerox,dc=com" to "cn=admin, dc=xerox, dc=com"
send_ldap_result 0::
ber_flush: 14 bytes to sd 11
0 0c 02 01 01 a 07 0a 01 00 04 00 04 00
listening for connections on 3, activity on: 5r 11r
before select active_threads 0
select activity on 1 descriptors
activity on: 11r
read activity on 11
ber_get_next
ber_get_next: tag 0x30 len 64 contents:
ber_dump: buf 0x1343f8, ptr 0x1343f8, end 0x134438
current len 64, contents:
02 01 02 J ; c n = t e s t c i t i
z e n 0 0 0 0 8 p , o u = c i t
i z e n s , d c = s i f s o l a
, d c = x e r o x , d c = c o m
(end)
do_delete
do_delete: dn (cn=testcitizen00008p,ou=citizens,dc=sifsola,dc=xerox,dc=com)
==> ldbm_back_delete: CN=TESTCITIZEN00008P,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM
dn2entry_w: dn: "CN=TESTCITIZEN00008P,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM"
=> dn2id( "CN=TESTCITIZEN00008P,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM" )
====> cache_find_entry_dn2id: found dn: CN=TESTCITIZEN00008P,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM
<= dn2id 83 (in cache)
=> id2entry_w( 83 )
====> cache_find_entry_dn2id: found id: 83 rw: 1
entry_rdwr_wtrylock: ID: 83
<= id2entry_w 0x1342e8 (cache)
=> has_children( 83 )
=> ldbm_cache_open( "/usr/ldapdata/id2children.dbb", 7, 600 )
<= ldbm_cache_open (cache 2)
<= has_children( 83 ): yes
<=- ldbm_back_delete: non leaf CN=TESTCITIZEN00008P,OU=CITIZENS,DC=SIFSOLA,DC=XEROX,DC=COM
send_ldap_result 66::
ber_flush: 14 bytes to sd 11
0 0c 02 01 02 k 07 0a 01 B 04 00 04 00
====> cache_return_entry_w
entry_rdwr_wunlock: ID: 83
listening for connections on 3, activity on: 5r 11r
before select active_threads 0
select activity on 1 descriptors
activity on: 11r
read activity on 11
ber_get_next
ber_get_next: tag 0x30 len 5 contents:
ber_dump: buf 0x134230, ptr 0x134230, end 0x134235
current len 5, contents:
02 01 03 B 00
do_unbind
listening for connections on 3, activity on: 5r
before select active_threads 0
select failed errno 4 (Interrupted system call)
slapd shutting down - waiting for 0 threads to terminate
slapd shutting down - waiting for backends to close down
ldbm backend saving nextid
ldbm backend syncing
ldbm flushing db (/usr/ldapdata/dn2id.dbb)
ldbm flushing db (/usr/ldapdata/id2entry.dbb)
ldbm flushing db (/usr/ldapdata/id2children.dbb)
ldbm flushing db (/usr/ldapdata/objectclass.dbb)
ldbm backend done syncing
slapd stopping