talloc & threads in rlm_eap
I'm wondering if we're breaking the talloc() threading restrictions in rlm_eap / main/tls.c somewhere? Specifically, I think tls_new_session can be called from multiple threads at the same time, and that calls talloc with a context of "conf" i.e. the module config, which is not per-thread. The talloc docs say each thread must use a separate context (or, presumably, lock). I wonder if this is what's triggering the corruption? Ditto cbtls_new_session (though OpenSSL locking might protect that) and I think a few other places. ( rlm_eap might be due a substantial cleanup; I find it really really hard to grasp, personally. What do people think? )
On 19 Jun 2014, at 17:39, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
I'm wondering if we're breaking the talloc() threading restrictions in rlm_eap / main/tls.c somewhere?
Specifically, I think tls_new_session can be called from multiple threads at the same time, and that calls talloc with a context of "conf" i.e. the module config, which is not per-thread. The talloc docs say each thread must use a separate context (or, presumably, lock).
I wonder if this is what's triggering the corruption?
Yes, the allocations must be protected with a mutex, or that area of the code should use malloc. That may explain some of the brokenness with RADSEC too. If we keep talloc there, the mutex should be in the fr_tls_server_conf_t structure to minimise contention.
Ditto cbtls_new_session (though OpenSSL locking might protect that) and I think a few other places. rlm_eap might be due a substantial cleanup; I find it really really hard to grasp, personally. What do people think?
Yes. There was some work planned for 4.0 that would help, but I think sanitising it now for 3.1 would also be a good idea. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
Using the (bizarrely named) handler as the context for eap should work I think. Afaict it's only accessed from one thread at a time. -- Sent from my Android device with K-9 Mail. Please excuse my brevity.
On 19 Jun 2014, at 18:38, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
Using the (bizarrely named) handler as the context for eap should work I think. Afaict it's only accessed from one thread at a time.
Yes, you're right, handler allocation is already mutex protected. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 19 Jun 2014, at 19:09, Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
On 19 Jun 2014, at 18:38, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
Using the (bizarrely named) handler as the context for eap should work I think. Afaict it's only accessed from one thread at a time.
Yes, you're right, handler allocation is already mutex protected.
Ok, done. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
Hmm assuming nothing else is talloc'ed off the parent of handler that is, or freeing handler itself is racey... I'm assuming talloc lets you alloc and free below a context in one thread whilst alloc and freeing off a sibling, ancestor or descendant context in another? On 19 June 2014 18:38:15 BST, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
Using the (bizarrely named) handler as the context for eap should work I think. Afaict it's only accessed from one thread at a time. -- Sent from my Android device with K-9 Mail. Please excuse my brevity.
------------------------------------------------------------------------
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/devel.html
-- Sent from my mobile device, please excuse brevity and typos
On 20 Jun 2014, at 10:56, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
Hmm assuming nothing else is talloc'ed off the parent of handler that is, or freeing handler itself is racey...
That's now fixed too. I think. The memory associated with the handler is now freed within the destructor for the handler, which synchronises the frees using the same mutex. Hopefully that's OK. https://github.com/FreeRADIUS/freeradius-server/commit/f74b0fe85f171faf5c144... If it explodes I guess we'll need to figure out another solution.
I'm assuming talloc lets you alloc and free below a context in one thread whilst alloc and freeing off a sibling, ancestor or descendant context in another?
Looks like that's safe. There's nothing that modifies anything above the context of the chunk. /* Allocate a bit of memory as a child of an existing pointer */ static inline void *__talloc_with_prefix(const void *context, size_t size, size_t prefix_len) { struct talloc_chunk *tc = NULL; struct talloc_memlimit *limit = NULL; size_t total_len = TC_HDR_SIZE + size + prefix_len; if (unlikely(context == NULL)) { context = null_context; } if (unlikely(size >= MAX_TALLOC_SIZE)) { return NULL; } if (unlikely(total_len < TC_HDR_SIZE)) { return NULL; } if (context != NULL) { struct talloc_chunk *ptc = talloc_chunk_from_ptr(context); if (ptc->limit != NULL) { limit = ptc->limit; } tc = talloc_alloc_pool(ptc, TC_HDR_SIZE+size, prefix_len); } if (tc == NULL) { char *ptr; /* * Only do the memlimit check/update on actual allocation. */ if (!talloc_memlimit_check(limit, total_len)) { errno = ENOMEM; return NULL; } ptr = malloc(total_len); if (unlikely(ptr == NULL)) { return NULL; } tc = (struct talloc_chunk *)(ptr + prefix_len); tc->flags = TALLOC_MAGIC; tc->pool = NULL; talloc_memlimit_grow(limit, total_len); } tc->limit = limit; tc->size = size; tc->destructor = NULL; tc->child = NULL; tc->name = NULL; tc->refs = NULL; if (likely(context)) { struct talloc_chunk *parent = talloc_chunk_from_ptr(context); if (parent->child) { parent->child->parent = NULL; tc->next = parent->child; tc->next->prev = tc; } else { tc->next = NULL; } tc->parent = parent; tc->prev = NULL; parent->child = tc; } else { tc->next = tc->prev = tc->parent = NULL; } return TC_PTR_FROM_CHUNK(tc); } static inline void *__talloc(const void *context, size_t size) { return __talloc_with_prefix(context, size, 0); } Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 20 Jun 2014, at 11:17, Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
On 20 Jun 2014, at 10:56, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
Hmm assuming nothing else is talloc'ed off the parent of handler that is, or freeing handler itself is racey...
That's now fixed too. I think. The memory associated with the handler is now freed within the destructor for the handler, which synchronises the frees using the same mutex. Hopefully that's OK.
https://github.com/FreeRADIUS/freeradius-server/commit/f74b0fe85f171faf5c144...
If it explodes I guess we'll need to figure out another solution.
Confirmed lack of explodyness. I also fixed some other explicit frees of VPs which were associated with the EAP specific opaque data. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 20/06/14 13:29, Arran Cudbard-Bell wrote:
Confirmed lack of explodyness.
I also fixed some other explicit frees of VPs which were associated with the EAP specific opaque data.
I'm still able to trigger a crash with #8bd9429 and my local config :o( I think it's harder i.e. takes longer, but similar sort of things: talloc: access after free error - first free may be at src/lib/valuepair.c:171 Bad talloc magic value - access after free talloc abort: Bad talloc magic value - access after free I have a core file, I'll take a look.
On 20 Jun 2014, at 13:39, Phil Mayers <p.mayers@IMPERIAL.AC.UK> wrote:
On 20/06/14 13:29, Arran Cudbard-Bell wrote:
Confirmed lack of explodyness.
I also fixed some other explicit frees of VPs which were associated with the EAP specific opaque data.
I'm still able to trigger a crash with #8bd9429 and my local config :o(
I think it's harder i.e. takes longer, but similar sort of things:
talloc: access after free error - first free may be at src/lib/valuepair.c:171 Bad talloc magic value - access after free talloc abort: Bad talloc magic value - access after free
Could you try and get the name of the VP if it's not been trampled over. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 20/06/14 14:05, Arran Cudbard-Bell wrote:
Could you try and get the name of the VP if it's not been trampled over.
Sadly vp->da is null as is the data; I think the VP has been freed and zero'ed. I haven't triggered a crash yet with a default config so it might be somewhere else, OTOH my local config always seems to trigger a crash faster so it might be just that I didn't give it enough time. Glumness. This is why I hate threads...
Erm... Oh dear: https://lists.samba.org/archive/samba-technical/2014-June/100669.html Does this mean what I think it does? -- Sent from my mobile device, please excuse brevity and typos
On 20 Jun 2014, at 18:39, Phil Mayers <p.mayers@IMPERIAL.AC.UK> wrote:
Erm... Oh dear:
https://lists.samba.org/archive/samba-technical/2014-June/100669.html
Does this mean what I think it does?
Appears so. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 20 Jun 2014, at 18:50, Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
On 20 Jun 2014, at 18:39, Phil Mayers <p.mayers@IMPERIAL.AC.UK> wrote:
Erm... Oh dear:
https://lists.samba.org/archive/samba-technical/2014-June/100669.html
Does this mean what I think it does?
Appears so.
OK, well that explains a lot. Basically we can't parent REQUEST structs from any shared contexts, same for the handlers. That's going to make request chaining using talloc a bit more difficult, but it's not impossible, and we can still keep the nice autofree behaviour we just need to use destructors instead. The rest of the code was written to assume REQUESTS were only used by one thread at a time so should be ok. Things like rbtrees, hashes, lists, etc are all synchronised so they're fine. I'm still not entirely sure why it's not thread safe, perhaps you could ask for an explanation of what parts of the talloc structures would be munged by two threads accessing them? Looking at the code the only issues I can see would be for the artificial memory limits you can set on blocks. They really need to update their documentation. It's not at all clear what is legal/illegal. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 20 Jun 2014, at 19:00, Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
On 20 Jun 2014, at 18:50, Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
On 20 Jun 2014, at 18:39, Phil Mayers <p.mayers@IMPERIAL.AC.UK> wrote:
Erm... Oh dear:
https://lists.samba.org/archive/samba-technical/2014-June/100669.html
Does this mean what I think it does?
Appears so.
OK, well that explains a lot. Basically we can't parent REQUEST structs from any shared contexts, same for the handlers. That's going to make request chaining using talloc a bit more difficult, but it's not impossible, and we can still keep the nice autofree behaviour we just need to use destructors instead.
The rest of the code was written to assume REQUESTS were only used by one thread at a time so should be ok.
Things like rbtrees, hashes, lists, etc are all synchronised so they're fine.
Ug, but parented off things like config structures. I just checked and they seem fine though. Anyway, handlers now alloced from the NULL context. So all should be well... Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 20 Jun 2014, at 20:18, Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
On 20 Jun 2014, at 19:00, Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
On 20 Jun 2014, at 18:50, Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
On 20 Jun 2014, at 18:39, Phil Mayers <p.mayers@IMPERIAL.AC.UK> wrote:
Erm... Oh dear:
https://lists.samba.org/archive/samba-technical/2014-June/100669.html
Does this mean what I think it does?
Appears so.
OK, well that explains a lot. Basically we can't parent REQUEST structs from any shared contexts, same for the handlers. That's going to make request chaining using talloc a bit more difficult, but it's not impossible, and we can still keep the nice autofree behaviour we just need to use destructors instead.
The rest of the code was written to assume REQUESTS were only used by one thread at a time so should be ok.
Things like rbtrees, hashes, lists, etc are all synchronised so they're fine.
Ug, but parented off things like config structures. I just checked and they seem fine though.
Anyway, handlers now alloced from the NULL context. So all should be well...
Connection pools allocated from the NULL context too. REQUESTs it seems were already being allocated from the NULL ctx. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
Something's still not quite right; I can still trigger a crash with my local config, though it's much much harder. Symptoms look similar i.e. heap corruption, though I've only triggered a few so far. :o( Can't seem to trigger one with a default config, so maybe it's a module I'm using, or maybe the combo of "real" options just makes it more likely and I didn't wait long enough. Will keep poking to see if I can make it more readily reproducible.
On 21 Jun 2014, at 12:13, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
Something's still not quite right; I can still trigger a crash with my local config, though it's much much harder. Symptoms look similar i.e. heap corruption, though I've only triggered a few so far.
:o(
Can't seem to trigger one with a default config, so maybe it's a module I'm using, or maybe the combo of "real" options just makes it more likely and I didn't wait long enough.
Will keep poking to see if I can make it more readily reproducible.
Double frees aren't always due to heap corruption, sometimes it's not reparenting attributes correctly into other contexts, so they get freed when their original parent does. If you can get the circular buffer debug stuff working, then you'll be able to see where the double freed VALUE_PAIR was allocated from originally, which will be a big clue. As a first diagnostic step i'd try getting rid of calls to rlm_cache and see if that helps. It's the module most likely to experience those kind of reparenting issues. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 21 Jun 2014, at 17:20, Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
On 21 Jun 2014, at 12:13, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
Something's still not quite right; I can still trigger a crash with my local config, though it's much much harder. Symptoms look similar i.e. heap corruption, though I've only triggered a few so far.
:o(
Can't seem to trigger one with a default config, so maybe it's a module I'm using, or maybe the combo of "real" options just makes it more likely and I didn't wait long enough.
Will keep poking to see if I can make it more readily reproducible.
Double frees aren't always due to heap corruption, sometimes it's not reparenting attributes correctly into other contexts, so they get freed when their original parent does.
If you can get the circular buffer debug stuff working, then you'll be able to see where the double freed VALUE_PAIR was allocated from originally, which will be a big clue.
As a first diagnostic step i'd try getting rid of calls to rlm_cache and see if that helps. It's the module most likely to experience those kind of reparenting issues.
Ug, its rbtree was parented off its instance data too... just fixed that. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 21 Jun 2014, at 17:23, Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
On 21 Jun 2014, at 17:20, Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
On 21 Jun 2014, at 12:13, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
Something's still not quite right; I can still trigger a crash with my local config, though it's much much harder. Symptoms look similar i.e. heap corruption, though I've only triggered a few so far.
:o(
Can't seem to trigger one with a default config, so maybe it's a module I'm using, or maybe the combo of "real" options just makes it more likely and I didn't wait long enough.
Will keep poking to see if I can make it more readily reproducible.
Double frees aren't always due to heap corruption, sometimes it's not reparenting attributes correctly into other contexts, so they get freed when their original parent does.
If you can get the circular buffer debug stuff working, then you'll be able to see where the double freed VALUE_PAIR was allocated from originally, which will be a big clue.
As a first diagnostic step i'd try getting rid of calls to rlm_cache and see if that helps. It's the module most likely to experience those kind of reparenting issues.
Ug, its rbtree was parented off its instance data too... just fixed that.
Arg and the handler and session trees :( Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 21 Jun 2014, at 16:30, Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
On 21 Jun 2014, at 17:23, Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
On 21 Jun 2014, at 17:20, Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
On 21 Jun 2014, at 12:13, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
Something's still not quite right; I can still trigger a crash with my local config, though it's much much harder. Symptoms look similar i.e. heap corruption, though I've only triggered a few so far.
:o(
Can't seem to trigger one with a default config, so maybe it's a module I'm using, or maybe the combo of "real" options just makes it more likely and I didn't wait long enough.
Will keep poking to see if I can make it more readily reproducible.
Double frees aren't always due to heap corruption, sometimes it's not reparenting attributes correctly into other contexts, so they get freed when their original parent does.
If you can get the circular buffer debug stuff working, then you'll be able to see where the double freed VALUE_PAIR was allocated from originally, which will be a big clue.
As a first diagnostic step i'd try getting rid of calls to rlm_cache and see if that helps. It's the module most likely to experience those kind of reparenting issues.
Ug, its rbtree was parented off its instance data too... just fixed that.
Arg and the handler and session trees :(
Any better with latest v3.0.x HEAD? Just fixed all the connection pool handle allocation. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 23/06/14 16:29, Arran Cudbard-Bell wrote:
Any better with latest v3.0.x HEAD? Just fixed all the connection pool handle allocation.
Don't think so, immediate bomb-out when hammering it with EAP; just rebuilding after make distclean to be absolutely sure I'm on the latest (it would be nice if git activity updated the version reported in "-v"; seems to only be captured at ./configure time and this makes me paranoid I've not updated the binaries correctly)
On 23/06/14 16:45, Phil Mayers wrote:
On 23/06/14 16:29, Arran Cudbard-Bell wrote:
Any better with latest v3.0.x HEAD? Just fixed all the connection pool handle allocation.
Don't think so, immediate bomb-out when hammering it with EAP; just rebuilding after make distclean to be absolutely sure I'm on the latest (it would be nice if git activity updated the version reported in "-v"; seems to only be captured at ./configure time and this makes me paranoid I've not updated the binaries correctly)
Yeah same sort of thing: radiusd: FreeRADIUS Version 3.0.4 (git #9da92a8) #0 0x000000379dcac90d in __libc_waitpid (pid=<value optimized out>, stat_loc=<value optimized out>, options=<value optimized out>) at ../sysdeps/unix/sysv/linux/waitpid.c:41 #1 0x000000379dc3e909 in do_system (line=<value optimized out>) at ../sysdeps/posix/system.c:149 #2 0x000000379dc3ec40 in __libc_system (line=<value optimized out>) at ../sysdeps/posix/system.c:190 #3 0x00007fec09653837 in fr_fault (sig=6) at src/lib/debug.c:527 #4 0x00007fec09653924 in _fr_talloc_fault (reason=0x36ad408378 "Bad talloc magic value - unknown value") at src/lib/debug.c:563 #5 0x00000036ad402df1 in talloc_abort_unknown_value (ptr=<value optimized out>) at ../talloc.c:341 #6 talloc_chunk_from_ptr (ptr=<value optimized out>) at ../talloc.c:360 #7 talloc_get_name (ptr=<value optimized out>) at ../talloc.c:1153 #8 0x00000036ad402e1e in talloc_check_name (ptr=0x7febf4eef4ee, name=0x7fec096786cc "char") at ../talloc.c:1172 #9 0x00007fec096542d1 in fr_verify_vp (file=0x7fec09678470 "src/lib/cursor.c", line=45, vp=0x7feb7405f150) at src/lib/debug.c:859 #10 0x00007fec0965289f in _fr_cursor_init (cursor=0x7ffffc4f1030, node=0x7ffffc4f1010) at src/lib/cursor.c:45 #11 0x00007fec0965454e in fr_verify_list (file=0x45b735 "src/main/process.c", line=1446, expected=0x17ce390, vps=0x7feb7405f150) at src/lib/debug.c:906 #12 0x00007fec098aaa9f in verify_request (file=0x45b735 "src/main/process.c", line=1446, request=0x17ce390) at src/main/util.c:1103 #13 0x0000000000435741 in request_running (request=0x17ce390, action=5) at src/main/process.c:1446 #14 0x00000000004334d9 in request_timer (ctx=0x17ce390) at src/main/process.c:471 #15 0x00007fec096763ed in fr_event_run (el=0x136a2a0, when=0x7ffffc4f1280) at src/lib/event.c:260 #16 0x00007fec09676cfa in fr_event_loop (el=0x136a2a0) at src/lib/event.c:483 #17 0x000000000043d710 in radius_event_process () at src/main/process.c:4923 #18 0x000000000042a3ea in main (argc=7, argv=0x7ffffc4f1448) at src/main/radiusd.c:582 As before basic setup is high rate of incoming EAP with rlm_cache, rlm_sql and various policy{} blocks, PEAP/TTLS and mschap to ntlm_auth.
On 23 Jun 2014, at 16:52, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
On 23/06/14 16:45, Phil Mayers wrote:
On 23/06/14 16:29, Arran Cudbard-Bell wrote:
Any better with latest v3.0.x HEAD? Just fixed all the connection pool handle allocation.
Don't think so, immediate bomb-out when hammering it with EAP; just rebuilding after make distclean to be absolutely sure I'm on the latest (it would be nice if git activity updated the version reported in "-v"; seems to only be captured at ./configure time and this makes me paranoid I've not updated the binaries correctly)
Yeah same sort of thing:
One more time... I found another one in the cache module... Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 23/06/14 16:55, Arran Cudbard-Bell wrote:
On 23 Jun 2014, at 16:52, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
On 23/06/14 16:45, Phil Mayers wrote:
On 23/06/14 16:29, Arran Cudbard-Bell wrote:
Any better with latest v3.0.x HEAD? Just fixed all the connection pool handle allocation.
Don't think so, immediate bomb-out when hammering it with EAP; just rebuilding after make distclean to be absolutely sure I'm on the latest (it would be nice if git activity updated the version reported in "-v"; seems to only be captured at ./configure time and this makes me paranoid I've not updated the binaries correctly)
Yeah same sort of thing:
One more time... I found another one in the cache module...
Nope, sorry :o( Mon Jun 23 17:00:07 2014 : Info: Ready to process requests Mon Jun 23 17:00:09 2014 : Info: talloc: access after free error - first free may be at src/lib/valuepair.c:171 Mon Jun 23 17:00:09 2014 : Info: Bad talloc magic value - access after free Mon Jun 23 17:00:09 2014 : Info: talloc abort: Bad talloc magic value - access after free Mon Jun 23 17:00:09 2014 : Info: CAUGHT SIGNAL: Aborted Mon Jun 23 17:00:09 2014 : Info: Backtrace of last 17 frames: #0 0x000000379dcac90d in __libc_waitpid (pid=<value optimized out>, stat_loc=<value optimized out>, options=<value optimized out>) at ../sysdeps/unix/sysv/linux/waitpid.c:41 #1 0x000000379dc3e909 in do_system (line=<value optimized out>) at ../sysdeps/posix/system.c:149 #2 0x000000379dc3ec40 in __libc_system (line=<value optimized out>) at ../sysdeps/posix/system.c:190 #3 0x00007f47cb668837 in fr_fault (sig=6) at src/lib/debug.c:527 #4 0x00007f47cb668924 in _fr_talloc_fault (reason=0x36ad408348 "Bad talloc magic value - access after free") at src/lib/debug.c:563 #5 0x00000036ad402dd8 in talloc_abort_access_after_free (ptr=<value optimized out>) at ../talloc.c:336 #6 talloc_chunk_from_ptr (ptr=<value optimized out>) at ../talloc.c:357 #7 talloc_get_name (ptr=<value optimized out>) at ../talloc.c:1153 #8 0x00000036ad4057eb in _talloc_get_type_abort (ptr=0x11baeb0, name=0x7f47cb68db43 "VALUE_PAIR", location=0x7f47cb68db2f "src/lib/debug.c:819") at ../talloc.c:1206 #9 0x00007f47cb6690ae in fr_verify_vp (file=0x7f47cb68d470 "src/lib/cursor.c", line=45, vp=0x11baeb0) at src/lib/debug.c:819 #10 0x00007f47cb66789f in _fr_cursor_init (cursor=0x7fff68457540, node=0x7fff68457520) at src/lib/cursor.c:45 #11 0x00007f47cb66954e in fr_verify_list (file=0x45b735 "src/main/process.c", line=1446, expected=0x11a2490, vps=0x11baeb0) at src/lib/debug.c:906 #12 0x00007f47cb8bf9eb in verify_packet (file=0x45b735 "src/main/process.c", line=1446, request=0x11a27d0, packet=0x11a2490) at src/main/util.c:1086 #13 0x00007f47cb8bfac9 in verify_request (file=0x45b735 "src/main/process.c", line=1446, request=0x11a27d0) at src/main/util.c:1106 #14 0x0000000000435741 in request_running (request=0x11a27d0, action=5) at src/main/process.c:1446 #15 0x00000000004334d9 in request_timer (ctx=0x11a27d0) at src/main/process.c:471 #16 0x00007f47cb68b3ed in fr_event_run (el=0xbe72a0, when=0x7fff684577f0) at src/lib/event.c:260 #17 0x00007f47cb68bcfa in fr_event_loop (el=0xbe72a0) at src/lib/event.c:483 #18 0x000000000043d710 in radius_event_process () at src/main/process.c:4923 #19 0x000000000042a3ea in main (argc=7, argv=0x7fff684579b8) at src/main/radiusd.c:582
On 23 Jun 2014, at 17:02, Phil Mayers <p.mayers@IMPERIAL.AC.UK> wrote:
On 23/06/14 16:55, Arran Cudbard-Bell wrote:
On 23 Jun 2014, at 16:52, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
On 23/06/14 16:45, Phil Mayers wrote:
On 23/06/14 16:29, Arran Cudbard-Bell wrote:
Any better with latest v3.0.x HEAD? Just fixed all the connection pool handle allocation.
Don't think so, immediate bomb-out when hammering it with EAP; just rebuilding after make distclean to be absolutely sure I'm on the latest (it would be nice if git activity updated the version reported in "-v"; seems to only be captured at ./configure time and this makes me paranoid I've not updated the binaries correctly)
Yeah same sort of thing:
One more time... I found another one in the cache module...
Replace: /** Dynamically allocate a new attribute * * Allocates a new attribute and a new dictionary attr if no DA is provided. * * @param[in] ctx for allocated memory, usually a pointer to a RADIUS_PACKET * @param[in] da Specifies the dictionary attribute to build the VP from. * @return a new value pair or NULL if an error occurred. */ VALUE_PAIR *pairalloc(TALLOC_CTX *ctx, DICT_ATTR const *da) { VALUE_PAIR *vp; /* * Caller must specify a da else we don't know what the attribute type is. */ if (!da) { fr_strerror_printf("Invalid arguments"); return NULL; } vp = talloc_zero(ctx, VALUE_PAIR); if (!vp) { fr_strerror_printf("Out of memory"); return NULL; } vp->da = da; vp->op = T_OP_EQ; vp->tag = TAG_ANY; vp->type = VT_NONE; vp->length = da->flags.length; talloc_set_destructor(vp, _pairfree); return vp; } With static fr_cbuff *vp_bt; VALUE_PAIR *pairalloc(TALLOC_CTX *ctx, DICT_ATTR const *da) { VALUE_PAIR *vp; /* * Caller must specify a da else we don't know what the attribute type is. */ if (!da) { fr_strerror_printf("Invalid arguments"); return NULL; } vp = talloc_zero(ctx, VALUE_PAIR); if (!vp) { fr_strerror_printf("Out of memory"); return NULL; } vp->da = da; vp->op = T_OP_EQ; vp->tag = TAG_ANY; vp->type = VT_NONE; vp->length = da->flags.length; talloc_set_destructor(vp, _pairfree); fr_backtrace_attach(vp_bt, vp); return vp; } run with PANIC_ACTION="gdb %e %p" radiusd -f -lstdout When it crashes p the value of the vp to get the pointer address then in gdb call backtrace_print(&vp_bt, <pointer to double freed vp>) Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
fr_backtrace_attach(vp_bt, vp);
*&vp_bt
return vp; }
run with
PANIC_ACTION="gdb %e %p" radiusd -f -lstdout
When it crashes p the value of the vp to get the pointer address then in gdb
call backtrace_print(&vp_bt, <pointer to double freed vp>)
Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team
FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/devel.html
Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 23/06/14 17:48, Phil Mayers wrote:
On 23/06/14 17:13, Arran Cudbard-Bell wrote:
call backtrace_print(&vp_bt
$3 = (const VALUE_PAIR *) 0x7f07f003e780 (gdb) call backtrace_print(&vp_bt, 0x7f07f003e780) No backtrace available for 0x7f07f003e780
Doesn't fr_do_bt need to be mutex'd off the cbuff? Also, don't see what happens with marker->obj - thrown away? So don't see how backtrace_print() can ever find it?
On 23 Jun 2014, at 17:51, Phil Mayers <p.mayers@IMPERIAL.AC.UK> wrote:
On 23/06/14 17:48, Phil Mayers wrote:
On 23/06/14 17:13, Arran Cudbard-Bell wrote:
call backtrace_print(&vp_bt
$3 = (const VALUE_PAIR *) 0x7f07f003e780 (gdb) call backtrace_print(&vp_bt, 0x7f07f003e780) No backtrace available for 0x7f07f003e780
Doesn't fr_do_bt need to be mutex'd off the cbuff?
Or just alloced from the NULL ctx because it gets reparented anyway, yes.
Also, don't see what happens with marker->obj - thrown away? So don't see how backtrace_print() can ever find it?
It wouldn't *sigh*. OK lets try that again with working code and without me fat fingering almost everything. static fr_cbuff_t *vp_bt; VALUE_PAIR *pairalloc(TALLOC_CTX *ctx, DICT_ATTR const *da) { ... fr_backtrace_attach(&vp_bt, vp); return vp; } You should see lots of "Backtrace attached to VALUE_PAIR 0x<pointer addr>" messages going to stderr. (lldb) call backtrace_print(vp_bt, (VALUE_PAIR *) 0x<pointer addr>) Stacktrace for: 0x<pointer addr> 0 libfreeradius-radius.dylib 0x00000001000c5e53 fr_backtrace_do + 323 1 libfreeradius-radius.dylib 0x00000001000c5f92 fr_backtrace_attach + 258 2 libfreeradius-radius.dylib 0x00000001000eb55c pairalloc + 236 3 libfreeradius-radius.dylib 0x00000001000e125e data2vp + 3214 4 libfreeradius-radius.dylib 0x00000001000e2af2 rad_attr2vp + 370 5 libfreeradius-radius.dylib 0x00000001000e3280 rad_decode + 176 6 radiusd 0x000000010000d0c0 client_socket_decode + 112 7 radiusd 0x0000000100034dae request_pre_handler + 254 8 radiusd 0x000000010003024f request_running + 175 9 radiusd 0x0000000100030168 request_queue_or_run + 392 10 radiusd 0x000000010002f2ba request_receive + 2106 11 radiusd 0x000000010000daa5 auth_socket_recv + 1173 12 radiusd 0x0000000100032df5 event_socket_handler + 325 13 libfreeradius-radius.dylib 0x00000001000f4927 fr_event_loop + 1271 14 radiusd 0x0000000100032621 radius_event_process + 49 15 radiusd 0x0000000100023b91 main + 3601 16 libdyld.dylib 0x00007fff836fa5fd start + 1 17 ??? 0x0000000000000002 0x0 + 2 Stacktrace for: 0x<pointer addr> 0 libfreeradius-radius.dylib 0x00000001000c5e53 fr_backtrace_do + 323 1 libtalloc.dylib 0x000000010012d3d0 _talloc_free_internal + 862 2 libtalloc.dylib 0x000000010012d33d _talloc_free_internal + 715 3 libfreeradius-radius.dylib 0x00000001000eb6f7 pairfree + 119 4 radiusd 0x0000000100036e07 request_finish + 951 5 radiusd 0x000000010003033c request_running + 412 6 radiusd 0x0000000100030168 request_queue_or_run + 392 7 radiusd 0x000000010002f2ba request_receive + 2106 8 radiusd 0x000000010000daa5 auth_socket_recv + 1173 9 radiusd 0x0000000100032df5 event_socket_handler + 325 10 libfreeradius-radius.dylib 0x00000001000f4927 fr_event_loop + 1271 11 radiusd 0x0000000100032621 radius_event_process + 49 12 radiusd 0x0000000100023b91 main + 3601 13 libdyld.dylib 0x00007fff836fa5fd start + 1 14 ??? 0x0000000000000002 0x0 + 2 (lldb) One for alloc, one for free. We can then see if there's a common point of allocation for the double freed VPs. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
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?
On 23 Jun 2014, at 20:29, Phil Mayers <p.mayers@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@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 23/06/2014 20:31, Arran Cudbard-Bell wrote:
The original cbuff code should work now and provide you with the alloc and free BTs.
Sorry I still get "No backtrace" #9 0x00007f0283082134 in fr_verify_vp (file=0x7f02830a6510 "src/lib/cursor.c", line=45, vp=0x7f0210005640) at src/lib/debug.c:813 No locals. #10 0x00007f028308093f in _fr_cursor_init (cursor=0x7fff3a10e310, node=0x7fff3a10e2f0) at src/lib/cursor.c:45 ---Type <return> to continue, or q <return> to quit---q Quit (gdb) call backtrace_print(&vp_bt, 0x7f0210005640) Backtrace attached to VALUE_PAIR 0x7f02040233d0 Backtrace attached to VALUE_PAIR 0x7f0204038cb0 Backtrace attached to VALUE_PAIR 0x7f020409c720 Backtrace attached to VALUE_PAIR 0x7f0200005c30 Backtrace attached to VALUE_PAIR 0x7f02100ff720 Backtrace attached to VALUE_PAIR 0x7f0224031c90 Backtrace attached to VALUE_PAIR 0x119ca90 Backtrace attached to VALUE_PAIR 0x7f021c015390 Backtrace attached to VALUE_PAIR 0x7f0230004f50 Backtrace attached to VALUE_PAIR 0x7f0204038cb0 Backtrace attached to VALUE_PAIR 0x119ccb0 Backtrace attached to VALUE_PAIR 0x7f02040baff0 Backtrace attached to VALUE_PAIR 0x7f0200005c30 Backtrace attached to VALUE_PAIR 0x7f02380d3a70 Backtrace attached to VALUE_PAIR 0x7f0230004f50 Backtrace attached to VALUE_PAIR 0x7f02380d4650 No backtrace available for 0x7f0210005640 ...though by the look of it, the process is still proceeding when backtrace_print() is called, no idea if that has something to do with it.
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?
Phil Mayers wrote:
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
Hmm... OK.
/opt/fr3/sbin/radiusd[0x435799] /opt/fr3/sbin/radiusd[0x433531]
That's unhelpful.
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?
Maybe. The main thread should NOT free anything associated with the REQUEST if the child thread is still running. There are a number of checks for that... Alan DeKok.
On 23 Jun 2014, at 21:41, Alan DeKok <aland@deployingradius.com> wrote:
Phil Mayers wrote:
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
Hmm... OK.
/opt/fr3/sbin/radiusd[0x435799] /opt/fr3/sbin/radiusd[0x433531]
That's unhelpful.
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?
Maybe. The main thread should NOT free anything associated with the REQUEST if the child thread is still running. There are a number of checks for that...
Alan found potential race condition in the VERIFY_REQUEST macro when used in process.c It might just have been that hitting the lists before the HEAD pointer had been set to NULL. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 23/06/2014 22:11, Arran Cudbard-Bell wrote:
Alan found potential race condition in the VERIFY_REQUEST macro when used in process.c
It might just have been that hitting the lists before the HEAD pointer had been set to NULL.
That's looking promising... No more virtually instant crash. Will let it run for a bit.
On 23 Jun 2014, at 22:38, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
On 23/06/2014 22:27, Phil Mayers wrote:
That's looking promising... No more virtually instant crash. Will let it run for a bit.
Think the #else on line 120 is dangling, but otherwise looking good so far.
Ug. Dig out that last commit from your repo and pull... Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
Phil Mayers wrote:
On 23/06/2014 22:27, Phil Mayers wrote:
That's looking promising... No more virtually instant crash. Will let it run for a bit.
Think the #else on line 120 is dangling, but otherwise looking good so far.
Of which file? There's no #else on line 120 of process.c. Alan DeKok.
On 23/06/2014 22:46, Alan DeKok wrote:
Phil Mayers wrote:
On 23/06/2014 22:27, Phil Mayers wrote:
That's looking promising... No more virtually instant crash. Will let it run for a bit.
Think the #else on line 120 is dangling, but otherwise looking good so far.
Of which file? There's no #else on line 120 of process.c.
I think Arran might have beat you to it in the Git DeLorean!
On 23 Jun 2014, at 22:50, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
On 23/06/2014 22:46, Alan DeKok wrote:
Phil Mayers wrote:
On 23/06/2014 22:27, Phil Mayers wrote:
That's looking promising... No more virtually instant crash. Will let it run for a bit.
Think the #else on line 120 is dangling, but otherwise looking good so far.
Of which file? There's no #else on line 120 of process.c.
I think Arran might have beat you to it in the Git DeLorean!
git rebase -i HEAD~88 Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 23/06/2014 21:41, Alan DeKok wrote:
/tmp/threadlog-26294-26326-src/main/process.c:1369
Hmm... OK.
/opt/fr3/sbin/radiusd[0x435799] /opt/fr3/sbin/radiusd[0x433531]
That's unhelpful.
Yeah, annoying that. I can run addr2line on those so I've no idea why backtrace() can't resolve them, but can resolve shared libs. Sigh. Anyway, they resolve to: [root@radtest ~]# addr2line -e /opt/fr3/sbin/radiusd 0x433531 /home/nsg/freeradius-server/src/main/process.c:472 [root@radtest ~]# addr2line -e /opt/fr3/sbin/radiusd 0x435799 /home/nsg/freeradius-server/src/main/process.c:1450
Maybe. The main thread should NOT free anything associated with the REQUEST if the child thread is still running. There are a number of checks for that...
In that particular case it was an access-after-free; I think maybe (ironically) the request_running() VERIFY_REQUEST() call is walking the vps at the same time the child thread is running through them? Are we (well, I) actually seeing access-after-free being triggered by the VERIFY_* stuff? Which wouldn't happen in a release build? That said I'm not seeing the locking or lock-free primitives which would ensure a request isn't accessed from main & worker thread; what's to stop a child thread updating request->child_state at the same time request_process_timer reading it?
Phil Mayers wrote:
In that particular case it was an access-after-free; I think maybe (ironically) the request_running() VERIFY_REQUEST() call is walking the vps at the same time the child thread is running through them?
Yes.
Are we (well, I) actually seeing access-after-free being triggered by the VERIFY_* stuff? Which wouldn't happen in a release build?
Yes.
That said I'm not seeing the locking or lock-free primitives which would ensure a request isn't accessed from main & worker thread; what's to stop a child thread updating request->child_state at the same time request_process_timer reading it?
There are none. The main thread ignores the request for most values of request->child_state. The child updates request->child_state carefully, so that the main thread doesn't blow up. Alan DeKok.
On 23/06/2014 22:26, Alan DeKok wrote:
There are none. The main thread ignores the request for most values of request->child_state. The child updates request->child_state carefully, so that the main thread doesn't blow up.
Ah, gotcha - it made sense there had to be something, it can't just be happy coincidence it's worked all these years ;o)
On 23 Jun 2014, at 22:34, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
On 23/06/2014 22:26, Alan DeKok wrote:
There are none. The main thread ignores the request for most values of request->child_state. The child updates request->child_state carefully, so that the main thread doesn't blow up.
Ah, gotcha - it made sense there had to be something, it can't just be happy coincidence it's worked all these years ;o)
Note that this wasn't the original bug, I only added VERIFY_REQUEST to process.c after your initial report. It real issue was not breaking up the ctx trees correctly and not using the NULL ctx. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 23/06/2014 22:37, Arran Cudbard-Bell wrote:
Note that this wasn't the original bug, I only added VERIFY_REQUEST to process.c after your initial report.
Oh sure; that (totally non-obvious) talloc restriction was definitely biting with different symptoms.
It real issue was not breaking up the ctx trees correctly and not using the NULL ctx.
It might just be slowly ramping up to stable use w.r.t. cached SSL sessions, but FYI the memory usage is very slowly climbing for the process; I'll leave it until tomorrow, but hopefully my repeated nagging hasn't lost us a talloc_free somewhere...
Le sigh... Tue Jun 24 00:20:15 2014 : Error: CONSISTENCY CHECK FAILED src/main/process.c[1455]: Expected RADIUS_PACKET to be parented by 0x290dc60 (REQUEST), but parented by (nil) (NUL Talloc chunk lineage: 0x2881010 (RADIUS_PACKET) Talloc context level 0: Tue Jun 24 00:20:15 2014 : Error: ASSERT FAILED src/main/util.c[1078]: 0 Tue Jun 24 00:20:15 2014 : Info: CAUGHT SIGNAL: Aborted Tue Jun 24 00:20:15 2014 : Info: Backtrace of last 12 frames: ...gdb backtrace: #0 0x000000379dcac90d in __libc_waitpid (pid=<value optimized out>, stat_loc=<value optimized out>, options=<value optimized out>) at ../sysdeps/unix/sysv/linux/waitpid.c:41 #1 0x000000379dc3e909 in do_system (line=<value optimized out>) at ../sysdeps/posix/system.c:149 #2 0x000000379dc3ec40 in __libc_system (line=<value optimized out>) at ../sysdeps/posix/system.c:190 #3 0x00007fa463fde88d in fr_fault (sig=6) at src/lib/debug.c:525 #4 0x00007fa464234502 in rad_assert_fail (file=0x7fa46423d1b1 "src/main/util.c", line=1078, expr=0x7fa46423d4c0 "0") at src/main/util.c:281 #5 0x00007fa4642359a7 in verify_packet (file=0x45be95 "src/main/process.c", line=1455, request=0x290dc60, packet=0x2881010) at src/main/util.c:1078 #6 0x00007fa464235ac9 in verify_request (file=0x45be95 "src/main/process.c", line=1455, request=0x290dc60) at src/main/util.c:1106 #7 0x00000000004358aa in request_running (request=0x290dc60, action=5) at src/main/process.c:1455 #8 0x000000000043351d in request_timer (ctx=0x290dc60) at src/main/process.c:480 #9 0x00007fa464001445 in fr_event_run (el=0x25252a0, when=0x7fffe8a4eb50) at src/lib/event.c:260 #10 0x00007fa464001d52 in fr_event_loop (el=0x25252a0) at src/lib/event.c:483 #11 0x000000000043dafc in radius_event_process () at src/main/process.c:4932 #12 0x000000000042a3ea in main (argc=5, argv=0x7fffe8a4ed18) at src/main/radiusd.c:582 Ran for quite a while before crashing though, several hours.
On 24/06/14 14:21, Alan DeKok wrote:
Phil Mayers wrote:
Le sigh...
I've found two places where request->packet wasn't parented correctly. Dynamic clients && incoming RadSec connections.
Interesting. We use neither, but I'll give it another go.
On 19 Jun 2014, at 17:39, Phil Mayers <p.mayers@IMPERIAL.AC.UK> wrote:
I'm wondering if we're breaking the talloc() threading restrictions in rlm_eap / main/tls.c somewhere?
Specifically, I think tls_new_session can be called from multiple threads at the same time, and that calls talloc with a context of "conf" i.e. the module config, which is not per-thread. The talloc docs say each thread must use a separate context (or, presumably, lock).
I wonder if this is what's triggering the corruption?
Ditto cbtls_new_session (though OpenSSL locking might protect that) and I think a few other places.
OpenSSL really shouldn't be putting the call to the callback inside the critical section in case it blocks or does something else bad. So we probably have to assume callbacks are not serialised, and we have to protect them. We also need to protect frees as well as allocs, which doesn't always seem to be done now. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 20 Jun 2014, at 09:02, Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
On 19 Jun 2014, at 17:39, Phil Mayers <p.mayers@IMPERIAL.AC.UK> wrote:
I'm wondering if we're breaking the talloc() threading restrictions in rlm_eap / main/tls.c somewhere?
Specifically, I think tls_new_session can be called from multiple threads at the same time, and that calls talloc with a context of "conf" i.e. the module config, which is not per-thread. The talloc docs say each thread must use a separate context (or, presumably, lock).
I wonder if this is what's triggering the corruption?
Ditto cbtls_new_session (though OpenSSL locking might protect that) and I think a few other places.
OpenSSL really shouldn't be putting the call to the callback inside the critical section in case it blocks or does something else bad. So we probably have to assume callbacks are not serialised, and we have to protect them.
Reading through that code, there we no point in using talloc anyway. The buffer is allocated and freed in the same call. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
participants (3)
-
Alan DeKok -
Arran Cudbard-Bell -
Phil Mayers