Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

crashes during debug #2314

Closed
linuxchips opened this Issue Sep 24, 2018 · 3 comments

Comments

Projects
None yet
3 participants
@linuxchips
Copy link

linuxchips commented Sep 24, 2018

Issue type

  • Defect - Crash or memory corruption.

the server crashes when debug is enabled, through radmin and also when using -xx

Defect

How to reproduce the issue

the server is running for a few hours, systemctl status radiusd.service shows that the server been up for a few hours. then:

# radmin  
radmin version 3.0.18, built on Sep 19 2018 at 12:29:01 - FreeRADIUS Server administration tool.
Copyright (C) 2008-2017 The FreeRADIUS server project and contributors.
There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
PARTICULAR PURPOSE.
You may redistribute copies of FreeRADIUS under the terms of the
GNU General Public License v2.
radmin> debug file dbg4
radmin> debug condition '(Acct-Status-Type == Interim-Update)'
radmin>

the server crashes after few seconds.

backtrace from GDB

there are a few places that it crashed on

1st

(gdb) bt
#0  0x000055bf1fd47a12 in request_proxy_reply (packet=0x55bf23041090) at src/main/process.c:2530
#1  0x000055bf1fd2d955 in proxy_socket_recv (listener=0x7f15d00279a0) at src/main/listen.c:2012
#2  0x000055bf1fd4690e in event_socket_handler (xel=<optimized out>, fd=<optimized out>, ctx=<optimized out>) at src/main/process.c:4666
#3  0x00007f1603b9fb05 in fr_event_loop (el=0x55bf217c0de0) at src/lib/event.c:649
#4  0x000055bf1fd4dbc1 in radius_event_process () at src/main/process.c:5738
#5  0x000055bf1fd26a1f in main (argc=<optimized out>, argv=<optimized out>) at src/main/radiusd.c:587
(gdb) p *packet
$6 = {sockfd = 525, src_ipaddr = {af = 2, ipaddr = {ip4addr = {s_addr = 3605196042}, ip6addr = {__in6_u = {__u6_addr8 = "\n\355\342\326", '\000' <repeats 11 times>, __u6_addr16 = {60682, 55010, 0, 0, 0, 0, 0, 0}, 
          __u6_addr32 = {3605196042, 0, 0, 0}}}}, prefix = 32 ' ', scope = 0}, dst_ipaddr = {af = 2, ipaddr = {ip4addr = {s_addr = 1442971914}, ip6addr = {__in6_u = {__u6_addr8 = "\n\001\002V", '\000' <repeats 11 times>, 
          __u6_addr16 = {266, 22018, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {1442971914, 0, 0, 0}}}}, prefix = 32 ' ', scope = 0}, src_port = 3799, dst_port = 48964, id = 94, code = 45, 
  vector = "1\\\371\b\222\b\"\375\376.\344#W\232\206", <incomplete sequence \311>, timestamp = {tv_sec = 0, tv_usec = 0}, data = 0x55bf22217400 "-^", data_len = 98, vps = 0x0, offset = -1, partial = 0, proto = 17}
(gdb) p *request
$7 = {number = 38826081, timestamp = 1537439217, data = 0x0, listener = 0x55bf221b38e0, client = 0x0, packet = 0x7f159c0332f0, username = 0x0, password = 0x0, reply = 0x7f159c13bb00, config = 0x7f159c13bc00, 
  state_ctx = 0x7f159c071940, state = 0x0, proxy_listener = 0x7f15d00279a0, proxy = 0x7f159c2380d0, proxy_reply = 0x0, home_server = 0x0, home_pool = 0x0, process = 0x55bf1fd4b000 <coa_wait_for_reply>, response_delay = {
    tv_sec = 0, tv_usec = 0}, timer_action = FR_ACTION_INVALID, ev = 0x0, handle = 0x7f1603dd0520 <null_handler>, rcode = RLM_MODULE_REJECT, module = 0x55bf1fd6667e "", component = 0x55bf1fd636ec "<core>", delay = 0, 
  master_state = REQUEST_ACTIVE, child_state = REQUEST_PROXIED, child_pid = 139732535175296, root = 0x55bf1ff83100 <main_config>, simul_max = 0, simul_count = 0, simul_mpp = 0, priority = RAD_LISTEN_NONE, 
  in_request_hash = false, in_proxy_hash = true, num_proxied_requests = 1, num_proxied_responses = 0, server = 0x55bf212d8840 "ELProxy", parent = 0x55bf26046ba0, log = {func = 0x7f1603dc8160 <vradlog_request>, 
    lvl = L_DBG_LVL_OFF, indent = 0 '\000'}, options = 1, coa = 0x0, num_coa_requests = 624}
(gdb) 

2nd

(gdb) bt
#0  fr_pair_value_from_str (vp=0x7fac34196120, value=0x7fac34264070 "S100.120.68.172", inlen=inlen@entry=18446744073709551615) at src/lib/pair.c:1198
#1  0x00007fac8fd28d36 in map_to_vp (ctx=0x7fac34263ef0, out=0x7fabd7fd57f0, request=0x55c8bd2e0770, map=0x55c8b86387e0, uctx=<optimized out>) at src/main/map.c:820
#2  0x00007fac8fd297d2 in map_to_request (request=request@entry=0x55c8bd2e0770, map=map@entry=0x55c8b86387e0, func=func@entry=0x7fac8fd28ab0 <map_to_vp>, ctx=ctx@entry=0x0) at src/main/map.c:1124
#3  0x000055c8b52e10be in modcall_recurse (request=0x55c8bd2e0770, component=MOD_PREACCT, depth=5, entry=entry@entry=0x7fabd7fd6a28, do_next_sibling=true) at src/main/modcall.c:596
#4  0x000055c8b52e0bc9 in modcall_child (request=<optimized out>, component=<optimized out>, depth=<optimized out>, entry=0x7fabd7fd6a10, c=<optimized out>, result=0x7fabd7fd5cd4, do_next_sibling=true)
    at src/main/modcall.c:408
#5  0x000055c8b52e0dae in modcall_recurse (request=0x55c8bd2e0770, component=MOD_PREACCT, depth=4, entry=entry@entry=0x7fabd7fd6a10, do_next_sibling=true) at src/main/modcall.c:789
#6  0x000055c8b52e0bc9 in modcall_child (request=<optimized out>, component=<optimized out>, depth=<optimized out>, entry=0x7fabd7fd69f8, c=<optimized out>, result=0x7fabd7fd5f84, do_next_sibling=true)
    at src/main/modcall.c:408
#7  0x000055c8b52e0dae in modcall_recurse (request=0x55c8bd2e0770, component=MOD_PREACCT, depth=3, entry=entry@entry=0x7fabd7fd69f8, do_next_sibling=true) at src/main/modcall.c:789
#8  0x000055c8b52e0bc9 in modcall_child (request=<optimized out>, component=<optimized out>, depth=<optimized out>, entry=0x7fabd7fd69e0, c=<optimized out>, result=0x7fabd7fd6234, do_next_sibling=true)
    at src/main/modcall.c:408
#9  0x000055c8b52e0dae in modcall_recurse (request=0x55c8bd2e0770, component=MOD_PREACCT, depth=2, entry=entry@entry=0x7fabd7fd69e0, do_next_sibling=true) at src/main/modcall.c:789
#10 0x000055c8b52e0bc9 in modcall_child (request=<optimized out>, component=<optimized out>, depth=<optimized out>, entry=0x7fabd7fd69c8, c=<optimized out>, result=0x7fabd7fd64e4, do_next_sibling=true)
    at src/main/modcall.c:408
#11 0x000055c8b52e0dae in modcall_recurse (request=0x55c8bd2e0770, component=MOD_PREACCT, depth=1, entry=entry@entry=0x7fabd7fd69c8, do_next_sibling=true) at src/main/modcall.c:789
#12 0x000055c8b52e0bc9 in modcall_child (request=<optimized out>, component=<optimized out>, depth=<optimized out>, entry=0x7fabd7fd69b0, c=<optimized out>, result=0x7fabd7fd6794, do_next_sibling=true)
    at src/main/modcall.c:408
#13 0x000055c8b52e0dae in modcall_recurse (request=request@entry=0x55c8bd2e0770, component=component@entry=MOD_PREACCT, depth=depth@entry=0, entry=entry@entry=0x7fabd7fd69b0, do_next_sibling=do_next_sibling@entry=true)
    at src/main/modcall.c:789
#14 0x000055c8b52e1fc6 in modcall (component=component@entry=MOD_PREACCT, c=c@entry=0x55c8b8635f50, request=request@entry=0x55c8bd2e0770) at src/main/modcall.c:1134
#15 0x000055c8b52dcbdd in indexed_modcall (comp=comp@entry=MOD_PREACCT, idx=idx@entry=0, request=0x55c8bd2e0770) at src/main/modules.c:1031
#16 0x000055c8b52ddd0f in module_preacct (request=<optimized out>) at src/main/modules.c:2181
#17 0x000055c8b52caeb5 in rad_accounting (request=0x55c8bd2e0770) at src/main/acct.c:56
#18 0x000055c8b52f068e in request_running (request=0x55c8bd2e0770, action=<optimized out>) at src/main/process.c:1571
#19 0x000055c8b52e914c in request_handler_thread (arg=0x55c8b8834f50) at src/main/threads.c:826
#20 0x00007fac8e535e25 in start_thread () from /lib64/libpthread.so.0
#21 0x00007fac8dde2bad in clone () from /lib64/libc.so.6
(gdb) p *vp
$1 = {da = 0x3533613363363536, next = 0x3433363339333133, op = 842216755, tag = 51 '3', value = {xlat = 0x3436323336363333 <Address 0x3436323336363333 out of bounds>}, type = 926102582, length = 3762249747183908147, data = {
    strvalue = 0x3336383331333633 <Address 0x3336383331333633 out of bounds>, octets = 0x3336383331333633 <Address 0x3336383331333633 out of bounds>, integer = 825439795, ipaddr = {s_addr = 825439795}, date = 825439795, 
    filter = {3690198737196627507, 3545233639517599283, 54096005640499, 0}, ifid = "36313863", ipv6addr = {__in6_u = {__u6_addr8 = "3631386336616331", __u6_addr16 = {13875, 12595, 14387, 13110, 13875, 12598, 13110, 12595}, 
        __u6_addr32 = {825439795, 859191347, 825636403, 825439030}}}, ipv6prefix = "363138633661633131", byte = 51 '3', ushort = 13875, ether = "363138", sinteger = 825439795, integer64 = 3690198737196627507, 
    ipv4prefix = "363138", ptr = 0x3336383331333633}}
(gdb) p *vp->da
Cannot access memory at address 0x3533613363363536
(gdb) 

the debug from this one is

(91858) Mon Sep 24 21:01:36 2018: Debug: Received Accounting-Request Id 35 from 10.237.226.214:1646 to 192.168.248.255:1913 length 613
(91858) Mon Sep 24 21:01:36 2018: Debug:   Acct-Session-Id = "0/0/1/246.203_0A01FFD301334D50"
(91858) Mon Sep 24 21:01:36 2018: Debug:   Cisco-Account-Info = "Vinfo[userindex:16021049,accounttype:55,expiration:1538498400,]"
(91858) Mon Sep 24 21:01:36 2018: Debug:   Cisco-Policy-Up = "_Light_Plus_IN"
(91858) Mon Sep 24 21:01:36 2018: Debug:   Cisco-Policy-Down = "_Light_Plus_OUT"
(91858) Mon Sep 24 21:01:36 2018: Debug:   Framed-Protocol = PPP
(91858) Mon Sep 24 21:01:36 2018: Debug:   Framed-IP-Address = 100.120.68.172
(91858) Mon Sep 24 21:01:36 2018: Debug:   User-Name = "mastafa@aff5"
(91858) Mon Sep 24 21:01:36 2018: Debug:   Cisco-AVPair = "connect-progress=LAN Ses Up"
(91858) Mon Sep 24 21:01:36 2018: Debug:   Cisco-AVPair = "nas-tx-speed=1000000000"
(91858) Mon Sep 24 21:01:36 2018: Debug:   Cisco-AVPair = "nas-tx-speed-kbps=1000000"
(91858) Mon Sep 24 21:01:36 2018: Debug:   Cisco-AVPair = "nas-rx-speed=1000000000"
(91858) Mon Sep 24 21:01:36 2018: Debug:   Cisco-AVPair = "nas-rx-speed-kbps=1000000"
(91858) Mon Sep 24 21:01:36 2018: Debug:   Acct-Session-Time = 23576
(91858) Mon Sep 24 21:01:36 2018: Debug:   Acct-Input-Gigawords = 0
(91858) Mon Sep 24 21:01:36 2018: Debug:   Acct-Output-Gigawords = 1
(91858) Mon Sep 24 21:01:36 2018: Debug:   Acct-Input-Octets = 235217949
(91858) Mon Sep 24 21:01:36 2018: Debug:   Acct-Output-Octets = 2195316480
(91858) Mon Sep 24 21:01:36 2018: Debug:   Acct-Input-Packets = 2765410
(91858) Mon Sep 24 21:01:36 2018: Debug:   Acct-Output-Packets = 5014695
(91858) Mon Sep 24 21:01:36 2018: Debug:   Acct-Authentic = RADIUS
(91858) Mon Sep 24 21:01:36 2018: Debug:   Acct-Status-Type = Interim-Update
(91858) Mon Sep 24 21:01:36 2018: Debug:   Cisco-Service-Info = "NOPNGDNS"
(91858) Mon Sep 24 21:01:36 2018: Debug:   Cisco-Service-Info = "NRDRCTDNS"
(91858) Mon Sep 24 21:01:36 2018: Debug:   Calling-Station-Id = "24-a4-3c-92-3c-74"
(91858) Mon Sep 24 21:01:36 2018: Debug:   NAS-Port-Type = PPPoEoQinQ
(91858) Mon Sep 24 21:01:36 2018: Debug:   Cisco-NAS-Port = "0/0/1/246.203"
(91858) Mon Sep 24 21:01:36 2018: Debug:   NAS-Port = 4294921552
(91858) Mon Sep 24 21:01:36 2018: Debug:   NAS-Port-Id = "0/0/1/246.203"
(91858) Mon Sep 24 21:01:36 2018: Debug:   Cisco-AVPair = "client-mac-address=24a4.3c92.3c74"
(91858) Mon Sep 24 21:01:36 2018: Debug:   Class = 0x656c3a3930323531313730323333366531333733613436313831323836346237343334
(91858) Mon Sep 24 21:01:36 2018: Debug:   Service-Type = Framed-User
(91858) Mon Sep 24 21:01:36 2018: Debug:   NAS-IP-Address = 10.237.226.214
(91858) Mon Sep 24 21:01:36 2018: Debug:   Event-Timestamp = "Sep 24 2018 21:01:35 +03"
(91858) Mon Sep 24 21:01:36 2018: Debug:   Acct-Delay-Time = 0
(91858) Mon Sep 24 21:01:36 2018: Debug: # Executing section preacct from file /etc/raddb/sites-enabled/ELProxy
(91858) Mon Sep 24 21:01:36 2018: Debug:   preacct {
...
...
...
(91858) Mon Sep 24 21:01:36 2018: Debug:             update coa {
(91858) Mon Sep 24 21:01:36 2018: Debug:               EXPAND S%{Framed-IP-Address}
(91858) Mon Sep 24 21:01:37 2018: Debug:                  --> S100.120.68.172

3rd

(gdb) bt
#0  0x00007f09c5b18277 in raise () from /lib64/libc.so.6
#1  0x00007f09c5b19968 in abort () from /lib64/libc.so.6
#2  0x00007f09c78dd79a in _fr_talloc_fault_simple (reason=<optimized out>) at src/lib/debug.c:782
#3  0x00007f09c6de6cb7 in _talloc_array () from /lib64/libtalloc.so.2
#4  0x00007f09c78e7260 in talloc_bstrndup (t=t@entry=0x7f09440b6d90, in=in@entry=0x7f09440577f0 "subscriber:sub-qos-policy-in=_Light_Plus_IN", inlen=inlen@entry=43) at src/lib/missing.c:436
#5  0x00007f09c78f6e7b in value_data_from_str (ctx=ctx@entry=0x7f09440b6d90, dst=dst@entry=0x7f09440b6dc0, src_type=src_type@entry=0x7f09167da254, src_enumv=<optimized out>, 
    src=src@entry=0x7f09440577f0 "subscriber:sub-qos-policy-in=_Light_Plus_IN", src_len=src_len@entry=-1, quote=quote@entry=34 '"') at src/lib/value.c:449
#6  0x00007f09c78e7e09 in fr_pair_value_from_str (vp=0x7f09440b6d90, value=0x7f09440577f0 "subscriber:sub-qos-policy-in=_Light_Plus_IN", inlen=inlen@entry=18446744073709551615) at src/lib/pair.c:1204
#7  0x00007f09c7b26d36 in map_to_vp (ctx=0x7f0944042da0, out=0x7f09167da7f0, request=0x5599d8edf500, map=0x5599d76c6350, uctx=<optimized out>) at src/main/map.c:820
#8  0x00007f09c7b277d2 in map_to_request (request=request@entry=0x5599d8edf500, map=map@entry=0x5599d76c6350, func=func@entry=0x7f09c7b26ab0 <map_to_vp>, ctx=ctx@entry=0x0) at src/main/map.c:1124
#9  0x00005599d43340be in modcall_recurse (request=0x5599d8edf500, component=MOD_PREACCT, depth=5, entry=entry@entry=0x7f09167dba28, do_next_sibling=true) at src/main/modcall.c:596
#10 0x00005599d4333bc9 in modcall_child (request=<optimized out>, component=<optimized out>, depth=<optimized out>, entry=0x7f09167dba10, c=<optimized out>, result=0x7f09167dacd4, do_next_sibling=true)
    at src/main/modcall.c:408
#11 0x00005599d4333dae in modcall_recurse (request=0x5599d8edf500, component=MOD_PREACCT, depth=4, entry=entry@entry=0x7f09167dba10, do_next_sibling=true) at src/main/modcall.c:789
#12 0x00005599d4333bc9 in modcall_child (request=<optimized out>, component=<optimized out>, depth=<optimized out>, entry=0x7f09167db9f8, c=<optimized out>, result=0x7f09167daf84, do_next_sibling=true)
    at src/main/modcall.c:408
#13 0x00005599d4333dae in modcall_recurse (request=0x5599d8edf500, component=MOD_PREACCT, depth=3, entry=entry@entry=0x7f09167db9f8, do_next_sibling=true) at src/main/modcall.c:789
#14 0x00005599d4333bc9 in modcall_child (request=<optimized out>, component=<optimized out>, depth=<optimized out>, entry=0x7f09167db9e0, c=<optimized out>, result=0x7f09167db234, do_next_sibling=true)
    at src/main/modcall.c:408
#15 0x00005599d4333dae in modcall_recurse (request=0x5599d8edf500, component=MOD_PREACCT, depth=2, entry=entry@entry=0x7f09167db9e0, do_next_sibling=true) at src/main/modcall.c:789
#16 0x00005599d4333bc9 in modcall_child (request=<optimized out>, component=<optimized out>, depth=<optimized out>, entry=0x7f09167db9c8, c=<optimized out>, result=0x7f09167db4e4, do_next_sibling=true)
    at src/main/modcall.c:408
#17 0x00005599d4333dae in modcall_recurse (request=0x5599d8edf500, component=MOD_PREACCT, depth=1, entry=entry@entry=0x7f09167db9c8, do_next_sibling=true) at src/main/modcall.c:789
#18 0x00005599d4333bc9 in modcall_child (request=<optimized out>, component=<optimized out>, depth=<optimized out>, entry=0x7f09167db9b0, c=<optimized out>, result=0x7f09167db794, do_next_sibling=true)
    at src/main/modcall.c:408
#19 0x00005599d4333dae in modcall_recurse (request=request@entry=0x5599d8edf500, component=component@entry=MOD_PREACCT, depth=depth@entry=0, entry=entry@entry=0x7f09167db9b0, do_next_sibling=do_next_sibling@entry=true)
    at src/main/modcall.c:789
#20 0x00005599d4334fc6 in modcall (component=component@entry=MOD_PREACCT, c=c@entry=0x5599d76c2f50, request=request@entry=0x5599d8edf500) at src/main/modcall.c:1134
#21 0x00005599d432fbdd in indexed_modcall (comp=comp@entry=MOD_PREACCT, idx=idx@entry=0, request=0x5599d8edf500) at src/main/modules.c:1031
#22 0x00005599d4330d0f in module_preacct (request=<optimized out>) at src/main/modules.c:2181
#23 0x00005599d431deb5 in rad_accounting (request=0x5599d8edf500) at src/main/acct.c:56
#24 0x00005599d434368e in request_running (request=0x5599d8edf500, action=<optimized out>) at src/main/process.c:1571
#25 0x00005599d433c14c in request_handler_thread (arg=0x5599d80b5620) at src/main/threads.c:826
#26 0x00007f09c6333e25 in start_thread () from /lib64/libpthread.so.0
#27 0x00007f09c5be0bad in clone () from /lib64/libc.so.6

I think this is related to issue #2304 (it is the same server, same config). because if I comment out the update coa section it becomes stable. and also, home_server is null where it should not be!
something is messing up the requests, or we have some kind of racing condition here.

@alanbuxey

This comment has been minimized.

Copy link
Member

alanbuxey commented Sep 26, 2018

@linuxchips

This comment has been minimized.

Copy link
Author

linuxchips commented Sep 26, 2018

it is correct.

update coa {
    &Cisco-Account-Info :="S%{Framed-IP-Address}"
    &NAS-IP-Address := "%{NAS-IP-Address}"
    ...
    ...
}

it is the way cisco NASs identify users (by there IPs, not user id). i can look up the docs for you if you like.

@alandekok

This comment has been minimized.

Copy link
Member

alandekok commented Jan 15, 2019

This is the same issues as #2304. We will track the bug there.

@alandekok alandekok closed this Jan 15, 2019

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.