SV: Freeradius stops authenticating
Svein Hansen
Svein.Hansen at hive.no
Wed Oct 26 15:18:37 CEST 2005
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 at 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 at 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 at 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
More information about the Freeradius-Users
mailing list