talloc & threads in rlm_eap

[Phil Mayers]

On 23/06/2014 20:29, Phil Mayers wrote:
> 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

So with a bit of fiddling I've managed to get a trace from this which shows:

1. Allocation of "User-Name" in a thread at:

/tmp/threadlog-26294-26326:allocing 0x7f0308000b90 User-Name
/tmp/threadlog-26294-26326-libfreeradius-radius.so(pairalloc+0x178)[0x7f03329519cd]
/tmp/threadlog-26294-26326-libfreeradius-radius.so(data2vp+0xb0b)[0x7f033294b1ff]
/tmp/threadlog-26294-26326-libfreeradius-radius.so(rad_attr2vp+0x143)[0x7f033294b7ab]
/tmp/threadlog-26294-26326-libfreeradius-radius.so(rad_decode+0xa8)[0x7f033294bbd8]
/tmp/threadlog-26294-26326-src/main/listen.c:2001
/tmp/threadlog-26294-26326-src/main/process.c:1228
/tmp/threadlog-26294-26326-src/main/process.c:1475
/tmp/threadlog-26294-26326-src/main/threads.c:688

2. Subsequent freeing in the same thread:

/tmp/threadlog-26294-26326:freeing 0x7f0308000b90
/tmp/threadlog-26294-26326-libfreeradius-radius.so(+0x267c3)[0x7f03329517c3]
/tmp/threadlog-26294-26326-libtalloc.so.2[0x36ad4025a4]
/tmp/threadlog-26294-26326-libfreeradius-radius.so(pairfree+0x63)[0x7f0332951ad4]
/tmp/threadlog-26294-26326-src/main/process.c:1369
/tmp/threadlog-26294-26326-src/main/process.c:1528
/tmp/threadlog-26294-26326-src/main/threads.c:688
/tmp/threadlog-26294-26326-/lib64/libpthread.so.0[0x379e4079d1]
/tmp/threadlog-26294-26326-/lib64/libc.so.6(clone+0x6d)[0x379dce8b7d]

3. Even more subsequent double-freeing in the main thread:

Mon Jun 23 21:25:52 2014 : Info: talloc: access after free error - first 
free may be at src/lib/valuepair.c:197
Mon Jun 23 21:25:52 2014 : Info: Bad talloc magic value - access after free
Mon Jun 23 21:25:52 2014 : Info: talloc abort: Bad talloc magic value - 
access after free
Mon Jun 23 21:25:52 2014 : Info: CAUGHT SIGNAL: Aborted
Mon Jun 23 21:25:52 2014 : Info: Backtrace of last 17 frames:

/opt/fr3/lib/libfreeradius-radius.so(fr_fault+0xd2)[0x7f033293575f]
/opt/fr3/lib/libfreeradius-radius.so(+0xaa9a)[0x7f0332935a9a]
/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)[0x7f0332936224]
/opt/fr3/lib/libfreeradius-radius.so(_fr_cursor_init+0x67)[0x7f0332934a2f]
/opt/fr3/lib/libfreeradius-radius.so(fr_verify_list+0x2e)[0x7f03329366c4]
/opt/fr3/lib/libfreeradius-server.so(+0x209eb)[0x7f0332b8d9eb]
/opt/fr3/lib/libfreeradius-server.so(verify_request+0xd4)[0x7f0332b8dac9]
/opt/fr3/sbin/radiusd[0x435799]
/opt/fr3/sbin/radiusd[0x433531]
/opt/fr3/lib/libfreeradius-radius.so(fr_event_run+0x142)[0x7f03329587d9]
/opt/fr3/lib/libfreeradius-radius.so(fr_event_loop+0x509)[0x7f03329590e6]
/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]

Given that "pairfree(&request->packet->vps)" in step #2 should null out 
the pointer, I can only assume what we're seeing here is a request being 
freed in the main thread at the same time as being freed in a child 
thread? Something inside the timeout machinery?