2.2.0 crash at a strange location
Hi, today I did some minor config changes which turned my stable-running 2.2.0 into a crash-every-5-min server :-( The change involved a) switching from Cleartext-Password to SSHA1-Password (retaining the pap module for checking the PW validity) b) a somewhat sophisticated unlang statement to express: if the SSHA1-PW was wrong, retrieve an alternative password from a VSA ("RESTENA-Debug-Password") and set it to be the Cleartext-Password; then try pap again with that This is obviously the implementation of a "backdoor" for our helpdesk if we need to login into a user's account for debugging without knowing his actual password because it's SSHA'ed in the DB. All nice and cute, and it worked while doing "mild" usage with a test account - but now in production things go down the drain with it. I've temporarily switched back to the previous SQL query which had Cleartext-Password. And voilà: the server is stable again. Even with the unlang construct still in place (below for reference). So I strongly suspect things to go wrong *only if* SSHA1-Passwords are used to authenticate the user. Strangely enough, the gdb backtrace shows that it fails somewhere inside glibc while trying to expand a %S in xlat - which appears totally unrelated to the changes I did. The backtrace is below. policy.conf: replacement for authenticate/pap: policy { pap_hash_debugfallback { group { pap { reject = 2 ok = return } if ( "%{control:RESTENA-Debug-Password}" ) { update control { SSHA1-Password !* "nogood" NT-Password !* "nogood" Cleartext-Password := "%{control:RESTENA-Debug-Password}" } ok = 1 ok } pap { reject = 2 ok = return } } } ... } Program received signal SIGSEGV, Segmentation fault. [Switching to Thread 0x4b015950 (LWP 24837)] 0x00002b380d7d5550 in ?? () from /lib64/libc.so.6 (gdb) bt #0 0x00002b380d7d5550 in ?? () from /lib64/libc.so.6 #1 0x00002b380d7d6c0c in malloc () from /lib64/libc.so.6 #2 0x00002b380d7da8f2 in strdup () from /lib64/libc.so.6 #3 0x00002b380d7ed928 in ?? () from /lib64/libc.so.6 #4 0x00002b380d7ee3f0 in tzset () from /lib64/libc.so.6 #5 0x00002b380d7f2c94 in strftime_l () from /lib64/libc.so.6 #6 0x000000000042277d in radius_xlat (out=0x4b013a30 "[Access-Accept", outlen=1023, fmt=0x667c4e "[%S] [AUTH OK ] '%{User-Name}' (%{RESTENA-Service-Type}:%{client:shortname})", request=0x2aaab0001f60, func=0x2aaaab2e33d0 <linelog_escape_func>) at xlat.c:1348 #7 0x00002aaaab2e31d4 in do_linelog (instance=0x835a60, request=0x2aaab0001f60) at rlm_linelog.c:328 #8 0x000000000041c920 in modcall (component=7, c=<value optimized out>, request=0x2aaab0001f60) at modcall.c:304 #9 0x0000000000419be8 in indexed_modcall (comp=0, idx=0, request=0x2aaab0001f60) at modules.c:740 #10 0x00000000004094fd in rad_postauth (request=0x2aaab0001f60) at auth.c:433 #11 0x0000000000409b83 in rad_authenticate (request=0x2aaab0001f60) at auth.c:831 #12 0x0000000000427538 in radius_handle_request (request=0x2aaab0001f60, fun=0x409540 <rad_authenticate>) at event.c:3784 #13 0x0000000000420728 in request_handler_thread (arg=<value optimized out>) at threads.c:537 #14 0x00002b380c8d8020 in start_thread () from /lib64/libpthread.so.0 #15 0x00002b380d829f8d in clone () from /lib64/libc.so.6 #16 0x0000000000000000 in ?? () (gdb) bt full #0 0x00002b380d7d5550 in ?? () from /lib64/libc.so.6 No symbol table info available. #1 0x00002b380d7d6c0c in malloc () from /lib64/libc.so.6 No symbol table info available. #2 0x00002b380d7da8f2 in strdup () from /lib64/libc.so.6 No symbol table info available. #3 0x00002b380d7ed928 in ?? () from /lib64/libc.so.6 No symbol table info available. #4 0x00002b380d7ee3f0 in tzset () from /lib64/libc.so.6 No symbol table info available. #5 0x00002b380d7f2c94 in strftime_l () from /lib64/libc.so.6 No symbol table info available. #6 0x000000000042277d in radius_xlat (out=0x4b013a30 "[Access-Accept", outlen=1023, fmt=0x667c4e "[%S] [AUTH OK ] '%{User-Name}' (%{RESTENA-Service-Type}:%{client:shortname})", request=0x2aaab0001f60, func=0x2aaaab2e33d0 <linelog_escape_func>) at xlat.c:1348 c = <value optimized out> len = <value optimized out> freespace = <value optimized out> p = 0x667c50 "S] [AUTH OK ] '%{User-Name}' (%{RESTENA-Service-Type}:%{client:shortname})" q = 0x4b013a31 "Access-Accept" tmp = (VALUE_PAIR *) 0x2aaab0001f60 TM = (struct tm *) 0x3 s_TM = {tm_sec = 45, tm_min = 15, tm_hour = 10, tm_mday = 6, tm_mon = 4, tm_year = 113, tm_wday = 1, tm_yday = 125, tm_isdst = 1, tm_gmtoff = 7200, tm_zone = 0x807da0 "CEST"} tmpdt = "\000\020\000\000\000\000\000\000\000\020\000\000\000\000\000\000\b\000\000\000\000\000\000\000\236A�G", '\0' <repeats 11 times> #7 0x00002aaaab2e31d4 in do_linelog (instance=0x835a60, request=0x2aaab0001f60) at rlm_linelog.c:328 ci = <value optimized out> cp = <value optimized out> fd = 56 buffer = "/var/log/radius/activity.log\000+\000\000�*\001K\001\000\000\000�+\001K\000\000\000\000�X\001K\000\000\000\000\000�\213\000\000\000\000\000\005\000\000\000\000\000\000\000�>\000��*\000\000\000\000\000\000\000\000\000\000�>\000��*\000\000\n\000\000\000\000\000\000\000�>\000��*\000\000P>\001K\000\000\000\000�w�\0178+\000\000:=\000\000\000\000\000\000\030", '\0' <repeats 15 times>, "�\025B\000\000\000\000\000\000�\213\000\000\000\000\000�*\001K\000\000\000\000P>\001K\000\000\000\000`\037\000��*\000\000\000\000\002\000\000\000\000\000\220�\213\000\000"... p = <value optimized out> line = "[Access-Accept", '\0' <repeats 434 times>, "Mon May 6 10:15:45 2013\000\000\000\000\000\000\000\000Mon May 6 10:15:45 2013", '\0' <repeats 116 times>, "\024\000\000\000`\001\000\000\000\000\000\0008\001\000\000\000\000\000\000\000\000\000\000\024", '\0' <repeats 35 times>, "\202\230'\f8+\000\000`\003j\000\000\000\000\000 \000\000��*\000\0008\001", '\0' <repeats 14 times>, "\001\000\000\000\000\000\000\000`\037\000��*\000\0000}\203\000\000\000\000\000\fl}\r8+\000\000�\204|", '\0' <repeats 13 times>... value = 0x667c4e "[%S] [AUTH OK ] '%{User-Name}' (%{RESTENA-Service-Type}:%{client:shortname})" gid = <value optimized out> grp = (struct group *) 0x0 endptr = 0x6889fc ")" #8 0x000000000041c920 in modcall (component=7, c=<value optimized out>, request=0x2aaab0001f60) at modcall.c:304 server = <value optimized out> myresult = 1 stack = {pointer = 0, priority = {0, 0, 3, 0, 0, 0, 0, 0, 0, 3, 0, 3, 0 <repeats 20 times>}, result = {7, 7, 2, 0, 0, 0, 0, 0, 0, 2, 2, 2, 2, 0 <repeats 19 times>}, children = {0x8f2910, 0x8f2730, 0x8f2800, 0x0, 0x837410, 0x0 <repeats 27 times>}, start = {0x0, 0x8f2730, 0x8f27a0, 0x0, 0x0, 0x837480, 0x8374f0, 0x8af080, 0x8e3ec0, 0x0 <repeats 23 times>}} parent = (modcallable *) 0x8f2730 child = (modcallable *) 0x8f2800 if_taken = 0 was_if = 0 #9 0x0000000000419be8 in indexed_modcall (comp=0, idx=0, request=0x2aaab0001f60) at modules.c:740 this = <value optimized out> rcode = <value optimized out> list = (modcallable *) 0x8f2910 server = (virtual_server_t *) 0x837330 #10 0x00000000004094fd in rad_postauth (request=0x2aaab0001f60) at auth.c:433 result = <value optimized out> postauth_type = 0 vp = (VALUE_PAIR *) 0x0 #11 0x0000000000409b83 in rad_authenticate (request=0x2aaab0001f60) at auth.c:831 namepair = (VALUE_PAIR *) 0x9a71f0 check_item = (VALUE_PAIR *) 0x0 auth_item = (VALUE_PAIR *) 0x9a8c10 module_msg = <value optimized out> tmp = (VALUE_PAIR *) 0x0 result = -1275060192 autz_retry = <value optimized out> autz_type = <value optimized out> #12 0x0000000000427538 in radius_handle_request (request=0x2aaab0001f60, fun=0x409540 <rad_authenticate>) at event.c:3784 ---Type <return> to continue, or q <return> to quit--- No locals. #13 0x0000000000420728 in request_handler_thread (arg=<value optimized out>) at threads.c:537 fun = (RAD_REQUEST_FUNP) 0x409540 <rad_authenticate> self = (THREAD_HANDLE *) 0x2aaab4001fe0 #14 0x00002b380c8d8020 in start_thread () from /lib64/libpthread.so.0 No symbol table info available. #15 0x00002b380d829f8d in clone () from /lib64/libc.so.6 No symbol table info available. #16 0x0000000000000000 in ?? () No symbol table info available. (gdb) -- Stefan WINTER Ingenieur de Recherche Fondation RESTENA - Réseau Téléinformatique de l'Education Nationale et de la Recherche 6, rue Richard Coudenhove-Kalergi L-1359 Luxembourg Tel: +352 424409 1 Fax: +352 422473
Hi again, running with -X I get: rlm_sql_mysql: query: (SELECT id, username, attribute, value, op FROM check_smtp_ssha1 WHERE username='someusername') [sql-smtp-hash] User found in radcheck table rlm_sql (sql-smtp-hash): Released sql socket id: 1 +++[sql-smtp-hash] returns ok ++- policy redundant returns ok [pap] Normalizing SSHA1-Password from base64 encoding ++[pap] returns updated Found Auth-Type = PAP # Executing group from file /usr/local/freeradius/config/raddb/sites-enabled/SMTP +- entering group PAP {...} ++- entering policy pap_hash_debugfallback {...} +++- entering group {...} [pap] login attempt with password "eq346ici" [pap] Using SSHA encryption. [pap] Normalizing SSHA1-Password from base64 encoding Segmentation fault Which is before the linelog is reached, so *maybe* the source of the problem is in the base64 normalisation code? Stefan On 06.05.2013 10:30, Stefan Winter wrote:
Hi,
today I did some minor config changes which turned my stable-running 2.2.0 into a crash-every-5-min server :-(
The change involved a) switching from Cleartext-Password to SSHA1-Password (retaining the pap module for checking the PW validity) b) a somewhat sophisticated unlang statement to express: if the SSHA1-PW was wrong, retrieve an alternative password from a VSA ("RESTENA-Debug-Password") and set it to be the Cleartext-Password; then try pap again with that
This is obviously the implementation of a "backdoor" for our helpdesk if we need to login into a user's account for debugging without knowing his actual password because it's SSHA'ed in the DB.
All nice and cute, and it worked while doing "mild" usage with a test account - but now in production things go down the drain with it.
I've temporarily switched back to the previous SQL query which had Cleartext-Password. And voilà: the server is stable again. Even with the unlang construct still in place (below for reference).
So I strongly suspect things to go wrong *only if* SSHA1-Passwords are used to authenticate the user.
Strangely enough, the gdb backtrace shows that it fails somewhere inside glibc while trying to expand a %S in xlat - which appears totally unrelated to the changes I did. The backtrace is below.
policy.conf: replacement for authenticate/pap:
policy {
pap_hash_debugfallback { group { pap { reject = 2 ok = return }
if ( "%{control:RESTENA-Debug-Password}" ) { update control { SSHA1-Password !* "nogood" NT-Password !* "nogood" Cleartext-Password := "%{control:RESTENA-Debug-Password}" } ok = 1 ok }
pap { reject = 2 ok = return } } } ... }
Program received signal SIGSEGV, Segmentation fault. [Switching to Thread 0x4b015950 (LWP 24837)] 0x00002b380d7d5550 in ?? () from /lib64/libc.so.6 (gdb) bt #0 0x00002b380d7d5550 in ?? () from /lib64/libc.so.6 #1 0x00002b380d7d6c0c in malloc () from /lib64/libc.so.6 #2 0x00002b380d7da8f2 in strdup () from /lib64/libc.so.6 #3 0x00002b380d7ed928 in ?? () from /lib64/libc.so.6 #4 0x00002b380d7ee3f0 in tzset () from /lib64/libc.so.6 #5 0x00002b380d7f2c94 in strftime_l () from /lib64/libc.so.6 #6 0x000000000042277d in radius_xlat (out=0x4b013a30 "[Access-Accept", outlen=1023, fmt=0x667c4e "[%S] [AUTH OK ] '%{User-Name}' (%{RESTENA-Service-Type}:%{client:shortname})", request=0x2aaab0001f60, func=0x2aaaab2e33d0 <linelog_escape_func>) at xlat.c:1348 #7 0x00002aaaab2e31d4 in do_linelog (instance=0x835a60, request=0x2aaab0001f60) at rlm_linelog.c:328 #8 0x000000000041c920 in modcall (component=7, c=<value optimized out>, request=0x2aaab0001f60) at modcall.c:304 #9 0x0000000000419be8 in indexed_modcall (comp=0, idx=0, request=0x2aaab0001f60) at modules.c:740 #10 0x00000000004094fd in rad_postauth (request=0x2aaab0001f60) at auth.c:433 #11 0x0000000000409b83 in rad_authenticate (request=0x2aaab0001f60) at auth.c:831 #12 0x0000000000427538 in radius_handle_request (request=0x2aaab0001f60, fun=0x409540 <rad_authenticate>) at event.c:3784 #13 0x0000000000420728 in request_handler_thread (arg=<value optimized out>) at threads.c:537 #14 0x00002b380c8d8020 in start_thread () from /lib64/libpthread.so.0 #15 0x00002b380d829f8d in clone () from /lib64/libc.so.6 #16 0x0000000000000000 in ?? () (gdb) bt full #0 0x00002b380d7d5550 in ?? () from /lib64/libc.so.6 No symbol table info available. #1 0x00002b380d7d6c0c in malloc () from /lib64/libc.so.6 No symbol table info available. #2 0x00002b380d7da8f2 in strdup () from /lib64/libc.so.6 No symbol table info available. #3 0x00002b380d7ed928 in ?? () from /lib64/libc.so.6 No symbol table info available. #4 0x00002b380d7ee3f0 in tzset () from /lib64/libc.so.6 No symbol table info available. #5 0x00002b380d7f2c94 in strftime_l () from /lib64/libc.so.6 No symbol table info available. #6 0x000000000042277d in radius_xlat (out=0x4b013a30 "[Access-Accept", outlen=1023, fmt=0x667c4e "[%S] [AUTH OK ] '%{User-Name}' (%{RESTENA-Service-Type}:%{client:shortname})", request=0x2aaab0001f60, func=0x2aaaab2e33d0 <linelog_escape_func>) at xlat.c:1348 c = <value optimized out> len = <value optimized out> freespace = <value optimized out> p = 0x667c50 "S] [AUTH OK ] '%{User-Name}' (%{RESTENA-Service-Type}:%{client:shortname})" q = 0x4b013a31 "Access-Accept" tmp = (VALUE_PAIR *) 0x2aaab0001f60 TM = (struct tm *) 0x3 s_TM = {tm_sec = 45, tm_min = 15, tm_hour = 10, tm_mday = 6, tm_mon = 4, tm_year = 113, tm_wday = 1, tm_yday = 125, tm_isdst = 1, tm_gmtoff = 7200, tm_zone = 0x807da0 "CEST"} tmpdt = "\000\020\000\000\000\000\000\000\000\020\000\000\000\000\000\000\b\000\000\000\000\000\000\000\236A�G", '\0' <repeats 11 times> #7 0x00002aaaab2e31d4 in do_linelog (instance=0x835a60, request=0x2aaab0001f60) at rlm_linelog.c:328 ci = <value optimized out> cp = <value optimized out> fd = 56 buffer = "/var/log/radius/activity.log\000+\000\000�*\001K\001\000\000\000�+\001K\000\000\000\000�X\001K\000\000\000\000\000�\213\000\000\000\000\000\005\000\000\000\000\000\000\000�>\000��*\000\000\000\000\000\000\000\000\000\000�>\000��*\000\000\n\000\000\000\000\000\000\000�>\000��*\000\000P>\001K\000\000\000\000�w�\0178+\000\000:=\000\000\000\000\000\000\030", '\0' <repeats 15 times>, "�\025B\000\000\000\000\000\000�\213\000\000\000\000\000�*\001K\000\000\000\000P>\001K\000\000\000\000`\037\000��*\000\000\000\000\002\000\000\000\000\000\220�\213\000\000"... p = <value optimized out> line = "[Access-Accept", '\0' <repeats 434 times>, "Mon May 6 10:15:45 2013\000\000\000\000\000\000\000\000Mon May 6 10:15:45 2013", '\0' <repeats 116 times>, "\024\000\000\000`\001\000\000\000\000\000\0008\001\000\000\000\000\000\000\000\000\000\000\024", '\0' <repeats 35 times>, "\202\230'\f8+\000\000`\003j\000\000\000\000\000 \000\000��*\000\0008\001", '\0' <repeats 14 times>, "\001\000\000\000\000\000\000\000`\037\000��*\000\0000}\203\000\000\000\000\000\fl}\r8+\000\000�\204|", '\0' <repeats 13 times>... value = 0x667c4e "[%S] [AUTH OK ] '%{User-Name}' (%{RESTENA-Service-Type}:%{client:shortname})" gid = <value optimized out> grp = (struct group *) 0x0 endptr = 0x6889fc ")" #8 0x000000000041c920 in modcall (component=7, c=<value optimized out>, request=0x2aaab0001f60) at modcall.c:304 server = <value optimized out> myresult = 1 stack = {pointer = 0, priority = {0, 0, 3, 0, 0, 0, 0, 0, 0, 3, 0, 3, 0 <repeats 20 times>}, result = {7, 7, 2, 0, 0, 0, 0, 0, 0, 2, 2, 2, 2, 0 <repeats 19 times>}, children = {0x8f2910, 0x8f2730, 0x8f2800, 0x0, 0x837410, 0x0 <repeats 27 times>}, start = {0x0, 0x8f2730, 0x8f27a0, 0x0, 0x0, 0x837480, 0x8374f0, 0x8af080, 0x8e3ec0, 0x0 <repeats 23 times>}} parent = (modcallable *) 0x8f2730 child = (modcallable *) 0x8f2800 if_taken = 0 was_if = 0 #9 0x0000000000419be8 in indexed_modcall (comp=0, idx=0, request=0x2aaab0001f60) at modules.c:740 this = <value optimized out> rcode = <value optimized out> list = (modcallable *) 0x8f2910 server = (virtual_server_t *) 0x837330 #10 0x00000000004094fd in rad_postauth (request=0x2aaab0001f60) at auth.c:433 result = <value optimized out> postauth_type = 0 vp = (VALUE_PAIR *) 0x0 #11 0x0000000000409b83 in rad_authenticate (request=0x2aaab0001f60) at auth.c:831 namepair = (VALUE_PAIR *) 0x9a71f0 check_item = (VALUE_PAIR *) 0x0 auth_item = (VALUE_PAIR *) 0x9a8c10 module_msg = <value optimized out> tmp = (VALUE_PAIR *) 0x0 result = -1275060192 autz_retry = <value optimized out> autz_type = <value optimized out> #12 0x0000000000427538 in radius_handle_request (request=0x2aaab0001f60, fun=0x409540 <rad_authenticate>) at event.c:3784 ---Type <return> to continue, or q <return> to quit--- No locals. #13 0x0000000000420728 in request_handler_thread (arg=<value optimized out>) at threads.c:537 fun = (RAD_REQUEST_FUNP) 0x409540 <rad_authenticate> self = (THREAD_HANDLE *) 0x2aaab4001fe0 #14 0x00002b380c8d8020 in start_thread () from /lib64/libpthread.so.0 No symbol table info available. #15 0x00002b380d829f8d in clone () from /lib64/libc.so.6 No symbol table info available. #16 0x0000000000000000 in ?? () No symbol table info available. (gdb)
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/devel.html
-- Stefan WINTER Ingenieur de Recherche Fondation RESTENA - Réseau Téléinformatique de l'Education Nationale et de la Recherche 6, rue Richard Coudenhove-Kalergi L-1359 Luxembourg Tel: +352 424409 1 Fax: +352 422473
Hi one more time, and another update: it's one specific SSHA1-Hash which makes the server crash; I can reproduce this easily. The magic hash value is: SSHA1-Password := PVwqvpqoyQBACLE3Nxk2ItoDjx1RT3JyKm9SdkRTb1o5aSUm and makes things fail specifically during a memcpy inside normify(). Below is what valgrind has to say. Note that the user input in User-Password is irrelevant; failure is before it's even checked. HTH, Stefan Found Auth-Type = PAP # Executing group from file /usr/local/freeradius/config/raddb/sites-enabled/SMTP +- entering group PAP {...} ++- entering policy pap_hash_debugfallback {...} +++- entering group {...} [pap] login attempt with password "foopass" [pap] Using SSHA encryption. [pap] Normalizing SSHA1-Password from base64 encoding ==13555== ==13555== Process terminating with default action of signal 11 (SIGSEGV) ==13555== Access not within mapped region at address 0x7FF001000 ==13555== at 0x4C2C476: memcpy@@GLIBC_2.14 (in /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so) ==13555== by 0x874B643: normify (rlm_pap.c:273) ==13555== by 0x874BDDF: pap_authenticate (rlm_pap.c:707) ==13555== by 0x41D764: modcall (modcall.c:304) ==13555== by 0x41BF38: indexed_modcall (modules.c:740) ==13555== by 0x40B176: rad_authenticate (auth.c:382) ==13555== by 0x4296E4: radius_handle_request (event.c:3784) ==13555== by 0x422227: thread_pool_addrequest (threads.c:887) ==13555== by 0x4272E5: event_socket_handler (event.c:3429) ==13555== by 0x4E4A2B4: fr_event_loop (event.c:415) ==13555== by 0x409F53: main (radiusd.c:408) ==13555== If you believe this happened as a result of a stack ==13555== overflow in your program's main thread (unlikely but ==13555== possible), you can try to increase the size of the ==13555== main thread stack using the --main-stacksize= flag. ==13555== The main thread stack size used in this run was 8388608. ==13555== ==13555== ---- Attach to debugger ? --- [Return/N/n/Y/y/C/c] ---- --13555-- VALGRIND INTERNAL ERROR: Valgrind received a signal 11 (SIGSEGV) - exiting --13555-- si_code=1; Faulting address: 0xC2394B0; sp: 0x402bda060 valgrind: the 'impossible' happened: Killed by fatal signal ==13555== at 0x38057958: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux) ==13555== by 0x3802124C: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux) ==13555== by 0x380213DA: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux) ==13555== by 0x3808F8D4: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux) ==13555== by 0x380551FF: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux) ==13555== by 0x38055304: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux) ==13555== by 0x3809EA61: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux) sched status: running_tid=1 Thread 1: status = VgTs_Runnable ==13555== at 0x4C2ABED: malloc (in /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so) ==13555== by 0x4013B76: _dl_close_worker (in /lib64/ld-2.15.so) ==13555== by 0x40140AB: _dl_close (in /lib64/ld-2.15.so) ==13555== by 0x400E5F5: _dl_catch_error (in /lib64/ld-2.15.so) ==13555== by 0x64543CE: dlerror_run (in /lib64/libc-2.15.so) ==13555== by 0x6485946: free_mem (in /lib64/libc-2.15.so) ==13555== by 0x6485691: __libc_freeres (in /lib64/libc-2.15.so) ==13555== by 0x4A246EC: _vgnU_freeres (in /usr/lib64/valgrind/vgpreload_core-amd64-linux.so) ==13555== by 0x801604F: ??? ==13555== by 0x874B643: normify (rlm_pap.c:273) ==13555== by 0x874BDDF: pap_authenticate (rlm_pap.c:707) ==13555== by 0x41D764: modcall (modcall.c:304) ==13555== by 0x41BF38: indexed_modcall (modules.c:740) ==13555== by 0x40B176: rad_authenticate (auth.c:382) ==13555== by 0x4296E4: radius_handle_request (event.c:3784) ==13555== by 0x422227: thread_pool_addrequest (threads.c:887) ==13555== by 0x4272E5: event_socket_handler (event.c:3429) ==13555== by 0x4E4A2B4: fr_event_loop (event.c:415) ==13555== by 0x409F53: main (radiusd.c:408) Note: see also the FAQ in the source distribution. It contains workarounds to several common problems. In particular, if Valgrind aborted or crashed after identifying problems in your program, there's a good chance that fixing those problems will prevent Valgrind aborting or crashing, especially if it happened in m_mallocfree.c. If that doesn't help, please report this bug to: www.valgrind.org In the bug report, send all the above text, the valgrind version, and what OS and version you are using. Thanks. On 06.05.2013 10:48, Stefan Winter wrote:
Hi again,
running with -X I get:
rlm_sql_mysql: query: (SELECT id, username, attribute, value, op FROM check_smtp_ssha1 WHERE username='someusername') [sql-smtp-hash] User found in radcheck table rlm_sql (sql-smtp-hash): Released sql socket id: 1 +++[sql-smtp-hash] returns ok ++- policy redundant returns ok [pap] Normalizing SSHA1-Password from base64 encoding ++[pap] returns updated Found Auth-Type = PAP # Executing group from file /usr/local/freeradius/config/raddb/sites-enabled/SMTP +- entering group PAP {...} ++- entering policy pap_hash_debugfallback {...} +++- entering group {...} [pap] login attempt with password "eq346ici" [pap] Using SSHA encryption. [pap] Normalizing SSHA1-Password from base64 encoding Segmentation fault
Which is before the linelog is reached, so *maybe* the source of the problem is in the base64 normalisation code?
Stefan
On 06.05.2013 10:30, Stefan Winter wrote:
Hi,
today I did some minor config changes which turned my stable-running 2.2.0 into a crash-every-5-min server :-(
The change involved a) switching from Cleartext-Password to SSHA1-Password (retaining the pap module for checking the PW validity) b) a somewhat sophisticated unlang statement to express: if the SSHA1-PW was wrong, retrieve an alternative password from a VSA ("RESTENA-Debug-Password") and set it to be the Cleartext-Password; then try pap again with that
This is obviously the implementation of a "backdoor" for our helpdesk if we need to login into a user's account for debugging without knowing his actual password because it's SSHA'ed in the DB.
All nice and cute, and it worked while doing "mild" usage with a test account - but now in production things go down the drain with it.
I've temporarily switched back to the previous SQL query which had Cleartext-Password. And voilà: the server is stable again. Even with the unlang construct still in place (below for reference).
So I strongly suspect things to go wrong *only if* SSHA1-Passwords are used to authenticate the user.
Strangely enough, the gdb backtrace shows that it fails somewhere inside glibc while trying to expand a %S in xlat - which appears totally unrelated to the changes I did. The backtrace is below.
policy.conf: replacement for authenticate/pap:
policy {
pap_hash_debugfallback { group { pap { reject = 2 ok = return }
if ( "%{control:RESTENA-Debug-Password}" ) { update control { SSHA1-Password !* "nogood" NT-Password !* "nogood" Cleartext-Password := "%{control:RESTENA-Debug-Password}" } ok = 1 ok }
pap { reject = 2 ok = return } } } ... }
Program received signal SIGSEGV, Segmentation fault. [Switching to Thread 0x4b015950 (LWP 24837)] 0x00002b380d7d5550 in ?? () from /lib64/libc.so.6 (gdb) bt #0 0x00002b380d7d5550 in ?? () from /lib64/libc.so.6 #1 0x00002b380d7d6c0c in malloc () from /lib64/libc.so.6 #2 0x00002b380d7da8f2 in strdup () from /lib64/libc.so.6 #3 0x00002b380d7ed928 in ?? () from /lib64/libc.so.6 #4 0x00002b380d7ee3f0 in tzset () from /lib64/libc.so.6 #5 0x00002b380d7f2c94 in strftime_l () from /lib64/libc.so.6 #6 0x000000000042277d in radius_xlat (out=0x4b013a30 "[Access-Accept", outlen=1023, fmt=0x667c4e "[%S] [AUTH OK ] '%{User-Name}' (%{RESTENA-Service-Type}:%{client:shortname})", request=0x2aaab0001f60, func=0x2aaaab2e33d0 <linelog_escape_func>) at xlat.c:1348 #7 0x00002aaaab2e31d4 in do_linelog (instance=0x835a60, request=0x2aaab0001f60) at rlm_linelog.c:328 #8 0x000000000041c920 in modcall (component=7, c=<value optimized out>, request=0x2aaab0001f60) at modcall.c:304 #9 0x0000000000419be8 in indexed_modcall (comp=0, idx=0, request=0x2aaab0001f60) at modules.c:740 #10 0x00000000004094fd in rad_postauth (request=0x2aaab0001f60) at auth.c:433 #11 0x0000000000409b83 in rad_authenticate (request=0x2aaab0001f60) at auth.c:831 #12 0x0000000000427538 in radius_handle_request (request=0x2aaab0001f60, fun=0x409540 <rad_authenticate>) at event.c:3784 #13 0x0000000000420728 in request_handler_thread (arg=<value optimized out>) at threads.c:537 #14 0x00002b380c8d8020 in start_thread () from /lib64/libpthread.so.0 #15 0x00002b380d829f8d in clone () from /lib64/libc.so.6 #16 0x0000000000000000 in ?? () (gdb) bt full #0 0x00002b380d7d5550 in ?? () from /lib64/libc.so.6 No symbol table info available. #1 0x00002b380d7d6c0c in malloc () from /lib64/libc.so.6 No symbol table info available. #2 0x00002b380d7da8f2 in strdup () from /lib64/libc.so.6 No symbol table info available. #3 0x00002b380d7ed928 in ?? () from /lib64/libc.so.6 No symbol table info available. #4 0x00002b380d7ee3f0 in tzset () from /lib64/libc.so.6 No symbol table info available. #5 0x00002b380d7f2c94 in strftime_l () from /lib64/libc.so.6 No symbol table info available. #6 0x000000000042277d in radius_xlat (out=0x4b013a30 "[Access-Accept", outlen=1023, fmt=0x667c4e "[%S] [AUTH OK ] '%{User-Name}' (%{RESTENA-Service-Type}:%{client:shortname})", request=0x2aaab0001f60, func=0x2aaaab2e33d0 <linelog_escape_func>) at xlat.c:1348 c = <value optimized out> len = <value optimized out> freespace = <value optimized out> p = 0x667c50 "S] [AUTH OK ] '%{User-Name}' (%{RESTENA-Service-Type}:%{client:shortname})" q = 0x4b013a31 "Access-Accept" tmp = (VALUE_PAIR *) 0x2aaab0001f60 TM = (struct tm *) 0x3 s_TM = {tm_sec = 45, tm_min = 15, tm_hour = 10, tm_mday = 6, tm_mon = 4, tm_year = 113, tm_wday = 1, tm_yday = 125, tm_isdst = 1, tm_gmtoff = 7200, tm_zone = 0x807da0 "CEST"} tmpdt = "\000\020\000\000\000\000\000\000\000\020\000\000\000\000\000\000\b\000\000\000\000\000\000\000\236A�G", '\0' <repeats 11 times> #7 0x00002aaaab2e31d4 in do_linelog (instance=0x835a60, request=0x2aaab0001f60) at rlm_linelog.c:328 ci = <value optimized out> cp = <value optimized out> fd = 56 buffer = "/var/log/radius/activity.log\000+\000\000�*\001K\001\000\000\000�+\001K\000\000\000\000�X\001K\000\000\000\000\000�\213\000\000\000\000\000\005\000\000\000\000\000\000\000�>\000��*\000\000\000\000\000\000\000\000\000\000�>\000��*\000\000\n\000\000\000\000\000\000\000�>\000��*\000\000P>\001K\000\000\000\000�w�\0178+\000\000:=\000\000\000\000\000\000\030", '\0' <repeats 15 times>, "�\025B\000\000\000\000\000\000�\213\000\000\000\000\000�*\001K\000\000\000\000P>\001K\000\000\000\000`\037\000��*\000\000\000\000\002\000\000\000\000\000\220�\213\000\000"... p = <value optimized out> line = "[Access-Accept", '\0' <repeats 434 times>, "Mon May 6 10:15:45 2013\000\000\000\000\000\000\000\000Mon May 6 10:15:45 2013", '\0' <repeats 116 times>, "\024\000\000\000`\001\000\000\000\000\000\0008\001\000\000\000\000\000\000\000\000\000\000\024", '\0' <repeats 35 times>, "\202\230'\f8+\000\000`\003j\000\000\000\000\000 \000\000��*\000\0008\001", '\0' <repeats 14 times>, "\001\000\000\000\000\000\000\000`\037\000��*\000\0000}\203\000\000\000\000\000\fl}\r8+\000\000�\204|", '\0' <repeats 13 times>... value = 0x667c4e "[%S] [AUTH OK ] '%{User-Name}' (%{RESTENA-Service-Type}:%{client:shortname})" gid = <value optimized out> grp = (struct group *) 0x0 endptr = 0x6889fc ")" #8 0x000000000041c920 in modcall (component=7, c=<value optimized out>, request=0x2aaab0001f60) at modcall.c:304 server = <value optimized out> myresult = 1 stack = {pointer = 0, priority = {0, 0, 3, 0, 0, 0, 0, 0, 0, 3, 0, 3, 0 <repeats 20 times>}, result = {7, 7, 2, 0, 0, 0, 0, 0, 0, 2, 2, 2, 2, 0 <repeats 19 times>}, children = {0x8f2910, 0x8f2730, 0x8f2800, 0x0, 0x837410, 0x0 <repeats 27 times>}, start = {0x0, 0x8f2730, 0x8f27a0, 0x0, 0x0, 0x837480, 0x8374f0, 0x8af080, 0x8e3ec0, 0x0 <repeats 23 times>}} parent = (modcallable *) 0x8f2730 child = (modcallable *) 0x8f2800 if_taken = 0 was_if = 0 #9 0x0000000000419be8 in indexed_modcall (comp=0, idx=0, request=0x2aaab0001f60) at modules.c:740 this = <value optimized out> rcode = <value optimized out> list = (modcallable *) 0x8f2910 server = (virtual_server_t *) 0x837330 #10 0x00000000004094fd in rad_postauth (request=0x2aaab0001f60) at auth.c:433 result = <value optimized out> postauth_type = 0 vp = (VALUE_PAIR *) 0x0 #11 0x0000000000409b83 in rad_authenticate (request=0x2aaab0001f60) at auth.c:831 namepair = (VALUE_PAIR *) 0x9a71f0 check_item = (VALUE_PAIR *) 0x0 auth_item = (VALUE_PAIR *) 0x9a8c10 module_msg = <value optimized out> tmp = (VALUE_PAIR *) 0x0 result = -1275060192 autz_retry = <value optimized out> autz_type = <value optimized out> #12 0x0000000000427538 in radius_handle_request (request=0x2aaab0001f60, fun=0x409540 <rad_authenticate>) at event.c:3784 ---Type <return> to continue, or q <return> to quit--- No locals. #13 0x0000000000420728 in request_handler_thread (arg=<value optimized out>) at threads.c:537 fun = (RAD_REQUEST_FUNP) 0x409540 <rad_authenticate> self = (THREAD_HANDLE *) 0x2aaab4001fe0 #14 0x00002b380c8d8020 in start_thread () from /lib64/libpthread.so.0 No symbol table info available. #15 0x00002b380d829f8d in clone () from /lib64/libc.so.6 No symbol table info available. #16 0x0000000000000000 in ?? () No symbol table info available. (gdb)
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/devel.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/devel.html
-- Stefan WINTER Ingenieur de Recherche Fondation RESTENA - Réseau Téléinformatique de l'Education Nationale et de la Recherche 6, rue Richard Coudenhove-Kalergi L-1359 Luxembourg Tel: +352 424409 1 Fax: +352 422473
Hi, gettings closer... I set a breakpoint into normify() and checked what it does right before the memcpy: Breakpoint 1, normify (request=request@entry=0x1241a00, vp=vp@entry=0x1242f00, min_length=min_length@entry=20) at rlm_pap.c:246 246 { (gdb) print vp $1 = (VALUE_PAIR *) 0x1242f00 (gdb) print *vp $2 = {name = 0x1060150 "SSHA1-Password", attribute = 1094, vendor = 0, type = 5, length = 36, operator = T_OP_SET, flags = {addport = 0, has_tag = 0, do_xlat = 0, unknown_attr = 0, array = 0, has_value = 0, has_value_alias = 0, has_tlv = 0, is_tlv = 0, encoded = 0, tag = 0 '\000', encrypt = 0 '\000'}, next = 0x1242490, lvalue = 0, data = { strvalue = "=\\*\276\232\250\311\000@\b\261\067\067\031\066\"\332\003\217\035QOrr*oRvDSoZ9i%&dkRTb1o5aSUm", '\000' <repeats 205 times>, octets = "=\\*\276\232\250\311\000@\b\261\067\067\031\066\"\332\003\217\035QOrr*oRvDSoZ9i%&dkRTb1o5aSUm", '\000' <repeats 205 times>, ipaddr = {s_addr = 3190447165}, ipv6addr = {__in6_u = { __u6_addr8 = "=\\*\276\232\250\311\000@\b\261\067\067\031\066\"", __u6_addr16 = {23613, 48682, 43162, 201, 2112, 14257, 6455, 8758}, __u6_addr32 = {3190447165, 13215898, 934348864, 573970743}}}, date = 3190447165, integer = 3190447165, sinteger = -1104520131, filter = "=\\*\276\232\250\311\000@\b\261\067\067\031\066\"\332\003\217\035QOrr*oRvDSoZ", ifid = "=\\*\276\232\250", <incomplete sequence \311>, ipv6prefix = "=\\*\276\232\250\311\000@\b\261\067\067\031\066\"\332\003", ether = "=\\*\276\232\250", tlv = 0xc9a89abe2a5c3d <Address 0xc9a89abe2a5c3d out of bounds>}} (gdb) ( ... step/next until memcpy ... ) 272 RDEBUG2("Normalizing %s from base64 encoding", vp->name); (gdb) next 273 memcpy(vp->vp_octets, buffer, decoded); (gdb) print buffer $8 = "Гp {...}\000h_debugfallback {...}\000\026C", '\000' <repeats 28 times>, " " And there is a suymptom of the problem! The hash PVwqvpqoyQBACLE3Nxk2ItoDjx1RT3JyKm9SdkRTb1o5aSUm decodes as =\*�����776"��QOrr*oRvDSoZ9i%& on my cmdline; i.e. it at least starts with equals-backslash-star. The buffer line doesn't. It suspciously contains parts of my config (parts of the "pap_hash_debugfallback" string). So I guess the problem is indeed inside the preceding base64_decode. I'll be step'ing into it to see where it goes wrong... which might be ugly. Stefan On 06.05.2013 11:28, Stefan Winter wrote:
Hi one more time,
and another update: it's one specific SSHA1-Hash which makes the server crash; I can reproduce this easily.
The magic hash value is:
SSHA1-Password := PVwqvpqoyQBACLE3Nxk2ItoDjx1RT3JyKm9SdkRTb1o5aSUm
and makes things fail specifically during a memcpy inside normify(). Below is what valgrind has to say. Note that the user input in User-Password is irrelevant; failure is before it's even checked.
HTH,
Stefan
Found Auth-Type = PAP # Executing group from file /usr/local/freeradius/config/raddb/sites-enabled/SMTP +- entering group PAP {...} ++- entering policy pap_hash_debugfallback {...} +++- entering group {...} [pap] login attempt with password "foopass" [pap] Using SSHA encryption. [pap] Normalizing SSHA1-Password from base64 encoding ==13555== ==13555== Process terminating with default action of signal 11 (SIGSEGV) ==13555== Access not within mapped region at address 0x7FF001000 ==13555== at 0x4C2C476: memcpy@@GLIBC_2.14 (in /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so) ==13555== by 0x874B643: normify (rlm_pap.c:273) ==13555== by 0x874BDDF: pap_authenticate (rlm_pap.c:707) ==13555== by 0x41D764: modcall (modcall.c:304) ==13555== by 0x41BF38: indexed_modcall (modules.c:740) ==13555== by 0x40B176: rad_authenticate (auth.c:382) ==13555== by 0x4296E4: radius_handle_request (event.c:3784) ==13555== by 0x422227: thread_pool_addrequest (threads.c:887) ==13555== by 0x4272E5: event_socket_handler (event.c:3429) ==13555== by 0x4E4A2B4: fr_event_loop (event.c:415) ==13555== by 0x409F53: main (radiusd.c:408) ==13555== If you believe this happened as a result of a stack ==13555== overflow in your program's main thread (unlikely but ==13555== possible), you can try to increase the size of the ==13555== main thread stack using the --main-stacksize= flag. ==13555== The main thread stack size used in this run was 8388608. ==13555== ==13555== ---- Attach to debugger ? --- [Return/N/n/Y/y/C/c] ---- --13555-- VALGRIND INTERNAL ERROR: Valgrind received a signal 11 (SIGSEGV) - exiting --13555-- si_code=1; Faulting address: 0xC2394B0; sp: 0x402bda060
valgrind: the 'impossible' happened: Killed by fatal signal ==13555== at 0x38057958: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux) ==13555== by 0x3802124C: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux) ==13555== by 0x380213DA: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux) ==13555== by 0x3808F8D4: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux) ==13555== by 0x380551FF: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux) ==13555== by 0x38055304: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux) ==13555== by 0x3809EA61: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux)
sched status: running_tid=1
Thread 1: status = VgTs_Runnable ==13555== at 0x4C2ABED: malloc (in /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so) ==13555== by 0x4013B76: _dl_close_worker (in /lib64/ld-2.15.so) ==13555== by 0x40140AB: _dl_close (in /lib64/ld-2.15.so) ==13555== by 0x400E5F5: _dl_catch_error (in /lib64/ld-2.15.so) ==13555== by 0x64543CE: dlerror_run (in /lib64/libc-2.15.so) ==13555== by 0x6485946: free_mem (in /lib64/libc-2.15.so) ==13555== by 0x6485691: __libc_freeres (in /lib64/libc-2.15.so) ==13555== by 0x4A246EC: _vgnU_freeres (in /usr/lib64/valgrind/vgpreload_core-amd64-linux.so) ==13555== by 0x801604F: ??? ==13555== by 0x874B643: normify (rlm_pap.c:273) ==13555== by 0x874BDDF: pap_authenticate (rlm_pap.c:707) ==13555== by 0x41D764: modcall (modcall.c:304) ==13555== by 0x41BF38: indexed_modcall (modules.c:740) ==13555== by 0x40B176: rad_authenticate (auth.c:382) ==13555== by 0x4296E4: radius_handle_request (event.c:3784) ==13555== by 0x422227: thread_pool_addrequest (threads.c:887) ==13555== by 0x4272E5: event_socket_handler (event.c:3429) ==13555== by 0x4E4A2B4: fr_event_loop (event.c:415) ==13555== by 0x409F53: main (radiusd.c:408)
Note: see also the FAQ in the source distribution. It contains workarounds to several common problems. In particular, if Valgrind aborted or crashed after identifying problems in your program, there's a good chance that fixing those problems will prevent Valgrind aborting or crashing, especially if it happened in m_mallocfree.c.
If that doesn't help, please report this bug to: www.valgrind.org
In the bug report, send all the above text, the valgrind version, and what OS and version you are using. Thanks.
On 06.05.2013 10:48, Stefan Winter wrote:
Hi again,
running with -X I get:
rlm_sql_mysql: query: (SELECT id, username, attribute, value, op FROM check_smtp_ssha1 WHERE username='someusername') [sql-smtp-hash] User found in radcheck table rlm_sql (sql-smtp-hash): Released sql socket id: 1 +++[sql-smtp-hash] returns ok ++- policy redundant returns ok [pap] Normalizing SSHA1-Password from base64 encoding ++[pap] returns updated Found Auth-Type = PAP # Executing group from file /usr/local/freeradius/config/raddb/sites-enabled/SMTP +- entering group PAP {...} ++- entering policy pap_hash_debugfallback {...} +++- entering group {...} [pap] login attempt with password "eq346ici" [pap] Using SSHA encryption. [pap] Normalizing SSHA1-Password from base64 encoding Segmentation fault
Which is before the linelog is reached, so *maybe* the source of the problem is in the base64 normalisation code?
Stefan
On 06.05.2013 10:30, Stefan Winter wrote:
Hi,
today I did some minor config changes which turned my stable-running 2.2.0 into a crash-every-5-min server :-(
The change involved a) switching from Cleartext-Password to SSHA1-Password (retaining the pap module for checking the PW validity) b) a somewhat sophisticated unlang statement to express: if the SSHA1-PW was wrong, retrieve an alternative password from a VSA ("RESTENA-Debug-Password") and set it to be the Cleartext-Password; then try pap again with that
This is obviously the implementation of a "backdoor" for our helpdesk if we need to login into a user's account for debugging without knowing his actual password because it's SSHA'ed in the DB.
All nice and cute, and it worked while doing "mild" usage with a test account - but now in production things go down the drain with it.
I've temporarily switched back to the previous SQL query which had Cleartext-Password. And voilà: the server is stable again. Even with the unlang construct still in place (below for reference).
So I strongly suspect things to go wrong *only if* SSHA1-Passwords are used to authenticate the user.
Strangely enough, the gdb backtrace shows that it fails somewhere inside glibc while trying to expand a %S in xlat - which appears totally unrelated to the changes I did. The backtrace is below.
policy.conf: replacement for authenticate/pap:
policy {
pap_hash_debugfallback { group { pap { reject = 2 ok = return }
if ( "%{control:RESTENA-Debug-Password}" ) { update control { SSHA1-Password !* "nogood" NT-Password !* "nogood" Cleartext-Password := "%{control:RESTENA-Debug-Password}" } ok = 1 ok }
pap { reject = 2 ok = return } } } ... }
Program received signal SIGSEGV, Segmentation fault. [Switching to Thread 0x4b015950 (LWP 24837)] 0x00002b380d7d5550 in ?? () from /lib64/libc.so.6 (gdb) bt #0 0x00002b380d7d5550 in ?? () from /lib64/libc.so.6 #1 0x00002b380d7d6c0c in malloc () from /lib64/libc.so.6 #2 0x00002b380d7da8f2 in strdup () from /lib64/libc.so.6 #3 0x00002b380d7ed928 in ?? () from /lib64/libc.so.6 #4 0x00002b380d7ee3f0 in tzset () from /lib64/libc.so.6 #5 0x00002b380d7f2c94 in strftime_l () from /lib64/libc.so.6 #6 0x000000000042277d in radius_xlat (out=0x4b013a30 "[Access-Accept", outlen=1023, fmt=0x667c4e "[%S] [AUTH OK ] '%{User-Name}' (%{RESTENA-Service-Type}:%{client:shortname})", request=0x2aaab0001f60, func=0x2aaaab2e33d0 <linelog_escape_func>) at xlat.c:1348 #7 0x00002aaaab2e31d4 in do_linelog (instance=0x835a60, request=0x2aaab0001f60) at rlm_linelog.c:328 #8 0x000000000041c920 in modcall (component=7, c=<value optimized out>, request=0x2aaab0001f60) at modcall.c:304 #9 0x0000000000419be8 in indexed_modcall (comp=0, idx=0, request=0x2aaab0001f60) at modules.c:740 #10 0x00000000004094fd in rad_postauth (request=0x2aaab0001f60) at auth.c:433 #11 0x0000000000409b83 in rad_authenticate (request=0x2aaab0001f60) at auth.c:831 #12 0x0000000000427538 in radius_handle_request (request=0x2aaab0001f60, fun=0x409540 <rad_authenticate>) at event.c:3784 #13 0x0000000000420728 in request_handler_thread (arg=<value optimized out>) at threads.c:537 #14 0x00002b380c8d8020 in start_thread () from /lib64/libpthread.so.0 #15 0x00002b380d829f8d in clone () from /lib64/libc.so.6 #16 0x0000000000000000 in ?? () (gdb) bt full #0 0x00002b380d7d5550 in ?? () from /lib64/libc.so.6 No symbol table info available. #1 0x00002b380d7d6c0c in malloc () from /lib64/libc.so.6 No symbol table info available. #2 0x00002b380d7da8f2 in strdup () from /lib64/libc.so.6 No symbol table info available. #3 0x00002b380d7ed928 in ?? () from /lib64/libc.so.6 No symbol table info available. #4 0x00002b380d7ee3f0 in tzset () from /lib64/libc.so.6 No symbol table info available. #5 0x00002b380d7f2c94 in strftime_l () from /lib64/libc.so.6 No symbol table info available. #6 0x000000000042277d in radius_xlat (out=0x4b013a30 "[Access-Accept", outlen=1023, fmt=0x667c4e "[%S] [AUTH OK ] '%{User-Name}' (%{RESTENA-Service-Type}:%{client:shortname})", request=0x2aaab0001f60, func=0x2aaaab2e33d0 <linelog_escape_func>) at xlat.c:1348 c = <value optimized out> len = <value optimized out> freespace = <value optimized out> p = 0x667c50 "S] [AUTH OK ] '%{User-Name}' (%{RESTENA-Service-Type}:%{client:shortname})" q = 0x4b013a31 "Access-Accept" tmp = (VALUE_PAIR *) 0x2aaab0001f60 TM = (struct tm *) 0x3 s_TM = {tm_sec = 45, tm_min = 15, tm_hour = 10, tm_mday = 6, tm_mon = 4, tm_year = 113, tm_wday = 1, tm_yday = 125, tm_isdst = 1, tm_gmtoff = 7200, tm_zone = 0x807da0 "CEST"} tmpdt = "\000\020\000\000\000\000\000\000\000\020\000\000\000\000\000\000\b\000\000\000\000\000\000\000\236A�G", '\0' <repeats 11 times> #7 0x00002aaaab2e31d4 in do_linelog (instance=0x835a60, request=0x2aaab0001f60) at rlm_linelog.c:328 ci = <value optimized out> cp = <value optimized out> fd = 56 buffer = "/var/log/radius/activity.log\000+\000\000�*\001K\001\000\000\000�+\001K\000\000\000\000�X\001K\000\000\000\000\000�\213\000\000\000\000\000\005\000\000\000\000\000\000\000�>\000��*\000\000\000\000\000\000\000\000\000\000�>\000��*\000\000\n\000\000\000\000\000\000\000�>\000��*\000\000P>\001K\000\000\000\000�w�\0178+\000\000:=\000\000\000\000\000\000\030", '\0' <repeats 15 times>, "�\025B\000\000\000\000\000\000�\213\000\000\000\000\000�*\001K\000\000\000\000P>\001K\000\000\000\000`\037\000��*\000\000\000\000\002\000\000\000\000\000\220�\213\000\000"... p = <value optimized out> line = "[Access-Accept", '\0' <repeats 434 times>, "Mon May 6 10:15:45 2013\000\000\000\000\000\000\000\000Mon May 6 10:15:45 2013", '\0' <repeats 116 times>, "\024\000\000\000`\001\000\000\000\000\000\0008\001\000\000\000\000\000\000\000\000\000\000\024", '\0' <repeats 35 times>, "\202\230'\f8+\000\000`\003j\000\000\000\000\000 \000\000��*\000\0008\001", '\0' <repeats 14 times>, "\001\000\000\000\000\000\000\000`\037\000��*\000\0000}\203\000\000\000\000\000\fl}\r8+\000\000�\204|", '\0' <repeats 13 times>... value = 0x667c4e "[%S] [AUTH OK ] '%{User-Name}' (%{RESTENA-Service-Type}:%{client:shortname})" gid = <value optimized out> grp = (struct group *) 0x0 endptr = 0x6889fc ")" #8 0x000000000041c920 in modcall (component=7, c=<value optimized out>, request=0x2aaab0001f60) at modcall.c:304 server = <value optimized out> myresult = 1 stack = {pointer = 0, priority = {0, 0, 3, 0, 0, 0, 0, 0, 0, 3, 0, 3, 0 <repeats 20 times>}, result = {7, 7, 2, 0, 0, 0, 0, 0, 0, 2, 2, 2, 2, 0 <repeats 19 times>}, children = {0x8f2910, 0x8f2730, 0x8f2800, 0x0, 0x837410, 0x0 <repeats 27 times>}, start = {0x0, 0x8f2730, 0x8f27a0, 0x0, 0x0, 0x837480, 0x8374f0, 0x8af080, 0x8e3ec0, 0x0 <repeats 23 times>}} parent = (modcallable *) 0x8f2730 child = (modcallable *) 0x8f2800 if_taken = 0 was_if = 0 #9 0x0000000000419be8 in indexed_modcall (comp=0, idx=0, request=0x2aaab0001f60) at modules.c:740 this = <value optimized out> rcode = <value optimized out> list = (modcallable *) 0x8f2910 server = (virtual_server_t *) 0x837330 #10 0x00000000004094fd in rad_postauth (request=0x2aaab0001f60) at auth.c:433 result = <value optimized out> postauth_type = 0 vp = (VALUE_PAIR *) 0x0 #11 0x0000000000409b83 in rad_authenticate (request=0x2aaab0001f60) at auth.c:831 namepair = (VALUE_PAIR *) 0x9a71f0 check_item = (VALUE_PAIR *) 0x0 auth_item = (VALUE_PAIR *) 0x9a8c10 module_msg = <value optimized out> tmp = (VALUE_PAIR *) 0x0 result = -1275060192 autz_retry = <value optimized out> autz_type = <value optimized out> #12 0x0000000000427538 in radius_handle_request (request=0x2aaab0001f60, fun=0x409540 <rad_authenticate>) at event.c:3784 ---Type <return> to continue, or q <return> to quit--- No locals. #13 0x0000000000420728 in request_handler_thread (arg=<value optimized out>) at threads.c:537 fun = (RAD_REQUEST_FUNP) 0x409540 <rad_authenticate> self = (THREAD_HANDLE *) 0x2aaab4001fe0 #14 0x00002b380c8d8020 in start_thread () from /lib64/libpthread.so.0 No symbol table info available. #15 0x00002b380d829f8d in clone () from /lib64/libc.so.6 No symbol table info available. #16 0x0000000000000000 in ?? () No symbol table info available. (gdb)
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/devel.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/devel.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/devel.html
-- Stefan WINTER Ingenieur de Recherche Fondation RESTENA - Réseau Téléinformatique de l'Education Nationale et de la Recherche 6, rue Richard Coudenhove-Kalergi L-1359 Luxembourg Tel: +352 424409 1 Fax: +352 422473
Hello, so: here's the reason why things go wrong. I see where we're getting off-rails at least; not sure why the end of the track is a SEGV, but here's at least a road to a fix... During authorize { }, the pap module normalises password input (function normify() ); it has a heuristics to find out if it has a Hex-encoded string (characters in the *-Password attribute exactly 2 times higher than expected? -> HEX) or maybe a BASE64 encoding (equal to or more than 4/3 of the expected length). This works well for any decoded attribute value whose length is known. E.g. MD5: raw 16 Byte; HEX-encoded 32 Byte; BASE64-encoded 20-odd byte. It fails gracefully if things go wrong; so even if the base64 Decoder is called - if it doesn't find valid base64 content, it just doesn't touch anything. FreeRADIUS applies this heuristics at *two* points (I don't understand why): it also runs normify() during the authenticate section). I believe this is some legacy: FR 2.x has this golden rule of "always call pap as the last module in authorise" - so any input *is* normalised, and doesn't have to be checked twice. The problem comes when salted hashes are in use; the heuristics has no idea what to "expect" as a length; it merrily takes the expected lengths of the non-salted variants. So, depending on how long your salt is, SSHA1 might end up being decoded for a first time in authorize { ... papa ... } and a second time in authenticate { ... pap ...}. As I said this is not normally an issue due to normify failing gracefully if it sees non-HEX|base64 content. The bad luck I had with my particular hash was: it *does* look like it - the decoded content starts with an = sign, which FreeRADIUS somewhat rightfully takes as "end of string". So the failing flow of code for me is Input: 48 Bytes of base-64 encoded, salted SHA1 password authorize/pap/normify: transforms to 36 Bytes of raw salted SHA1 password authenticate/pap/normify: transform to 24 Bytes of garbage Again, why the garbage leads to a SEGV I don't know. But fixing this should be rather straightforward: make sure that normify only operates *once* on an input string! Either take away the calls to normify() from pap_authenticate() or add another flag to VALUE_PAIR which would indicate "has_already_been_normalised". This is a good candidate to go into 2.2.1 IMHO :-) Greetings, Stefan Winter On 06.05.2013 11:59, Stefan Winter wrote:
Hi,
gettings closer...
I set a breakpoint into normify() and checked what it does right before the memcpy:
Breakpoint 1, normify (request=request@entry=0x1241a00, vp=vp@entry=0x1242f00, min_length=min_length@entry=20) at rlm_pap.c:246 246 { (gdb) print vp $1 = (VALUE_PAIR *) 0x1242f00 (gdb) print *vp $2 = {name = 0x1060150 "SSHA1-Password", attribute = 1094, vendor = 0, type = 5, length = 36, operator = T_OP_SET, flags = {addport = 0, has_tag = 0, do_xlat = 0, unknown_attr = 0, array = 0, has_value = 0, has_value_alias = 0, has_tlv = 0, is_tlv = 0, encoded = 0, tag = 0 '\000', encrypt = 0 '\000'}, next = 0x1242490, lvalue = 0, data = { strvalue = "=\\*\276\232\250\311\000@\b\261\067\067\031\066\"\332\003\217\035QOrr*oRvDSoZ9i%&dkRTb1o5aSUm", '\000' <repeats 205 times>, octets = "=\\*\276\232\250\311\000@\b\261\067\067\031\066\"\332\003\217\035QOrr*oRvDSoZ9i%&dkRTb1o5aSUm", '\000' <repeats 205 times>, ipaddr = {s_addr = 3190447165}, ipv6addr = {__in6_u = { __u6_addr8 = "=\\*\276\232\250\311\000@\b\261\067\067\031\066\"", __u6_addr16 = {23613, 48682, 43162, 201, 2112, 14257, 6455, 8758}, __u6_addr32 = {3190447165, 13215898, 934348864, 573970743}}}, date = 3190447165, integer = 3190447165, sinteger = -1104520131, filter = "=\\*\276\232\250\311\000@\b\261\067\067\031\066\"\332\003\217\035QOrr*oRvDSoZ", ifid = "=\\*\276\232\250", <incomplete sequence \311>, ipv6prefix = "=\\*\276\232\250\311\000@\b\261\067\067\031\066\"\332\003", ether = "=\\*\276\232\250", tlv = 0xc9a89abe2a5c3d <Address 0xc9a89abe2a5c3d out of bounds>}} (gdb)
( ... step/next until memcpy ... )
272 RDEBUG2("Normalizing %s from base64 encoding", vp->name); (gdb) next 273 memcpy(vp->vp_octets, buffer, decoded);
(gdb) print buffer $8 = "Гp {...}\000h_debugfallback {...}\000\026C", '\000' <repeats 28 times>, " "
And there is a suymptom of the problem! The hash
PVwqvpqoyQBACLE3Nxk2ItoDjx1RT3JyKm9SdkRTb1o5aSUm
decodes as
=\*�����776"��QOrr*oRvDSoZ9i%&
on my cmdline; i.e. it at least starts with equals-backslash-star.
The buffer line doesn't. It suspciously contains parts of my config (parts of the "pap_hash_debugfallback" string). So I guess the problem is indeed inside the preceding base64_decode.
I'll be step'ing into it to see where it goes wrong... which might be ugly.
Stefan
On 06.05.2013 11:28, Stefan Winter wrote:
Hi one more time,
and another update: it's one specific SSHA1-Hash which makes the server crash; I can reproduce this easily.
The magic hash value is:
SSHA1-Password := PVwqvpqoyQBACLE3Nxk2ItoDjx1RT3JyKm9SdkRTb1o5aSUm
and makes things fail specifically during a memcpy inside normify(). Below is what valgrind has to say. Note that the user input in User-Password is irrelevant; failure is before it's even checked.
HTH,
Stefan
Found Auth-Type = PAP # Executing group from file /usr/local/freeradius/config/raddb/sites-enabled/SMTP +- entering group PAP {...} ++- entering policy pap_hash_debugfallback {...} +++- entering group {...} [pap] login attempt with password "foopass" [pap] Using SSHA encryption. [pap] Normalizing SSHA1-Password from base64 encoding ==13555== ==13555== Process terminating with default action of signal 11 (SIGSEGV) ==13555== Access not within mapped region at address 0x7FF001000 ==13555== at 0x4C2C476: memcpy@@GLIBC_2.14 (in /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so) ==13555== by 0x874B643: normify (rlm_pap.c:273) ==13555== by 0x874BDDF: pap_authenticate (rlm_pap.c:707) ==13555== by 0x41D764: modcall (modcall.c:304) ==13555== by 0x41BF38: indexed_modcall (modules.c:740) ==13555== by 0x40B176: rad_authenticate (auth.c:382) ==13555== by 0x4296E4: radius_handle_request (event.c:3784) ==13555== by 0x422227: thread_pool_addrequest (threads.c:887) ==13555== by 0x4272E5: event_socket_handler (event.c:3429) ==13555== by 0x4E4A2B4: fr_event_loop (event.c:415) ==13555== by 0x409F53: main (radiusd.c:408) ==13555== If you believe this happened as a result of a stack ==13555== overflow in your program's main thread (unlikely but ==13555== possible), you can try to increase the size of the ==13555== main thread stack using the --main-stacksize= flag. ==13555== The main thread stack size used in this run was 8388608. ==13555== ==13555== ---- Attach to debugger ? --- [Return/N/n/Y/y/C/c] ---- --13555-- VALGRIND INTERNAL ERROR: Valgrind received a signal 11 (SIGSEGV) - exiting --13555-- si_code=1; Faulting address: 0xC2394B0; sp: 0x402bda060
valgrind: the 'impossible' happened: Killed by fatal signal ==13555== at 0x38057958: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux) ==13555== by 0x3802124C: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux) ==13555== by 0x380213DA: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux) ==13555== by 0x3808F8D4: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux) ==13555== by 0x380551FF: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux) ==13555== by 0x38055304: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux) ==13555== by 0x3809EA61: ??? (in /usr/lib64/valgrind/memcheck-amd64-linux)
sched status: running_tid=1
Thread 1: status = VgTs_Runnable ==13555== at 0x4C2ABED: malloc (in /usr/lib64/valgrind/vgpreload_memcheck-amd64-linux.so) ==13555== by 0x4013B76: _dl_close_worker (in /lib64/ld-2.15.so) ==13555== by 0x40140AB: _dl_close (in /lib64/ld-2.15.so) ==13555== by 0x400E5F5: _dl_catch_error (in /lib64/ld-2.15.so) ==13555== by 0x64543CE: dlerror_run (in /lib64/libc-2.15.so) ==13555== by 0x6485946: free_mem (in /lib64/libc-2.15.so) ==13555== by 0x6485691: __libc_freeres (in /lib64/libc-2.15.so) ==13555== by 0x4A246EC: _vgnU_freeres (in /usr/lib64/valgrind/vgpreload_core-amd64-linux.so) ==13555== by 0x801604F: ??? ==13555== by 0x874B643: normify (rlm_pap.c:273) ==13555== by 0x874BDDF: pap_authenticate (rlm_pap.c:707) ==13555== by 0x41D764: modcall (modcall.c:304) ==13555== by 0x41BF38: indexed_modcall (modules.c:740) ==13555== by 0x40B176: rad_authenticate (auth.c:382) ==13555== by 0x4296E4: radius_handle_request (event.c:3784) ==13555== by 0x422227: thread_pool_addrequest (threads.c:887) ==13555== by 0x4272E5: event_socket_handler (event.c:3429) ==13555== by 0x4E4A2B4: fr_event_loop (event.c:415) ==13555== by 0x409F53: main (radiusd.c:408)
Note: see also the FAQ in the source distribution. It contains workarounds to several common problems. In particular, if Valgrind aborted or crashed after identifying problems in your program, there's a good chance that fixing those problems will prevent Valgrind aborting or crashing, especially if it happened in m_mallocfree.c.
If that doesn't help, please report this bug to: www.valgrind.org
In the bug report, send all the above text, the valgrind version, and what OS and version you are using. Thanks.
On 06.05.2013 10:48, Stefan Winter wrote:
Hi again,
running with -X I get:
rlm_sql_mysql: query: (SELECT id, username, attribute, value, op FROM check_smtp_ssha1 WHERE username='someusername') [sql-smtp-hash] User found in radcheck table rlm_sql (sql-smtp-hash): Released sql socket id: 1 +++[sql-smtp-hash] returns ok ++- policy redundant returns ok [pap] Normalizing SSHA1-Password from base64 encoding ++[pap] returns updated Found Auth-Type = PAP # Executing group from file /usr/local/freeradius/config/raddb/sites-enabled/SMTP +- entering group PAP {...} ++- entering policy pap_hash_debugfallback {...} +++- entering group {...} [pap] login attempt with password "eq346ici" [pap] Using SSHA encryption. [pap] Normalizing SSHA1-Password from base64 encoding Segmentation fault
Which is before the linelog is reached, so *maybe* the source of the problem is in the base64 normalisation code?
Stefan
On 06.05.2013 10:30, Stefan Winter wrote:
Hi,
today I did some minor config changes which turned my stable-running 2.2.0 into a crash-every-5-min server :-(
The change involved a) switching from Cleartext-Password to SSHA1-Password (retaining the pap module for checking the PW validity) b) a somewhat sophisticated unlang statement to express: if the SSHA1-PW was wrong, retrieve an alternative password from a VSA ("RESTENA-Debug-Password") and set it to be the Cleartext-Password; then try pap again with that
This is obviously the implementation of a "backdoor" for our helpdesk if we need to login into a user's account for debugging without knowing his actual password because it's SSHA'ed in the DB.
All nice and cute, and it worked while doing "mild" usage with a test account - but now in production things go down the drain with it.
I've temporarily switched back to the previous SQL query which had Cleartext-Password. And voilà: the server is stable again. Even with the unlang construct still in place (below for reference).
So I strongly suspect things to go wrong *only if* SSHA1-Passwords are used to authenticate the user.
Strangely enough, the gdb backtrace shows that it fails somewhere inside glibc while trying to expand a %S in xlat - which appears totally unrelated to the changes I did. The backtrace is below.
policy.conf: replacement for authenticate/pap:
policy {
pap_hash_debugfallback { group { pap { reject = 2 ok = return }
if ( "%{control:RESTENA-Debug-Password}" ) { update control { SSHA1-Password !* "nogood" NT-Password !* "nogood" Cleartext-Password := "%{control:RESTENA-Debug-Password}" } ok = 1 ok }
pap { reject = 2 ok = return } } } ... }
Program received signal SIGSEGV, Segmentation fault. [Switching to Thread 0x4b015950 (LWP 24837)] 0x00002b380d7d5550 in ?? () from /lib64/libc.so.6 (gdb) bt #0 0x00002b380d7d5550 in ?? () from /lib64/libc.so.6 #1 0x00002b380d7d6c0c in malloc () from /lib64/libc.so.6 #2 0x00002b380d7da8f2 in strdup () from /lib64/libc.so.6 #3 0x00002b380d7ed928 in ?? () from /lib64/libc.so.6 #4 0x00002b380d7ee3f0 in tzset () from /lib64/libc.so.6 #5 0x00002b380d7f2c94 in strftime_l () from /lib64/libc.so.6 #6 0x000000000042277d in radius_xlat (out=0x4b013a30 "[Access-Accept", outlen=1023, fmt=0x667c4e "[%S] [AUTH OK ] '%{User-Name}' (%{RESTENA-Service-Type}:%{client:shortname})", request=0x2aaab0001f60, func=0x2aaaab2e33d0 <linelog_escape_func>) at xlat.c:1348 #7 0x00002aaaab2e31d4 in do_linelog (instance=0x835a60, request=0x2aaab0001f60) at rlm_linelog.c:328 #8 0x000000000041c920 in modcall (component=7, c=<value optimized out>, request=0x2aaab0001f60) at modcall.c:304 #9 0x0000000000419be8 in indexed_modcall (comp=0, idx=0, request=0x2aaab0001f60) at modules.c:740 #10 0x00000000004094fd in rad_postauth (request=0x2aaab0001f60) at auth.c:433 #11 0x0000000000409b83 in rad_authenticate (request=0x2aaab0001f60) at auth.c:831 #12 0x0000000000427538 in radius_handle_request (request=0x2aaab0001f60, fun=0x409540 <rad_authenticate>) at event.c:3784 #13 0x0000000000420728 in request_handler_thread (arg=<value optimized out>) at threads.c:537 #14 0x00002b380c8d8020 in start_thread () from /lib64/libpthread.so.0 #15 0x00002b380d829f8d in clone () from /lib64/libc.so.6 #16 0x0000000000000000 in ?? () (gdb) bt full #0 0x00002b380d7d5550 in ?? () from /lib64/libc.so.6 No symbol table info available. #1 0x00002b380d7d6c0c in malloc () from /lib64/libc.so.6 No symbol table info available. #2 0x00002b380d7da8f2 in strdup () from /lib64/libc.so.6 No symbol table info available. #3 0x00002b380d7ed928 in ?? () from /lib64/libc.so.6 No symbol table info available. #4 0x00002b380d7ee3f0 in tzset () from /lib64/libc.so.6 No symbol table info available. #5 0x00002b380d7f2c94 in strftime_l () from /lib64/libc.so.6 No symbol table info available. #6 0x000000000042277d in radius_xlat (out=0x4b013a30 "[Access-Accept", outlen=1023, fmt=0x667c4e "[%S] [AUTH OK ] '%{User-Name}' (%{RESTENA-Service-Type}:%{client:shortname})", request=0x2aaab0001f60, func=0x2aaaab2e33d0 <linelog_escape_func>) at xlat.c:1348 c = <value optimized out> len = <value optimized out> freespace = <value optimized out> p = 0x667c50 "S] [AUTH OK ] '%{User-Name}' (%{RESTENA-Service-Type}:%{client:shortname})" q = 0x4b013a31 "Access-Accept" tmp = (VALUE_PAIR *) 0x2aaab0001f60 TM = (struct tm *) 0x3 s_TM = {tm_sec = 45, tm_min = 15, tm_hour = 10, tm_mday = 6, tm_mon = 4, tm_year = 113, tm_wday = 1, tm_yday = 125, tm_isdst = 1, tm_gmtoff = 7200, tm_zone = 0x807da0 "CEST"} tmpdt = "\000\020\000\000\000\000\000\000\000\020\000\000\000\000\000\000\b\000\000\000\000\000\000\000\236A�G", '\0' <repeats 11 times> #7 0x00002aaaab2e31d4 in do_linelog (instance=0x835a60, request=0x2aaab0001f60) at rlm_linelog.c:328 ci = <value optimized out> cp = <value optimized out> fd = 56 buffer = "/var/log/radius/activity.log\000+\000\000�*\001K\001\000\000\000�+\001K\000\000\000\000�X\001K\000\000\000\000\000�\213\000\000\000\000\000\005\000\000\000\000\000\000\000�>\000��*\000\000\000\000\000\000\000\000\000\000�>\000��*\000\000\n\000\000\000\000\000\000\000�>\000��*\000\000P>\001K\000\000\000\000�w�\0178+\000\000:=\000\000\000\000\000\000\030", '\0' <repeats 15 times>, "�\025B\000\000\000\000\000\000�\213\000\000\000\000\000�*\001K\000\000\000\000P>\001K\000\000\000\000`\037\000��*\000\000\000\000\002\000\000\000\000\000\220�\213\000\000"... p = <value optimized out> line = "[Access-Accept", '\0' <repeats 434 times>, "Mon May 6 10:15:45 2013\000\000\000\000\000\000\000\000Mon May 6 10:15:45 2013", '\0' <repeats 116 times>, "\024\000\000\000`\001\000\000\000\000\000\0008\001\000\000\000\000\000\000\000\000\000\000\024", '\0' <repeats 35 times>, "\202\230'\f8+\000\000`\003j\000\000\000\000\000 \000\000��*\000\0008\001", '\0' <repeats 14 times>, "\001\000\000\000\000\000\000\000`\037\000��*\000\0000}\203\000\000\000\000\000\fl}\r8+\000\000�\204|", '\0' <repeats 13 times>... value = 0x667c4e "[%S] [AUTH OK ] '%{User-Name}' (%{RESTENA-Service-Type}:%{client:shortname})" gid = <value optimized out> grp = (struct group *) 0x0 endptr = 0x6889fc ")" #8 0x000000000041c920 in modcall (component=7, c=<value optimized out>, request=0x2aaab0001f60) at modcall.c:304 server = <value optimized out> myresult = 1 stack = {pointer = 0, priority = {0, 0, 3, 0, 0, 0, 0, 0, 0, 3, 0, 3, 0 <repeats 20 times>}, result = {7, 7, 2, 0, 0, 0, 0, 0, 0, 2, 2, 2, 2, 0 <repeats 19 times>}, children = {0x8f2910, 0x8f2730, 0x8f2800, 0x0, 0x837410, 0x0 <repeats 27 times>}, start = {0x0, 0x8f2730, 0x8f27a0, 0x0, 0x0, 0x837480, 0x8374f0, 0x8af080, 0x8e3ec0, 0x0 <repeats 23 times>}} parent = (modcallable *) 0x8f2730 child = (modcallable *) 0x8f2800 if_taken = 0 was_if = 0 #9 0x0000000000419be8 in indexed_modcall (comp=0, idx=0, request=0x2aaab0001f60) at modules.c:740 this = <value optimized out> rcode = <value optimized out> list = (modcallable *) 0x8f2910 server = (virtual_server_t *) 0x837330 #10 0x00000000004094fd in rad_postauth (request=0x2aaab0001f60) at auth.c:433 result = <value optimized out> postauth_type = 0 vp = (VALUE_PAIR *) 0x0 #11 0x0000000000409b83 in rad_authenticate (request=0x2aaab0001f60) at auth.c:831 namepair = (VALUE_PAIR *) 0x9a71f0 check_item = (VALUE_PAIR *) 0x0 auth_item = (VALUE_PAIR *) 0x9a8c10 module_msg = <value optimized out> tmp = (VALUE_PAIR *) 0x0 result = -1275060192 autz_retry = <value optimized out> autz_type = <value optimized out> #12 0x0000000000427538 in radius_handle_request (request=0x2aaab0001f60, fun=0x409540 <rad_authenticate>) at event.c:3784 ---Type <return> to continue, or q <return> to quit--- No locals. #13 0x0000000000420728 in request_handler_thread (arg=<value optimized out>) at threads.c:537 fun = (RAD_REQUEST_FUNP) 0x409540 <rad_authenticate> self = (THREAD_HANDLE *) 0x2aaab4001fe0 #14 0x00002b380c8d8020 in start_thread () from /lib64/libpthread.so.0 No symbol table info available. #15 0x00002b380d829f8d in clone () from /lib64/libc.so.6 No symbol table info available. #16 0x0000000000000000 in ?? () No symbol table info available. (gdb)
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/devel.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/devel.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/devel.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/devel.html
-- Stefan WINTER Ingenieur de Recherche Fondation RESTENA - Réseau Téléinformatique de l'Education Nationale et de la Recherche 6, rue Richard Coudenhove-Kalergi L-1359 Luxembourg Tel: +352 424409 1 Fax: +352 422473
Stefan Winter wrote:
Hi one more time,
and another update: it's one specific SSHA1-Hash which makes the server crash; I can reproduce this easily.
The magic hash value is:
SSHA1-Password := PVwqvpqoyQBACLE3Nxk2ItoDjx1RT3JyKm9SdkRTb1o5aSUm
and makes things fail specifically during a memcpy inside normify(). Below is what valgrind has to say. Note that the user input in User-Password is irrelevant; failure is before it's even checked.
Weird. I've fixed it, after some poking of the function. It now base64-decodes the password once, and only once. Alan DeKok.
Hi,
Weird. I've fixed it, after some poking of the function. It now base64-decodes the password once, and only once.
Well... is that a complete fix? Looks to me like there is still the *small* chance of a) the decoded SSHA1 value containing only bytes which are allowed in base64 b) the salt being so long that it grows the whole decoded string to more than 4/3 of the min_length c) the salt having exclusively bytes which are allowed in base64; possibly ending in = sign(s) If all these are met, a second decoding would be done, and be successful - except the user wouldn't be able to log in because the new decoded content would not match his password any more. I guess I can live with that small chance, but... clean is something else. How about if you owe me a beer if that unlikely situation becomes true :-) Stefan -- Stefan WINTER Ingenieur de Recherche Fondation RESTENA - Réseau Téléinformatique de l'Education Nationale et de la Recherche 6, rue Richard Coudenhove-Kalergi L-1359 Luxembourg Tel: +352 424409 1 Fax: +352 422473
Stefan Winter wrote:
If all these are met, a second decoding would be done, and be successful - except the user wouldn't be able to log in because the new decoded content would not match his password any more.
I guess I can live with that small chance, but... clean is something else. How about if you owe me a beer if that unlikely situation becomes true :-)
Arran fixed the "master" branch to use a more robust base64 encoder / decoder. So it won't happen there. There won't be any new development on the v2.2.x branch. We hope to release v3 soon. (As I've been saying for years) Alan DeKok.
What's the best way to get the latest code? Thanks, Chris -----Original Message----- From: freeradius-devel-bounces+chris.taylor=corp.eastlink.ca@lists.freeradius.org [mailto:freeradius-devel-bounces+chris.taylor=corp.eastlink.ca@lists.freeradius.org] On Behalf Of Alan DeKok Sent: Monday, May 06, 2013 9:25 AM To: FreeRadius developers mailing list Subject: Re: 2.2.0 crash at a strange location Stefan Winter wrote:
If all these are met, a second decoding would be done, and be successful - except the user wouldn't be able to log in because the new decoded content would not match his password any more.
I guess I can live with that small chance, but... clean is something else. How about if you owe me a beer if that unlikely situation becomes true :-)
Arran fixed the "master" branch to use a more robust base64 encoder / decoder. So it won't happen there. There won't be any new development on the v2.2.x branch. We hope to release v3 soon. (As I've been saying for years) Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/devel.html
Just check it out from github: https://github.com/FreeRADIUS/freeradius-server -- Aaron On May 6, 2013, at 8:40 AM, Chris Taylor <Chris.Taylor@corp.eastlink.ca> wrote:
What's the best way to get the latest code?
Thanks,
Chris
-----Original Message----- From: freeradius-devel-bounces+chris.taylor=corp.eastlink.ca@lists.freeradius.org [mailto:freeradius-devel-bounces+chris.taylor=corp.eastlink.ca@lists.freeradius.org] On Behalf Of Alan DeKok Sent: Monday, May 06, 2013 9:25 AM To: FreeRadius developers mailing list Subject: Re: 2.2.0 crash at a strange location
Stefan Winter wrote:
If all these are met, a second decoding would be done, and be successful - except the user wouldn't be able to log in because the new decoded content would not match his password any more.
I guess I can live with that small chance, but... clean is something else. How about if you owe me a beer if that unlikely situation becomes true :-)
Arran fixed the "master" branch to use a more robust base64 encoder / decoder. So it won't happen there.
There won't be any new development on the v2.2.x branch. We hope to release v3 soon. (As I've been saying for years)
Alan DeKok. - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/devel.html - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/devel.html
Hi,
[pap] login attempt with password "eq346ici" [pap] Using SSHA encryption. [pap] Normalizing SSHA1-Password from base64 encoding Segmentation fault
this looks very much like another case which was being discussed on the users mailing list only last week(?) - same looking crash location. alan
Hi,
[pap] login attempt with password "eq346ici" [pap] Using SSHA encryption. [pap] Normalizing SSHA1-Password from base64 encoding Segmentation fault
this looks very much like another case which was being discussed on the users mailing list only last week(?) - same looking crash location.
I found the issue finally, detailed mail coming up, but for short: Passwords can bei either HEX or BASE64 encoded. FreeRADIUS has a heuristics to determine what it has to do with the incoming string. In this case, the heuristics failed quite horribly. Stefan -- Stefan WINTER Ingenieur de Recherche Fondation RESTENA - Réseau Téléinformatique de l'Education Nationale et de la Recherche 6, rue Richard Coudenhove-Kalergi L-1359 Luxembourg Tel: +352 424409 1 Fax: +352 422473
participants (5)
-
A.L.M.Buxey＠lboro.ac.uk -
Aaron Hurt -
Alan DeKok -
Chris Taylor -
Stefan Winter