Update: Some error's in log today..(needed a restart): # less /var/log/radius/radius.log ..... Wed Oct 26 12:50:34 2005 : Error: Discarding duplicate request from client c3:1560 - ID: 206 due to unfinished request 5410 ......... Wed Oct 26 13:26:21 2005 : Error: Assertion failed in modcall.c, line 68 ........ Avarage authentications: 2000 a day (08:00 - 17:00). Svein
Svein.Hansen@hive.no 19.10.2005 10:11 >>> I have a Cisco VPN 3000 Concentrator and a Trapeze Wireless Mobility Exchange(MX-400) that authenticate users in Freeradius by using MSChapV2 and smbpasswd.
My radius stops authenticating approx. 2 times a day(not during the weekends..). The pid usually dies, but sometimes it lives (but not authenticating). I followed the instructions on the BUG page, and got a core dump: (gdb) bt #0 0x0017f7a2 in _dl_sysinfo_int80 () from /lib/ld-linux.so.2 #1 0x0040e7d5 in raise () from /lib/tls/libc.so.6 #2 0x00410149 in abort () from /lib/tls/libc.so.6 #3 0x0044227a in __libc_message () from /lib/tls/libc.so.6 #4 0x00448abf in _int_free () from /lib/tls/libc.so.6 #5 0x00448e3a in free () from /lib/tls/libc.so.6 #6 0x00439366 in fclose@@GLIBC_2.1 () from /lib/tls/libc.so.6 #7 0x00f24de1 in get_next (name=0x9d69ffc "tonemere", ht=0x9d65e70) at rlm_passwd.c:280 #8 0x00f25c21 in passwd_authorize (instance=0x9d65db0, request=0xb7e00858) at rlm_passwd.c:540 #9 0x003d7c54 in modcall (component=1, c=0x9d65030, request=0xb7e00858) at modcall.c:219 #10 0x003d7ee1 in modcall (component=1, c=0x9d642e8, request=0xb7e00858) at modcall.c:252 #11 0x003d7126 in indexed_modcall (comp=1, idx=6, request=0x0) at modules.c:473 #12 0x003d3ef3 in rad_authenticate (request=0xb7e00858) at auth.c:592 #13 0x003cd04c in rad_respond (request=0xb7e00858, fun=0x3d3e57 <rad_authenticate>) at radiusd.c:1642 #14 0x003da481 in request_handler_thread (arg=0x9d68728) at threads.c:517 #15 0x0095e341 in start_thread () from /lib/tls/libpthread.so.0 #16 0x004adfee in clone () from /lib/tls/libc.so.6 (gdb) As I understand of this printout, it's glibc that faults.. I suspected that there had to be a module in freeradius that makes glibc fault, so I tried to run freeradius in Valgrind: [root@eva etc]# valgrind -v --tool=memcheck radiusd -yf ==5070== Memcheck, a memory error detector for x86-linux. ==5070== Copyright (C) 2002-2004, and GNU GPL'd, by Julian Seward et al. ==5070== Using valgrind-2.2.0, a program supervision framework for x86-linux. ==5070== Copyright (C) 2000-2004, and GNU GPL'd, by Julian Seward et al. ==5070== Valgrind library directory: /usr/lib/valgrind ==5070== Command line ==5070== radiusd ==5070== -yf ==5070== Startup, with flags: ==5070== -v ==5070== --tool=memcheck ==5070== Contents of /proc/version: ==5070== Linux version 2.6.9-11.ELsmp (bhcompile@decompose.build.redhat.com) (gcc version 3.4.3 20050227 (Red Hat 3.4.3-18:26:27 EDT 2005 ==5070== Reading syms from /usr/sbin/radiusd (0x0) ==5070== object doesn't have a symbol table ==5070== Reading syms from /lib/ld-2.3.4.so (0x1B8E4000) ==5070== object doesn't have any debug info ==5070== Reading syms from /usr/lib/valgrind/stage2 (0xB0000000) ==5070== Reading syms from /lib/ld-2.3.4.so (0xB1000000) ==5070== object doesn't have any debug info ==5070== Reading syms from /usr/lib/valgrind/vgskin_memcheck.so (0xB7C8C000) ==5070== Reading syms from /lib/tls/libc-2.3.4.so (0xB7EB5000) ==5070== object doesn't have any debug info ==5070== Reading syms from /lib/libdl-2.3.4.so (0xB7FDF000) ==5070== object doesn't have any debug info ==5070== Reading suppressions file: /usr/lib/valgrind/default.supp ==5070== REDIRECT soname:libc.so.6(__GI___errno_location) to soname:libpthread.so.0(__errno_location) ==5070== REDIRECT soname:libc.so.6(__errno_location) to soname:libpthread.so.0(__errno_location) ==5070== REDIRECT soname:libc.so.6(__GI___h_errno_location) to soname:libpthread.so.0(__h_errno_location) ==5070== REDIRECT soname:libc.so.6(__h_errno_location) to soname:libpthread.so.0(__h_errno_location) ==5070== REDIRECT soname:libc.so.6(__GI___res_state) to soname:libpthread.so.0(__res_state) ==5070== REDIRECT soname:libc.so.6(__res_state) to soname:libpthread.so.0(__res_state) ==5070== REDIRECT soname:libc.so.6(stpcpy) to *vgpreload_memcheck.so*(stpcpy) ==5070== REDIRECT soname:libc.so.6(strnlen) to *vgpreload_memcheck.so*(strnlen) ==5070== REDIRECT soname:ld-linux.so.2(stpcpy) to *vgpreload_memcheck.so*(stpcpy) ==5070== REDIRECT soname:ld-linux.so.2(strchr) to *vgpreload_memcheck.so*(strchr) ==5070== ==5070== Reading syms from /usr/lib/valgrind/vg_inject.so (0x1B8FC000) ==5070== Reading syms from /usr/lib/valgrind/vgpreload_memcheck.so (0x1B901000) ==5070== TRANSLATE: 0x1B8F5EE0 redirected to 0x1B904100 ==5070== Reading syms from /lib/libcrypt-2.3.4.so (0x8D2000) ==5070== object doesn't have any debug info ==5070== Reading syms from /lib/libssl.so.0.9.7a (0x3AB000) ==5070== object doesn't have a symbol table ==5070== object doesn't have any debug info ==5070== Reading syms from /lib/libcrypto.so.0.9.7a (0x644000) ==5070== object doesn't have a symbol table ==5070== object doesn't have any debug info ==5070== Reading syms from /lib/libnsl-2.3.4.so (0x8BA000) ==5070== object doesn't have any debug info ==5070== Reading syms from /lib/libresolv-2.3.4.so (0xD8F000) ==5070== object doesn't have any debug info ==5070== Reading syms from /usr/lib/valgrind/libpthread.so (0x1B928000) ==5070== Reading syms from /usr/lib/libradius-1.0.5.so (0x1B957000) ==5070== object doesn't have a symbol table ==5070== Reading syms from /usr/lib/libltdl.so.3.1.0 (0xDA3000) ==5070== object doesn't have a symbol table ==5070== object doesn't have any debug info ==5070== Reading syms from /lib/libdl-2.3.4.so (0xBFD000) ==5070== object doesn't have any debug info ==5070== Reading syms from /lib/tls/libc-2.3.4.so (0xAAD000) ==5070== object doesn't have any debug info ==5070== Reading syms from /usr/lib/libgssapi_krb5.so.2.2 (0x46E000) ==5070== object doesn't have a symbol table ==5070== object doesn't have any debug info ==5070== Reading syms from /usr/lib/libkrb5.so.3.2 (0x304000) ==5070== object doesn't have a symbol table ==5070== object doesn't have any debug info ==5070== Reading syms from /lib/libcom_err.so.2.1 (0x2DC000) ==5070== object doesn't have a symbol table ==5070== object doesn't have any debug info ==5070== Reading syms from /usr/lib/libk5crypto.so.3.0 (0x2E1000) ==5070== object doesn't have a symbol table ==5070== object doesn't have any debug info ==5070== Reading syms from /usr/lib/libz.so.1.2.1.2 (0xC03000) ==5070== object doesn't have a symbol table ==5070== object doesn't have any debug info ==5070== TRANSLATE: 0xB10E80 redirected to 0x1B9048F8 ==5070== TRANSLATE: 0x1B8E47A0 redirected to 0x52BFF040 ==5070== TRANSLATE: 0xB0EDB0 redirected to 0x1B904E24 ==5070== TRANSLATE: 0xB15D20 redirected to 0x1B9042D0 Thu Oct 6 09:11:38 2005 : Info: Starting - reading configuration files ... ==5070== TRANSLATE: 0xB17090 redirected to 0x1B9046F4 ==5070== TRANSLATE: 0xB10BA0 redirected to 0x1B905274 ==5070== Reading syms from /lib/libnss_files-2.3.4.so (0x1B90C000) ==5070== object doesn't have any debug info ==5070== Reading syms from /usr/lib/rlm_expr-1.0.5.so (0x1B918000) ==5070== object doesn't have a symbol table ==5070== Reading syms from /usr/lib/rlm_counter-1.0.5.so (0x1B91B000) ==5070== object doesn't have a symbol table ==5070== Reading syms from /usr/lib/libgdbm.so.2.0.0 (0xBD8000) ==5070== object doesn't have a symbol table ==5070== object doesn't have any debug info ==5070== Reading syms from /usr/lib/rlm_mschap-1.0.5.so (0x1CF87000) ==5070== object doesn't have a symbol table ==5070== Reading syms from /usr/lib/rlm_preprocess-1.0.5.so (0x1B921000) ==5070== object doesn't have a symbol table ==5070== Reading syms from /usr/lib/rlm_realm-1.0.5.so (0x1CF8E000) ==5070== object doesn't have a symbol table ==5070== Reading syms from /usr/lib/rlm_files-1.0.5.so (0x1CF92000) ==5070== object doesn't have a symbol table ==5070== Reading syms from /usr/lib/rlm_passwd-1.0.5.so (0x1CF96000) ==5070== object doesn't have a symbol table ==5070== Reading syms from /usr/lib/rlm_acct_unique-1.0.5.so (0x1CF9B000) ==5070== object doesn't have a symbol table ==5070== Reading syms from /usr/lib/rlm_detail-1.0.5.so (0x1CF9E000) ==5070== object doesn't have a symbol table ==5070== TRANSLATE: 0xB114C0 redirected to 0x1B905326 ==5070== Reading syms from /usr/lib/rlm_radutmp-1.0.5.so (0x1CFA2000) ==5070== object doesn't have a symbol table ==5070== TRANSLATE: 0xB11160 redirected to 0x1B905413 ==5070== warning: Valgrind's pthread_attr_destroy does nothing ==5070== your program may misbehave as a result ==5070== warning: Valgrind's pthread_attr_destroy does nothing ==5070== your program may misbehave as a result ==5070== warning: Valgrind's pthread_attr_destroy does nothing ==5070== your program may misbehave as a result ==5070== Thread 8: ==5070== Invalid read of size 4 ==5070== at 0xAFF2E8: _IO_fclose@@GLIBC_2.1 (in /lib/tls/libc-2.3.4.so) ==5070== by 0x1CF97CC0: ??? (rlm_passwd.c:303) ==5070== by 0xFC53: modcall (modcall.c:219) ==5070== by 0xFEE0: modcall (modcall.c:252) ==5070== Address 0x20C29C6C is 92 bytes inside a block of size 352 free'd ==5070== at 0x1B904EA5: free (vg_replace_malloc.c:153) ==5070== by 0xAFF365: _IO_fclose@@GLIBC_2.1 (in /lib/tls/libc-2.3.4.so) ==5070== by 0x1CF96DE0: ??? (rlm_passwd.c:280) ==5070== by 0x1CF97C20: ??? (rlm_passwd.c:540) ==5070== ==5070== Thread 8: ==5070== Invalid read of size 4 ==5070== at 0xAFF403: _IO_fclose@@GLIBC_2.1 (in /lib/tls/libc-2.3.4.so) ==5070== by 0x1CF97CC0: ??? (rlm_passwd.c:303) ==5070== by 0xFC53: modcall (modcall.c:219) ==5070== by 0xFEE0: modcall (modcall.c:252) ==5070== Address 0x20C29C34 is 36 bytes inside a block of size 352 free'd ==5070== at 0x1B904EA5: free (vg_replace_malloc.c:153) ==5070== by 0xAFF365: _IO_fclose@@GLIBC_2.1 (in /lib/tls/libc-2.3.4.so) ==5070== by 0x1CF96DE0: ??? (rlm_passwd.c:280) ==5070== by 0x1CF97C20: ??? (rlm_passwd.c:540) ==5070== ==5070== Thread 8: ==5070== Invalid write of size 4 ==5070== at 0xAFF358: _IO_fclose@@GLIBC_2.1 (in /lib/tls/libc-2.3.4.so) ==5070== by 0x1CF97CC0: ??? (rlm_passwd.c:303) ==5070== by 0xFC53: modcall (modcall.c:219) ==5070== by 0xFEE0: modcall (modcall.c:252) ==5070== Address 0x20C29C10 is 0 bytes inside a block of size 352 free'd ==5070== at 0x1B904EA5: free (vg_replace_malloc.c:153) ==5070== by 0xAFF365: _IO_fclose@@GLIBC_2.1 (in /lib/tls/libc-2.3.4.so) ==5070== by 0x1CF96DE0: ??? (rlm_passwd.c:280) ==5070== by 0x1CF97C20: ??? (rlm_passwd.c:540) ==5070== ==5070== Thread 8: ==5070== Invalid free() / delete / delete[] ==5070== at 0x1B904EA5: free (vg_replace_malloc.c:153) ==5070== by 0xAFF365: _IO_fclose@@GLIBC_2.1 (in /lib/tls/libc-2.3.4.so) ==5070== by 0x1CF97CC0: ??? (rlm_passwd.c:303) ==5070== by 0xFC53: modcall (modcall.c:219) ==5070== Address 0x20C29C10 is 0 bytes inside a block of size 352 free'd ==5070== at 0x1B904EA5: free (vg_replace_malloc.c:153) ==5070== by 0xAFF365: _IO_fclose@@GLIBC_2.1 (in /lib/tls/libc-2.3.4.so) ==5070== by 0x1CF96DE0: ??? (rlm_passwd.c:280) ==5070== by 0x1CF97C20: ??? (rlm_passwd.c:540) I'm not a programmer, but can it be that radius tries a double-close or a double-free? I have had the same problem on Freeradius 1.0.1, 1.0.4 and 1.0.5. My current conf: rhel 4 Kernel: 2.6.9-22.ELsmp radiusd: FreeRADIUS Version 1.0.5, for host , built on Sep 28 2005 at 09:42:46 glibc-2.3.4-2.13 (Sorry for my bad english..) Svein Hansen - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html