segfault in current master
Just tried to build current master branch under OSX: ./configure -with-redis-include-dir=/usr/local/include/hiredis --enable-boilermake --prefix=/Users/brian/Build/freeradius-master && make && make install (Note: This is from a git checkout where I had switched branches, but I have done a "make distclean" first) Then I symlinked ../mods-available/redis and rediswho into mods-enabled/. That's the only config change I made. Started it with sbin/radiusd -X (as unpriviledged user), send a radclient packet like this: echo -e "User-Name = brian\nFramed-IP-Address = 1.2.3.4\nAcct-Status-Type = Start\n" | bin/radclient localhost acct testing123 and this is what happened: rad_recv: Accounting-Request packet from host 127.0.0.1 port 54630, id=248, length=39 User-Name = "brian" Framed-IP-Address = 1.2.3.4 Acct-Status-Type = Start (0) # Executing section preacct from file /Users/brian/Build/freeradius-master/etc/raddb/sites-enabled/default (0) group preacct { (0) - entering group preacct {...} (0) [preprocess] = ok (0) policy acct_unique { (0) - entering policy acct_unique {...} (0) ? if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) (0) expand: '%{string:Class}' -> '' Segmentation fault: 11 Oops. But annoyingly, running it again under gdb it was fine: gdb sbin/radiusd run -X ... rad_recv: Accounting-Request packet from host 127.0.0.1 port 62354, id=3, length=39 User-Name = "brian" Framed-IP-Address = 1.2.3.4 Acct-Status-Type = Start (0) # Executing section preacct from file /Users/brian/Build/freeradius-master/etc/raddb/sites-enabled/default (0) group preacct { (0) - entering group preacct {...} (0) [preprocess] = ok (0) policy acct_unique { (0) - entering policy acct_unique {...} (0) ? if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) (0) expand: '%{string:Class}' -> '' (0) ? Evaluating ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) -> FALSE (0) ? if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) -> FALSE (0) else else { (0) - entering else else {...} (0) update request { (0) expand: '%{User-Name}%{Acct-Session-ID}%{NAS-IP-Address}%{NAS-Identifier}%{NAS-Port-ID}%{NAS-Port}' -> 'brian127.0.0.1' (0) expand: '%{md5:%{User-Name}%{Acct-Session-ID}%{NAS-IP-Address}%{NAS-Identifier}%{NAS-Port-ID}%{NAS-Port}}' -> '434d399a6c4094ac3ee91533331275e8' (0) } # update request = ok (0) - else else returns ok (0) - policy acct_unique returns ok (0) suffix : No '@' in User-Name = "brian", looking up realm NULL (0) suffix : No such realm "NULL" (0) [suffix] = noop (0) [files] = noop (0) # Executing section accounting from file /Users/brian/Build/freeradius-master/etc/raddb/sites-enabled/default (0) group accounting { (0) - entering group accounting {...} (0) detail : expand: '%{Packet-Src-IP-Address}' -> '127.0.0.1' (0) detail : expand: '/Users/brian/Build/freeradius-master/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d' -> '/Users/brian/Build/freeradius-master/var/log/radius/radacct/127.0.0.1/detail-20130214' (0) detail : /Users/brian/Build/freeradius-master/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /Users/brian/Build/freeradius-master/var/log/radius/radacct/127.0.0.1/detail-20130214 (0) detail : expand: '%t' -> 'Thu Feb 14 14:58:07 2013' (0) [detail] = ok (0) [unix] = noop (0) [exec] = noop (0) attr_filter.accounting_response : expand: '%{User-Name}' -> 'brian' (0) attr_filter.accounting_response : Matched entry DEFAULT at line 12 (0) [attr_filter.accounting_response] = updated Sending Accounting-Response of id 3 from 0.0.0.0 port 1813 to 127.0.0.1 port 62354 (0) Finished request 0. Waking up in 0.3 seconds. (0) Cleaning up request packet ID 3 with timestamp +41 Ready to process requests. Running again without gdb, it still crashes. So next thing is to try to get a core dump: (configure: allow_core_dumps = yes in radiusd.conf) (check /cores directory is writeable) ulimit -c unlimited sbin/radiusd -X Crashes but no dump :-( Suspiciously, the message "Core dumps are enabled." does not appear on the console output. I'll keep poking around, but if someone knows why the core dumps aren't being created, that would save me some time. Cheers, Brian.
On Thu, Feb 14, 2013 at 03:17:49PM +0000, Brian Candler wrote:
I'll keep poking around, but if someone knows why the core dumps aren't being created, that would save me some time.
In switch_users(): /* * Don't do chroot/setuid/setgid if we're in debugging * as non-root. */ if (debug_flag && (getuid() != 0)) return 1; So that's why I don't see the radlog message. But if core dumps are allowed at the start, I can't see why they are being disabled. Anyway, if I run sbin/radiusd -f instead of sbin/radiusd -X then I get the core dump: 389M of it. Reading symbols for shared libraries . done Reading symbols for shared libraries .......................................................................... done #0 0x00007fff8e477df2 in select$DARWIN_EXTSN () (gdb) bt #0 0x00007fff8e477df2 in select$DARWIN_EXTSN () #1 0x000000010910efc0 in fr_event_loop (el=0x7f99e3815200) at event.c:391 #2 0x000000010907a7ad in radius_event_process () at process.c:4233 #3 0x000000010905c9b8 in main (argc=2, argv=0x7fff68c30bd8) at radiusd.c:428 (gdb) thread apply all bt Thread 6 (core thread 5): #0 0x00007fff8e4766b6 in semaphore_wait_trap () #1 0x000000010906525b in request_handler_thread (arg=0x7f99e352e010) at threads.c:567 #2 0x00007fff943628bf in _pthread_start () #3 0x00007fff94365b75 in thread_start () Thread 5 (core thread 4): #0 0x00007fff8e4766b6 in semaphore_wait_trap () #1 0x000000010906525b in request_handler_thread (arg=0x7f99e352dfd0) at threads.c:567 #2 0x00007fff943628bf in _pthread_start () #3 0x00007fff94365b75 in thread_start () Thread 4 (core thread 3): #0 0x00007fff8e4766b6 in semaphore_wait_trap () #1 0x000000010906525b in request_handler_thread (arg=0x7f99e352df90) at threads.c:567 #2 0x00007fff943628bf in _pthread_start () #3 0x00007fff94365b75 in thread_start () Thread 3 (core thread 2): #0 0x00007fff8e4766b6 in semaphore_wait_trap () #1 0x000000010906525b in request_handler_thread (arg=0x7f99e352df50) at threads.c:567 #2 0x00007fff943628bf in _pthread_start () #3 0x00007fff94365b75 in thread_start () Thread 2 (core thread 1): #0 0x00007fff94394eab in regexec () #1 0x0000000109081d01 in radius_do_cmp (request=0x7f99e352e430, presult=0x1097a4a14, lt=T_DOUBLE_QUOTED_STRING, pleft=0x1097a3dd0 "", token=T_OP_REG_EQ, rt=T_DOUBLE_QUOTED_STRING, ---Type <return> to continue, or q <return> to quit--- pright=0x1097a41e4 "ai:([0-9a-f]{32})", cflags=1, modreturn=2) at evaluate.c:393 #2 0x0000000109082e03 in radius_evaluate_condition (request=0x7f99e352e430, modreturn=2, depth=1, ptr=0x1097a4c30, evaluate_it=1, presult=0x1097a5c84) at evaluate.c:743 #3 0x000000010908241e in radius_evaluate_condition (request=0x7f99e352e430, modreturn=2, depth=0, ptr=0x1097a6960, evaluate_it=1, presult=0x1097a696c) at evaluate.c:525 #4 0x00000001090570ef in modcall (component=2, c=0x7f99e3527560, request=0x7f99e352e430) at modcall.c:468 #5 0x0000000109053fde in indexed_modcall (comp=2, idx=0, request=0x7f99e352e430) at modules.c:801 #6 0x0000000109055f29 in module_preacct (request=0x7f99e352e430) at modules.c:1666 #7 0x0000000109031b28 in rad_accounting (request=0x7f99e352e430) at acct.c:57 #8 0x000000010907223e in request_running (request=0x7f99e352e430, action=1) at process.c:1197 #9 0x000000010906553c in request_handler_thread (arg=0x7f99e352df10) at threads.c:637 #10 0x00007fff943628bf in _pthread_start () #11 0x00007fff94365b75 in thread_start () Thread 1 (core thread 0): #0 0x00007fff8e477df2 in select$DARWIN_EXTSN () #1 0x000000010910efc0 in fr_event_loop (el=0x7f99e3815200) at event.c:391 #2 0x000000010907a7ad in radius_event_process () at process.c:4233 #3 0x000000010905c9b8 in main (argc=2, argv=0x7fff68c30bd8) at radiusd.c:428 (gdb) Hmm, so it looks like thread 2. (gdb) thread 2 [Switching to thread 2 (core thread 1)] 0x00007fff94394eab in regexec () (gdb) frame 1 #1 0x0000000109081d01 in radius_do_cmp (request=0x7f99e352e430, presult=0x1097a4a14, lt=T_DOUBLE_QUOTED_STRING, pleft=0x1097a3dd0 "", token=T_OP_REG_EQ, rt=T_DOUBLE_QUOTED_STRING, pright=0x1097a41e4 "ai:([0-9a-f]{32})", cflags=1, modreturn=2) at evaluate.c:393 393 compare = regexec(®, pleft, (gdb) print reg $3 = {re_pcre = 0xf265, re_nsub = 1, re_erroffset = 0} (gdb) print pleft $4 = 0x1097a3dd0 "" (gdb) print rxmatch $5 = {{rm_so = 0, rm_eo = 0}, {rm_so = 0, rm_eo = 0}, {rm_so = 0, rm_eo = 0}, { rm_so = 0, rm_eo = 0}, {rm_so = 0, rm_eo = 0}, {rm_so = 0, rm_eo = 0}, { rm_so = 0, rm_eo = 0}, {rm_so = 0, rm_eo = 0}, {rm_so = 0, rm_eo = 0}} (gdb) Very strange: obviously regcomp succeeded, so why should regexec crash? And why not when run under gdb?? So I made a completely clean checkout and built from scratch. Exactly the same problem. Any ideas? Cheers, Brian.
Brian Candler wrote:
Very strange: obviously regcomp succeeded, so why should regexec crash?
Memory corruption? Access to free'd resources?
And why not when run under gdb??
So I made a completely clean checkout and built from scratch. Exactly the same problem.
Any ideas?
Valgrind. Alan Dekok.
On 14 Feb 2013, at 11:36, Alan DeKok <aland@DEPLOYINGRADIUS.COM> wrote:
Brian Candler wrote:
Very strange: obviously regcomp succeeded, so why should regexec crash?
Memory corruption? Access to free'd resources?
And why not when run under gdb??
So I made a completely clean checkout and built from scratch. Exactly the same problem.
Any ideas?
Valgrind.
The test case was pretty simple, but I can't produce the crash and valgrind shows nothing (but that may be because it's broken on OSX 10.8) User-Name = "testu" Framed-IP-Address = 1.2.3.4 Acct-Status-Type = Start (1) # Executing section preacct from file /usr/local/freeradius/etc/raddb/sites-enabled/default (1) group preacct { (1) - entering group preacct {...} (1) [preprocess] = ok (1) policy acct_unique { (1) - entering policy acct_unique {...} (1) ? if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) (1) expand: '%{string:Class}' -> '' (1) ? Evaluating ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) -> FALSE (1) ? if ("%{string:Class}" =~ /ai:([0-9a-f]{32})/i) -> FALSE (1) else else { Brian, could you post the results of running it under valgrind? -Arran
On Thu, Feb 14, 2013 at 12:06:24PM -0500, Arran Cudbard-Bell wrote:
Brian, could you post the results of running it under valgrind?
OK, this is with valgrind 3.8.1 installed from homebrew, no options specified, just valgrind sbin/radiusd -X Unfortunately when run like this, radiusd doesn't segfault any more (same as when it was run under gdb). There are lots of warnings while starting up due to OpenSSL, but none shown when processing the request. Any other ideas? Brian.
On 14 Feb 2013, at 13:35, Brian Candler <B.Candler@pobox.com> wrote:
On Thu, Feb 14, 2013 at 12:06:24PM -0500, Arran Cudbard-Bell wrote:
Brian, could you post the results of running it under valgrind?
OK, this is with valgrind 3.8.1 installed from homebrew, no options specified, just
valgrind sbin/radiusd -X
Unfortunately when run like this, radiusd doesn't segfault any more (same as when it was run under gdb). There are lots of warnings while starting up due to OpenSSL, but none shown when processing the request.
Any other ideas?
Apparently Alan just pushed some fixes to xlat.c.
On Thu, Feb 14, 2013 at 01:37:48PM -0500, Arran Cudbard-Bell wrote:
Apparently Alan just pushed some fixes to xlat.c.
I can't see them yet: $ git log ./src/main/xlat.c commit bc06a68ef97c654f54f6947125e548e04c5b2709 Author: Arran Cudbard-Bell <a.cudbardb@freeradius.org> Date: Tue Feb 12 18:58:51 2013 -0500 commit 953e166d9711744474db134a5a4a7744016e1753 Author: Arran Cudbard-Bell <a.cudbardb@freeradius.org> Date: Sun Jan 20 12:42:55 2013 +0000
participants (3)
-
Alan DeKok -
Arran Cudbard-Bell -
Brian Candler