foreach may cause ABORT #639

Closed
olivierbeytrison opened this Issue May 15, 2014 · 1 comment

Projects

None yet

2 participants

@olivierbeytrison
Contributor

This is happening with current v3.0.x HEAD branch

Debug log + backtrace below.

gdb process still running, if you need more debugging information just ask.

I'm trying to produce a minimal config that trigger the bug.

Received Access-Accept Id 42 from 160.98.240.25:1812 to 160.98.240.15:36937 length 507
        Reply-Message = '0'
        User-Name = 'olivier.beytriso@test.hes-so.ch'
        Chargeable-User-Identity = '187ce34e7b30f8131bfcf05408531fc5cca2ad29'
        HESSO-Mail = 'olivier.beytrisxx.ch'
        HESSO-FullName = 'Olivier Beytrison'
        Class = 0x6865732d69706572736f6e3a3331393335373632
        Class = 0x6865732d6f6e3a316865732d736f2e6368
        Class = 0x6865732d6375693a31383763653334653762333066383133316266636630353430383533316663356363613261643239
        HESSO-Role-Raw = '31935762-440774439#RORG-HEFR-EIFR-INTR-INFO#EMP#COL'
        HESSO-Role-Raw = '31935762-440774439#RORG-HEFR-EIFR-INTR-INFO#STD#'
        MS-MPPE-Recv-Key = 0x6f0f611f4de9470a70ef811ed61b0954a47e2585667ef4d2860ef48b38f1fabe
        MS-MPPE-Send-Key = 0x68e317f1f49a9c81cd56458451cd5a335f5022d6639f3a7a4e9381987f664909
        EAP-Message = 0x030b0004
        Message-Authenticator = 0x77213b4510057305e1b008b24b8342c7
        Proxy-State = 0x323439
Debug: (9) proxy: request is no longer in proxy hash
Debug: (9) # Executing section post-proxy from file /srv/freeradius/etc/raddb/sites-enabled/eduroam
Debug: (9)   post-proxy {
Debug: (9)   modsingle[post-proxy]: calling post_proxy_log (rlm_detail) for request 9
Debug: /srv/freeradius/var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d
Debug: Parsed xlat tree:
Debug: literal --> /srv/freeradius/var/log/radacct/
Debug: if {
Debug:       attribute --> Packet-Src-IP-Address
Debug:       {
Debug:               ref  2
Debug:               list 1
Debug:               tag -128
Debug:       }
Debug: }
Debug: else {
Debug:       attribute --> Packet-Src-IPv6-Address
Debug:       {
Debug:               ref  2
Debug:               list 1
Debug:               tag -128
Debug:       }
Debug: }
Debug: literal --> /post-proxy-detail-
Debug: percent --> Y
Debug: percent --> m
Debug: percent --> d
Debug: (9) post_proxy_log : EXPAND /srv/freeradius/var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d
Debug: (9) post_proxy_log :    --> /srv/freeradius/var/log/radacct/160.98.157.2/post-proxy-detail-20140515
Debug: (9) post_proxy_log : /srv/freeradius/var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/post-proxy-detail-%Y%m%d expands to /srv/freeradius/var/log/radacct/160.98.157.2/post-proxy-detail-20140515
Debug: %t
Debug: Parsed xlat tree:
Debug: percent --> t
Debug: (9) post_proxy_log : EXPAND %t
Debug: (9) post_proxy_log :    --> Thu May 15 15:39:00 2014
Debug: (9)   modsingle[post-proxy]: returned from post_proxy_log (rlm_detail) for request 9
Debug: (9)   [post_proxy_log] = ok
Debug: (9)  } #  post-proxy = ok
Debug: (9) Found Auth-Type = Accept
Debug: (9) Auth-Type = Accept, accepting the user
Debug: (9) # Executing section post-auth from file /srv/freeradius/etc/raddb/sites-enabled/eduroam
Debug: (9)   post-auth {
Debug: (9)   remove_reply_message_if_eap remove_reply_message_if_eap {
Debug: (9)     if (reply:EAP-Message && reply:Reply-Message)
Debug: (9)     if (reply:EAP-Message && reply:Reply-Message)  -> TRUE
Debug: (9)    if (reply:EAP-Message && reply:Reply-Message)  {
Debug: (9)     update reply {
Debug: (9)   Reply-Message !* ''''
Debug: (9)     } # update reply = noop
Debug: (9)    } # if (reply:EAP-Message && reply:Reply-Message)  = noop
Debug: (9)     ... skipping else for request 9: Preceding "if" was taken
Debug: (9)   } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
Debug: (9)   modsingle[post-auth]: calling auth_log (rlm_detail) for request 9
Debug: /srv/freeradius/var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d
Debug: Parsed xlat tree:
Debug: literal --> /srv/freeradius/var/log/radacct/
Debug: if {
Debug:       attribute --> Packet-Src-IP-Address
Debug:       {
Debug:               ref  2
Debug:               list 1
Debug:               tag -128
Debug:       }
Debug: }
Debug: else {
Debug:       attribute --> Packet-Src-IPv6-Address
Debug:       {
Debug:               ref  2
Debug:               list 1
Debug:               tag -128
Debug:       }
Debug: }
Debug: literal --> /auth-detail-
Debug: percent --> Y
Debug: percent --> m
Debug: percent --> d
Debug: (9) auth_log : EXPAND /srv/freeradius/var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d
Debug: (9) auth_log :    --> /srv/freeradius/var/log/radacct/160.98.157.2/auth-detail-20140515
Debug: (9) auth_log : /srv/freeradius/var/log/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/auth-detail-%Y%m%d expands to /srv/freeradius/var/log/radacct/160.98.157.2/auth-detail-20140515
Debug: %t
Debug: Parsed xlat tree:
Debug: percent --> t
Debug: (9) auth_log : EXPAND %t
Debug: (9) auth_log :    --> Thu May 15 15:39:00 2014
Debug: (9)   modsingle[post-auth]: returned from auth_log (rlm_detail) for request 9
Debug: (9)   [auth_log] = ok
Debug: (9)   eap_resumption eap_resumption {
Debug: (9)     if (request:Realm && request:Realm == 'SOFR' && !reply:HESSO-Role-Raw)
Debug: (9)     if (request:Realm && request:Realm == 'SOFR' && !reply:HESSO-Role-Raw)  -> FALSE
Debug: (9)   } # eap_resumption eap_resumption = ok
Debug: (9)    if (!reply:Airespace-Interface-Name)
Debug: (9)    if (!reply:Airespace-Interface-Name)  -> TRUE
Debug: (9)   if (!reply:Airespace-Interface-Name)  {
Debug: (9)    wireless-policy wireless-policy {
Debug: (9)     foreach reply:HESSO-Role-Raw
Debug: (9)      #  Foreach-Variable-0 = "31935762-440774439#RORG-HEFR-EIFR-INTR-INFO#EMP#COL"
Debug: (9)       if ("%{Foreach-Variable-0}" =~ /.*RORG-HEFR-EIFR-INTR-INFO#EMP.*$/)
Debug: (9) EXPAND %{Foreach-Variable-0}
Debug: (9)    --> 31935762-440774439#RORG-HEFR-EIFR-INTR-INFO#EMP#COL
Debug: (9)       if ("%{Foreach-Variable-0}" =~ /.*RORG-HEFR-EIFR-INTR-INFO#EMP.*$/)  -> TRUE
Debug: (9)      if ("%{Foreach-Variable-0}" =~ /.*RORG-HEFR-EIFR-INTR-INFO#EMP.*$/)  {
Debug: (9)       update reply {
Debug: (9)   Airespace-Interface-Name := 'wifi_si'
Debug: (9)       } # update reply = noop
Debug: (9)        # break Foreach-Variable-0
Debug: (9)      } # if ("%{Foreach-Variable-0}" =~ /.*RORG-HEFR-EIFR-INTR-INFO#EMP.*$/)  = noop
Debug: (9)       # unwind to enclosing foreach
Info: talloc: access after free error - first free may be at src/lib/valuepair.c:170
Info: Bad talloc magic value - access after free
Info: talloc abort: Bad talloc magic value - access after free
Info: CAUGHT SIGNAL: Aborted
Info: Backtrace of last 27 frames:


(gdb) bt 
#0  0x00007ffff6b0eb7b in raise (sig=<optimized out>) at ../nptl/sysdeps/unix/sysv/linux/pt-raise.c:42
#1  0x00007ffff7972492 in fr_debug_break () at src/lib/debug.c:107
#2  0x00007ffff797d153 in _fr_exit_now (file=0x7ffff799b5dc "src/lib/debug.c", line=520, status=1) at src/lib/log.c:234
#3  0x00007ffff7972edb in fr_fault (sig=6) at src/lib/debug.c:520
#4  0x00007ffff7972f2c in _fr_talloc_fault (reason=0x7ffff712c428 "Bad talloc magic value - access after free") at src/lib/debug.c:531
#5  0x00007ffff7126c47 in talloc_abort_access_after_free () at ../talloc.c:336
#6  talloc_chunk_from_ptr (ptr=<optimized out>) at ../talloc.c:357
#7  talloc_chunk_from_ptr (ptr=<optimized out>) at ../talloc.c:1151
#8  talloc_get_name (ptr=<optimized out>) at ../talloc.c:1153
#9  0x00007ffff7128fdb in _talloc_get_type_abort (ptr=0xb405f0, name=0x7ffff799ba02 "VALUE_PAIR", location=0x7ffff799b9ee "src/lib/debug.c:748") at ../talloc.c:1206
#10 0x00007ffff79734fd in fr_verify_vp (vp=0xb405f0) at src/lib/debug.c:748
#11 0x00007ffff797218a in fr_cursor_next (cursor=0x7fffffffc560) at src/lib/cursor.c:131
#12 0x0000000000425bba in modcall_recurse (request=0xb3fd60, component=RLM_COMPONENT_POST_AUTH, depth=3, entry=0x7fffffffdd38) at src/main/modcall.c:672
#13 0x0000000000424e1b in modcall_child (request=0xb3fd60, component=RLM_COMPONENT_POST_AUTH, depth=3, entry=0x7fffffffdd20, c=0xb18310, result=0x7fffffffcc58) at src/main/modcall.c:409
#14 0x0000000000425fa4 in modcall_recurse (request=0xb3fd60, component=RLM_COMPONENT_POST_AUTH, depth=2, entry=0x7fffffffdd20) at src/main/modcall.c:779
#15 0x0000000000424e1b in modcall_child (request=0xb3fd60, component=RLM_COMPONENT_POST_AUTH, depth=2, entry=0x7fffffffdd08, c=0xb18180, result=0x7fffffffd268) at src/main/modcall.c:409
#16 0x0000000000425fa4 in modcall_recurse (request=0xb3fd60, component=RLM_COMPONENT_POST_AUTH, depth=1, entry=0x7fffffffdd08) at src/main/modcall.c:779
#17 0x0000000000424e1b in modcall_child (request=0xb3fd60, component=RLM_COMPONENT_POST_AUTH, depth=1, entry=0x7fffffffdcf0, c=0xb15b60, result=0x7fffffffd878) at src/main/modcall.c:409
#18 0x0000000000425fa4 in modcall_recurse (request=0xb3fd60, component=RLM_COMPONENT_POST_AUTH, depth=0, entry=0x7fffffffdcf0) at src/main/modcall.c:779
#19 0x0000000000426d5f in modcall (component=RLM_COMPONENT_POST_AUTH, c=0xb15ad0, request=0xb3fd60) at src/main/modcall.c:1089
#20 0x00000000004225db in indexed_modcall (comp=RLM_COMPONENT_POST_AUTH, idx=0, request=0xb3fd60) at src/main/modules.c:818
#21 0x00000000004246e3 in process_post_auth (postauth_type=0, request=0xb3fd60) at src/main/modules.c:1864
#22 0x000000000040d5f0 in rad_postauth (request=0xb3fd60) at src/main/auth.c:303
#23 0x00000000004370ce in request_finish (request=0xb3fd60, action=6) at src/main/process.c:1280
#24 0x0000000000437575 in request_running (request=0xb3fd60, action=6) at src/main/process.c:1455
#25 0x000000000043938f in request_proxy_reply (packet=0xb41120) at src/main/process.c:2289
#26 0x000000000041685c in proxy_socket_recv (listener=0xb324b0) at src/main/listen.c:1914
#27 0x000000000043d9c2 in event_socket_handler (xel=0x671a00, fd=45, ctx=0xb324b0) at src/main/process.c:3845
#28 0x00007ffff7999c9a in fr_event_loop (el=0x671a00) at src/lib/event.c:495
#29 0x000000000043f251 in radius_event_process () at src/main/process.c:4729
#30 0x000000000042c4d8 in main (argc=2, argv=0x7fffffffe6c8) at src/main/radiusd.c:555
@olivierbeytrison
Contributor

Got a piece of config that make the server crash. add it at the beginning of the auth{} section. Not the same BT as my previous message but I guess it's the same root cause (see below) :

update {  
   request:Reply-Message += "1"
   request:Reply-Message += "2"
}         
foreach request:Reply-Message {
   if("%{Foreach-Variable-0}" == "1") {
      update {            
         request:Reply-Message += "3"
      }                   
      break               
   }              
   else {         
      noop                
   }              
}         

debug :

Debug: (0)   update  {
Debug: (0)   request:Reply-Message += '1'
Debug: (0)   request:Reply-Message += '2'
Debug: (0)   } # update  = noop
Debug: (0)   foreach request:Reply-Message
Debug: (0)     if ("%{Foreach-Variable-0}" == "1")
Debug: (0) EXPAND %{Foreach-Variable-0}
Debug: (0)    --> 1
Debug: (0)     if ("%{Foreach-Variable-0}" == "1")  -> TRUE
Debug: (0)    if ("%{Foreach-Variable-0}" == "1")  {
Debug: (0)     update  {
Debug: (0)   request:Reply-Message += '3'
Debug: (0)     } # update  = noop
Debug: (0)      # break Foreach-Variable-0
Debug: (0)    } # if ("%{Foreach-Variable-0}" == "1")  = noop
Debug: (0)     # unwind to enclosing foreach
Debug: (0)     if ("%{Foreach-Variable-0}" == "1")
Debug: (0) EXPAND %{Foreach-Variable-0}
Debug: (0)    --> 1
Debug: (0)     if ("%{Foreach-Variable-0}" == "1")  -> TRUE
Debug: (0)    if ("%{Foreach-Variable-0}" == "1")  {
Debug: (0)     update  {
Debug: (0)   request:Reply-Message += '3'
Debug: (0)     } # update  = noop
Debug: (0)      # break Foreach-Variable-0

BT :

(gdb) bt
#0  0x00007ffff6554425 in __GI_raise (sig=<optimized out>) at ../nptl/sysdeps/unix/sysv/linux/raise.c:64
#1  0x00007ffff6557b8b in __GI_abort () at abort.c:91
#2  0x00007ffff713d1a6 in talloc_abort (reason=0x7ffff7144428 "Bad talloc magic value - access after free") at ../talloc.c:317
#3  0x00007ffff713e908 in talloc_abort_access_after_free () at ../talloc.c:336
#4  talloc_chunk_from_ptr (ptr=0xa0bea0) at ../talloc.c:357
#5  talloc_chunk_from_ptr (ptr=0xa0bea0) at ../talloc.c:1340
#6  _talloc_free (ptr=0xa0bea0, location=0x7ffff79acf12 "src/lib/valuepair.c:170") at ../talloc.c:1348
#7  0x00007ffff799f867 in pairfree (vps=0x7fffffffd5d0) at src/lib/valuepair.c:170
#8  0x0000000000420042 in modcall_recurse (request=0xa0ac00, component=RLM_COMPONENT_AUTZ, depth=<optimized out>, entry=<optimized out>) at src/main/modcall.c:733
#9  0x000000000041ed51 in modcall_child (request=<optimized out>, component=<optimized out>, depth=<optimized out>, entry=0x7fffffffd8a0, c=<optimized out>, result=0x7fffffffd43c) at src/main/modcall.c:409
#10 0x000000000041ef25 in modcall_recurse (request=0xa0ac00, component=RLM_COMPONENT_AUTZ, depth=<optimized out>, entry=<optimized out>) at src/main/modcall.c:779
#11 0x000000000041f8dd in modcall_recurse (request=0xa0ac00, component=RLM_COMPONENT_AUTZ, depth=<optimized out>, entry=<optimized out>) at src/main/modcall.c:698
#12 0x000000000041ed51 in modcall_child (request=<optimized out>, component=<optimized out>, depth=<optimized out>, entry=0x7fffffffd870, c=<optimized out>, result=0x7fffffffd79c) at src/main/modcall.c:409
#13 0x000000000041ef25 in modcall_recurse (request=0xa0ac00, component=RLM_COMPONENT_AUTZ, depth=<optimized out>, entry=<optimized out>) at src/main/modcall.c:779
#14 0x00000000004200dd in modcall (component=<optimized out>, c=<optimized out>, request=<optimized out>) at src/main/modcall.c:1089
#15 0x000000000041d62a in indexed_modcall (comp=RLM_COMPONENT_AUTZ, idx=0, request=0xa0ac00) at src/main/modules.c:818
#16 0x000000000040e7da in rad_authenticate (request=0xa0ac00) at src/main/auth.c:420
#17 0x000000000042c7c7 in request_running (action=1, request=0xa0ac00) at src/main/process.c:1418
#18 request_running (request=0xa0ac00, action=1) at src/main/process.c:1376
#19 0x0000000000428e55 in request_queue_or_run (request=0xa0ac00, process=<optimized out>) at src/main/process.c:965
#20 0x000000000042af41 in request_receive (listener=0xa0a000, packet=<optimized out>, client=0x8c5630, fun=0x40e510 <rad_authenticate>) at src/main/process.c:1635
#21 0x00000000004188c3 in auth_socket_recv (listener=0xa0a000) at src/main/listen.c:1532
#22 0x000000000042a310 in event_socket_handler (xel=<optimized out>, fd=<optimized out>, ctx=<optimized out>) at src/main/process.c:3845
#23 0x00007ffff79a4b3c in fr_event_loop (el=0x6598e0) at src/lib/event.c:495
#24 0x000000000040da66 in main (argc=<optimized out>, argv=<optimized out>) at src/main/radiusd.c:555
@arr2036 arr2036 added a commit that referenced this issue May 16, 2014
@arr2036 arr2036 Don't free foreach VPs on break #639
Wwe go back up the stack in an orderly way and don't need this hack anymore
c8ab4e6
@arr2036 arr2036 added a commit that referenced this issue May 16, 2014
@arr2036 arr2036 Don't free foreach VPs on break #639
Wwe go back up the stack in an orderly way and don't need this hack anymore
860f645
@arr2036 arr2036 closed this May 16, 2014
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment