[Date Prev][Date Next]
[Chronological]
[Thread]
[Top]
(ITS#6891) pcache crashes after 2.4.25 upgrade; complains of unclean shutdowns and missing DB_CONFIGs after every restart
- To: openldap-its@OpenLDAP.org
- Subject: (ITS#6891) pcache crashes after 2.4.25 upgrade; complains of unclean shutdowns and missing DB_CONFIGs after every restart
- From: tgates81@gmail.com
- Date: Wed, 6 Apr 2011 02:42:12 GMT
- Auto-submitted: auto-generated (OpenLDAP-ITS)
Full_Name: Tyler Gates
Version: 2.4.25
OS: Ubuntu 10.04 LTS
URL: ftp://ftp.openldap.org/incoming/
Submission from: (NULL) (65.184.61.44)
After upgrading from 2.4.24 to 2.4.25 my pcache overlay using hdb
backend first failed to start with messages complaining about a
missing suffix. Now that I've added one I'm getting the following
message:
hdb_db_open: database "dc=example,dc=com": unclean shutdown detected;
attempting recovery.
hdb_db_open: warning - no DB_CONFIG file found in directory
/var/lib/ldap: (14).#012Expect poor performance for suffix
"dc=example,dc=com".
slapd starting
bdb(dc=example,dc=com): PANIC: fatal region error detected; run recovery
last message repeated 3 times
But DB_CONFIG does exist and has proper permissions and the unclean
shutdown message repeats after every restart. I've never had to add
the suffix to the pcache backend database before and the documentation
examples (http://www.openldap.org/doc/admin24/proxycache.html) never
mention it either.
PCACHE OVERLAY:
dn: olcOverlay={0}pcache
objectClass: olcOverlayConfig
objectClass: olcPcacheConfig
olcOverlay: {0}pcache
olcPcache: hdb 100000 3 1000 100
olcPcacheAttrset: 0 uid userPassword uidNumber gidNumber cn homeDirectory logi
nShell gecos description memberUid uniqueMember objectClass
olcPcacheAttrset: 1 cn automountInformation
olcPcacheAttrset: 2 cn mail
olcPcacheTemplate: "(|(cn=)(mail=)(sn=))" 2 7200 0 0 0
olcPcacheTemplate: "(&(objectClass=)(|(cn=)(cn=)(cn=)))" 1 3600 600 0 0
olcPcacheTemplate: "(&(objectClass=)(|(cn=)(cn=)))" 1 3600 600 0 0
olcPcacheTemplate: "(&(objectClass=)(|(cn=)(gidNumber=)))" 1 3600 600 0 0
olcPcacheTemplate: "(&(objectClass=)(gidNumber=))" 0 1800 0 0 0
olcPcacheTemplate: "(&(objectClass=)(uidNumber=))" 0 1800 0 0 0
olcPcacheTemplate: "(&(objectClass=)(uniqueMember=))" 0 1800 900 0 0
olcPcacheTemplate: "(&(objectClass=)(memberUid=))" 0 1800 900 0 0
olcPcacheTemplate: "(objectClass=)" 0 1800 0 0 0
olcPcacheTemplate: "(&(objectClass=))" 0 1800 0 0 0
olcPcacheTemplate: "(&(objectClass=)(cn=))" 0 1800 0 0 0
olcPcacheTemplate: "(&(objectClass=)(uid=))" 0 1800 0 0 0
olcPcacheTemplate: "(&(objectClass=)(|(memberUid=)(uniqueMember=)))" 0 1800 0
0 0
olcPcachePosition: tail
olcPcacheMaxQueries: 10000
olcPcachePersist: FALSE
olcPcacheValidate: FALSE
olcPcacheOffline: FALSE
HDB backend:
dn: olcDatabase={0}hdb
objectClass: olcHdbConfig
objectClass: olcPcacheDatabase
olcDatabase: {0}hdb
olcDbDirectory: /var/lib/ldap
olcDbCacheSize: 1000
olcDbNoSync: FALSE
olcDbDirtyRead: FALSE
olcDbIDLcacheSize: 3000
olcDbLinearIndex: FALSE
olcDbMode: 0600
olcDbSearchStack: 16
olcDbShmKey: 0
olcDbCacheFree: 1
olcDbDNcacheSize: 0
createTimestamp: 20110225174535Z
olcDbConfig: {0}set_cachesize 0 10485760 1
olcDbConfig: {1}set_lg_regionmax 262144
olcDbConfig: {2}set_lg_bsize 2097152
olcDbConfig: {3}set_flags DB_LOG_AUTOREMOVE
olcDbConfig: {4}set_lg_max 10485760
olcDbIndex: objectClass eq
olcDbIndex: cn eq,subinitial
olcDbIndex: uid eq,subinitial
olcDbIndex: uidNumber eq
olcDbIndex: gidNumber eq
olcDbIndex: userPassword eq
olcDbIndex: description eq
olcDbIndex: loginShell eq
olcDbIndex: homeDirectory eq
olcDbIndex: memberUid eq
olcDbIndex: gecos eq
olcDbIndex: automountInformation eq
olcDbIndex: uniqueMember eq
olcDbIndex: mail eq,subinitial
olcDbIndex: sn eq,subinitial
olcDbIndex: givenName eq,subinitial
olcDbIndex: member eq
olcDbIndex: nisMapName eq
olcDbIndex: pcacheQueryID eq
olcSuffix: dc=example,dc=com
slapd doesn't actually 'crash' as in stops running but querying is rendered
useless. Here's the output from gdb:
>>> slap_listener(ldapi:///)
daemon: listen=9, new connection on 12
daemon: added 12r (active) listener=(nil)
conn=1000 fd=12 ACCEPT from PATH=/var/run/slapd/ldapi
(PATH=/var/run/slapd/ldapi)
daemon: activity on 1 descriptor
daemon: activity on:
daemon: epoll: listen=9 active_threads=1 tvp=zero
daemon: activity on 1 descriptor
daemon: activity on: 12r
daemon: read active on 12
daemon: epoll: listen=9 active_threads=1 tvp=zero
connection_get(12)
connection_get(12): got connid=1000
connection_read(12): checking for input on id=1000
ber_get_next
ldap_read: want=8, got=8
0000: 30 0c 02 01 01 60 07 02 0....`..
ldap_read: want=6, got=6
0000: 01 03 04 00 80 00 ......
ber_get_next: tag 0x30 len 12 contents:
ber_dump: buf=0xb891a5a0 ptr=0xb891a5a0 end=0xb891a5ac len=12
0000: 02 01 01 60 07 02 01 03 04 00 80 00 ...`........
op tag 0x60, time 1302056893
ber_get_next
ldap_read: want=8 error=Resource temporarily unavailable
conn=1000 op=0 do_bind
ber_scanf fmt ({imt) ber:
ber_dump: buf=0xb891a5a0 ptr=0xb891a5a3 end=0xb891a5ac len=9
0000: 60 07 02 01 03 04 00 80 00 `........
ber_scanf fmt (m}) ber:
ber_dump: buf=0xb891a5a0 ptr=0xb891a5aa end=0xb891a5ac len=2
0000: 00 00 ..
>>> dnPrettyNormal: <>
daemon: activity on 1 descriptor
<<< dnPrettyNormal: <>, <>
conn=1000 op=0 BIND dn="" method=128
do_bind: version=3 dn="" method=128
send_ldap_result: conn=1000 op=0 p=3
send_ldap_result: err=0 matched="" text=""
send_ldap_response: msgid=1 tag=97 err=0
ber_flush2: 14 bytes to sd 12
0000: 30 0c 02 01 01 61 07 0a 01 00 04 00 04 00 0....a........
ldap_write: want=14, written=14
0000: 30 0c 02 01 01 61 07 0a 01 00 04 00 04 00 0....a........
conn=1000 op=0 RESULT tag=97 err=0 text=
do_bind: v3 anonymous bind
daemon: activity on:
daemon: epoll: listen=9 active_threads=1 tvp=zero
daemon: activity on 1 descriptor
daemon: activity on: 12r
daemon: read active on 12
daemon: epoll: listen=9 active_threads=1 tvp=zero
connection_get(12)
connection_get(12): got connid=1000
connection_read(12): checking for input on id=1000
ber_get_next
ldap_read: want=8, got=8
0000: 30 44 02 01 02 63 3f 04 0D...c?.
ldap_read: want=62, got=62
0000: 16 64 63 3d 63 61 73 74 6c 65 62 72 61 6e 63 68 .dc=castlebranch
0010: 2c 64 63 3d 63 6f 6d 0a 01 02 0a 01 03 02 01 00 ,dc=com.........
0020: 02 01 00 01 01 00 a0 10 a3 0e 04 03 75 69 64 04 ............uid.
0030: 07 74 6a 67 61 74 65 73 30 04 04 02 64 6e .tjgates0...dn
ber_get_next: tag 0x30 len 68 contents:
ber_dump: buf=0xb891a570 ptr=0xb891a570 end=0xb891a5b4 len=68
0000: 02 01 02 63 3f 04 16 64 63 3d 63 61 73 74 6c 65 ...c?..dc=castle
0010: 62 72 61 6e 63 68 2c 64 63 3d 63 6f 6d 0a 01 02 branch,dc=com...
0020: 0a 01 03 02 01 00 02 01 00 01 01 00 a0 10 a3 0e ................
0030: 04 03 75 69 64 04 07 74 6a 67 61 74 65 73 30 04 ..uid..tjgates0.
0040: 04 02 64 6e ..dn
op tag 0x63, time 1302056893
ber_get_next
ldap_read: want=8 error=Resource temporarily unavailable
conn=1000 op=1 do_search
ber_scanf fmt ({miiiib) ber:
ber_dump: buf=0xb891a570 ptr=0xb891a573 end=0xb891a5b4 len=65
0000: 63 3f 04 16 64 63 3d 63 61 73 74 6c 65 62 72 61 c?..dc=castlebra
0010: 6e 63 68 2c 64 63 3d 63 6f 6d 0a 01 02 0a 01 03 nch,dc=com......
0020: 02 01 00 02 01 00 01 01 00 a0 10 a3 0e 04 03 75 ...............u
0030: 69 64 04 07 74 6a 67 61 74 65 73 30 04 04 02 64 id..tjgates0...d
0040: 6e n
>>> dnPrettyNormal: <dc=castlebranch,dc=com>
=> ldap_bv2dn(dc=castlebranch,dc=com,0)
<= ldap_bv2dn(dc=castlebranch,dc=com)=0
=> ldap_dn2bv(272)
<= ldap_dn2bv(dc=castlebranch,dc=com)=0
=> ldap_dn2bv(272)
<= ldap_dn2bv(dc=castlebranch,dc=com)=0
<<< dnPrettyNormal: <dc=castlebranch,dc=com>, <dc=castlebranch,dc=com>
SRCH "dc=castlebranch,dc=com" 2 3 0 0 0
begin get_filter
AND
begin get_filter_list
daemon: activity on 1 descriptor
begin get_filter
EQUALITY
ber_scanf fmt ({mm}) ber:
ber_dump: buf=0xb891a570 ptr=0xb891a59e end=0xb891a5b4 len=22
0000: a3 0e 04 03 75 69 64 04 07 74 6a 67 61 74 65 73 ....uid..tjgates
0010: 30 04 04 02 64 6e 0...dn
end get_filter 0
end get_filter_list
end get_filter 0
filter: (&(uid=tjgates))
ber_scanf fmt ({M}}) ber:
ber_dump: buf=0xb891a570 ptr=0xb891a5ae end=0xb891a5b4 len=6
0000: 00 04 04 02 64 6e ....dn
attrs: dn
conn=1000 op=1 SRCH base="dc=castlebranch,dc=com" scope=2 deref=3
filter="(&(uid=tjgates))"
conn=1000 op=1 SRCH attr=dn
==> limits_get: conn=1000 op=1 self="[anonymous]" this="dc=castlebranch,dc=com"
=> hdb_search
bdb(dc=castlebranch,dc=com): PANIC: fatal region error detected; run recovery
daemon: activity on:
daemon: epoll: listen=9 active_threads=1 tvp=zero
bdb(dc=castlebranch,dc=com): PANIC: fatal region error detected; run recovery
bdb(dc=castlebranch,dc=com): PANIC: fatal region error detected; run recovery
bdb(dc=castlebranch,dc=com): PANIC: fatal region error detected; run recovery
send_ldap_result: conn=1000 op=1 p=3
send_ldap_result: err=80 matched="" text="internal error"
send_ldap_response: msgid=2 tag=101 err=80
ber_flush2: 28 bytes to sd 12
0000: 30 1a 02 01 02 65 15 0a 01 50 04 00 04 0e 69 6e 0....e...P....in
0010: 74 65 72 6e 61 6c 20 65 72 72 6f 72 ternal error
ldap_write: want=28, written=28
0000: 30 1a 02 01 02 65 15 0a 01 50 04 00 04 0e 69 6e 0....e...P....in
0010: 74 65 72 6e 61 6c 20 65 72 72 6f 72 ternal error
conn=1000 op=1 SEARCH RESULT tag=101 err=80 nentries=0 text=internal error
daemon: activity on 1 descriptor
daemon: activity on: 12r
daemon: read active on 12
daemon: epoll: listen=9 active_threads=1 tvp=zero
connection_get(12)
connection_get(12): got connid=1000
connection_read(12): checking for input on id=1000
ber_get_next
ldap_read: want=8, got=7
0000: 30 05 02 01 03 42 00 0....B.
ber_get_next: tag 0x30 len 5 contents:
ber_dump: buf=0xb88fc8f8 ptr=0xb88fc8f8 end=0xb88fc8fd len=5
0000: 02 01 03 42 00 ...B.
op tag 0x42, time 1302056893
ber_get_next
ldap_read: want=8 error=Resource temporarily unavailable
conn=1000 op=2 do_unbind
conn=1000 op=2 UNBIND
connection_closing: readying conn=1000 sd=12 for close
connection_resched: attempting closing conn=1000 sd=12
connection_close: conn=1000 sd=12
=>ldap_back_conn_destroy: fetching conn 1000
daemon: removing 12
conn=1000 fd=12 closed
daemon: activity on 1 descriptor
daemon: activity on:
daemon: epoll: listen=9 active_threads=0 tvp=NULL
daemon: activity on 1 descriptor
daemon: activity on:
slap_listener_activate(9):
daemon: epoll: listen=9 busy
>>> slap_listener(ldapi:///)
daemon: listen=9, new connection on 12
daemon: added 12r (active) listener=(nil)
conn=1001 fd=12 ACCEPT from PATH=/var/run/slapd/ldapi
(PATH=/var/run/slapd/ldapi)
daemon: activity on 1 descriptor
daemon: activity on:
daemon: epoll: listen=9 active_threads=1 tvp=zero
daemon: activity on 1 descriptor
daemon: activity on: 12r
daemon: read active on 12
daemon: epoll: listen=9 active_threads=1 tvp=zero
connection_get(12)
connection_get(12): got connid=1001
connection_read(12): checking for input on id=1001
ber_get_next
ldap_read: want=8, got=8
0000: 30 0c 02 01 01 60 07 02 0....`..
ldap_read: want=6, got=6
0000: 01 03 04 00 80 00 ......
ber_get_next: tag 0x30 len 12 contents:
ber_dump: buf=0xb891acc8 ptr=0xb891acc8 end=0xb891acd4 len=12
0000: 02 01 01 60 07 02 01 03 04 00 80 00 ...`........
op tag 0x60, time 1302056901
ber_get_next
ldap_read: want=8 error=Resource temporarily unavailable
conn=1001 op=0 do_bind
ber_scanf fmt ({imt) ber:
ber_dump: buf=0xb891acc8 ptr=0xb891accb end=0xb891acd4 len=9
0000: 60 07 02 01 03 04 00 80 00 `........
ber_scanf fmt (m}) ber:
ber_dump: buf=0xb891acc8 ptr=0xb891acd2 end=0xb891acd4 len=2
0000: 00 00 ..
>>> dnPrettyNormal: <>
daemon: activity on 1 descriptor
<<< dnPrettyNormal: <>, <>
conn=1001 op=0 BIND dn="" method=128
do_bind: version=3 dn="" method=128
send_ldap_result: conn=1001 op=0 p=3
send_ldap_result: err=0 matched="" text=""
send_ldap_response: msgid=1 tag=97 err=0
ber_flush2: 14 bytes to sd 12
0000: 30 0c 02 01 01 61 07 0a 01 00 04 00 04 00 0....a........
ldap_write: want=14, written=14
0000: 30 0c 02 01 01 61 07 0a 01 00 04 00 04 00 0....a........
conn=1001 op=0 RESULT tag=97 err=0 text=
do_bind: v3 anonymous bind
daemon: activity on:
daemon: epoll: listen=9 active_threads=1 tvp=zero
daemon: activity on 1 descriptor
daemon: activity on: 12r
daemon: read active on 12
daemon: epoll: listen=9 active_threads=1 tvp=zero
connection_get(12)
connection_get(12): got connid=1001
connection_read(12): checking for input on id=1001
ber_get_next
ldap_read: want=8, got=8
0000: 30 44 02 01 02 63 3f 04 0D...c?.
ldap_read: want=62, got=62
0000: 16 64 63 3d 63 61 73 74 6c 65 62 72 61 6e 63 68 .dc=castlebranch
0010: 2c 64 63 3d 63 6f 6d 0a 01 02 0a 01 03 02 01 00 ,dc=com.........
0020: 02 01 00 01 01 00 a0 10 a3 0e 04 03 75 69 64 04 ............uid.
0030: 07 74 6a 67 61 74 65 73 30 04 04 02 64 6e .tjgates0...dn
ber_get_next: tag 0x30 len 68 contents:
ber_dump: buf=0xb891a570 ptr=0xb891a570 end=0xb891a5b4 len=68
0000: 02 01 02 63 3f 04 16 64 63 3d 63 61 73 74 6c 65 ...c?..dc=castle
0010: 62 72 61 6e 63 68 2c 64 63 3d 63 6f 6d 0a 01 02 branch,dc=com...
0020: 0a 01 03 02 01 00 02 01 00 01 01 00 a0 10 a3 0e ................
0030: 04 03 75 69 64 04 07 74 6a 67 61 74 65 73 30 04 ..uid..tjgates0.
0040: 04 02 64 6e ..dn
op tag 0x63, time 1302056901
ber_get_next
ldap_read: want=8 error=Resource temporarily unavailable
conn=1001 op=1 do_search
ber_scanf fmt ({miiiib) ber:
ber_dump: buf=0xb891a570 ptr=0xb891a573 end=0xb891a5b4 len=65
0000: 63 3f 04 16 64 63 3d 63 61 73 74 6c 65 62 72 61 c?..dc=castlebra
0010: 6e 63 68 2c 64 63 3d 63 6f 6d 0a 01 02 0a 01 03 nch,dc=com......
0020: 02 01 00 02 01 00 01 01 00 a0 10 a3 0e 04 03 75 ...............u
0030: 69 64 04 07 74 6a 67 61 74 65 73 30 04 04 02 64 id..tjgates0...d
0040: 6e n
>>> dnPrettyNormal: <dc=castlebranch,dc=com>
daemon: activity on 1 descriptor
=> ldap_bv2dn(dc=castlebranch,dc=com,0)
<= ldap_bv2dn(dc=castlebranch,dc=com)=0
=> ldap_dn2bv(272)
<= ldap_dn2bv(dc=castlebranch,dc=com)=0
=> ldap_dn2bv(272)
<= ldap_dn2bv(dc=castlebranch,dc=com)=0
<<< dnPrettyNormal: <dc=castlebranch,dc=com>, <dc=castlebranch,dc=com>
SRCH "dc=castlebranch,dc=com" 2 3 0 0 0
begin get_filter
AND
begin get_filter_list
begin get_filter
EQUALITY
ber_scanf fmt ({mm}) ber:
ber_dump: buf=0xb891a570 ptr=0xb891a59e end=0xb891a5b4 len=22
0000: a3 0e 04 03 75 69 64 04 07 74 6a 67 61 74 65 73 ....uid..tjgates
0010: 30 04 04 02 64 6e 0...dn
end get_filter 0
end get_filter_list
end get_filter 0
filter: (&(uid=tjgates))
ber_scanf fmt ({M}}) ber:
ber_dump: buf=0xb891a570 ptr=0xb891a5ae end=0xb891a5b4 len=6
0000: 00 04 04 02 64 6e ....dn
attrs: dn
conn=1001 op=1 SRCH base="dc=castlebranch,dc=com" scope=2 deref=3
filter="(&(uid=tjgates))"
conn=1001 op=1 SRCH attr=dn
==> limits_get: conn=1001 op=1 self="[anonymous]" this="dc=castlebranch,dc=com"
=> hdb_search
bdb(dc=castlebranch,dc=com): PANIC: fatal region error detected; run recovery
daemon: activity on:
daemon: epoll: listen=9 active_threads=1 tvp=zero
bdb(dc=castlebranch,dc=com): PANIC: fatal region error detected; run recovery
bdb(dc=castlebranch,dc=com): PANIC: fatal region error detected; run recovery
bdb(dc=castlebranch,dc=com): PANIC: fatal region error detected; run recovery
send_ldap_result: conn=1001 op=1 p=3
send_ldap_result: err=80 matched="" text="internal error"
send_ldap_response: msgid=2 tag=101 err=80
ber_flush2: 28 bytes to sd 12
0000: 30 1a 02 01 02 65 15 0a 01 50 04 00 04 0e 69 6e 0....e...P....in
0010: 74 65 72 6e 61 6c 20 65 72 72 6f 72 ternal error
ldap_write: want=28, written=28
0000: 30 1a 02 01 02 65 15 0a 01 50 04 00 04 0e 69 6e 0....e...P....in
0010: 74 65 72 6e 61 6c 20 65 72 72 6f 72 ternal error
conn=1001 op=1 SEARCH RESULT tag=101 err=80 nentries=0 text=internal error
daemon: activity on 1 descriptor
daemon: activity on: 12r
daemon: read active on 12
daemon: epoll: listen=9 active_threads=1 tvp=zero
connection_get(12)
connection_get(12): got connid=1001
connection_read(12): checking for input on id=1001
ber_get_next
ldap_read: want=8, got=7
0000: 30 05 02 01 03 42 00 0....B.
ber_get_next: tag 0x30 len 5 contents:
ber_dump: buf=0xb88f9d00 ptr=0xb88f9d00 end=0xb88f9d05 len=5
0000: 02 01 03 42 00 ...B.
op tag 0x42, time 1302056901
ber_get_next
ldap_read: want=8 error=Resource temporarily unavailable
conn=1001 op=2 do_unbind
conn=1001 op=2 UNBIND
connection_closing: readying conn=1001 sd=12 for close
connection_resched: attempting closing conn=1001 sd=12
connection_close: conn=1001 sd=12
=>ldap_back_conn_destroy: fetching conn 1001
daemon: removing 12
conn=1001 fd=12 closed
daemon: activity on 1 descriptor
daemon: activity on:
daemon: epoll: listen=9 active_threads=0 tvp=NULL
I don't know if it is related but I have been having crashing issues with
previous versions of openldap using pcache which I have submitted and ITS(6878)
for: http://www.openldap.org/its/index.cgi/Incoming?selectid=6878;statetype=-1