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