2.2.0 crash at a strange location

6 May 2013

      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

2.2.0 crash at a strange location

Stefan Winter