(ITS#6891) pcache crashes after 2.4.25 upgrade; complains of unclean shutdowns and missing DB_CONFIGs after every restart
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
-
tgates81＠gmail.com