Re: (ITS#6021) slapo-pcache/back-ldap slapd crashes

Hi there, I've been collecting a bit more information on these crashes...

Since we started running 2.4.15:

26 core files, of these, 15 have crashed in memory.c:152

It looks like the majority of these were removing stale entries from the cache when slapd crashed, which wasn't the case with the original ticket I submitted. Also, the last thing logged by slapd in quite a few of these cases was along this lines of ...

Mar 30 20:50:16 albany slapd[14239]: DELETING ENTRY TEMPLATE=db78c810-0c2a-49de-96af-f5796bbe8ca3 Mar 30 20:50:17 albany last message repeated 14 times

... I don't know whether this is useful?

Here's the details of the latest crash, slapd log and backtrace:

Mar 30 20:50:16 albany slapd[14239]: Lock CR index = 0x83a5140 Mar 30 20:50:16 albany slapd[14239]: TEMPLATE 0x83a5140 QUERIES-- 0 Mar 30 20:50:16 albany slapd[14239]: Unlock CR index = 0x83a5140 Mar 30 20:50:16 albany slapd[14239]: DELETING ENTRY TEMPLATE=e7ccb20c-d263-4d6c-ba23-62afe55f0158 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, SIZE=1 Mar 30 20:50:16 albany slapd[14239]: STORED QUERIES = 30 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, CACHE =22 entries Mar 30 20:50:16 albany slapd[14239]: Lock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: TEMPLATE 0x83a4e90 QUERIES-- 15 Mar 30 20:50:16 albany slapd[14239]: Unlock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, SIZE=0 Mar 30 20:50:16 albany slapd[14239]: STORED QUERIES = 29 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, CACHE =22 entries Mar 30 20:50:16 albany slapd[14239]: Lock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: TEMPLATE 0x83a4e90 QUERIES-- 14 Mar 30 20:50:16 albany slapd[14239]: Unlock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, SIZE=0 Mar 30 20:50:16 albany slapd[14239]: STORED QUERIES = 28 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, CACHE =22 entries Mar 30 20:50:16 albany slapd[14239]: Lock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: TEMPLATE 0x83a4e90 QUERIES-- 13 Mar 30 20:50:16 albany slapd[14239]: Unlock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, SIZE=0 Mar 30 20:50:16 albany slapd[14239]: STORED QUERIES = 27 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, CACHE =22 entries Mar 30 20:50:16 albany slapd[14239]: Lock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: TEMPLATE 0x83a4e90 QUERIES-- 12 Mar 30 20:50:16 albany slapd[14239]: Unlock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, SIZE=0 Mar 30 20:50:16 albany slapd[14239]: STORED QUERIES = 26 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, CACHE =22 entries Mar 30 20:50:16 albany slapd[14239]: Lock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: TEMPLATE 0x83a4e90 QUERIES-- 11 Mar 30 20:50:16 albany slapd[14239]: Unlock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, SIZE=0 Mar 30 20:50:16 albany slapd[14239]: STORED QUERIES = 25 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, CACHE =22 entries Mar 30 20:50:16 albany slapd[14239]: Lock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: TEMPLATE 0x83a4e90 QUERIES-- 10 Mar 30 20:50:16 albany slapd[14239]: Unlock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, SIZE=0 Mar 30 20:50:16 albany slapd[14239]: STORED QUERIES = 24 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, CACHE =22 entries Mar 30 20:50:16 albany slapd[14239]: Lock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: TEMPLATE 0x83a4e90 QUERIES-- 9 Mar 30 20:50:16 albany slapd[14239]: Unlock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, SIZE=0 Mar 30 20:50:16 albany slapd[14239]: STORED QUERIES = 23 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, CACHE =22 entries Mar 30 20:50:16 albany slapd[14239]: Lock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: TEMPLATE 0x83a4e90 QUERIES-- 8 Mar 30 20:50:16 albany slapd[14239]: Unlock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, SIZE=0 Mar 30 20:50:16 albany slapd[14239]: STORED QUERIES = 22 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, CACHE =22 entries Mar 30 20:50:16 albany slapd[14239]: Lock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: TEMPLATE 0x83a4e90 QUERIES-- 7 Mar 30 20:50:16 albany slapd[14239]: Unlock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, SIZE=0 Mar 30 20:50:16 albany slapd[14239]: STORED QUERIES = 21 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, CACHE =22 entries Mar 30 20:50:16 albany slapd[14239]: Lock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: TEMPLATE 0x83a4e90 QUERIES-- 6 Mar 30 20:50:16 albany slapd[14239]: Unlock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, SIZE=0 Mar 30 20:50:16 albany slapd[14239]: STORED QUERIES = 20 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, CACHE =22 entries Mar 30 20:50:16 albany slapd[14239]: Lock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: TEMPLATE 0x83a4e90 QUERIES-- 5 Mar 30 20:50:16 albany slapd[14239]: Unlock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, SIZE=0 Mar 30 20:50:16 albany slapd[14239]: STORED QUERIES = 19 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, CACHE =22 entries Mar 30 20:50:16 albany slapd[14239]: Lock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: TEMPLATE 0x83a4e90 QUERIES-- 4 Mar 30 20:50:16 albany slapd[14239]: Unlock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, SIZE=0 Mar 30 20:50:16 albany slapd[14239]: STORED QUERIES = 18 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, CACHE =22 entries Mar 30 20:50:16 albany slapd[14239]: Lock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: TEMPLATE 0x83a4e90 QUERIES-- 3 Mar 30 20:50:16 albany slapd[14239]: Unlock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, SIZE=0 Mar 30 20:50:16 albany slapd[14239]: STORED QUERIES = 17 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, CACHE =22 entries Mar 30 20:50:16 albany slapd[14239]: Lock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: TEMPLATE 0x83a4e90 QUERIES-- 2 Mar 30 20:50:16 albany slapd[14239]: Unlock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, SIZE=0 Mar 30 20:50:16 albany slapd[14239]: STORED QUERIES = 16 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, CACHE =22 entries Mar 30 20:50:16 albany slapd[14239]: Lock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: TEMPLATE 0x83a4e90 QUERIES-- 1 Mar 30 20:50:16 albany slapd[14239]: Unlock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, SIZE=0 Mar 30 20:50:16 albany slapd[14239]: STORED QUERIES = 15 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, CACHE =22 entries Mar 30 20:50:16 albany slapd[14239]: Lock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: TEMPLATE 0x83a4e90 QUERIES-- 0 Mar 30 20:50:16 albany slapd[14239]: Unlock CR index = 0x83a4e90 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, SIZE=0 Mar 30 20:50:16 albany slapd[14239]: STORED QUERIES = 14 Mar 30 20:50:16 albany slapd[14239]: STALE QUERY REMOVED, CACHE =22 entries Mar 30 20:50:16 albany slapd[14239]: Lock CR index = 0x83a4e28 Mar 30 20:50:16 albany slapd[14239]: TEMPLATE 0x83a4e28 QUERIES-- 0 Mar 30 20:50:16 albany slapd[14239]: Unlock CR index = 0x83a4e28 Mar 30 20:50:16 albany slapd[14239]: DELETING ENTRY TEMPLATE=db78c810-0c2a-49de-96af-f5796bbe8ca3 Mar 30 20:50:17 albany last message repeated 14 times

Program terminated with signal 6, Aborted. #0 0x00185402 in __kernel_vsyscall () (gdb) bt #0 0x00185402 in __kernel_vsyscall () #1 0x00476d20 in raise () from /lib/libc.so.6 #2 0x00478631 in abort () from /lib/libc.so.6 #3 0x004aee6b in __libc_message () from /lib/libc.so.6 #4 0x004b6b16 in _int_free () from /lib/libc.so.6 #5 0x004ba070 in free () from /lib/libc.so.6 #6 0x081d5746 in ber_memfree_x (p=0x841e688, ctx=0x0) at memory.c:152 #7 0x081d630c in ber_bvarray_free_x (a=0x843af58, ctx=0x0) at memory.c:731 #8 0x081d6343 in ber_bvarray_free (a=0x843af58) at memory.c:741 #9 0x0807979c in attr_clean (a=0xb62934ec) at attr.c:146 #10 0x0807983b in attrs_free (a=0xb62934ec) at attr.c:196 #11 0x0807c059 in entry_clean (e=0xb6727584) at entry.c:504 #12 0x0807c080 in entry_free (e=0xb6727584) at entry.c:514 #13 0x08140030 in bdb_entry_return (e=0xb6727584) at id2entry.c:229 #14 0x08134c0c in bdb_cache_delete_cleanup (cache=0x838956c, ei=0xb332a060) at cache.c:1316 #15 0x0813a824 in bdb_delete (op=0xb32fed5c, rs=0xb32febec) at delete.c:575 #16 0x08177be1 in remove_query_data (op=0xb32fed5c, rs=0xb32fecf8, query_uuid=0x83ff288) at pcache.c:1460 #17 0x0817af8f in consistency_check (ctx=0xb32ff1d0, arg=0x83f57e8) at pcache.c:2611 #18 0x0819ecad in ldap_int_thread_pool_wrapper (xpool=0x8366f90) at tpool.c:663 #19 0x005c746b in start_thread () from /lib/libpthread.so.0 #20 0x0051edbe in clone () from /lib/libc.so.6 (gdb)

Also, I'll include details of another type of crash that I've seen 3 times since running 2.4.15 in the lab, at the risk of overloading information into this ticket. I'm including it here as the slapd behaviour at time of crash was similar to that noted above, i.e. removing stale entries from the cache:

Mar 13 04:37:48 pemberton slapd[6767]: Lock CR index = 0x9ac9188 Mar 13 04:37:48 pemberton slapd[6767]: TEMPLATE 0x9ac9188 QUERIES-- 2 Mar 13 04:37:48 pemberton slapd[6767]: Unlock CR index = 0x9ac9188 Mar 13 04:37:48 pemberton slapd[6767]: DELETING ENTRY TEMPLATE=febcaede-1a2f-42ef-af2e-9206f0a4f678 Mar 13 04:37:48 pemberton slapd[6767]: STALE QUERY REMOVED, SIZE=1 Mar 13 04:37:48 pemberton slapd[6767]: STORED QUERIES = 32 Mar 13 04:37:48 pemberton slapd[6767]: STALE QUERY REMOVED, CACHE =19 entries Mar 13 04:37:48 pemberton slapd[6767]: Lock CR index = 0x9ac8eb0 Mar 13 04:37:48 pemberton slapd[6767]: TEMPLATE 0x9ac8eb0 QUERIES-- 15 Mar 13 04:37:48 pemberton slapd[6767]: Unlock CR index = 0x9ac8eb0 Mar 13 04:37:48 pemberton slapd[6767]: STALE QUERY REMOVED, SIZE=0 Mar 13 04:37:48 pemberton slapd[6767]: STORED QUERIES = 31 Mar 13 04:37:48 pemberton slapd[6767]: STALE QUERY REMOVED, CACHE =19 entries Mar 13 04:37:48 pemberton slapd[6767]: Lock CR index = 0x9ac8eb0 Mar 13 04:37:48 pemberton slapd[6767]: TEMPLATE 0x9ac8eb0 QUERIES-- 14 Mar 13 04:37:48 pemberton slapd[6767]: Unlock CR index = 0x9ac8eb0 Mar 13 04:37:48 pemberton slapd[6767]: STALE QUERY REMOVED, SIZE=0 Mar 13 04:37:48 pemberton slapd[6767]: STORED QUERIES = 30 Mar 13 04:37:48 pemberton slapd[6767]: STALE QUERY REMOVED, CACHE =19 entries Mar 13 04:37:48 pemberton slapd[6767]: Lock CR index = 0x9ac8eb0 Mar 13 04:37:48 pemberton slapd[6767]: TEMPLATE 0x9ac8eb0 QUERIES-- 13 Mar 13 04:37:48 pemberton slapd[6767]: Unlock CR index = 0x9ac8eb0 Mar 13 04:37:48 pemberton slapd[6767]: STALE QUERY REMOVED, SIZE=0 Mar 13 04:37:48 pemberton slapd[6767]: STORED QUERIES = 29 Mar 13 04:37:48 pemberton slapd[6767]: STALE QUERY REMOVED, CACHE =19 entries Mar 13 04:37:48 pemberton slapd[6767]: Lock CR index = 0x9ac8eb0 Mar 13 04:37:48 pemberton slapd[6767]: TEMPLATE 0x9ac8eb0 QUERIES-- 12 Mar 13 04:37:48 pemberton slapd[6767]: Unlock CR index = 0x9ac8eb0 Mar 13 04:37:48 pemberton slapd[6767]: STALE QUERY REMOVED, SIZE=0 Mar 13 04:37:48 pemberton slapd[6767]: STORED QUERIES = 28 Mar 13 04:37:48 pemberton slapd[6767]: STALE QUERY REMOVED, CACHE =19 entries Mar 13 04:37:48 pemberton slapd[6767]: Lock CR index = 0x9ac8eb0 Mar 13 04:37:48 pemberton slapd[6767]: TEMPLATE 0x9ac8eb0 QUERIES-- 11 Mar 13 04:37:48 pemberton slapd[6767]: Unlock CR index = 0x9ac8eb0 Mar 13 04:37:48 pemberton slapd[6767]: STALE QUERY REMOVED, SIZE=0 Mar 13 04:37:48 pemberton slapd[6767]: STORED QUERIES = 27 Mar 13 04:37:48 pemberton slapd[6767]: STALE QUERY REMOVED, CACHE =19 entries Mar 13 04:37:48 pemberton slapd[6767]: Lock CR index = 0x9ac8eb0 Mar 13 04:37:48 pemberton slapd[6767]: TEMPLATE 0x9ac8eb0 QUERIES-- 10 Mar 13 04:37:48 pemberton slapd[6767]: Unlock CR index = 0x9ac8eb0 Mar 13 04:37:48 pemberton slapd[6767]: STALE QUERY REMOVED, SIZE=0 Mar 13 04:37:48 pemberton slapd[6767]: STORED QUERIES = 26 Mar 13 04:37:48 pemberton slapd[6767]: STALE QUERY REMOVED, CACHE =19 entries Mar 13 04:37:48 pemberton slapd[6767]: Lock CR index = 0x9ac8e48 Mar 13 04:37:48 pemberton slapd[6767]: TEMPLATE 0x9ac8e48 QUERIES-- 1 Mar 13 04:37:48 pemberton slapd[6767]: Unlock CR index = 0x9ac8e48 Mar 13 04:37:48 pemberton slapd[6767]: DELETING ENTRY TEMPLATE=3eff8b71-4ca6-4918-b760-c32023dbe215 Mar 13 04:37:48 pemberton last message repeated 12 times Mar 13 04:37:48 pemberton slapd[6767]: REMOVING TEMP ATTR : TEMPLATE=3eff8b71-4ca6-4918-b760-c32023dbe215 Mar 13 04:37:48 pemberton last message repeated 2 times Mar 13 04:37:48 pemberton slapd[6767]: STALE QUERY REMOVED, SIZE=13 Mar 13 04:37:48 pemberton slapd[6767]: STORED QUERIES = 25 Mar 13 04:37:48 pemberton slapd[6767]: STALE QUERY REMOVED, CACHE =6 entries Mar 13 04:37:48 pemberton slapd[6767]: Lock CR index = 0x9ac8da8

Program terminated with signal 11, Segmentation fault. #0 0x081772d2 in remove_from_template (qc=0xaef209a8, template=0x9ac8da8) at pcache.c:1297 1297 qc->prev->next = qc->next; (gdb) bt #0 0x081772d2 in remove_from_template (qc=0xaef209a8, template=0x9ac8da8) at pcache.c:1297 #1 0x0817adc8 in consistency_check (ctx=0xaeeff1d0, arg=0x9b19860) at pcache.c:2594 #2 0x0819ecad in ldap_int_thread_pool_wrapper (xpool=0x9a8afa0) at tpool.c:663 #3 0x00bb046b in start_thread () from /lib/libpthread.so.0 #4 0x00b07dbe in clone () from /lib/libc.so.6 (gdb) (gdb) p qc->prev->next Cannot access memory at address 0x54 (gdb) p qc->prev $2 = (struct cached_query_s *) 0x30 (gdb) p *qc->prev Cannot access memory at address 0x30 (gdb)

As always, if there's any more information that would be useful, let me know...

Cheers Toby