talloc & threads in rlm_eap

[Arran Cudbard-Bell]

On 23 Jun 2014, at 20:29, Phil Mayers <p.mayers at imperial.ac.uk> 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 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

Backtrace for both frees and the trace for the alloc.

The original cbuff code should work now and provide you with the alloc and free BTs.

Arran Cudbard-Bell <a.cudbardb at freeradius.org>
FreeRADIUS Development Team

FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2

-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 881 bytes
Desc: Message signed with OpenPGP using GPGMail
URL: <http://lists.freeradius.org/pipermail/freeradius-devel/attachments/20140623/0548d64f/attachment.pgp>