We've got a version of 3.0.x HEAD running on our test server. It's sporadically hanging - stopping answering requests. I've caught a process doing it - backtrace here: https://gist.github.com/philmayers/5582ca9fb89f373919b5 Looks like it's actually faulted, but the fault handler stuff is stuck on a mutex - inside talloc? No idea what's triggering the fault.
On 16/06/14 11:51, Phil Mayers wrote:
We've got a version of 3.0.x HEAD running on our test server. It's sporadically hanging - stopping answering requests.
I've caught a process doing it - backtrace here:
https://gist.github.com/philmayers/5582ca9fb89f373919b5
Looks like it's actually faulted, but the fault handler stuff is stuck on a mutex - inside talloc?
Huh, looks like backtrace() is actually calling malloc(). Oh dear: https://sourceware.org/bugzilla/show_bug.cgi?id=956 I'd love to say I'm surprised by the tone in the comments of that bug, but I've read enough glibc bugs to know that it was a common problem in the mid-2000s... See however the far more reasonable and clueful: https://sourceware.org/bugzilla/show_bug.cgi?id=16159 Basically - backtrace() not safe to call from signal handlers by the looks of it? Glumness. Still not clear why the process is SEGVing - vp->length is 3, talloc_array should not fail. I guess memory corruption of some sort?
On 16 Jun 2014, at 12:16, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
On 16/06/14 11:51, Phil Mayers wrote:
We've got a version of 3.0.x HEAD running on our test server. It's sporadically hanging - stopping answering requests.
I've caught a process doing it - backtrace here:
https://gist.github.com/philmayers/5582ca9fb89f373919b5
Looks like it's actually faulted, but the fault handler stuff is stuck on a mutex - inside talloc?
Huh, looks like backtrace() is actually calling malloc().
Yes.
Oh dear:
What a complete and utter shithead.
I'd love to say I'm surprised by the tone in the comments of that bug, but I've read enough glibc bugs to know that it was a common problem in the mid-2000s...
See however the far more reasonable and clueful:
https://sourceware.org/bugzilla/show_bug.cgi?id=16159
Basically - backtrace() not safe to call from signal handlers by the looks of it? Glumness.
I've added the suggested workaround for __GLIBC__ only, with the assumption that other versions of backtrace (OSX and FreeBSD have their own) are sane and don't allocate heap memory... because that's a spectacularly stupid thing to do. That's why we use backtrace_symbols_fd FFS (to avoid allocating strings for symbol names).
Still not clear why the process is SEGVing - vp->length is 3, talloc_array should not fail. I guess memory corruption of some sort?
Maybe a bad parent, which is weird... valgrind? Could you also try reverting 6075844989ca8301a2743aed06ddd95382a6e78b Which i'd say is the most likely candidate for introducing this bug, if it's only started appearing relatively recently. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 16/06/14 13:08, Arran Cudbard-Bell wrote:
Maybe a bad parent, which is weird... valgrind?
It takes a long time to happen as the test server only receives a small amount of traffic; would running it under valgrind for extended period produce useful info here?
Could you also try reverting 6075844989ca8301a2743aed06ddd95382a6e78b
I could, though I might work on triggering it reliably first.
Which i'd say is the most likely candidate for introducing this bug, if it's only started appearing relatively recently.
TBH it's only very recently that I've had time to look into 3.0.x in production, so I'm not sure I have enough history to know it was recent for sure.
On 16/06/14 13:08, Arran Cudbard-Bell wrote:
I've added the suggested workaround for __GLIBC__ only, with the assumption that other versions of backtrace (OSX and FreeBSD have their own) are sane and don't allocate heap memory... because that's a spectacularly stupid thing to do.
I still get a hang on "kill -11". Is the #ifdef logic around the backtrace() calls correct, looks inverted compared to the logic around the workaround?
On 16/06/14 14:18, Phil Mayers wrote:
I still get a hang on "kill -11". Is the #ifdef logic around the backtrace() calls correct, looks inverted compared to the logic around the workaround?
Ah see you've just fixed it, working now and libgcc_s is now in /proc/pid/maps. Will work on repro-ing the actual fault now.
On 16/06/2014 14:24, Phil Mayers wrote:
On 16/06/14 14:18, Phil Mayers wrote:
I still get a hang on "kill -11". Is the #ifdef logic around the backtrace() calls correct, looks inverted compared to the logic around the workaround?
Ah see you've just fixed it, working now and libgcc_s is now in /proc/pid/maps.
Will work on repro-ing the actual fault now.
Weird. It's reliably core-ing now, and crash in a completely different place: https://gist.github.com/philmayers/6234dd21c91982d80987
On 16 Jun 2014, at 19:07, Phil Mayers <p.mayers@IMPERIAL.AC.UK> wrote:
On 16/06/2014 14:24, Phil Mayers wrote:
On 16/06/14 14:18, Phil Mayers wrote:
I still get a hang on "kill -11". Is the #ifdef logic around the backtrace() calls correct, looks inverted compared to the logic around the workaround?
Ah see you've just fixed it, working now and libgcc_s is now in /proc/pid/maps.
Great, thanks for confirming.
Will work on repro-ing the actual fault now.
Weird. It's reliably core-ing now, and crash in a completely different place:
That really is weird. No idea about that one. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 16/06/14 22:03, Arran Cudbard-Bell wrote:
That really is weird. No idea about that one.
I think there must be some heap corruption going on; I've got another one, and the glibc malloc internals appear to be inconsistent. It's happening so sporadically I'm not sure valgrind will show it, but I'll give it a go.
On 17 Jun 2014, at 12:08, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
On 16/06/14 22:03, Arran Cudbard-Bell wrote:
That really is weird. No idea about that one.
I think there must be some heap corruption going on; I've got another one, and the glibc malloc internals appear to be inconsistent.
It's happening so sporadically I'm not sure valgrind will show it, but I'll give it a go.
Try rebuilding from current v3.0.x HEAD too. I just added a bunch of talloc checks which may catch the issue earlier if it's just random heap corruption. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 17/06/14 12:13, Arran Cudbard-Bell wrote:
On 17 Jun 2014, at 12:08, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
On 16/06/14 22:03, Arran Cudbard-Bell wrote:
That really is weird. No idea about that one.
I think there must be some heap corruption going on; I've got another one, and the glibc malloc internals appear to be inconsistent.
It's happening so sporadically I'm not sure valgrind will show it, but I'll give it a go.
Try rebuilding from current v3.0.x HEAD too. I just added a bunch of talloc checks which may catch the issue earlier if it's just random heap corruption.
Bang! (14) eap_peap : processing EAP-TLS (14) eap_peap : eaptls_verify returned 7 (14) eap_peap : Done initial handshake (14) eap_peap : eaptls_process returned 7 (14) eap_peap : FR_TLS_OK (14) eap_peap : Session established. Decoding tunneled attributes (14) eap_peap : Peap state send tlv success (14) eap_peap : Received EAP-TLV response (14) eap_peap : Success (14) eap_peap : Adding cached attributes for session ccc34bdb20c4b4da035afaa3e8baf7f5a02fd34bcfaa57fa7ef8d7cdc9a70191: User-Name := '@ic.ac.uk' Cached-Session-Policy = 'zone=,ickind=,icuser=' (14) eap : Freeing handler (14) [eap] = ok (14) } # authenticate = ok Expected VALUE_PAIR (User-Name) to be parented by 0x239f840 (RADIUS_PACKET), but parented by 0x239f3f0 (RADIUS_PACKET): Unknown value 'Challenge' for attribute 'Post-Auth-Type' Current state of talloced memory: CAUGHT SIGNAL: Segmentation fault
On 17/06/14 12:24, Phil Mayers wrote:
Current state of talloced memory: CAUGHT SIGNAL: Segmentation fault
Note the talloc dump seems to fail because of: #1 0x00007ffff7b999a8 in fr_log_talloc_report (ctx=0x9ebb10) at src/lib/debug.c:602 602 null_ctx = talloc_get_name(NULL); ...which ends up in: #0 talloc_get_name (ptr=0x0) at ../talloc.c:1153 1153 struct talloc_chunk *tc = talloc_chunk_from_ptr(ptr); ...which segfaults; not sure if talloc_get_name(NULL) is legal, or if this is a result of the bug or what?
On 17 Jun 2014, at 12:29, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
On 17/06/14 12:24, Phil Mayers wrote:
Current state of talloced memory: CAUGHT SIGNAL: Segmentation fault
Note the talloc dump seems to fail because of:
#1 0x00007ffff7b999a8 in fr_log_talloc_report (ctx=0x9ebb10) at src/lib/debug.c:602 602 null_ctx = talloc_get_name(NULL);
...which ends up in:
#0 talloc_get_name (ptr=0x0) at ../talloc.c:1153 1153 struct talloc_chunk *tc = talloc_chunk_from_ptr(ptr);
...which segfaults; not sure if talloc_get_name(NULL) is legal, or if this is a result of the bug or what?
I'm honestly not sure. To be safe i've changed the code... It wasn't wrong, but it's the sort of thing that might break between talloc versions. Anyway, the SEGV is secondary, the issue here is bad parenting of the VALUE_PAIR. Could you use latest head and try again? If you run it in with: PANIC_ACTION="gdb %e %p" radiusd -lstdout -f It'll dump you into an interactive GDB prompt, and you can poke around a bit. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 17 Jun 2014, at 13:32, Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
On 17 Jun 2014, at 12:29, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
On 17/06/14 12:24, Phil Mayers wrote:
Current state of talloced memory: CAUGHT SIGNAL: Segmentation fault
Note the talloc dump seems to fail because of:
#1 0x00007ffff7b999a8 in fr_log_talloc_report (ctx=0x9ebb10) at src/lib/debug.c:602 602 null_ctx = talloc_get_name(NULL);
...which ends up in:
#0 talloc_get_name (ptr=0x0) at ../talloc.c:1153 1153 struct talloc_chunk *tc = talloc_chunk_from_ptr(ptr);
...which segfaults; not sure if talloc_get_name(NULL) is legal, or if this is a result of the bug or what?
I'm honestly not sure. To be safe i've changed the code... It wasn't wrong, but it's the sort of thing that might break between talloc versions.
Anyway, the SEGV is secondary, the issue here is bad parenting of the VALUE_PAIR. Could you use latest head and try again?
and again if you want the file and line number where the sanity check failed... Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 17/06/14 13:51, Arran Cudbard-Bell wrote:
and again if you want the file and line number where the sanity check failed...
Sorry, I should have added I'm getting core files for all these and could have given the file/line; but debugging now says: (14) eap_peap : Adding cached attributes for session 741ab1e198f2a941d954b4d61c11237c25ce100a44ba3292184575c7e148286b: User-Name := '@ic.ac.uk' Cached-Session-Policy = 'zone=,ickind=,icuser=' (14) eap : Freeing handler (14) [eap] = ok (14) } # authenticate = ok CONSISTENCY CHECK FAILED src/main/process.c[2520]: Expected VALUE_PAIR (User-Name) to be parented by 0x1092ef0 (RADIUS_PACKET), but parented by 0x1093470 (RADIUS_PACKET)Current state of talloced memory: ...and then a *lot* of talloc debugging. Given the last items in the debug I'm wondering if it's the saving of cached attributes? Looks like it's inside request_will_proxy: #11 0x0000000000437920 in request_will_proxy (request=0x10928a0) at src/main/process.c:2520 2520 VERIFY_REQUEST(request); ...but I guess the damage was done earlier...
On 17/06/14 14:11, Phil Mayers wrote:
...and then a *lot* of talloc debugging. Given the last items in the debug I'm wondering if it's the saving of cached attributes?
Correction: closer examination of the debugging shows it's *restoring* the saved attributes i.e. during an SSL-resumed PEAP re-auth that it's failing.
On 17/06/14 14:13, Phil Mayers wrote:
On 17/06/14 14:11, Phil Mayers wrote:
...and then a *lot* of talloc debugging. Given the last items in the debug I'm wondering if it's the saving of cached attributes?
Correction: closer examination of the debugging shows it's *restoring* the saved attributes i.e. during an SSL-resumed PEAP re-auth that it's failing.
Ok, I think the parenting problem is here: https://github.com/FreeRADIUS/freeradius-server/blob/v3.0.x/src/main/tls.c#L... I think that paircopyvp should have request->reply as the 1st argument for stuff added to the reply vps?
On 17 Jun 2014, at 14:30, Phil Mayers <p.mayers@IMPERIAL.AC.UK> wrote:
On 17/06/14 14:13, Phil Mayers wrote:
On 17/06/14 14:11, Phil Mayers wrote:
...and then a *lot* of talloc debugging. Given the last items in the debug I'm wondering if it's the saving of cached attributes?
Correction: closer examination of the debugging shows it's *restoring* the saved attributes i.e. during an SSL-resumed PEAP re-auth that it's failing.
Ok, I think the parenting problem is here:
https://github.com/FreeRADIUS/freeradius-server/blob/v3.0.x/src/main/tls.c#L...
I think that paircopyvp should have request->reply as the 1st argument for stuff added to the reply vps?
Yep, you're right. Good catch. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 17/06/14 14:30, Phil Mayers wrote:
I think that paircopyvp should have request->reply as the 1st argument for stuff added to the reply vps?
Yeah, that works. Not entirely sure this was my original problem but now I can run it with the extended debugging on.
On 17 Jun 2014, at 14:32, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
On 17/06/14 14:30, Phil Mayers wrote:
I think that paircopyvp should have request->reply as the 1st argument for stuff added to the reply vps?
Yeah, that works.
Not entirely sure this was my original problem but now I can run it with the extended debugging on.
No, it probably wasn't, but it was useful to fix anyway. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
Ok, now that backtrace and debugging are working again, back to top of thread for the issue. Just had another crash on HEAD of 3.0.x; digging into the core file, it does look like malloc state has become corrupted - segfault is inside glibc with: #5 _int_malloc (av=0x7f4ccc000020, bytes=<value optimized out>) at malloc.c:4476 4476 bck->fd = unsorted_chunks(av); (gdb) print bck $1 = (struct malloc_chunk *) 0x0 Higher stack has: #7 0x00000036ad40663f in __talloc (ctx=<value optimized out>, el_size=<value optimized out>, count=<value optimized out>, name=<value optimized out>) at ../talloc.c:560 560 tc = (struct talloc_chunk *)malloc(TC_HDR_SIZE+size); (gdb) print size $2 = 191 i.e. a perfectly ordinary malloc from talloc. Does everyone else agree this suggests heap corruption? Full backtrace here: https://gist.github.com/philmayers/18a04e642803153a4d5a Will try and re-trigger under valgrind, though memcheck seems to report a *lot* for 3.0.x head - many alloc-without-free for regexp compilations at compile parse time and similar.
On 17 Jun 2014, at 15:33, Phil Mayers <p.mayers@IMPERIAL.AC.UK> wrote:
Ok, now that backtrace and debugging are working again, back to top of thread for the issue.
Just had another crash on HEAD of 3.0.x; digging into the core file, it does look like malloc state has become corrupted - segfault is inside glibc with:
#5 _int_malloc (av=0x7f4ccc000020, bytes=<value optimized out>) at malloc.c:4476 4476 bck->fd = unsorted_chunks(av); (gdb) print bck $1 = (struct malloc_chunk *) 0x0
Higher stack has:
#7 0x00000036ad40663f in __talloc (ctx=<value optimized out>, el_size=<value optimized out>, count=<value optimized out>, name=<value optimized out>) at ../talloc.c:560 560 tc = (struct talloc_chunk *)malloc(TC_HDR_SIZE+size); (gdb) print size $2 = 191
i.e. a perfectly ordinary malloc from talloc. Does everyone else agree this suggests heap corruption?
Yes, it would seem to.
Full backtrace here:
https://gist.github.com/philmayers/18a04e642803153a4d5a
Will try and re-trigger under valgrind, though memcheck seems to report a *lot* for 3.0.x head - many alloc-without-free for regexp compilations at compile parse time and similar.
You need to run with -m to free allocated memory on exit, else you may get false positives. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 17/06/14 15:33, Phil Mayers wrote:
Will try and re-trigger under valgrind, though memcheck seems to report a *lot* for 3.0.x head - many alloc-without-free for regexp compilations at compile parse time and similar.
Ok, looks like use-after-free somewhere. Valgrind report is really really big, but it looks like the pertinent stuff is: Thread 1: Invalid read of size 4 at 0x36AD402D84: talloc_get_name (talloc.c:349) by 0x36AD4057EA: _talloc_get_type_abort (talloc.c:1206) by 0x4E46F23: fr_verify_vp (debug.c:804) by 0x4E4587E: _fr_cursor_init (cursor.c:45) by 0x4E47242: fr_verify_list (debug.c:868) by 0x4C2EABB: verify_request (util.c:1105) by 0x4354BF: request_running (process.c:1446) by 0x433230: request_timer (process.c:471) by 0x4E691CC: fr_event_run (event.c:260) by 0x4E69AD9: fr_event_loop (event.c:483) by 0x43D4C2: radius_event_process (process.c:4923) by 0x42A184: main (radiusd.c:565) Address 0xa5f31d0 is 64 bytes inside a block of size 160 free'd at 0x4A063F0: free (vg_replace_malloc.c:446) by 0x36AD402388: _talloc_free_internal (talloc.c:876) by 0x4E623E1: pairfree (valuepair.c:171) by 0x4351F3: request_finish (process.c:1366) by 0x43561E: request_running (process.c:1526) by 0x430D70: request_handler_thread (threads.c:685) by 0x379E4079D0: start_thread (pthread_create.c:301) by 0x379DCE8B7C: clone (clone.S:115) Invalid read of size 8 at 0x36AD402DBA: talloc_get_name (talloc.c:356) by 0x36AD4057EA: _talloc_get_type_abort (talloc.c:1206) by 0x4E46F23: fr_verify_vp (debug.c:804) by 0x4E4587E: _fr_cursor_init (cursor.c:45) by 0x4E47242: fr_verify_list (debug.c:868) by 0x4C2EABB: verify_request (util.c:1105) by 0x4354BF: request_running (process.c:1446) by 0x433230: request_timer (process.c:471) by 0x4E691CC: fr_event_run (event.c:260) by 0x4E69AD9: fr_event_loop (event.c:483) by 0x43D4C2: radius_event_process (process.c:4923) by 0x42A184: main (radiusd.c:565) Address 0xa5f31c0 is 48 bytes inside a block of size 160 free'd at 0x4A063F0: free (vg_replace_malloc.c:446) by 0x36AD402388: _talloc_free_internal (talloc.c:876) by 0x4E623E1: pairfree (valuepair.c:171) by 0x4351F3: request_finish (process.c:1366) by 0x43561E: request_running (process.c:1526) by 0x430D70: request_handler_thread (threads.c:685) by 0x379E4079D0: start_thread (pthread_create.c:301) by 0x379DCE8B7C: clone (clone.S:115) Sadly the corefile is unusable after dying under valgrind? Stack trace doesn't work.
On 17 Jun 2014, at 15:55, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
On 17/06/14 15:33, Phil Mayers wrote:
Will try and re-trigger under valgrind, though memcheck seems to report a *lot* for 3.0.x head - many alloc-without-free for regexp compilations at compile parse time and similar.
Ok, looks like use-after-free somewhere. Valgrind report is really really big, but it looks like the pertinent stuff is:
From the backtrace below we know it's a control attribute. What modules are you using? Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 17/06/2014 18:05, Arran Cudbard-Bell wrote:
What modules are you using?
Man, what are we not... The main things are: 1. A bunch of policy modules, in particular one which wraps a linelog instance. This lots a *lot* of conditional logic to generate linelog in the format we want, but keep the main config clean, and uses control:Tmp-String-0 a lot e.g. policy { mylog.authorize { if (...) { update control { Tmp-String-0 := "%{Some-Thing}" } } } } 2. A bunch of rlm_cache modules wrapping some SQL xlats into control:Tmp-String-0, which are then split out into request variables by a policy e.g. modules { cache mydb { update { control:Tmp-String-0 := "%{sql:select foo||','||bar ...}" } } } policy { mydb-lookup { mydb if (control:Tmp-String-0 =~ /^(.+),(.+)$/) { update request { My-Attr = "%{0}" Other-a = "%{1}" } } } } 3. In the 3.x config a foreach over &Cisco-AVPair, string-ified into Tmp-String-0 (see a pattern yet) then regexp-matched e.g. if (Cisco-AVPair) { foreach &Cisco-AVPair { # foreach-variable-x can't be regexp-matched # and need to be string-ified, so we do this # explicitly to avoid doubt update request { Tmp-String-0 := "%{Foreach-Variable-0}" } if (Tmp-String-0 =~ /^audit-session-id=(.+)$/) { update request { IC-Cisco-ASID := "%{1}" } } } } 4. The usual array of eap (peap, mschapv2), mschap w/ ntlm_auth, and as above linelog and sql.
On 17 Jun 2014, at 19:32, Phil Mayers <p.mayers@IMPERIAL.AC.UK> wrote:
On 17/06/2014 18:05, Arran Cudbard-Bell wrote:
What modules are you using?
Man, what are we not...
The main things are: ...
I figured the cache module would be involved in there somewhere. It's really the only thing that does anything major with control attributes... That's interesting... well I noticed a check was missing for the parenting of VALUE_PAIR data buffers. If one wasn't being copied somewhere in the cache module, and being freed due to incorrect parenting, it'd result in heap corruption. I've added the check, could you run up v3.0.x HEAD and see if it fails? I also noticed a missed free when removing cache control attribute, but that'd quite minor, and wouldn't of even resulted in a memory leak... -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 17/06/2014 20:02, Arran Cudbard-Bell wrote:
On 17 Jun 2014, at 19:32, Phil Mayers <p.mayers@IMPERIAL.AC.UK> wrote:
On 17/06/2014 18:05, Arran Cudbard-Bell wrote:
What modules are you using?
Man, what are we not...
The main things are: ...
I figured the cache module would be involved in there somewhere. It's really the only thing that does anything major with control attributes...
That's interesting... well I noticed a check was missing for the parenting of VALUE_PAIR data buffers. If one wasn't being copied somewhere in the cache module, and being freed due to incorrect parenting, it'd result in heap corruption.
I've added the check, could you run up v3.0.x HEAD and see if it fails?
Yeah, looks like that's it, it bombs out almost immediately with: CONSISTENCY CHECK FAILED src/lib/valuepair.c[2350]: VALUE_PAIR ICzone uint8_t data buffer is not parented by VALUE_PAIR 0xa08820, instead parented by 0x892f10 (value_pair_tmpl_t) SOFT ASSERT FAILED src/lib/debug.c[871]: 0 "ICzone" is populated like this: policy { lookup_mac_zone { # just look the zone for a mac # designed for things where the vlan it not useful # or static i.e. not a switch cached into HDB # hdb lookup, via cache hdbmaczone if (control:Tmp-String-0 =~ /^(.+),(.+)$/) { update request { Calling-Station-Id := "%{1}" ICzone = "%{2}" } updated } else { update request { ICzone = "SUPERBANNED" } notfound } } } ...and the "hdbmaczone" is: cache hdbmaczone { key = "%{Calling-Station-Id}" ttl = 15 # LEAVE THIS AT 0 - it's intended for use internally epoch = 0 add-stats = no update { control:Tmp-String-0 := "%{newsql:select ...}" } } The assert is triggered on a comparison immediately after the "policy" module has run: (0) hdbmaczone : EXPAND %{newsql:select mac||','||zone from lookup_mac_zone('%{Calling-Station-Id}') order by prio desc limit 1} (0) hdbmaczone : --> 02:00:00:00:00:01,PREREG (0) hdbmaczone : Adding to cache entry: (0) hdbmaczone : control:Tmp-String-0 := "02:00:00:00:00:01,PREREG" (0) hdbmaczone : Adding to request: (0) hdbmaczone : control:Tmp-String-0 := "02:00:00:00:00:01,PREREG" (0) hdbmaczone : Inserted entry, TTL 15 seconds (0) [hdbmaczone] = updated (0) if (control:Tmp-String-0 =~ /^(.+),(.+)$/) (0) if (control:Tmp-String-0 =~ /^(.+),(.+)$/) -> TRUE (0) if (control:Tmp-String-0 =~ /^(.+),(.+)$/) { (0) update request { (0) EXPAND %{1} (0) --> 02:00:00:00:00:01 (0) Calling-Station-Id := "02:00:00:00:00:01" (0) EXPAND %{2} (0) --> PREREG (0) ICzone = "PREREG" (0) } # update request = noop (0) [updated] = updated (0) } # if (control:Tmp-String-0 =~ /^(.+),(.+)$/) = updated (0) ... skipping else for request 0: Preceding "if" was taken (0) } # lookup_mac_zone lookup_mac_zone = updated (0) if (ICzone == "SUPERBANNED") CONSISTENCY CHECK FAILED src/lib/valuepair.c[2350]: VALUE_PAIR ICzone uint8_t data buffer is not parented by VALUE_PAIR 0xa08820, instead parented by 0x892f10 (value_pair_tmpl_t)
On 17 Jun 2014, at 21:16, Phil Mayers <p.mayers@IMPERIAL.AC.UK> wrote:
On 17/06/2014 20:02, Arran Cudbard-Bell wrote:
On 17 Jun 2014, at 19:32, Phil Mayers <p.mayers@IMPERIAL.AC.UK> wrote:
On 17/06/2014 18:05, Arran Cudbard-Bell wrote:
What modules are you using?
Man, what are we not...
The main things are: ...
I figured the cache module would be involved in there somewhere. It's really the only thing that does anything major with control attributes...
That's interesting... well I noticed a check was missing for the parenting of VALUE_PAIR data buffers. If one wasn't being copied somewhere in the cache module, and being freed due to incorrect parenting, it'd result in heap corruption.
I've added the check, could you run up v3.0.x HEAD and see if it fails?
Yeah, looks like that's it, it bombs out almost immediately with:
CONSISTENCY CHECK FAILED src/lib/valuepair.c[2350]: VALUE_PAIR ICzone uint8_t data buffer is not parented by VALUE_PAIR 0xa08820, instead parented by 0x892f10 (value_pair_tmpl_t) SOFT ASSERT FAILED src/lib/debug.c[871]: 0
OK. Fixed the obvious places which might have triggered that. The code in tmpl2str for printing literals was not threadsafe and that's been fixed too. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 17/06/14 23:57, Arran Cudbard-Bell wrote:
OK. Fixed the obvious places which might have triggered that. The code in tmpl2str for printing literals was not threadsafe and that's been fixed too.
Ok, runs now. Will set it going and see if it dies after time. n.b. there are still a couple of valgrind-reported leaks with "-m" in the clients and another bit I don't understand, but otherwise clean valgrind report: 2,784 (168 direct, 2,616 indirect) bytes in 1 blocks ar at 0x4A069EE: malloc (vg_replace_malloc.c:270) by 0x36AD405228: _talloc_zero (talloc.c:560) by 0x4E5DECA: rbtree_create (rbtree.c:116) by 0x40E69B: client_add (client.c:222) by 0x41002E: clients_parse_section (client.c:889) by 0x41424E: common_socket_parse (listen.c:1222) by 0x41CB30: listen_parse (listen.c:2863) by 0x41D22C: listen_init (listen.c:3104) by 0x43CFEA: radius_event_start (process.c:4760) by 0x429EDF: main (radiusd.c:462) 26,637 bytes in 13 blocks are definitely lost in loss r at 0x4A069EE: malloc (vg_replace_malloc.c:270) by 0x4E50012: fr_strerror_printf (log.c:68) by 0x4E646F6: pairparsevalue (valuepair.c:1426) by 0x4E6553D: pairmake (valuepair.c:1886) by 0x435141: request_finish (process.c:1342) by 0x4355F7: request_running (process.c:1526) by 0x430D70: request_handler_thread (threads.c:685) by 0x379E4079D0: start_thread (pthread_create.c:301) by 0x379DCE8B7C: clone (clone.S:115)
On 18 Jun 2014, at 11:24, Phil Mayers <p.mayers@IMPERIAL.AC.UK> wrote:
On 17/06/14 23:57, Arran Cudbard-Bell wrote:
OK. Fixed the obvious places which might have triggered that. The code in tmpl2str for printing literals was not threadsafe and that's been fixed too.
Ok, runs now. Will set it going and see if it dies after time.
n.b. there are still a couple of valgrind-reported leaks with "-m" in the clients and another bit I don't understand, but otherwise clean valgrind report:
2,784 (168 direct, 2,616 indirect) bytes in 1 blocks ar at 0x4A069EE: malloc (vg_replace_malloc.c:270) by 0x36AD405228: _talloc_zero (talloc.c:560) by 0x4E5DECA: rbtree_create (rbtree.c:116) by 0x40E69B: client_add (client.c:222) by 0x41002E: clients_parse_section (client.c:889) by 0x41424E: common_socket_parse (listen.c:1222) by 0x41CB30: listen_parse (listen.c:2863) by 0x41D22C: listen_init (listen.c:3104) by 0x43CFEA: radius_event_start (process.c:4760) by 0x429EDF: main (radiusd.c:462)
Ok that should now be fixed.
26,637 bytes in 13 blocks are definitely lost in loss r at 0x4A069EE: malloc (vg_replace_malloc.c:270) by 0x4E50012: fr_strerror_printf (log.c:68) by 0x4E646F6: pairparsevalue (valuepair.c:1426) by 0x4E6553D: pairmake (valuepair.c:1886) by 0x435141: request_finish (process.c:1342) by 0x4355F7: request_running (process.c:1526) by 0x430D70: request_handler_thread (threads.c:685) by 0x379E4079D0: start_thread (pthread_create.c:301) by 0x379DCE8B7C: clone (clone.S:115)
Magic Thread Local Storage stuff, don't worry about it. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 18/06/14 11:24, Phil Mayers wrote:
Ok, runs now. Will set it going and see if it dies after time.
Still crashing after a while with 5c9c917592 :o( Valgrind says: Thread 1: Invalid read of size 4 at 0x36AD402D84: talloc_get_name (talloc.c:349) by 0x36AD4057EA: _talloc_get_type_abort (talloc.c:1206) by 0x4E4708D: fr_verify_vp (debug.c:823) by 0x4E458DE: _fr_cursor_init (cursor.c:45) by 0x4E4752D: fr_verify_list (debug.c:910) by 0x4C2EA3B: verify_request (util.c:1105) by 0x4354B8: request_running (process.c:1446) by 0x433250: request_timer (process.c:471) by 0x4E69304: fr_event_run (event.c:260) by 0x4E69C11: fr_event_loop (event.c:483) by 0x43D487: radius_event_process (process.c:4923) by 0x42A1A4: main (radiusd.c:565) Address 0x9d4bb70 is 64 bytes inside a block of size 160 free'd at 0x4A063F0: free (vg_replace_malloc.c:446) by 0x36AD402388: _talloc_free_internal (talloc.c:876) by 0x4E62601: pairfree (valuepair.c:171) by 0x4351F9: request_finish (process.c:1366) by 0x435617: request_running (process.c:1526) by 0x430D90: request_handler_thread (threads.c:685) by 0x379E4079D0: start_thread (pthread_create.c:301) by 0x379DCE8B7C: clone (clone.S:115) Invalid read of size 8 at 0x36AD402DBA: talloc_get_name (talloc.c:356) by 0x36AD4057EA: _talloc_get_type_abort (talloc.c:1206) by 0x4E4708D: fr_verify_vp (debug.c:823) by 0x4E458DE: _fr_cursor_init (cursor.c:45) by 0x4E4752D: fr_verify_list (debug.c:910) by 0x4C2EA3B: verify_request (util.c:1105) by 0x4354B8: request_running (process.c:1446) by 0x433250: request_timer (process.c:471) by 0x4E69304: fr_event_run (event.c:260) by 0x4E69C11: fr_event_loop (event.c:483) by 0x43D487: radius_event_process (process.c:4923) by 0x42A1A4: main (radiusd.c:565) Address 0x9d4bb60 is 48 bytes inside a block of size 160 free'd at 0x4A063F0: free (vg_replace_malloc.c:446) by 0x36AD402388: _talloc_free_internal (talloc.c:876) by 0x4E62601: pairfree (valuepair.c:171) by 0x4351F9: request_finish (process.c:1366) by 0x435617: request_running (process.c:1526) by 0x430D90: request_handler_thread (threads.c:685) by 0x379E4079D0: start_thread (pthread_create.c:301) by 0x379DCE8B7C: clone (clone.S:115) I didn't get a talloc report (or a valid core, grr valgrind!) but it looks like it might have then died inside fr_fault after getting the signal, hence no talloc report.
On 18/06/14 13:55, Phil Mayers wrote:
I didn't get a talloc report (or a valid core, grr valgrind!) but it
Never mind, the talloc report is of course not expected (or useful if the heap is corrupted) Caught another one under gdb; again looks like heap corruption, but digging around in glibc internals is not proving fruitful in terms of finding what was written into the RAM, since the failure happens much later when not running under valgrind :o(
So run under valgrind, I'm reliably seeing use-after-free errors like this: Invalid read of size 4 at 0x36AD402D84: talloc_get_name (talloc.c:349) by 0x36AD4057EA: _talloc_get_type_abort (talloc.c:1206) by 0x4E470EC: fr_verify_vp (debug.c:829) by 0x4E458DE: _fr_cursor_init (cursor.c:45) by 0x4E4758C: fr_verify_list (debug.c:916) by 0x4C2EB30: verify_request (util.c:1113) by 0x4354B8: request_running (process.c:1446) by 0x433250: request_timer (process.c:471) by 0x4E69364: fr_event_run (event.c:260) by 0x4E69C71: fr_event_loop (event.c:483) by 0x43D487: radius_event_process (process.c:4923) by 0x42A1A4: main (radiusd.c:565) Address 0x9ce99e0 is 64 bytes inside a block of size 160 free'd at 0x4A063F0: free (vg_replace_malloc.c:446) by 0x36AD402388: _talloc_free_internal (talloc.c:876) by 0x4E62661: pairfree (valuepair.c:171) by 0x4351F9: request_finish (process.c:1366) by 0x435617: request_running (process.c:1526) by 0x430D90: request_handler_thread (threads.c:685) by 0x379E4079D0: start_thread (pthread_create.c:301) by 0x379DCE8B7C: clone (clone.S:115) Invalid read of size 8 at 0x36AD402DBA: talloc_get_name (talloc.c:356) by 0x36AD4057EA: _talloc_get_type_abort (talloc.c:1206) by 0x4E470EC: fr_verify_vp (debug.c:829) by 0x4E458DE: _fr_cursor_init (cursor.c:45) by 0x4E4758C: fr_verify_list (debug.c:916) by 0x4C2EB30: verify_request (util.c:1113) by 0x4354B8: request_running (process.c:1446) by 0x433250: request_timer (process.c:471) by 0x4E69364: fr_event_run (event.c:260) by 0x4E69C71: fr_event_loop (event.c:483) by 0x43D487: radius_event_process (process.c:4923) by 0x42A1A4: main (radiusd.c:565) Address 0x9ce99d0 is 48 bytes inside a block of size 160 free'd at 0x4A063F0: free (vg_replace_malloc.c:446) by 0x36AD402388: _talloc_free_internal (talloc.c:876) by 0x4E62661: pairfree (valuepair.c:171) by 0x4351F9: request_finish (process.c:1366) by 0x435617: request_running (process.c:1526) by 0x430D90: request_handler_thread (threads.c:685) by 0x379E4079D0: start_thread (pthread_create.c:301) by 0x379DCE8B7C: clone (clone.S:115) Sadly I'm blocked. I can't get "vgdb" to run properly (it complains with some bullshit error message about putpkt failing), so can't break into the process when the invalid read happens and inspect the memory contents, to know what attributes are triggering it. If I run it under gdb, the errors seem to happen later, presumably because the invalid reads aren't handled in the same way. I'm then stuck in glibc/malloc and the twisty internals don't tell me a lot. If anyone has any suggestions I'm all ears... :o(
On 18 Jun 2014, at 16:45, Phil Mayers <p.mayers@IMPERIAL.AC.UK> wrote:
So run under valgrind, I'm reliably seeing use-after-free errors like this:
Invalid read of size 4 at 0x36AD402D84: talloc_get_name (talloc.c:349) by 0x36AD4057EA: _talloc_get_type_abort (talloc.c:1206) by 0x4E470EC: fr_verify_vp (debug.c:829)
Git pull. Set envvar TALLOC_FREE_FILL=B Talloc should now abort a little more gracefully. If it doesn't then lib/debug.c:828 if (*((uint8_t const *)vp) == 0x42) fr_debug_break(); If you run it under gdb, it should break when it sees a VALUE_PAIR which has already been freed unless that memory has already been overwritten. You could also try: if (*(((uint8_t const *)vp) - 1) == 0x42) fr_debug_break(); Which is less likely to be overwritten as it should be talloc header memory. Then see debug.c: fr_backtrace_attach() add a call to that in pairalloc Follow the instructions in the doxygen header, you should be able to a basic backtrace for how the memory was originally allocated. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 18/06/14 18:03, Arran Cudbard-Bell wrote:
On 18 Jun 2014, at 16:45, Phil Mayers <p.mayers@IMPERIAL.AC.UK> wrote:
So run under valgrind, I'm reliably seeing use-after-free errors like this:
Invalid read of size 4 at 0x36AD402D84: talloc_get_name (talloc.c:349) by 0x36AD4057EA: _talloc_get_type_abort (talloc.c:1206) by 0x4E470EC: fr_verify_vp (debug.c:829)
Git pull.
Set envvar TALLOC_FREE_FILL=B
Sadly: error: ‘TALLOC_FREE_FILL’ undeclared (first use in this function) Guess it's newer than my talloc version :o(
On 18 Jun 2014, at 18:10, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
On 18/06/14 18:08, Phil Mayers wrote:
Guess it's newer than my talloc version :o(
Oh wait never mind, missing quotes.
Eh, it's a bit of both. The macro isn't in the talloc headers, but the string version should work. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 18/06/14 18:03, Arran Cudbard-Bell wrote:
On 18 Jun 2014, at 16:45, Phil Mayers <p.mayers@IMPERIAL.AC.UK> wrote:
So run under valgrind, I'm reliably seeing use-after-free errors like this:
Invalid read of size 4 at 0x36AD402D84: talloc_get_name (talloc.c:349) by 0x36AD4057EA: _talloc_get_type_abort (talloc.c:1206) by 0x4E470EC: fr_verify_vp (debug.c:829)
Git pull.
Set envvar TALLOC_FREE_FILL=B
Talloc should now abort a little more gracefully.
If it doesn't then lib/debug.c:828
Sorry, none of that seems to work; I just get: Wed Jun 18 19:04:16 2014 : Info: talloc: access after free error - first free may be at src/lib/valuepair.c:171 Wed Jun 18 19:04:16 2014 : Info: Bad talloc magic value - access after free Wed Jun 18 19:04:16 2014 : Info: talloc abort: Bad talloc magic value - access after free Wed Jun 18 19:04:16 2014 : Info: CAUGHT SIGNAL: Aborted Wed Jun 18 19:04:16 2014 : Info: Backtrace of last 17 frames: /opt/fr3/lib/libfreeradius-radius.so(fr_fault+0xd2)[0x7f19f465d674] /opt/fr3/lib/libfreeradius-radius.so(+0xa9af)[0x7f19f465d9af] /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+0xb1)[0x7f19f465e162] /opt/fr3/lib/libfreeradius-radius.so(_fr_cursor_init+0x67)[0x7f19f465c91f] /opt/fr3/lib/libfreeradius-radius.so(fr_verify_list+0x2e)[0x7f19f465e602] /opt/fr3/lib/libfreeradius-server.so(+0x20a7d)[0x7f19f48b4a7d] /opt/fr3/lib/libfreeradius-server.so(verify_request+0xd4)[0x7f19f48b4b5b] /opt/fr3/sbin/radiusd[0x4354b9] /opt/fr3/sbin/radiusd[0x433251] /opt/fr3/lib/libfreeradius-radius.so(fr_event_run+0x142)[0x7f19f46803d9] /opt/fr3/lib/libfreeradius-radius.so(fr_event_loop+0x509)[0x7f19f4680ce6] /opt/fr3/sbin/radiusd(radius_event_process+0x26)[0x43d488] /opt/fr3/sbin/radiusd(main+0xbf5)[0x42a1a5] /lib64/libc.so.6(__libc_start_main+0xfd)[0x379dc1ed1d] /opt/fr3/sbin/radiusd[0x40cd09] ,..and then it calls panic_action and aborts. I can reliably reproduce it now; the trick seems to be to set a bunch of eapol_test running in a loop, stop the server and start it. I think this means it's concurrency/racey. I have some circumstantial evidence that eap_ttls is implicated, and that it might be related to the handling of the fake requests for the inner tunnel - but it's very circumstantial. The heap corruption makes it really hard to be sure of anything - *someone* is trampling over memory they shouldn't, but valgrind seems to get very very confused when this happens, and swamps me with messages.
On 18/06/2014 19:11, Phil Mayers wrote:
I have some circumstantial evidence that eap_ttls is implicated, and that it might be related to the handling of the fake requests for the inner tunnel - but it's very circumstantial. The heap corruption makes it really hard to be sure of anything - *someone* is trampling over memory they shouldn't, but valgrind seems to get very very confused when this happens, and swamps me with messages.
I can reproduce this with an almost-vanilla config now. Changes I made (verified with diff) from the default "make install" config: 1. Adding a client to clients.conf 2. Enabling a test user in "users" with a Cleartext-Password 3. Increase max_requests to 65536 (to allow it to take the test load) 4. Allow vulnerable openssl 5. Throwing a load of PEAP & TTLS at it using "eapol_test -r 1" - 1x PEAP and 3x TTLS requests every 0.1 seconds, like this: while true; do eapol_test -r 1 $PEAP & eapol_test -r 1 $TTLS & eapol_test -r 1 $TTLS & eapol_test -r 1 $TTLS & sleep 0.1 done Under this config it takes a few seconds to minutes to crash, but seems to be pretty reliably doing it under #73629e9
On 18 Jun 2014, at 21:50, Phil Mayers <p.mayers@IMPERIAL.AC.UK> wrote:
On 18/06/2014 19:11, Phil Mayers wrote:
I have some circumstantial evidence that eap_ttls is implicated, and that it might be related to the handling of the fake requests for the inner tunnel - but it's very circumstantial. The heap corruption makes it really hard to be sure of anything - *someone* is trampling over memory they shouldn't, but valgrind seems to get very very confused when this happens, and swamps me with messages.
I can reproduce this with an almost-vanilla config now. Changes I made (verified with diff) from the default "make install" config:
1. Adding a client to clients.conf 2. Enabling a test user in "users" with a Cleartext-Password 3. Increase max_requests to 65536 (to allow it to take the test load) 4. Allow vulnerable openssl 5. Throwing a load of PEAP & TTLS at it using "eapol_test -r 1" - 1x PEAP and 3x TTLS requests every 0.1 seconds, like this:
while true; do eapol_test -r 1 $PEAP & eapol_test -r 1 $TTLS & eapol_test -r 1 $TTLS & eapol_test -r 1 $TTLS & sleep 0.1 done
Under this config it takes a few seconds to minutes to crash, but seems to be pretty reliably doing it under #73629e9
Ok, i'll try and reproduce it tomorrow. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
Phil Mayers wrote:
I can reproduce this with an almost-vanilla config now. Changes I made (verified with diff) from the default "make install" config:
Please re-try with Arran's latest patch. That should fix it. The patch also makes me wonder why I didn't think of that myself... Alan DeKok.
On 18 Jun 2014, at 19:11, Phil Mayers <p.mayers@IMPERIAL.AC.UK> wrote:
On 18/06/14 18:03, Arran Cudbard-Bell wrote:
On 18 Jun 2014, at 16:45, Phil Mayers <p.mayers@IMPERIAL.AC.UK> wrote:
So run under valgrind, I'm reliably seeing use-after-free errors like this:
Invalid read of size 4 at 0x36AD402D84: talloc_get_name (talloc.c:349) by 0x36AD4057EA: _talloc_get_type_abort (talloc.c:1206) by 0x4E470EC: fr_verify_vp (debug.c:829)
Git pull.
Set envvar TALLOC_FREE_FILL=B
Talloc should now abort a little more gracefully.
If it doesn't then lib/debug.c:828
Sorry, none of that seems to work; I just get:
That's still slightly better as you're getting debug output, and panic_action is running? That's what I meant be slightly more gracefully. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 17-06-14 19:05, Arran Cudbard-Bell wrote:
On 17 Jun 2014, at 15:55, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
On 17/06/14 15:33, Phil Mayers wrote:
Will try and re-trigger under valgrind, though memcheck seems to report a *lot* for 3.0.x head - many alloc-without-free for regexp compilations at compile parse time and similar.
Ok, looks like use-after-free somewhere. Valgrind report is really really big, but it looks like the pertinent stuff is:
From the backtrace below we know it's a control attribute.
What modules are you using?
I've got a very similar crash with a nearly vanilla config. Logging and backtrace of it can be found at https://gist.github.com/qnet-herwin/8444b0f2e9304b9432a3 Got this error with 3.0.x (5187f6729b5ff51c5b10f3c4c8bd3da5db72e07b), with two simple changes to the config: disable the ssl check (debian) and enable the user bob from the users file, with the attribute Reply-Message. Then a simple PAP authentication attempt (even with a wrong password) crashes the server. -- Herwin Weststrate
On 18 Jun 2014, at 10:08, Herwin Weststrate <herwin@quarantainenet.nl> wrote:
On 17-06-14 19:05, Arran Cudbard-Bell wrote:
On 17 Jun 2014, at 15:55, Phil Mayers <p.mayers@imperial.ac.uk> wrote:
On 17/06/14 15:33, Phil Mayers wrote:
Will try and re-trigger under valgrind, though memcheck seems to report a *lot* for 3.0.x head - many alloc-without-free for regexp compilations at compile parse time and similar.
Ok, looks like use-after-free somewhere. Valgrind report is really really big, but it looks like the pertinent stuff is:
From the backtrace below we know it's a control attribute.
What modules are you using?
I've got a very similar crash with a nearly vanilla config. Logging and backtrace of it can be found at https://gist.github.com/qnet-herwin/8444b0f2e9304b9432a3
Got this error with 3.0.x (5187f6729b5ff51c5b10f3c4c8bd3da5db72e07b), with two simple changes to the config: disable the ssl check (debian) and enable the user bob from the users file, with the attribute Reply-Message. Then a simple PAP authentication attempt (even with a wrong password) crashes the server.
No, that's different and with older code. Could you run v3.0.x and see if it still occurs. Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 18-06-14 11:10, Arran Cudbard-Bell wrote:
On 18 Jun 2014, at 10:08, Herwin Weststrate <herwin@quarantainenet.nl> wrote:
I've got a very similar crash with a nearly vanilla config. Logging and backtrace of it can be found at https://gist.github.com/qnet-herwin/8444b0f2e9304b9432a3
Got this error with 3.0.x (5187f6729b5ff51c5b10f3c4c8bd3da5db72e07b), with two simple changes to the config: disable the ssl check (debian) and enable the user bob from the users file, with the attribute Reply-Message. Then a simple PAP authentication attempt (even with a wrong password) crashes the server.
No, that's different and with older code. Could you run v3.0.x and see if it still occurs.
This is the current HEAD of v3.0.x, did you mean to ask running it from master? -- Herwin Weststrate
On 18-06-14 11:21, Herwin Weststrate wrote:
On 18-06-14 11:10, Arran Cudbard-Bell wrote:
On 18 Jun 2014, at 10:08, Herwin Weststrate <herwin@quarantainenet.nl> wrote:
I've got a very similar crash with a nearly vanilla config. Logging and backtrace of it can be found at https://gist.github.com/qnet-herwin/8444b0f2e9304b9432a3
Got this error with 3.0.x (5187f6729b5ff51c5b10f3c4c8bd3da5db72e07b), with two simple changes to the config: disable the ssl check (debian) and enable the user bob from the users file, with the attribute Reply-Message. Then a simple PAP authentication attempt (even with a wrong password) crashes the server.
No, that's different and with older code. Could you run v3.0.x and see if it still occurs.
This is the current HEAD of v3.0.x, did you mean to ask running it from master?
Master actually gives a very similar message: https://gist.github.com/qnet-herwin/98cda58811f50a21f815 -- Herwin Weststrate
On 18 Jun 2014, at 11:49, Herwin Weststrate <herwin@quarantainenet.nl> wrote:
On 18-06-14 11:21, Herwin Weststrate wrote:
On 18-06-14 11:10, Arran Cudbard-Bell wrote:
On 18 Jun 2014, at 10:08, Herwin Weststrate <herwin@quarantainenet.nl> wrote:
I've got a very similar crash with a nearly vanilla config. Logging and backtrace of it can be found at https://gist.github.com/qnet-herwin/8444b0f2e9304b9432a3
Got this error with 3.0.x (5187f6729b5ff51c5b10f3c4c8bd3da5db72e07b), with two simple changes to the config: disable the ssl check (debian) and enable the user bob from the users file, with the attribute Reply-Message. Then a simple PAP authentication attempt (even with a wrong password) crashes the server.
No, that's different and with older code. Could you run v3.0.x and see if it still occurs.
This is the current HEAD of v3.0.x, did you mean to ask running it from master?
Master actually gives a very similar message: https://gist.github.com/qnet-herwin/98cda58811f50a21f815
Ok, fixed. This was actually a separate issue but uncovered by adding more sanity checking code. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 18-06-14 13:04, Arran Cudbard-Bell wrote:
On 18 Jun 2014, at 11:49, Herwin Weststrate <herwin@quarantainenet.nl> wrote:
On 18-06-14 11:21, Herwin Weststrate wrote:
On 18-06-14 11:10, Arran Cudbard-Bell wrote:
On 18 Jun 2014, at 10:08, Herwin Weststrate <herwin@quarantainenet.nl> wrote:
I've got a very similar crash with a nearly vanilla config. Logging and backtrace of it can be found at https://gist.github.com/qnet-herwin/8444b0f2e9304b9432a3
Got this error with 3.0.x (5187f6729b5ff51c5b10f3c4c8bd3da5db72e07b), with two simple changes to the config: disable the ssl check (debian) and enable the user bob from the users file, with the attribute Reply-Message. Then a simple PAP authentication attempt (even with a wrong password) crashes the server.
No, that's different and with older code. Could you run v3.0.x and see if it still occurs.
This is the current HEAD of v3.0.x, did you mean to ask running it from master?
Master actually gives a very similar message: https://gist.github.com/qnet-herwin/98cda58811f50a21f815
Ok, fixed. This was actually a separate issue but uncovered by adding more sanity checking code.
Something has changed, but I'm still experiencing crashes, with a slightly different failed message this time: https://gist.github.com/qnet-herwin/e7735052a8d9ba25434c. The dump is made with v3.0.x, master has similar issues. I cut away some of the logs, since the null_context in talloc holds quite a bit of information (like the complete configuration, and tons of rbtrees. -- Herwin Weststrate
On 18 Jun 2014, at 12:32, Herwin Weststrate <herwin@quarantainenet.nl> wrote:
On 18-06-14 13:04, Arran Cudbard-Bell wrote:
On 18 Jun 2014, at 11:49, Herwin Weststrate <herwin@quarantainenet.nl> wrote:
On 18-06-14 11:21, Herwin Weststrate wrote:
On 18-06-14 11:10, Arran Cudbard-Bell wrote:
On 18 Jun 2014, at 10:08, Herwin Weststrate <herwin@quarantainenet.nl> wrote:
I've got a very similar crash with a nearly vanilla config. Logging and backtrace of it can be found at https://gist.github.com/qnet-herwin/8444b0f2e9304b9432a3
Got this error with 3.0.x (5187f6729b5ff51c5b10f3c4c8bd3da5db72e07b), with two simple changes to the config: disable the ssl check (debian) and enable the user bob from the users file, with the attribute Reply-Message. Then a simple PAP authentication attempt (even with a wrong password) crashes the server.
No, that's different and with older code. Could you run v3.0.x and see if it still occurs.
This is the current HEAD of v3.0.x, did you mean to ask running it from master?
Master actually gives a very similar message: https://gist.github.com/qnet-herwin/98cda58811f50a21f815
Ok, fixed. This was actually a separate issue but uncovered by adding more sanity checking code.
Something has changed, but I'm still experiencing crashes, with a slightly different failed message this time: https://gist.github.com/qnet-herwin/e7735052a8d9ba25434c. The dump is made with v3.0.x, master has similar issues. I cut away some of the logs, since the null_context in talloc holds quite a bit of information (like the complete configuration, and tons of rbtrees.
Yeah it won't usually print that unless the chunk was parented directly from the null context. Sorry about that... simple fix (git pull). On a positive note that diagnostic output is starting to look quite nice :) -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 18-06-14 13:37, Arran Cudbard-Bell wrote:
On 18 Jun 2014, at 12:32, Herwin Weststrate <herwin@quarantainenet.nl> wrote:
On 18-06-14 13:04, Arran Cudbard-Bell wrote:
On 18 Jun 2014, at 11:49, Herwin Weststrate <herwin@quarantainenet.nl> wrote:
On 18-06-14 11:21, Herwin Weststrate wrote:
On 18-06-14 11:10, Arran Cudbard-Bell wrote:
On 18 Jun 2014, at 10:08, Herwin Weststrate <herwin@quarantainenet.nl> wrote:
> I've got a very similar crash with a nearly vanilla config. Logging and > backtrace of it can be found at > https://gist.github.com/qnet-herwin/8444b0f2e9304b9432a3 > > Got this error with 3.0.x (5187f6729b5ff51c5b10f3c4c8bd3da5db72e07b), > with two simple changes to the config: disable the ssl check (debian) > and enable the user bob from the users file, with the attribute > Reply-Message. Then a simple PAP authentication attempt (even with a > wrong password) crashes the server.
No, that's different and with older code. Could you run v3.0.x and see if it still occurs.
This is the current HEAD of v3.0.x, did you mean to ask running it from master?
Master actually gives a very similar message: https://gist.github.com/qnet-herwin/98cda58811f50a21f815
Ok, fixed. This was actually a separate issue but uncovered by adding more sanity checking code.
Something has changed, but I'm still experiencing crashes, with a slightly different failed message this time: https://gist.github.com/qnet-herwin/e7735052a8d9ba25434c. The dump is made with v3.0.x, master has similar issues. I cut away some of the logs, since the null_context in talloc holds quite a bit of information (like the complete configuration, and tons of rbtrees.
Yeah it won't usually print that unless the chunk was parented directly from the null context.
Sorry about that... simple fix (git pull).
Getting compile errors now for master: https://gist.github.com/qnet-herwin/62ee17b7342479c3a9fc. v3.0.x compiles (but haven't had the chance to test it yet)
On a positive note that diagnostic output is starting to look quite nice :)
Have to agree to that. -- Herwin Weststrate
On 18 Jun 2014, at 12:54, Herwin Weststrate <herwin@quarantainenet.nl> wrote:
On 18-06-14 13:37, Arran Cudbard-Bell wrote:
On 18 Jun 2014, at 12:32, Herwin Weststrate <herwin@quarantainenet.nl> wrote:
On 18-06-14 13:04, Arran Cudbard-Bell wrote:
On 18 Jun 2014, at 11:49, Herwin Weststrate <herwin@quarantainenet.nl> wrote:
On 18-06-14 11:21, Herwin Weststrate wrote:
On 18-06-14 11:10, Arran Cudbard-Bell wrote: > > On 18 Jun 2014, at 10:08, Herwin Weststrate <herwin@quarantainenet.nl> wrote: > >> I've got a very similar crash with a nearly vanilla config. Logging and >> backtrace of it can be found at >> https://gist.github.com/qnet-herwin/8444b0f2e9304b9432a3 >> >> Got this error with 3.0.x (5187f6729b5ff51c5b10f3c4c8bd3da5db72e07b), >> with two simple changes to the config: disable the ssl check (debian) >> and enable the user bob from the users file, with the attribute >> Reply-Message. Then a simple PAP authentication attempt (even with a >> wrong password) crashes the server. > > No, that's different and with older code. Could you run v3.0.x and see > if it still occurs.
This is the current HEAD of v3.0.x, did you mean to ask running it from master?
Master actually gives a very similar message: https://gist.github.com/qnet-herwin/98cda58811f50a21f815
Ok, fixed. This was actually a separate issue but uncovered by adding more sanity checking code.
Something has changed, but I'm still experiencing crashes, with a slightly different failed message this time: https://gist.github.com/qnet-herwin/e7735052a8d9ba25434c. The dump is made with v3.0.x, master has similar issues. I cut away some of the logs, since the null_context in talloc holds quite a bit of information (like the complete configuration, and tons of rbtrees.
Yeah it won't usually print that unless the chunk was parented directly from the null context.
Sorry about that... simple fix (git pull).
Getting compile errors now for master:
Yeah sorry fixed already... My time and attention is more fragmented than usual and it's leading to more mistakes. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS Development Team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
On 18-06-14 14:13, Phil Mayers wrote:
On 18/06/14 12:57, Arran Cudbard-Bell wrote:
Yeah sorry fixed already... My time and attention is more fragmented than usual and it's leading to more mistakes.
Arran,
I think we all appreciate your hard work; no need to apologise!
Fully agree to this. Never before I've seen an open source project where most bugs are fixed in less than 24 hours after reporting. Here it's mostly in less than 24 minutes. -- Herwin Weststrate
On 18-06-14 13:57, Arran Cudbard-Bell wrote:
On 18 Jun 2014, at 12:54, Herwin Weststrate <herwin@quarantainenet.nl> wrote:
On 18-06-14 13:37, Arran Cudbard-Bell wrote:
On 18 Jun 2014, at 12:32, Herwin Weststrate <herwin@quarantainenet.nl> wrote:
On 18-06-14 13:04, Arran Cudbard-Bell wrote:
On 18 Jun 2014, at 11:49, Herwin Weststrate <herwin@quarantainenet.nl> wrote:
On 18-06-14 11:21, Herwin Weststrate wrote: > On 18-06-14 11:10, Arran Cudbard-Bell wrote: >> >> On 18 Jun 2014, at 10:08, Herwin Weststrate <herwin@quarantainenet.nl> wrote: >> >>> I've got a very similar crash with a nearly vanilla config. Logging and >>> backtrace of it can be found at >>> https://gist.github.com/qnet-herwin/8444b0f2e9304b9432a3 >>> >>> Got this error with 3.0.x (5187f6729b5ff51c5b10f3c4c8bd3da5db72e07b), >>> with two simple changes to the config: disable the ssl check (debian) >>> and enable the user bob from the users file, with the attribute >>> Reply-Message. Then a simple PAP authentication attempt (even with a >>> wrong password) crashes the server. >> >> No, that's different and with older code. Could you run v3.0.x and see >> if it still occurs. > > This is the current HEAD of v3.0.x, did you mean to ask running it from > master?
Master actually gives a very similar message: https://gist.github.com/qnet-herwin/98cda58811f50a21f815
Ok, fixed. This was actually a separate issue but uncovered by adding more sanity checking code.
Something has changed, but I'm still experiencing crashes, with a slightly different failed message this time: https://gist.github.com/qnet-herwin/e7735052a8d9ba25434c. The dump is made with v3.0.x, master has similar issues. I cut away some of the logs, since the null_context in talloc holds quite a bit of information (like the complete configuration, and tons of rbtrees.
Yeah it won't usually print that unless the chunk was parented directly from the null context.
Sorry about that... simple fix (git pull).
Getting compile errors now for master:
Yeah sorry fixed already... My time and attention is more fragmented than usual and it's leading to more mistakes.
Both v3.0.x and master compile and users from files with extra attributes work as well. I'm still triggering an error with 3.0.x, but that's with a completely unrelated configuration, I'll send a new e-mail to the list once I've got that one narrowed down. -- Herwin Weststrate
participants (4)
-
Alan DeKok -
Arran Cudbard-Bell -
Herwin Weststrate -
Phil Mayers