On 23/06/2014 17:51, Phil Mayers wrote:
Also, don't see what happens with marker->obj - thrown away? So don't see how backtrace_print() can ever find it?
So I rigged a copy of FR to open a thread-local file descriptor and log every pairalloc & vp->da->name, as well as _pairfree & backtrace. It looks like the request might be being freed in two threads - a worker and the main. The process bombs out in the main thread as per below: Mon Jun 23 20:25:16 2014 : Info: talloc: access after free error - first free may be at src/lib/valuepair.c:194 Mon Jun 23 20:25:16 2014 : Info: Bad talloc magic value - access after free Mon Jun 23 20:25:16 2014 : Info: talloc abort: Bad talloc magic value - access after free Mon Jun 23 20:25:16 2014 : Info: CAUGHT SIGNAL: Aborted Mon Jun 23 20:25:16 2014 : Info: Backtrace of last 17 frames: /opt/fr3/lib/libfreeradius-radius.so(fr_fault+0xd2)[0x7fbbbe279729] /opt/fr3/lib/libfreeradius-radius.so(+0xaa64)[0x7fbbbe279a64] /usr/lib64/libtalloc.so.2(talloc_get_name+0x58)[0x36ad402dd8] /usr/lib64/libtalloc.so.2(_talloc_get_type_abort+0x2b)[0x36ad4057eb] /opt/fr3/lib/libfreeradius-radius.so(fr_verify_vp+0x8d)[0x7fbbbe27a1ee] /opt/fr3/lib/libfreeradius-radius.so(_fr_cursor_init+0x67)[0x7fbbbe2789df] /opt/fr3/lib/libfreeradius-radius.so(fr_verify_list+0x2e)[0x7fbbbe27a68e] /opt/fr3/lib/libfreeradius-server.so(+0x209eb)[0x7fbbbe4d19eb] /opt/fr3/lib/libfreeradius-server.so(verify_request+0xd4)[0x7fbbbe4d1ac9] /opt/fr3/sbin/radiusd[0x435799] /opt/fr3/sbin/radiusd[0x433531] /opt/fr3/lib/libfreeradius-radius.so(fr_event_run+0x142)[0x7fbbbe29c75d] /opt/fr3/lib/libfreeradius-radius.so(fr_event_loop+0x509)[0x7fbbbe29d06a] /opt/fr3/sbin/radiusd(radius_event_process+0x26)[0x43d768] /opt/fr3/sbin/radiusd(main+0xc46)[0x42a43a] /lib64/libc.so.6(__libc_start_main+0xfd)[0x379dc1ed1d] /opt/fr3/sbin/radiusd[0x40cee9] ...backtrace reveals the vp pointer was alloc'ed and free'ed in another thread a bit earlier (18695 being the linux tid, which is != pid 18675 so is not the main thread): /tmp/threadlog-18675-18695:allocing 0x7fbb64001820 User-Name ... /tmp/threadlog-18675-18695:freeing 0x7fbb64001820 /tmp/threadlog-18675-18695-/opt/fr3/lib/libfreeradius-radius.so(+0x2678b)[0x7fbbbe29578b] /tmp/threadlog-18675-18695-/usr/lib64/libtalloc.so.2[0x36ad4025a4] /tmp/threadlog-18675-18695-/opt/fr3/lib/libfreeradius-radius.so(pairfree+0x63)[0x7fbbbe295a59] /tmp/threadlog-18675-18695-/opt/fr3/sbin/radiusd[0x4354ee] /tmp/threadlog-18675-18695-/opt/fr3/sbin/radiusd[0x4358f8] /tmp/threadlog-18675-18695-/opt/fr3/sbin/radiusd[0x431073] /tmp/threadlog-18675-18695-/lib64/libpthread.so.0[0x379e4079d1] /tmp/threadlog-18675-18695-/lib64/libc.so.6(clone+0x6d)[0x379dce8b7d] ...unfortunately the backtrace for the thread that did doesn't tell me much. I can extend this instrumentation further - what would be useful to know?