search

FreeRADIUS / freeradius-server

FreeRADIUS - A multi-protocol policy server.
http://freeradius.org
GNU General Public License v2.0
2.13k stars 1.08k forks source link

Problems with "%{debug_attr:}" (SIGSEGV) #1301

Closed jpereira closed 8 years ago

jpereira commented 9 years ago

Hi,

I have found a bug. But, I can't figure out well what's going on.

1) I have the setting.

server default {
   authorize {
       "%{debug_attr:request:}"
        ...
       "%{debug_attr:request:}"
       ....
   }
............

And send the packet.

$ radclient 127.0.0.1:1812 auth testing123 -xx -f auth-debug-bug.attr 
Sent Access-Request Id 42 from 0.0.0.0:51507 to 127.0.0.1:1812 length 126
    Acct-Session-Id = "12345"
    User-Name = "caipirinha"
    User-Password = "senha"
    Class = 0x01020304050000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
    Cleartext-Password = "senha"
$

And get the SEGV

..........................................
Mon Oct  5 16:32:45 2015 : Debug: (0)     Sent Access-Accept Id 78 from 127.0.0.1:1812 to 10.1.2.128:44251 length 0
  Socket:   13
  Proto:    0
  Src IP:   127.0.0.1
    port:   1812
  Dst IP:   10.1.2.128
    port:   44251
  Code:     (2) Access-Accept
  Id:       78
  Length:   20
  Vector:   a1fc092ac95c5b4ec13f2a4bd478a51a
Mon Oct  5 16:32:45 2015 : Debug: (0)     Finished request

Program received signal SIGSEGV, Segmentation fault.
0x00007ffff67224b2 in _IO_vfprintf_internal (s=s@entry=0x7fffffffd220, format=<optimized out>, 
    format@entry=0x7ffff7103918 "talloc: access after free error - first free may be at %s\n", ap=ap@entry=0x7fffffffd3b8)
    at vfprintf.c:1642
1642    vfprintf.c: No such file or directory.
(gdb) bt
#0  0x00007ffff67224b2 in _IO_vfprintf_internal (s=s@entry=0x7fffffffd220, format=<optimized out>, 
    format@entry=0x7ffff7103918 "talloc: access after free error - first free may be at %s\n", ap=ap@entry=0x7fffffffd3b8)
    at vfprintf.c:1642
#1  0x00007ffff67ea5a6 in ___vsnprintf_chk (s=0x7fffffffd3d0 "talloc: access after free error - first free may be at ", 
    maxlen=<optimized out>, flags=0x1, slen=<optimized out>, 
    format=0x7ffff7103918 "talloc: access after free error - first free may be at %s\n", args=0x7fffffffd3b8) at vsnprintf_chk.c:63
#2  0x00007ffff70fe28e in talloc_vasprintf () from /usr/lib/x86_64-linux-gnu/libtalloc.so.2
#3  0x00007ffff70fa43c in ?? () from /usr/lib/x86_64-linux-gnu/libtalloc.so.2
#4  0x00007ffff70f9c03 in ?? () from /usr/lib/x86_64-linux-gnu/libtalloc.so.2
#5  0x00007ffff70fe826 in _talloc_get_type_abort () from /usr/lib/x86_64-linux-gnu/libtalloc.so.2
#6  0x00007ffff7981c30 in fr_event_insert (el=0x8d90b0, callback=0x43d493 <request_timer at src/main/process.c:527>, ctx=0x998e40, 
    when=0x7fffffffd9e0, parent=0x998ee0) at src/lib/event.c:237
#7  0x000000000043cb76 in state_machine_timer (file=0x46cf22 "src/main/process.c", line=0x366, request=0x998e40, when=0x7fffffffd9e0, 
    action=FR_ACTION_TIMER) at src/main/process.c:135
#8  0x000000000043dff3 in request_cleanup_delay_init (request=0x998e40) at src/main/process.c:870
#9  0x000000000043f4e2 in request_finish (request=0x998e40, action=0x1) at src/main/process.c:1467
#10 0x000000000043f764 in request_running (request=0x998e40, action=0x1) at src/main/process.c:1555
#11 0x000000000043e454 in request_queue_or_run (request=0x998e40, process=0x43f5c1 <request_running at src/main/process.c:1498>)
    at src/main/process.c:1015
#12 0x000000000043ffb0 in request_receive (ctx=0x998b70, listener=0x996750, packet=0x998bd0, client=0x88c410, 
    fun=0x40f7cd <rad_authenticate at src/main/auth.c:404>) at src/main/process.c:1782
#13 0x0000000000418c3e in auth_socket_recv (listener=0x996750) at src/main/listen.c:1568
#14 0x0000000000447446 in event_socket_handler (xel=0x8d90b0, fd=0xd, ctx=0x996750) at src/main/process.c:4556
#15 0x00007ffff79828cf in fr_event_loop (el=0x8d90b0) at src/lib/event.c:641
#16 0x00000000004493e3 in radius_event_process () at src/main/process.c:5621
#17 0x0000000000432d64 in main (argc=0x2, argv=0x7fffffffe028) at src/main/radiusd.c:579
(gdb)
jpereira commented 9 years ago

I guess that the problem is related with binary data (attr Class) in src/lib/value.c:1515

    case PW_TYPE_ABINARY:
#ifdef WITH_ASCEND_BINARY
        p = talloc_array(ctx, char, 128);
        if (!p) return NULL;
        print_abinary(p, 128, (uint8_t *) &data->filter, inlen, 0);
        break;
#else
          /* FALL THROUGH */
#endif
arr2036 commented 9 years ago

Works fine on v3.1.x.

ct  5 15:53:02 2015 : Debug: xlat --> debug_attr
Mon Oct  5 15:53:02 2015 : Debug: {
Mon Oct  5 15:53:02 2015 : Debug:   literal --> request:
Mon Oct  5 15:53:02 2015 : Debug: }
Mon Oct  5 15:53:02 2015 : Info: (0)     Attributes matching "request:"
Mon Oct  5 15:53:02 2015 : Info: (0)       &request:Acct-Session-Id = 12345
Mon Oct  5 15:53:02 2015 : Info: (0)       Type   : string
Mon Oct  5 15:53:02 2015 : Info: (0)       Length : 5
Mon Oct  5 15:53:02 2015 : Debug: (0)         as integer    : 12345
Mon Oct  5 15:53:02 2015 : Debug: (0)         as ipaddr     : 0.0.48.57
Mon Oct  5 15:53:02 2015 : Debug: (0)         as date       : Dec 31 1969 22:25:45 EST
Mon Oct  5 15:53:02 2015 : Debug: (0)         as octets     : 0x3132333435
Mon Oct  5 15:53:02 2015 : Debug: (0)         as short      : 12345
Mon Oct  5 15:53:02 2015 : Debug: (0)         as ether      : 00:00:00:00:00:00
Mon Oct  5 15:53:02 2015 : Debug: (0)         as signed     : 12345
Mon Oct  5 15:53:02 2015 : Debug: (0)         as uint16     : 12345
Mon Oct  5 15:53:02 2015 : Debug: (0)         as uint32     : 12345
Mon Oct  5 15:53:02 2015 : Debug: (0)         as int32      : 12345
Mon Oct  5 15:53:02 2015 : Debug: (0)         as integer64  : 12345
Mon Oct  5 15:53:02 2015 : Debug: (0)         as uint64     : 12345
Mon Oct  5 15:53:02 2015 : Debug: (0)         as ipv4prefix : 0.0.48.57/32
Mon Oct  5 15:53:02 2015 : Debug: (0)         as cidr       : 0.0.48.57/32
Mon Oct  5 15:53:02 2015 : Info: (0)       &request:User-Name = caipirinha
Mon Oct  5 15:53:02 2015 : Info: (0)       Type   : string
Mon Oct  5 15:53:02 2015 : Info: (0)       Length : 10
Mon Oct  5 15:53:02 2015 : Debug: (0)         as integer    : 0
Mon Oct  5 15:53:02 2015 : Debug: (0)         as octets     : 0x636169706972696e6861
Mon Oct  5 15:53:02 2015 : Debug: (0)         as byte       : 0
Mon Oct  5 15:53:02 2015 : Debug: (0)         as short      : 0
Mon Oct  5 15:53:02 2015 : Debug: (0)         as signed     : 0
Mon Oct  5 15:53:02 2015 : Debug: (0)         as uint8      : 0
Mon Oct  5 15:53:02 2015 : Debug: (0)         as uint16     : 0
Mon Oct  5 15:53:02 2015 : Debug: (0)         as uint32     : 0
Mon Oct  5 15:53:02 2015 : Debug: (0)         as int32      : 0
Mon Oct  5 15:53:02 2015 : Info: (0)       &request:User-Password = senha
Mon Oct  5 15:53:02 2015 : Info: (0)       Type   : string
Mon Oct  5 15:53:02 2015 : Info: (0)       Length : 5
Mon Oct  5 15:53:02 2015 : Debug: (0)         as integer    : 0
Mon Oct  5 15:53:02 2015 : Debug: (0)         as octets     : 0x73656e6861
Mon Oct  5 15:53:02 2015 : Debug: (0)         as byte       : 0
Mon Oct  5 15:53:02 2015 : Debug: (0)         as short      : 0
Mon Oct  5 15:53:02 2015 : Debug: (0)         as signed     : 0
Mon Oct  5 15:53:02 2015 : Debug: (0)         as uint8      : 0
Mon Oct  5 15:53:02 2015 : Debug: (0)         as uint16     : 0
Mon Oct  5 15:53:02 2015 : Debug: (0)         as uint32     : 0
Mon Oct  5 15:53:02 2015 : Debug: (0)         as int32      : 0
Mon Oct  5 15:53:02 2015 : Info: (0)       &request:Class = 0x01020304050000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
Mon Oct  5 15:53:02 2015 : Info: (0)       Type   : octets
Mon Oct  5 15:53:02 2015 : Info: (0)       Length : 67
Mon Oct  5 15:53:02 2015 : Debug: (0)         as integer    : 16909060
Mon Oct  5 15:53:02 2015 : Debug: (0)         as string     : 0x01020304050000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
Mon Oct  5 15:53:02 2015 : Debug: (0)         as abinary    : 0x01020304050000000000000000000000000000000000000000000000000000004300000000000000000000000000000000000000000000000000000000000
Mon Oct  5 15:53:02 2015 : Debug: (0)         as short      : 258
Mon Oct  5 15:53:02 2015 : Debug: (0)         as signed     : 16909060
Mon Oct  5 15:53:02 2015 : Debug: (0)         as uint16     : 258
Mon Oct  5 15:53:02 2015 : Debug: (0)         as uint32     : 16909060
Mon Oct  5 15:53:02 2015 : Debug: (0)         as int32      : 16909060
Mon Oct  5 15:53:02 2015 : Debug: (0)         as integer64  : 72623859789987840
Mon Oct  5 15:53:02 2015 : Debug: (0)         as uint64     : 72623859789987840
Mon Oct  5 15:53:02 2015 : Debug: (0)       EXPAND %{debug_attr:request:}
Mon Oct  5 15:53:02 2015 : Debug: (0)          --> 
Mon Oct  5 15:53:02 2015 : Debug: (0)     } # authorize = notfound

Guess it must be a bug in v3.0.x

jpereira commented 9 years ago

I added "%{debug_attr:request:}" two times.

server default {
   authorize {
       "%{debug_attr:request:}"
        ...
       "%{debug_attr:request:}"
       ....
   }
............

I get this in v3.0.x

(0) 4.361808 \ STATE request_finish action run live M-active C-running ** Mon Oct 5 16:58:16 2015 : Debug: (0) # Executing section post-auth from file /opt/radius/etc/raddb/sites-enabled/default Mon Oct 5 16:58:16 2015 : Debug: (0) post-auth { Mon Oct 5 16:58:16 2015 : Debug: (0) update { Mon Oct 5 16:58:16 2015 : Debug: (0) No attributes updated Mon Oct 5 16:58:16 2015 : Debug: (0) } # update = noop Mon Oct 5 16:58:16 2015 : Debug: (0) modsingle[post-auth]: calling exec (rlm_exec) for request 0 Mon Oct 5 16:58:16 2015 : Debug: (0) modsingle[post-auth]: returned from exec (rlm_exec) for request 0 Mon Oct 5 16:58:16 2015 : Debug: (0) [exec] = noop Mon Oct 5 16:58:16 2015 : Debug: (0) policy remove_reply_message_if_eap { Mon Oct 5 16:58:16 2015 : Debug: (0) if (&reply:EAP-Message && &reply:Reply-Message) { Mon Oct 5 16:58:16 2015 : Debug: (0) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE Mon Oct 5 16:58:16 2015 : Debug: (0) else { Mon Oct 5 16:58:16 2015 : Debug: (0) modsingle[post-auth]: calling noop (rlm_always) for request 0 Mon Oct 5 16:58:16 2015 : Debug: (0) modsingle[post-auth]: returned from noop (rlm_always) for request 0 Mon Oct 5 16:58:16 2015 : Debug: (0) [noop] = noop Mon Oct 5 16:58:16 2015 : Debug: (0) } # else = noop Mon Oct 5 16:58:16 2015 : Debug: (0) } # policy remove_reply_message_if_eap = noop Mon Oct 5 16:58:16 2015 : Debug: (0) } # post-auth = noop Mon Oct 5 16:58:16 2015 : Debug: (0) Sent Access-Accept Id 155 from 127.0.0.1:1812 to 10.1.2.128:35639 length 0 Socket: 7 Proto: 0 Src IP: 127.0.0.1 port: 1812 Dst IP: 10.1.2.128 port: 35639 Code: (2) Access-Accept Id: 155 Length: 20 Vector: 4a945f09237ee69487e2fc29fbf8c0b1 Mon Oct 5 16:58:16 2015 : Debug: (0) Finished request (0) **** NEXT-STATE request_cleanup_delay_init -> request_cleanup_delay Mon Oct 5 16:58:16 2015 : Debug: Waking up in 4.9 seconds.

Program received signal SIGSEGV, Segmentation fault. 0x00007ffff67224b2 in _IO_vfprintf_internal (s=s@entry=0x7fffffffd5f0, format=, format@entry=0x7ffff7103918 "talloc: access after free error - first free may be at %s\n", ap=ap@entry=0x7fffffffd788) at vfprintf.c:1642 1642 vfprintf.c: No such file or directory. (gdb) bt

0 0x00007ffff67224b2 in _IO_vfprintf_internal (s=s@entry=0x7fffffffd5f0, format=,

format@entry=0x7ffff7103918 "talloc: access after free error - first free may be at %s\n", ap=ap@entry=0x7fffffffd788)
at vfprintf.c:1642

1 0x00007ffff67ea5a6 in ___vsnprintf_chk (s=0x7fffffffd7a0 "talloc: access after free error - first free may be at ",

maxlen=<optimized out>, flags=0x1, slen=<optimized out>, 
format=0x7ffff7103918 "talloc: access after free error - first free may be at %s\n", args=0x7fffffffd788) at vsnprintf_chk.c:63

2 0x00007ffff70fe28e in talloc_vasprintf () from /usr/lib/x86_64-linux-gnu/libtalloc.so.2

3 0x00007ffff70fa43c in ?? () from /usr/lib/x86_64-linux-gnu/libtalloc.so.2

4 0x00007ffff70f9c03 in ?? () from /usr/lib/x86_64-linux-gnu/libtalloc.so.2

5 0x00007ffff70fe826 in _talloc_get_type_abort () from /usr/lib/x86_64-linux-gnu/libtalloc.so.2

6 0x00007ffff7981dc7 in fr_event_run () from /opt/radius/lib/libfreeradius-radius.so

7 0x00007ffff79827e2 in fr_event_loop () from /opt/radius/lib/libfreeradius-radius.so

8 0x000000000044a67a in radius_event_process ()

9 0x0000000000432d64 in main ()

(gdb)

arr2036 commented 9 years ago

I added it two times and it still didn't crash.

Mon Oct  5 15:59:50 2015 : Debug: (0) Received Access-Request Id 10 from 127.0.0.1:53362 to 127.0.0.1:1812 length 126
Mon Oct  5 15:59:50 2015 : Debug: (0)   Acct-Session-Id = "12345"
Mon Oct  5 15:59:50 2015 : Debug: (0)   User-Name = "caipirinha"
Mon Oct  5 15:59:50 2015 : Debug: (0)   User-Password = "senha"
Mon Oct  5 15:59:50 2015 : Debug: (0)   Class = 0x01020304050000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
Mon Oct  5 15:59:50 2015 : Debug: (0) No &request:State attribute, can't restore &session-state
Mon Oct  5 15:59:50 2015 : Debug: (0) # Executing section authorize from file /usr/local/freeradius/etc/raddb/sites-enabled/default
Mon Oct  5 15:59:50 2015 : Debug: (0)   authorize {
Mon Oct  5 15:59:50 2015 : Debug: %{debug_attr:request:}
Mon Oct  5 15:59:50 2015 : Debug: Parsed xlat tree:
Mon Oct  5 15:59:50 2015 : Debug: xlat --> debug_attr
Mon Oct  5 15:59:50 2015 : Debug: {
Mon Oct  5 15:59:50 2015 : Debug:   literal --> request:
Mon Oct  5 15:59:50 2015 : Debug: }
Mon Oct  5 15:59:50 2015 : Info: (0)     Attributes matching "request:"
Mon Oct  5 15:59:50 2015 : Info: (0)       &request:Acct-Session-Id = 12345
Mon Oct  5 15:59:50 2015 : Info: (0)       Type   : string
Mon Oct  5 15:59:50 2015 : Info: (0)       Length : 5
Mon Oct  5 15:59:50 2015 : Debug: (0)         as integer    : 12345
Mon Oct  5 15:59:50 2015 : Debug: (0)         as ipaddr     : 0.0.48.57
Mon Oct  5 15:59:50 2015 : Debug: (0)         as date       : Dec 31 1969 22:25:45 EST
Mon Oct  5 15:59:50 2015 : Debug: (0)         as octets     : 0x3132333435
Mon Oct  5 15:59:50 2015 : Debug: (0)         as short      : 12345
Mon Oct  5 15:59:50 2015 : Debug: (0)         as ether      : 00:00:00:00:00:00
Mon Oct  5 15:59:50 2015 : Debug: (0)         as signed     : 12345
Mon Oct  5 15:59:50 2015 : Debug: (0)         as uint16     : 12345
Mon Oct  5 15:59:50 2015 : Debug: (0)         as uint32     : 12345
Mon Oct  5 15:59:50 2015 : Debug: (0)         as int32      : 12345
Mon Oct  5 15:59:50 2015 : Debug: (0)         as integer64  : 12345
Mon Oct  5 15:59:50 2015 : Debug: (0)         as uint64     : 12345
Mon Oct  5 15:59:50 2015 : Debug: (0)         as ipv4prefix : 0.0.48.57/32
Mon Oct  5 15:59:50 2015 : Debug: (0)         as cidr       : 0.0.48.57/32
Mon Oct  5 15:59:50 2015 : Info: (0)       &request:User-Name = caipirinha
Mon Oct  5 15:59:50 2015 : Info: (0)       Type   : string
Mon Oct  5 15:59:50 2015 : Info: (0)       Length : 10
Mon Oct  5 15:59:50 2015 : Debug: (0)         as integer    : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)         as octets     : 0x636169706972696e6861
Mon Oct  5 15:59:50 2015 : Debug: (0)         as byte       : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)         as short      : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)         as signed     : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)         as uint8      : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)         as uint16     : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)         as uint32     : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)         as int32      : 0
Mon Oct  5 15:59:50 2015 : Info: (0)       &request:User-Password = senha
Mon Oct  5 15:59:50 2015 : Info: (0)       Type   : string
Mon Oct  5 15:59:50 2015 : Info: (0)       Length : 5
Mon Oct  5 15:59:50 2015 : Debug: (0)         as integer    : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)         as octets     : 0x73656e6861
Mon Oct  5 15:59:50 2015 : Debug: (0)         as byte       : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)         as short      : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)         as signed     : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)         as uint8      : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)         as uint16     : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)         as uint32     : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)         as int32      : 0
Mon Oct  5 15:59:50 2015 : Info: (0)       &request:Class = 0x01020304050000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
Mon Oct  5 15:59:50 2015 : Info: (0)       Type   : octets
Mon Oct  5 15:59:50 2015 : Info: (0)       Length : 67
Mon Oct  5 15:59:50 2015 : Debug: (0)         as integer    : 16909060
Mon Oct  5 15:59:50 2015 : Debug: (0)         as string     : 0x01020304050000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
Mon Oct  5 15:59:50 2015 : Debug: (0)         as abinary    : 0x01020304050000000000000000000000000000000000000000000000000000004300000000000000000000000000000000000000000000000000000000000
Mon Oct  5 15:59:50 2015 : Debug: (0)         as short      : 258
Mon Oct  5 15:59:50 2015 : Debug: (0)         as signed     : 16909060
Mon Oct  5 15:59:50 2015 : Debug: (0)         as uint16     : 258
Mon Oct  5 15:59:50 2015 : Debug: (0)         as uint32     : 16909060
Mon Oct  5 15:59:50 2015 : Debug: (0)         as int32      : 16909060
Mon Oct  5 15:59:50 2015 : Debug: (0)         as integer64  : 72623859789987840
Mon Oct  5 15:59:50 2015 : Debug: (0)         as uint64     : 72623859789987840
Mon Oct  5 15:59:50 2015 : Debug: (0)       EXPAND %{debug_attr:request:}
Mon Oct  5 15:59:50 2015 : Debug: (0)          --> 
Mon Oct  5 15:59:50 2015 : Debug: %{debug_attr:request:}
Mon Oct  5 15:59:50 2015 : Debug: Parsed xlat tree:
Mon Oct  5 15:59:50 2015 : Debug: xlat --> debug_attr
Mon Oct  5 15:59:50 2015 : Debug: {
Mon Oct  5 15:59:50 2015 : Debug:   literal --> request:
Mon Oct  5 15:59:50 2015 : Debug: }
Mon Oct  5 15:59:50 2015 : Info: (0)       Attributes matching "request:"
Mon Oct  5 15:59:50 2015 : Info: (0)         &request:Acct-Session-Id = 12345
Mon Oct  5 15:59:50 2015 : Info: (0)         Type   : string
Mon Oct  5 15:59:50 2015 : Info: (0)         Length : 5
Mon Oct  5 15:59:50 2015 : Debug: (0)           as integer    : 12345
Mon Oct  5 15:59:50 2015 : Debug: (0)           as ipaddr     : 0.0.48.57
Mon Oct  5 15:59:50 2015 : Debug: (0)           as date       : Dec 31 1969 22:25:45 EST
Mon Oct  5 15:59:50 2015 : Debug: (0)           as octets     : 0x3132333435
Mon Oct  5 15:59:50 2015 : Debug: (0)           as short      : 12345
Mon Oct  5 15:59:50 2015 : Debug: (0)           as ether      : 00:00:00:00:00:00
Mon Oct  5 15:59:50 2015 : Debug: (0)           as signed     : 12345
Mon Oct  5 15:59:50 2015 : Debug: (0)           as uint16     : 12345
Mon Oct  5 15:59:50 2015 : Debug: (0)           as uint32     : 12345
Mon Oct  5 15:59:50 2015 : Debug: (0)           as int32      : 12345
Mon Oct  5 15:59:50 2015 : Debug: (0)           as integer64  : 12345
Mon Oct  5 15:59:50 2015 : Debug: (0)           as uint64     : 12345
Mon Oct  5 15:59:50 2015 : Debug: (0)           as ipv4prefix : 0.0.48.57/32
Mon Oct  5 15:59:50 2015 : Debug: (0)           as cidr       : 0.0.48.57/32
Mon Oct  5 15:59:50 2015 : Info: (0)         &request:User-Name = caipirinha
Mon Oct  5 15:59:50 2015 : Info: (0)         Type   : string
Mon Oct  5 15:59:50 2015 : Info: (0)         Length : 10
Mon Oct  5 15:59:50 2015 : Debug: (0)           as integer    : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)           as octets     : 0x636169706972696e6861
Mon Oct  5 15:59:50 2015 : Debug: (0)           as byte       : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)           as short      : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)           as signed     : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)           as uint8      : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)           as uint16     : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)           as uint32     : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)           as int32      : 0
Mon Oct  5 15:59:50 2015 : Info: (0)         &request:User-Password = senha
Mon Oct  5 15:59:50 2015 : Info: (0)         Type   : string
Mon Oct  5 15:59:50 2015 : Info: (0)         Length : 5
Mon Oct  5 15:59:50 2015 : Debug: (0)           as integer    : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)           as octets     : 0x73656e6861
Mon Oct  5 15:59:50 2015 : Debug: (0)           as byte       : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)           as short      : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)           as signed     : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)           as uint8      : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)           as uint16     : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)           as uint32     : 0
Mon Oct  5 15:59:50 2015 : Debug: (0)           as int32      : 0
Mon Oct  5 15:59:50 2015 : Info: (0)         &request:Class = 0x01020304050000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
Mon Oct  5 15:59:50 2015 : Info: (0)         Type   : octets
Mon Oct  5 15:59:50 2015 : Info: (0)         Length : 67
Mon Oct  5 15:59:50 2015 : Debug: (0)           as integer    : 16909060
Mon Oct  5 15:59:50 2015 : Debug: (0)           as string     : 0x01020304050000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
Mon Oct  5 15:59:50 2015 : Debug: (0)           as abinary    : 0x01020304050000000000000000000000000000000000000000000000000000004300000000000000000000000000000000000000000000000000000000000
Mon Oct  5 15:59:50 2015 : Debug: (0)           as short      : 258
Mon Oct  5 15:59:50 2015 : Debug: (0)           as signed     : 16909060
Mon Oct  5 15:59:50 2015 : Debug: (0)           as uint16     : 258
Mon Oct  5 15:59:50 2015 : Debug: (0)           as uint32     : 16909060
Mon Oct  5 15:59:50 2015 : Debug: (0)           as int32      : 16909060
Mon Oct  5 15:59:50 2015 : Debug: (0)           as integer64  : 72623859789987840
Mon Oct  5 15:59:50 2015 : Debug: (0)           as uint64     : 72623859789987840
Mon Oct  5 15:59:50 2015 : Debug: (0)         EXPAND %{debug_attr:request:}
Mon Oct  5 15:59:50 2015 : Debug: (0)            --> 
Mon Oct  5 15:59:50 2015 : Debug: (0)       } # authorize = notfound
Mon Oct  5 15:59:50 2015 : ERROR: (0)     No Auth-Type found: rejecting the user via Post-Auth-Type = Reject
Mon Oct  5 15:59:50 2015 : Debug: (0)     Failed to authenticate the user
Mon Oct  5 15:59:50 2015 : Debug: (0)     Using Post-Auth-Type Reject
Mon Oct  5 15:59:50 2015 : Debug: (0)     Post-Auth-Type sub-section not found.  Ignoring.
Mon Oct  5 15:59:50 2015 : Debug: (0)     # Executing group from file /usr/local/freeradius/etc/raddb/sites-enabled/default
Mon Oct  5 15:59:50 2015 : Debug: (0)     Delaying response for 1.000000 seconds
Mon Oct  5 15:59:50 2015 : Debug: Waking up in 0.3 seconds.
Mon Oct  5 15:59:50 2015 : Debug: Waking up in 0.6 seconds.
Mon Oct  5 15:59:51 2015 : Debug: (0)     Sending delayed response
Mon Oct  5 15:59:51 2015 : Debug: (0)     Sent Access-Reject Id 10 from 127.0.0.1:1812 to 127.0.0.1:53362 length 20
  Socket:   9
  Proto:    0
  Src IP:   127.0.0.1
    port:   1812
  Dst IP:   127.0.0.1
    port:   53362
  Code:     (3) Access-Reject
  Id:       10
  Length:   20
  Vector:   57c462d7893e457e35130aa7e2a87c89
Mon Oct  5 15:59:51 2015 : Debug: Waking up in 3.9 seconds.
jpereira commented 9 years ago

your branch is v3.0.x?

arr2036 commented 9 years ago

no, as I said v3.1.x

jpereira commented 9 years ago

My code tree.

[jpereira@jpereira-desktop freeradius-server.git]$ git log | head -5
commit a99443955ecaa9bc4e8be7988103a9eb329bd714
Author: Alan T. DeKok <aland@freeradius.org>
Date:   Mon Oct 5 15:02:17 2015 -0400

    Bump for 3.0.11
[jpereira@jpereira-desktop freeradius-server.git]$
[jpereira@jpereira-desktop freeradius-server.git]$ git st
On branch v3.0.x
Your branch is up-to-date with 'upstream/v3.0.x'.
nothing to commit, working directory clean
[jpereira@jpereira-desktop freeradius-server.git]$

[jpereira@jpereira-desktop freeradius-server.git]$ cat ../build-3.0.x.sh 
#!/bin/bash
prefix="/opt/radius"
mkdir -p $prefix
make distclean
export CFLAGS="-DDEBUG_STATE_MACHINE"
./configure --prefix="${prefix}" \
            --with-experimental-modules \
            --enable-developer \
            --config-cache \
            --disable-openssl-version-check \
            --with-large-files \
            --with-udpfromto \
            --without-rlm_eap_tnc \
            --with-rlm_eap_ikev2 \
            --with-rlm_sql_db2 \
            --with-rlm_sql_firebird \
            --with-rlm_sql_freetds \
            --with-rlm_sql_iodbc \
            --with-rlm_sql_mysql \
            --with-rlm_sql_oracle \
            --with-rlm_sql_postgresql \
            --with-rlm_sql_sqlite \
            --with-rlm_sql_unixodbc \
            --with-rlm_redis \
            --with-rlm_rediswho $2
[jpereira@jpereira-desktop freeradius-server.git]$
[jpereira@jpereira-desktop freeradius-server.git]$ (git clean -fdx; ../build-3.0.x.sh; make && make install) 1> /dev/null 2>&1
[jpereira@jpereira-desktop freeradius-server.git]$

My setup

[jpereira@jpereira-desktop freeradius-server.git]$ grep -v -E "^($|.*#)" /opt/radius/etc/raddb/sites-enabled/default 
server default {
listen {
    type = auth
    ipaddr = *
    port = 0
    limit {
          max_connections = 16
          lifetime = 0
          idle_timeout = 30
    }
}
listen {
    ipaddr = *
    port = 0
    type = acct
    limit {
    }
}
listen {
    type = auth
    port = 0
    limit {
          max_connections = 16
          lifetime = 0
          idle_timeout = 30
    }
}
listen {
    ipv6addr = ::
    port = 0
    type = acct
    limit {
    }
}
authorize {
    "%{debug_attr:request}"
    "%{debug_attr:request}"
    accept
}
authenticate {
    Auth-Type PAP {
        pap
    }
    Auth-Type CHAP {
        chap
    }
    Auth-Type MS-CHAP {
        mschap
    }
    digest
    eap
}
preacct {
    preprocess
    acct_unique
    suffix
    files
}
accounting {
    detail
    unix
    -sql
    exec
    attr_filter.accounting_response
}
session {
}
post-auth {
    update {
        &reply: += &session-state:
    }
    -sql
    exec
    remove_reply_message_if_eap
    Post-Auth-Type REJECT {
        -sql
        attr_filter.access_reject
        eap
        remove_reply_message_if_eap
    }
}
pre-proxy {
}
post-proxy {
    eap
}
}
[jpereira@jpereira-desktop freeradius-server.git]$

My packet

[jpereira@jpereira-desktop radius-unit-test]$ cat auth-debug-bug.attr
Acct-Session-Id = "12345"
User-Name = "caipirinha"
User-Password = "senha"
Class = 0x010203040500000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000000
[jpereira@jpereira-desktop radius-unit-test]$

And result is

Mon Oct  5 17:05:46 2015 : Debug: (0)     Sent Access-Accept Id 196 from 127.0.0.1:1812 to 10.1.2.128:50257 length 0
  Socket:   7
  Proto:    0
  Src IP:   127.0.0.1
    port:   1812
  Dst IP:   10.1.2.128
    port:   50257
  Code:     (2) Access-Accept
  Id:       196
  Length:   20
  Vector:   73fe9c2416ef2ea93313e770c330b91c
Mon Oct  5 17:05:46 2015 : Debug: (0)     Finished request
(0) ********    NEXT-STATE request_cleanup_delay_init -> request_cleanup_delay

Program received signal SIGSEGV, Segmentation fault.
0x00007ffff67224b2 in _IO_vfprintf_internal (s=s@entry=0x7fffffffd1d0, format=<optimized out>, 
    format@entry=0x7ffff7103918 "talloc: access after free error - first free may be at %s\n", ap=ap@entry=0x7fffffffd368)
    at vfprintf.c:1642
1642    vfprintf.c: No such file or directory.
(gdb) bt
#0  0x00007ffff67224b2 in _IO_vfprintf_internal (s=s@entry=0x7fffffffd1d0, format=<optimized out>, 
    format@entry=0x7ffff7103918 "talloc: access after free error - first free may be at %s\n", ap=ap@entry=0x7fffffffd368)
    at vfprintf.c:1642
#1  0x00007ffff67ea5a6 in ___vsnprintf_chk (s=0x7fffffffd380 "talloc: access after free error - first free may be at ", 
    maxlen=<optimized out>, flags=0x1, slen=<optimized out>, 
    format=0x7ffff7103918 "talloc: access after free error - first free may be at %s\n", args=0x7fffffffd368) at vsnprintf_chk.c:63
#2  0x00007ffff70fe28e in talloc_vasprintf () from /usr/lib/x86_64-linux-gnu/libtalloc.so.2
#3  0x00007ffff70fa43c in ?? () from /usr/lib/x86_64-linux-gnu/libtalloc.so.2
#4  0x00007ffff70f9c03 in ?? () from /usr/lib/x86_64-linux-gnu/libtalloc.so.2
#5  0x00007ffff70fe826 in _talloc_get_type_abort () from /usr/lib/x86_64-linux-gnu/libtalloc.so.2
#6  0x00007ffff7981c30 in fr_event_insert () from /opt/radius/lib/libfreeradius-radius.so
#7  0x000000000043cb76 in state_machine_timer ()
#8  0x000000000043e242 in request_cleanup_delay_init ()
#9  0x000000000043fd1e in request_finish ()
#10 0x000000000044013d in request_running ()
#11 0x000000000043e8c8 in request_queue_or_run ()
#12 0x000000000044099c in request_receive ()
#13 0x0000000000418c3e in auth_socket_recv ()
#14 0x00000000004486dd in event_socket_handler ()
#15 0x00007ffff79828cf in fr_event_loop () from /opt/radius/lib/libfreeradius-radius.so
#16 0x000000000044a67a in radius_event_process ()
#17 0x0000000000432d64 in main ()
(gdb)
alandekok commented 9 years ago

Works for me in v3.0.x

jpereira commented 9 years ago

OMG!! btw, my host is!

[jpereira@jpereira-desktop radius-unit-test]$ lsb_release -a
No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 15.04
Release:    15.04
Codename:   vivid
[jpereira@jpereira-desktop radius-unit-test]$ gcc -v
Using built-in specs.
COLLECT_GCC=gcc
COLLECT_LTO_WRAPPER=/usr/lib/gcc/x86_64-linux-gnu/4.9/lto-wrapper
Target: x86_64-linux-gnu
Configured with: ../src/configure -v --with-pkgversion='Ubuntu 4.9.2-10ubuntu13' --with-bugurl=file:///usr/share/doc/gcc-4.9/README.Bugs --enable-languages=c,c++,java,go,d,fortran,objc,obj-c++ --prefix=/usr --program-suffix=-4.9 --enable-shared --enable-linker-build-id --libexecdir=/usr/lib --without-included-gettext --enable-threads=posix --with-gxx-include-dir=/usr/include/c++/4.9 --libdir=/usr/lib --enable-nls --with-sysroot=/ --enable-clocale=gnu --enable-libstdcxx-debug --enable-libstdcxx-time=yes --enable-gnu-unique-object --disable-vtable-verify --enable-plugin --with-system-zlib --disable-browser-plugin --enable-java-awt=gtk --enable-gtk-cairo --with-java-home=/usr/lib/jvm/java-1.5.0-gcj-4.9-amd64/jre --enable-java-home --with-jvm-root-dir=/usr/lib/jvm/java-1.5.0-gcj-4.9-amd64 --with-jvm-jar-dir=/usr/lib/jvm-exports/java-1.5.0-gcj-4.9-amd64 --with-arch-directory=amd64 --with-ecj-jar=/usr/share/java/eclipse-ecj.jar --enable-objc-gc --enable-multiarch --disable-werror --with-arch-32=i686 --with-abi=m64 --with-multilib-list=m32,m64,mx32 --enable-multilib --with-tune=generic --enable-checking=release --build=x86_64-linux-gnu --host=x86_64-linux-gnu --target=x86_64-linux-gnu
Thread model: posix
gcc version 4.9.2 (Ubuntu 4.9.2-10ubuntu13) 
[jpereira@jpereira-desktop radius-unit-test]$
jpereira commented 9 years ago

guys,

about

B+ │233             if (*parent) {                                                                                                    │
   │234                     int ret;                                                                                                  │
   │235                                                                                                                               │
   │236                     fr_strerror_printf("@@@@@@@@@@@@@@@@@@@@dumping talloc_report_full()");                                   │
   │237                     talloc_report_full(parent, stderr);                                                                      │
   │238                                                                                                                               │
   │239     #ifndef NDEBUG                                                                                                            │
   │240                     ev = talloc_get_type_abort(*parent, fr_event_t);                                                          │
   │241     #else                                                                                                                     │
   │242                     ev = *parent;                                                                                             │
   │243     #endif                                                                                                                    │
   │244                                                                                                                               │
   │245                     ret = fr_heap_extract(el->times, ev);                                                                     │
   │246                     fr_assert(ret == 1);    /* events MUST be in the heap */                                                  │
   │247                                                                                                                               │
   │248                     memset(ev, 0, sizeof(*ev));                                                                               │
   │249             } else {                                                                                                          │
  >│250                     ev = talloc_zero(el, fr_event_t);                                                                         │
   │251                     if (!ev) return 0;                                                                                        │
   │252             }

this make sense?

(gdb) p el
$1 = (fr_event_list_t *) 0x8cd0e0
(gdb) p ev
$2 = (fr_event_t *) 0x7ffff7ffe188
(gdb)
jpereira commented 9 years ago

@alandekok and @arr2036: what the configure flags you use? I noticed that every places where match with

#ifndef NDEBUG
    /*
     *  Validate the event_t struct to detect memory issues early.
     */
    ev = talloc_get_type_abort(*parent, fr_event_t);

#else
    ev = *parent;
#endif

cause a crash in talloc_get_type_abort

arr2036 commented 9 years ago

just --prefix. Run it under valgrind, see if anything useful appears.

jpereira commented 9 years ago

good idea @arr2036, I will!

jpereira commented 9 years ago

@arr2036 What talloc version you use?

arr2036 commented 9 years ago

talloc-2.1.2

arr2036 commented 8 years ago

Will re-open if you have a fix or can provide more details, but as neither @alandekok or myself can reproduce this, we can't do much to fix it.