I'm having the exact same problem as described below, with Freeradius
1.7 hanging at 99 percent. Also using PEAP, MSCHAPV2, and eDir, and
running 1.7 on a SLES 10 SP1.
I have been using the same configuration since 1.3 without any problems
problems, but since upgrading from 1.6 to 1.7 it's "crashed" 3 times
within a month.
This is the last line of my log files each time it hangs at 99
percent:
usr/local/var/log/radius/radius.log-20070928.bz2:Thu Sep 27 16:32:23
2007 : Error: Discarding duplicate request from client 3WXM-2:20006 -
ID: 247 due to unfinished request 23061
/usr/local/var/log/radius/radius.log-20071010.bz2:Sun Oct 7 21:19:47
2007 : Error: Discarding duplicate request from client 3WXM-1:20002 -
ID: 188 due to unfinished request 60866
/usr/local/var/log/radius/radius.log-20071024.bz2:Wed Oct 24 08:10:05
2007 : Error: Discarding duplicate request from client 3WXM-2:20008 -
ID: 211 due to unfinished request 94412
As per Phil Mayers request, I recompiled with the developer option (and
--edir as I am using that). The following is the output:
Attaching to program: /usr/local/sbin/radiusd, process 23141
Loaded symbols for /usr/local/sbin/radiusd
Reading symbols from /lib/libnsl.so.1...done.
Loaded symbols for /lib/libnsl.so.1
Reading symbols from /lib/libresolv.so.2...done.
Loaded symbols for /lib/libresolv.so.2
Reading symbols from /lib/libpthread.so.0...done.
[Thread debugging using libthread_db enabled]
[New Thread -1212410192 (LWP 23141)]
[New Thread -1272144992 (LWP 3414)]
[New Thread -1263752288 (LWP 1784)]
[New Thread -1255359584 (LWP 1757)]
[New Thread -1246966880 (LWP 23146)]
[New Thread -1238574176 (LWP 23145)]
[New Thread -1230181472 (LWP 23144)]
[New Thread -1221788768 (LWP 23143)]
[New Thread -1213396064 (LWP 23142)]
Loaded symbols for /lib/libpthread.so.0
Reading symbols from /usr/local/lib/libradius-1.1.7.so...done.
Loaded symbols for /usr/local/lib/libradius-1.1.7.so
Reading symbols from /lib/libcrypt.so.1...done.
Loaded symbols for /lib/libcrypt.so.1
Reading symbols from /usr/lib/libltdl.so.3...done.
Loaded symbols for /usr/lib/libltdl.so.3
Reading symbols from /lib/libdl.so.2...done.
Loaded symbols for /lib/libdl.so.2
Reading symbols from /usr/lib/libssl.so.0.9.8...done.
Loaded symbols for /usr/lib/libssl.so.0.9.8
Reading symbols from /usr/lib/libcrypto.so.0.9.8...done.
Loaded symbols for /usr/lib/libcrypto.so.0.9.8
Reading symbols from /lib/libc.so.6...done.
Loaded symbols for /lib/libc.so.6
Reading symbols from /lib/ld-linux.so.2...done.
Loaded symbols for /lib/ld-linux.so.2
Reading symbols from /lib/libnss_files.so.2...done.
Loaded symbols for /lib/libnss_files.so.2
Reading symbols from /usr/local/lib/rlm_exec-1.1.7.so...done.
Loaded symbols for /usr/local/lib/rlm_exec-1.1.7.so
Reading symbols from /usr/local/lib/rlm_expr-1.1.7.so...done.
Loaded symbols for /usr/local/lib/rlm_expr-1.1.7.so
Reading symbols from /usr/local/lib/rlm_pap-1.1.7.so...done.
Loaded symbols for /usr/local/lib/rlm_pap-1.1.7.so
Reading symbols from /usr/local/lib/rlm_mschap-1.1.7.so...done.
Loaded symbols for /usr/local/lib/rlm_mschap-1.1.7.so
Reading symbols from /usr/local/lib/rlm_ldap-1.1.7.so...done.
Loaded symbols for /usr/local/lib/rlm_ldap-1.1.7.so
Reading symbols from /usr/lib/libldap_r-2.3.so.0...done.
Loaded symbols for /usr/lib/libldap_r-2.3.so.0
Reading symbols from /usr/lib/liblber-2.3.so.0...done.
Loaded symbols for /usr/lib/liblber-2.3.so.0
Reading symbols from /usr/lib/libsasl2.so.2...done.
Loaded symbols for /usr/lib/libsasl2.so.2
Reading symbols from /usr/local/lib/rlm_unix-1.1.7.so...done.
Loaded symbols for /usr/local/lib/rlm_unix-1.1.7.so
Reading symbols from /usr/local/lib/rlm_eap-1.1.7.so...done.
Loaded symbols for /usr/local/lib/rlm_eap-1.1.7.so
Reading symbols from /usr/local/lib/libeap-1.1.7.so...done.
Loaded symbols for /usr/local/lib/libeap-1.1.7.so
Reading symbols from /usr/local/lib/rlm_eap_md5-1.1.7.so...done.
Loaded symbols for /usr/local/lib/rlm_eap_md5-1.1.7.so
Reading symbols from /usr/local/lib/rlm_eap_leap-1.1.7.so...done.
Loaded symbols for /usr/local/lib/rlm_eap_leap-1.1.7.so
Reading symbols from /usr/local/lib/rlm_eap_gtc-1.1.7.so...done.
Loaded symbols for /usr/local/lib/rlm_eap_gtc-1.1.7.so
Reading symbols from /usr/local/lib/rlm_eap_tls-1.1.7.so...done.
Loaded symbols for /usr/local/lib/rlm_eap_tls-1.1.7.so
Reading symbols from /usr/local/lib/rlm_eap_ttls-1.1.7.so...done.
Loaded symbols for /usr/local/lib/rlm_eap_ttls-1.1.7.so
Reading symbols from /usr/local/lib/rlm_eap_peap-1.1.7.so...done.
Loaded symbols for /usr/local/lib/rlm_eap_peap-1.1.7.so
Reading symbols from /usr/local/lib/rlm_eap_mschapv2-1.1.7.so...done.
Loaded symbols for /usr/local/lib/rlm_eap_mschapv2-1.1.7.so
Reading symbols from /usr/local/lib/rlm_realm-1.1.7.so...done.
Loaded symbols for /usr/local/lib/rlm_realm-1.1.7.so
Reading symbols from /usr/local/lib/rlm_preprocess-1.1.7.so...done.
Loaded symbols for /usr/local/lib/rlm_preprocess-1.1.7.so
Reading symbols from /usr/local/lib/rlm_files-1.1.7.so...done.
Loaded symbols for /usr/local/lib/rlm_files-1.1.7.so
Reading symbols from /usr/local/lib/rlm_acct_unique-1.1.7.so...done.
Loaded symbols for /usr/local/lib/rlm_acct_unique-1.1.7.so
Reading symbols from /usr/local/lib/rlm_detail-1.1.7.so...done.
Loaded symbols for /usr/local/lib/rlm_detail-1.1.7.so
Reading symbols from /usr/local/lib/rlm_radutmp-1.1.7.so...done.
Loaded symbols for /usr/local/lib/rlm_radutmp-1.1.7.so
0xffffe410 in __kernel_vsyscall ()
Thread 9 (Thread -1213396064 (LWP 23142)):
#0 0xffffe410 in __kernel_vsyscall ()
No symbol table info available.
#1 0xb7ea9faf in sem_wait(a)GLIBC_2.0 () from /lib/libpthread.so.0
No symbol table info available.
#2 0x800148ce in request_handler_thread (arg=0x80118b30) at
threads.c:534
fun = (RAD_REQUEST_FUNP) 0x80005a30 <rad_authenticate>
set = {__val = {16391, 0 <repeats 31 times>}}
#3 0xb7ea42ab in start_thread () from /lib/libpthread.so.0
No symbol table info available.
#4 0xb7c81a4e in clone () from /lib/libc.so.6
No symbol table info available.
Thread 8 (Thread -1221788768 (LWP 23143)):
#0 0xffffe410 in __kernel_vsyscall ()
No symbol table info available.
#1 0xb7ea9faf in sem_wait(a)GLIBC_2.0 () from /lib/libpthread.so.0
No symbol table info available.
#2 0x800148ce in request_handler_thread (arg=0x8011d080) at
threads.c:534
fun = (RAD_REQUEST_FUNP) 0x80005a30 <rad_authenticate>
set = {__val = {16391, 0 <repeats 31 times>}}
#3 0xb7ea42ab in start_thread () from /lib/libpthread.so.0
No symbol table info available.
#4 0xb7c81a4e in clone () from /lib/libc.so.6
No symbol table info available.
Thread 7 (Thread -1230181472 (LWP 23144)):
#0 0xffffe410 in __kernel_vsyscall ()
No symbol table info available.
#1 0xb7ea9faf in sem_wait(a)GLIBC_2.0 () from /lib/libpthread.so.0
No symbol table info available.
#2 0x800148ce in request_handler_thread (arg=0x8011d138) at
threads.c:534
fun = (RAD_REQUEST_FUNP) 0x80005a30 <rad_authenticate>
set = {__val = {16391, 0 <repeats 31 times>}}
#3 0xb7ea42ab in start_thread () from /lib/libpthread.so.0
No symbol table info available.
#4 0xb7c81a4e in clone () from /lib/libc.so.6
No symbol table info available.
Thread 6 (Thread -1238574176 (LWP 23145)):
#0 0xffffe410 in __kernel_vsyscall ()
No symbol table info available.
#1 0xb7ea9faf in sem_wait(a)GLIBC_2.0 () from /lib/libpthread.so.0
No symbol table info available.
#2 0x800148ce in request_handler_thread (arg=0x8011d1f0) at
threads.c:534
fun = (RAD_REQUEST_FUNP) 0x80005a30 <rad_authenticate>
set = {__val = {16391, 0 <repeats 31 times>}}
#3 0xb7ea42ab in start_thread () from /lib/libpthread.so.0
No symbol table info available.
#4 0xb7c81a4e in clone () from /lib/libc.so.6
No symbol table info available.
Thread 5 (Thread -1246966880 (LWP 23146)):
#0 0xffffe410 in __kernel_vsyscall ()
No symbol table info available.
#1 0xb7ea9faf in sem_wait(a)GLIBC_2.0 () from /lib/libpthread.so.0
No symbol table info available.
#2 0x800148ce in request_handler_thread (arg=0x8011d2a8) at
threads.c:534
fun = (RAD_REQUEST_FUNP) 0x80005a30 <rad_authenticate>
set = {__val = {16391, 0 <repeats 31 times>}}
#3 0xb7ea42ab in start_thread () from /lib/libpthread.so.0
No symbol table info available.
#4 0xb7c81a4e in clone () from /lib/libc.so.6
No symbol table info available.
Thread 4 (Thread -1255359584 (LWP 1757)):
#0 0xffffe410 in __kernel_vsyscall ()
No symbol table info available.
#1 0xb7ea9faf in sem_wait(a)GLIBC_2.0 () from /lib/libpthread.so.0
No symbol table info available.
#2 0x800148ce in request_handler_thread (arg=0x801a4d20) at
threads.c:534
fun = (RAD_REQUEST_FUNP) 0x80005a30 <rad_authenticate>
set = {__val = {16391, 0 <repeats 31 times>}}
#3 0xb7ea42ab in start_thread () from /lib/libpthread.so.0
No symbol table info available.
#4 0xb7c81a4e in clone () from /lib/libc.so.6
No symbol table info available.
Thread 3 (Thread -1263752288 (LWP 1784)):
#0 0xffffe410 in __kernel_vsyscall ()
No symbol table info available.
#1 0xb7ea9faf in sem_wait(a)GLIBC_2.0 () from /lib/libpthread.so.0
No symbol table info available.
#2 0x800148ce in request_handler_thread (arg=0x80153e70) at
threads.c:534
fun = (RAD_REQUEST_FUNP) 0x80005a30 <rad_authenticate>
set = {__val = {16391, 0 <repeats 31 times>}}
#3 0xb7ea42ab in start_thread () from /lib/libpthread.so.0
No symbol table info available.
#4 0xb7c81a4e in clone () from /lib/libc.so.6
No symbol table info available.
Thread 2 (Thread -1272144992 (LWP 3414)):
#0 0xb7c28b0d in _int_malloc () from /lib/libc.so.6
No symbol table info available.
#1 0xb7c2a085 in calloc () from /lib/libc.so.6
No symbol table info available.
#2 0xb7c5dd75 in re_acquire_state_context () from /lib/libc.so.6
No symbol table info available.
#3 0xb7c63c01 in re_compile_internal () from /lib/libc.so.6
No symbol table info available.
#4 0xb7c64cc4 in regcomp () from /lib/libc.so.6
No symbol table info available.
#5 0x800161df in paircmp (req=0x80242e50, request=0xb391bf68,
check=0x80118008, reply=0x80175368) at valuepair.c:365
i = <value optimized out>
rxmatch = {{rm_so = 0, rm_eo = -1272151048}, {rm_so =
-2147422548, rm_eo = 0}, {rm_so = -2146357296, rm_eo = -2145114136},
{rm_so = -2147359520, rm_eo = -2146357296}, {rm_so = 0, rm_eo =
-1272150952}, {rm_so = -2147423649, rm_eo = -1272150972}, {rm_so =
-1272150968, rm_eo = -1272151000}, {rm_so = -1209472631, rm_eo =
-1272150920}, {rm_so = -2146465632, rm_eo = 1036177532}}
check_item = (VALUE_PAIR *) 0x80118008
auth_item = (VALUE_PAIR *) 0xb3912ef8
compare = <value optimized out>
other = 1
reg = {buffer = 0xb39248f0 "\220ã\221³*", allocated = 140, used
= 140, syntax = 242428, fastmap = 0xb3911510 "H\001\220³H\001\220³",
translate = 0x0, re_nsub = 0, can_be_null = 0, regs_allocated = 0,
fastmap_accurate = 0, no_sub = 0, not_bol = 0, not_eol = 0,
newline_anchor = 0}
#6 0xb7adb092 in file_authorize (instance=0x801067f0,
request=0x80242e50) at rlm_files.c:321
namepair = <value optimized out>
request_pairs = (VALUE_PAIR *) 0xb391bf68
check_tmp = (VALUE_PAIR *) 0xb7ade2ab
reply_tmp = (VALUE_PAIR *) 0x802427e8
pl = (PAIR_LIST *) 0x80118d68
found = 0
check_pairs = (VALUE_PAIR **) 0x80242e60
reply_pairs = (VALUE_PAIR **) 0x80175368
check_save = (VALUE_PAIR *) 0x6
#7 0x8000e85f in modcall (component=1, c=0x80117980,
request=0x80242e50) at modcall.c:238
myresult = 6
#8 0x8000eeac in call_one (component=676979, p=0x0,
request=0xffffffc0, priority=0xb42c8574, result=0xb42c8578) at
modcall.c:272
r = <value optimized out>
#9 0x8000ea5f in modcall (component=1, c=0x801155d8,
request=0x80242e50) at modcall.c:327
g = (modgroup *) 0x801155d8
myresult = 6
#10 0x8000cade in indexed_modcall (comp=1, idx=0, request=0x80242e50)
at modules.c:469
this = (indexed_modcallable *) 0x80115680
#11 0x80005b10 in rad_authenticate (request=0x80242e50) at auth.c:602
namepair = <value optimized out>
check_item = <value optimized out>
reply_item = <value optimized out>
auth_item = (VALUE_PAIR *) 0x0
module_msg = <value optimized out>
tmp = (VALUE_PAIR *) 0x0
result = <value optimized out>
r = <value optimized out>
umsg =
"\221,´Ý´è·Ø\234\002\200h\221,´x\221,´\211éè·È\221,´('\221³\027f\220ÝX\237\002\200H\001\000\000à\nη\000\000\000\000£êè·ô\017η\020\000\220³\000\000\000\000¨\221,´P\000\000\000\020\000\220³D\001\000\000hÙé·\000\000\000\0000'\221³Ø\221,´m
é·
©%\200\024\000\000\000D\001\000\000l\000\000\000\000\000\000\000\032\000\000\0000'\221³hÙé·\000\000\000\0000'\221³X\222,´ÊOé·
©%\200\024\000\000\000\020\000\000\000\\\221é·ô\017ηl'\221³`X
\200\200ª%\200\000\000\000\000\020\000\000\000\000\000\000\000\001\000\000\000\001"...
user_msg = <value optimized out>
exec_program = <value optimized out>
exec_wait = <value optimized out>
seen_callback_id = <value optimized out>
buf = '\0' <repeats 100 times>,
"3T·\004rÁ·\000\000\000\000\000\000\000\0004\220,´
\233,´ô\017ηz²é·t\221,´Ä\220,´üè¿·à\220,´z²é·", '\0' <repeats 20
times>, " \233,´\227÷¿·\000\000\000\000\000\000\000\000
\220,´\000\000\000\000\000\000\000\0004\220,´\000\000\000\000\000\000\000\0003T·\004rÁ·\000\000\000\000\032\000\000\000¤\220,´t\221,´ô\017η\237\223\001\200ä\221,´4\221,´üè¿·P\221,´\000\000\000\000ÿÿÿÿ\v\000\000\000o²é·4\220,´\003\000\000\000\n",
'\0' <repeats 15 times>, "\n\000\000\0002"...
logstr = '\0' <repeats 1023 times>
autz_retry = 0 '\0'
autz_type = 676979
#12 0x80010087 in rad_respond (request=0x80242e50, fun=0x80005a30
<rad_authenticate>) at radiusd.c:1669
rcode = <value optimized out>
packet = <value optimized out>
original = <value optimized out>
secret = 0x80242e70 "Troldhavelaage900#"
finished = <value optimized out>
reprocess = <value optimized out>
#13 0x800149ec in request_handler_thread (arg=0x801bfb30) at
threads.c:570
fun = (RAD_REQUEST_FUNP) 0x80005a30 <rad_authenticate>
set = {__val = {16391, 0 <repeats 31 times>}}
#14 0xb7ea42ab in start_thread () from /lib/libpthread.so.0
No symbol table info available.
#15 0xb7c81a4e in clone () from /lib/libc.so.6
No symbol table info available.
Thread 1 (Thread -1212410192 (LWP 23141)):
#0 0xffffe410 in __kernel_vsyscall ()
No symbol table info available.
#1 0xb7c8d57e in __lll_mutex_lock_wait () from /lib/libc.so.6
No symbol table info available.
#2 0xb7c2b111 in _L_mutex_lock_4125 () from /lib/libc.so.6
No symbol table info available.
#3 0xb7b5e598 in ?? () from /usr/lib/libldap_r-2.3.so.0
No symbol table info available.
#4 0xb7ea735c in __pthread_mutex_unlock_usercnt () from
/lib/libpthread.so.0
No symbol table info available.
#5 0xb7b1e31a in ber_memfree_x () from /usr/lib/liblber-2.3.so.0
No symbol table info available.
#6 0xb7b3b67a in ldap_ld_free () from /usr/lib/libldap_r-2.3.so.0
No symbol table info available.
#7 0xb7b3b8a6 in ldap_unbind_ext () from /usr/lib/libldap_r-2.3.so.0
No symbol table info available.
#8 0xb7b3b93d in ldap_unbind_s () from /usr/lib/libldap_r-2.3.so.0
No symbol table info available.
#9 0xb7b75ecf in ldap_detach (instance=0x80104850) at rlm_ldap.c:2402
i = 0
pair = <value optimized out>
nextpair = <value optimized out>
#10 0x8000dc02 in detach_modules () at modules.c:130
ml = <value optimized out>
next = <value optimized out>
#11 0x80011d3a in main (argc=1, argv=0xbfd4c134) at radiusd.c:1191
fun = (RAD_REQUEST_FUNP) 0x80005a30 <rad_authenticate>
request = (REQUEST *) 0x80242e50
packet = (RADIUS_PACKET *) 0x0
secret = (u_char *) 0x800fd6d0 "Troldhavelaage900#"
buffer = "*", '\0' <repeats 831 times>, "¹ ï·²C½·ØÅî·ôoð·
sð·\000\000\000\000ü´Ô¿°?ï·", '\0' <repeats 24 times>,
"²C½·\000\000\000\000 pð·", '\0' <repeats 12 times>, "È|è·",
'\0' <repeats 48 times>, "¹ ï· hз\020\177è·ôoð·È|è· hз\200µÔ¿°?ï·
hзÎhз", '\0' <repeats 16 times>, " hз\000\000\000\000 pð·",
'\0' <repeats 12 times>, "0zè·", '\0' <repeats 20 times>, "Îhз", '\0'
<repeats 20 times>, "¹ ï·Ñ<á·\020\177è"...
readfds = {fds_bits = {8, 0 <repeats 31 times>}}
argval = <value optimized out>
pid = <value optimized out>
max_fd = 182868
status = <value optimized out>
tv = (struct timeval *) 0x8001ece4
act = {__sigaction_handler = {sa_handler = 0x8000fe30
<sig_fatal>, sa_sigaction = 0x8000fe30 <sig_fatal>}, sa_mask = {__val =
{0 <repeats 32 times>}}, sa_flags = 0, sa_restorer = 0}
listener = (rad_listen_t *) 0x0
#0 0xffffe410 in __kernel_vsyscall ()
- Best regards
- Nicolai
On Mon, 2007-09-24 at 13:40 -0700, Phil Mayers wrote:
>> I am a newbie, running 3 (for redundancy) FreeRadius servers
(1.1.7)
>> on SUSE 10 SP1 (32-bit) to authenticate our wireless clients (PEAP
>> MSCHAPv2) to our eDirectory via LDAP. We average 800-900
simultaneous
>> wireless clients (need to support a potential 4K in the future).
>>
>> The setup works well and authenticates users very quickly, but
every
>> couple days, the radiusd process will either blow up and start
>> consuming 99% of the CPU or die altogether. More often it blows
up.
>> We had stability problems initially, even when the process was
>> running, so I took everything out of the config that we didn't need
>> and that seemed to help.
>First question; are you HUPing the daemon? If so, don't - it won't
work
>well.
>
>Second question; if this happens reliably can you recompile from
>scratch:
>
>./configure --enable-developer
>make
>make install
>
>...and when it happens do this:
>
>gdb /usr/local/sbin/radiusd
>set pagination off
>set logging file /root/radiusd-wireless.txt
>set logging on
>attach $PID
>thread apply all bt full
>
>...that'll give some details as to what the server is doing when it
>pegs the CPU. Other options are strace or (if your Linux system has
it)
>SystemTap. The aim being to determine what it's doing when it goes
wrong.
