Stack trace of crash with FR 3.0.10
Hi, we've been running FR 3.0.10 in production for about a month now. We have four production servers on RHEL 6. Every few days one of the radiusd processes quits without an error message. We have now enabled the panic action and installed the debuginfo RPMs. Last night we got the first usable gbd.log. Here's the relevant part: Thread 4 (Thread 0x7f8b6cb36700 (LWP 9823)): #0 0x0000003a1ae0cdab in pthread_once () from /lib64/libpthread.so.0 No symbol table info available. #1 0x0000003a1aafea04 in backtrace () from /lib64/libc.so.6 No symbol table info available. #2 0x0000003a1aa7054b in __libc_message () from /lib64/libc.so.6 No symbol table info available. #3 0x0000003a1aa75e66 in malloc_printerr () from /lib64/libc.so.6 No symbol table info available. #4 0x0000003a1aa799a4 in _int_malloc () from /lib64/libc.so.6 No symbol table info available. #5 0x0000003a1aa7a3e6 in calloc () from /lib64/libc.so.6 No symbol table info available. #6 0x0000003a1a60addf in _dl_new_object () from /lib64/ld-linux-x86-64.so.2 No symbol table info available. #7 0x0000003a1a6071de in _dl_map_object_from_fd () from /lib64/ld-linux-x86-64.so.2 No symbol table info available. #8 0x0000003a1a60839a in _dl_map_object () from /lib64/ld-linux-x86-64.so.2 No symbol table info available. #9 0x0000003a1a612b95 in dl_open_worker () from /lib64/ld-linux-x86-64.so.2 No symbol table info available. #10 0x0000003a1a60e286 in _dl_catch_error () from /lib64/ld-linux-x86-64.so.2 No symbol table info available. #11 0x0000003a1a61263a in _dl_open () from /lib64/ld-linux-x86-64.so.2 No symbol table info available. #12 0x0000003a1ab26cd0 in do_dlopen () from /lib64/libc.so.6 No symbol table info available. #13 0x0000003a1a60e286 in _dl_catch_error () from /lib64/ld-linux-x86-64.so.2 No symbol table info available. #14 0x0000003a1ab26e27 in __libc_dlopen_mode () from /lib64/libc.so.6 No symbol table info available. #15 0x0000003a1aafe8d5 in init () from /lib64/libc.so.6 No symbol table info available. #16 0x0000003a1ae0cdb3 in pthread_once () from /lib64/libpthread.so.0 No symbol table info available. #17 0x0000003a1aafea04 in backtrace () from /lib64/libc.so.6 No symbol table info available. #18 0x0000003a1aa7054b in __libc_message () from /lib64/libc.so.6 No symbol table info available. #19 0x0000003a1aa75e66 in malloc_printerr () from /lib64/libc.so.6 No symbol table info available. #20 0x0000003a1aa789ba in _int_free () from /lib64/libc.so.6 No symbol table info available. #21 0x0000003a20202389 in ?? () from /usr/lib64/libtalloc.so.2 No symbol table info available. #22 0x000000396dc15dbc in fr_pair_value_strsteal (vp=0x7f8b48732dc0, src=0x7f8b4874f5e0 "leap:session-key=\200hl\240:l\236\255t\256\247\366Z\315%f\233\220q~\343-\207VΟ\334\366N%i\372p\274Q\242\243\232ީ/\257\362\315\376f\344\067>0\356\262\v\233\343\240\344pH\213\177") at /usr/src/debug/freeradius-server-3.0.10/src/lib/pair.c:2125 q = <value optimized out> #23 0x00007f8b751ac8da in mod_post_proxy (inst=0x19c0c60, request=0x1c6c590) at /usr/src/debug/freeradius-server-3.0.10/src/modules/rlm_eap/rlm_eap.c:675 i = 34 len = 130 p = 0x7f8b4874f5e0 "leap:session-key=\200hl\240:l\236\255t\256\247\366Z\315%f\233\220q~\343-\207VΟ\334\366N%i\372p\274Q\242\243\232ީ/\257\362\315\376f\344\067>0\356\262\v\233\343\240\344pH\213\177" vp = 0x7f8b48732dc0 handler = <value optimized out> cursor = {first = 0x1c170d8, found = 0x7f8b48732dc0, last = 0x0, current = 0x7f8b48732dc0, next = 0x7f8b48708160} #24 0x0000000000425f4f in call_modsingle (request=0x1c6c590, component=MOD_POST_PROXY, depth=1, entry=0x7f8b6cb359c8, do_next_sibling=true) at /usr/src/debug/freeradius-server-3.0.10/src/main/modcall.c:302 blocked = <value optimized out> indent = 4 #25 modcall_recurse (request=0x1c6c590, component=MOD_POST_PROXY, depth=1, entry=0x7f8b6cb359c8, do_next_sibling=true) at /usr/src/debug/freeradius-server-3.0.10/src/main/modcall.c:574 sp = 0x1a672f0 if_taken = false was_if = false c = <value optimized out> priority = <value optimized out> result = RLM_MODULE_OK #26 0x00000000004267ba in modcall_child (request=<value optimized out>, component=<value optimized out>, depth=<value optimized out>, entry=0x7f8b6cb359b0, c=<value optimized out>, result=0x7f8b6cb3580c, do_next_sibling=true) at /usr/src/debug/freeradius-server-3.0.10/src/main/modcall.c:408 next = 0x7f8b6cb359c8 #27 0x0000000000425575 in modcall_recurse (request=0x1c6c590, component=MOD_POST_PROXY, depth=0, entry=0x7f8b6cb359b0, do_next_sibling=true) at /usr/src/debug/freeradius-server-3.0.10/src/main/modcall.c:785 g = 0x1a67150 if_taken = false was_if = false c = <value optimized out> priority = <value optimized out> result = RLM_MODULE_UNKNOWN #28 0x0000000000426753 in modcall (component=<value optimized out>, c=<value optimized out>, request=<value optimized out>) at /usr/src/debug/freeradius-server-3.0.10/src/main/modcall.c:1130 stack = {{result = RLM_MODULE_NOOP, priority = 0, unwind = 0, c = 0x1a67150}, {result = RLM_MODULE_OK, priority = 3, unwind = 0, c = 0x1a672f0}, {result = 1823693344, priority = 32651, unwind = 29811200, c = 0x0}, {result = 1841447521, priority = 57, unwind = 1823693888, c = 0x3a1d2e8029}, {result = RLM_MODULE_FAIL, priority = 0, unwind = 490166044, c = 0x7f8b48708160}, {result = 1215624496, priority = 32651, unwind = 3, c = 0x1d5}, {result = 24099536, priority = 0, unwind = 1823693448, c = 0x7f8b480008c0}, {result = 24099488, priority = 0, unwind = 24099536, c = 0x3a1d2e7e92}, {result = 1823693504, priority = 32651, unwind = 489586107, c = 0x0}, {result = RLM_MODULE_REJECT, priority = 0, unwind = 0, c = 0x7f8b6cb35d20}, {result = 11, priority = 32651, unwind = 489586811, c = 0x0}, {result = RLM_MODULE_REJECT, priority = 0, unwind = 9, c = 0x2}, {result = RLM_MODULE_REJECT, priority = 0, unwind = 176, c = 0x0}, {result = RLM_MODULE_REJECT, priority = 0, unwind = 0, c = 0x3200000009}, {result = 91, priority = 124, unwind = 119, c = 0x396dc2f86a}, {result = 1215353712, priority = 32651, unwind = 129, c = 0x7f8b48000020}, {result = 29454432, priority = 0, unwind = 1823693888, c = 0x7f8b6cb35c40}, {result = 4382876, priority = 0, unwind = 1215353712, c = 0xe6dfd36399d685d1}, {result = 49, priority = 0, unwind = 29454432, c = 0x1c1727c}, {result = 29811200, priority = 0, unwind = 29454432, c = 0x7f8b6cb35c40}, {result = 1823693888, priority = 32651, unwind = 1841429743, c = 0x3}, {result = RLM_MODULE_HANDLED, priority = 0, unwind = 1823693888, c = 0x10}, {result = RLM_MODULE_USERLOCK, priority = 0, unwind = 26404800, c = 0x8}, {result = 1841415815, priority = 57, unwind = 8, c = 0x7f8b589caf50}, {result = 1841506360, priority = 57, unwind = 1486663584, c = 0x0}, {result = 1843648576, priority = 57, unwind = 1843648576, c = 0x3a20202389}, {result = 1486663584, priority = 32651, unwind = 27885456, c = 0x0}, {result = 1486663584, priority = 32651, unwind = 1843648576, c = 0x396dc20f10}, {result = RLM_MODULE_REJECT, priority = 0, unwind = 1486663584, c = 0x1a97f90}, {result = 27852576, priority = 0, unwind = 29811200, c = 0x1}, {result = 1823693984, priority = 32651, unwind = 1516734484, c = 0x7f8b6cb35ce0}, {result = 4323808, priority = 0, unwind = 1823694016, c = 0x1c6c590}} #29 0x000000000041fd95 in indexed_modcall (comp=MOD_POST_PROXY, idx=0, request=0x1c6c590) at /usr/src/debug/freeradius-server-3.0.10/src/main/modules.c:1009 rcode = <value optimized out> list = 0x1a67150 server = 0x1a5df00 #30 0x000000000042e8f3 in process_proxy_reply (request=0x1c6c590, reply=0x1c17060) at /usr/src/debug/freeradius-server-3.0.10/src/main/process.c:2394 rcode = <value optimized out> post_proxy_type = <value optimized out> vp = <value optimized out> #31 0x00000000004354c9 in proxy_running (request=0x1c6c590, action=<value optimized out>) at /usr/src/debug/freeradius-server-3.0.10/src/main/process.c:2741 __FUNCTION__ = "proxy_running" #32 0x000000000042cb4a in request_handler_thread (arg=0x16fbaa0) at /usr/src/debug/freeradius-server-3.0.10/src/main/threads.c:690 self = 0x16fbaa0 #33 0x0000003a1ae07a51 in start_thread () from /lib64/libpthread.so.0 No symbol table info available. #34 0x0000003a1aae89ad in clone () from /lib64/libc.so.6 No symbol table info available. As far as we have been able to discern, previous crashes didn't all occur in post-proxy. The same user authenticated successfully before, so it also doesn't seem to related to that specific user. I will post future backtraces if they offer new evidence. Please let me know if additional info would be helpful. -- .:.Sebastian Hagedorn - Weyertal 121 (Gebäude 133), Zimmer 2.02.:. .:.Regionales Rechenzentrum (RRZK).:. .:.Universität zu Köln / Cologne University - ✆ +49-221-470-89578.:.
On Nov 18, 2015, at 5:22 AM, Sebastian Hagedorn <Hagedorn@uni-koeln.de> wrote:
Hi,
we've been running FR 3.0.10 in production for about a month now. We have four production servers on RHEL 6. Every few days one of the radiusd processes quits without an error message. We have now enabled the panic action and installed the debuginfo RPMs. Last night we got the first usable gbd.log. Here's the relevant part:
Thanks.
#22 0x000000396dc15dbc in fr_pair_value_strsteal (vp=0x7f8b48732dc0, src=0x7f8b4874f5e0 "leap:session-key=\200hl\240:l\236\255t\256\247\366Z\315%f\233\220q~\343-\207VΟ\334\366N%i\372p\274Q\242\243\232ީ/\257\362\315\376f\344\067>0\356\262\v\233\343\240\344pH\213\177") at /usr/src/debug/freeradius-server-3.0.10/src/lib/pair.c:2125 q = <value optimized out>
LEAP? Don't use that. It's insecure.
As far as we have been able to discern, previous crashes didn't all occur in post-proxy.
OK. So it's something else.
The same user authenticated successfully before, so it also doesn't seem to related to that specific user. I will post future backtraces if they offer new evidence. Please let me know if additional info would be helpful.
Any other back traces would help. This might be hard to track down without local tests... Alan DeKok.
--On 18. November 2015 um 09:13:46 -0500 Alan DeKok <aland@deployingradius.com> wrote:
we've been running FR 3.0.10 in production for about a month now. We have four production servers on RHEL 6. Every few days one of the radiusd processes quits without an error message. We have now enabled the panic action and installed the debuginfo RPMs. Last night we got the first usable gbd.log. Here's the relevant part:
Thanks.
# 22 0x000000396dc15dbc in fr_pair_value_strsteal (vp=0x7f8b48732dc0, # src=0x7f8b4874f5e0 # "leap:session-key=\200hl\240:l\236\255t\256\247\366Z\315%f\233\220q~\3 # 43-\207VΟ\334\366N%i\372p\274Q\242\243\232ީ/\257\362\315\376f\344\06 # 7>0\356\262\v\233\343\240\344pH\213\177") at # /usr/src/debug/freeradius-server-3.0.10/src/lib/pair.c:2125 q = <value optimized out>
LEAP? Don't use that. It's insecure.
Actually we don't use LEAP and were surprised by that message. The session in question was using EAP-TTLS.
As far as we have been able to discern, previous crashes didn't all occur in post-proxy.
OK. So it's something else.
The same user authenticated successfully before, so it also doesn't seem to related to that specific user. I will post future backtraces if they offer new evidence. Please let me know if additional info would be helpful.
Any other back traces would help.
This might be hard to track down without local tests...
I'm willing to test anything you suggest. Meanwhile here's a new back trace: Thread 1 (Thread 0x7f57f27b87e0 (LWP 28274)): #0 0x0000003a1aaac70d in waitpid () from /lib64/libc.so.6 No symbol table info available. #1 0x0000003a1aa3e609 in do_system () from /lib64/libc.so.6 No symbol table info available. #2 0x0000003a1aa3e940 in system () from /lib64/libc.so.6 No symbol table info available. #3 0x000000396dc0c15c in fr_fault (sig=<value optimized out>) at /usr/src/debug/freeradius-server-3.0.10/src/lib/debug.c:725 disable = true cmd = "gdb -silent -x /etc/raddb/panic.gdb /usr/sbin/radiusd 28274 2>&1 | tee /var/log/radius/gdb-radiusd-28274.log", '\000' <repeats 423 times> out = 0x7fff54dafcd8 ".log" left = 428 ret = <value optimized out> p = 0x396de3d962 ".log" q = 0x0 code = <value optimized out> #4 <signal handler called> No symbol table info available. #5 0x0000003a20202d19 in ?? () from /usr/lib64/libtalloc.so.2 No symbol table info available. #6 0x0000003a2020244f in ?? () from /usr/lib64/libtalloc.so.2 No symbol table info available. #7 0x0000003a20202323 in ?? () from /usr/lib64/libtalloc.so.2 No symbol table info available. #8 0x0000003a20202323 in ?? () from /usr/lib64/libtalloc.so.2 No symbol table info available. #9 0x0000000000431257 in request_done (request=0x2bd3de0, action=2) at /usr/src/debug/freeradius-server-3.0.10/src/main/process.c:806 now = {tv_sec = 40078192, tv_usec = 45947520} when = {tv_sec = 140734617027872, tv_usec = 40077872} #10 0x0000000000432c31 in request_receive (ctx=0x2bd1a80, listener=0x2638a30, packet=0x2bd1ae0, client=0x263e340, fun=0x40efb0 <rad_authenticate>) at /usr/src/debug/freeradius-server-3.0.10/src/main/process.c:1656 child_state = <value optimized out> count = <value optimized out> packet_p = <value optimized out> request = <value optimized out> now = {tv_sec = 1447842529, tv_usec = 339180} sock = 0x2638b70 #11 0x0000000000419751 in auth_socket_recv (listener=0x2638a30) at /usr/src/debug/freeradius-server-3.0.10/src/main/listen.c:1568 rcode = <value optimized out> code = 1 src_port = <value optimized out> packet = <value optimized out> fun = 0x40efb0 <rad_authenticate> client = 0x263e340 src_ipaddr = {af = 2, ipaddr = {ip4addr = {s_addr = 36312236}, ip6addr = {__in6_u = {__u6_addr8 = "\254\024*\002", '\000' <repeats 11 times>, __u6_addr16 = {5292, 554, 0, 0, 0, 0, 0, 0}, __u6_addr32 = {36312236, 0, 0, 0}}}}, prefix = 32 ' ', scope = 0} ctx = 0x2bd1a80 #12 0x0000000000430fa0 in event_socket_handler (xel=<value optimized out>, fd=<value optimized out>, ctx=<value optimized out>) at /usr/src/debug/freeradius-server-3.0.10/src/main/process.c:4556 listener = <value optimized out> #13 0x000000396dc28cfb in fr_event_loop (el=0x2535930) at /usr/src/debug/freeradius-server-3.0.10/src/lib/event.c:641 ef = <value optimized out> i = <value optimized out> rcode = 1 when = {tv_sec = 1447842529, tv_usec = 345425} wake = <value optimized out> maxfd = 31 read_fds = {fds_bits = {4194304, 0 <repeats 15 times>}} master_fds = {fds_bits = {4294049680, 0 <repeats 15 times>}} #14 0x0000000000427204 in main (argc=<value optimized out>, argv=<value optimized out>) at /usr/src/debug/freeradius-server-3.0.10/src/main/radiusd.c:579 rcode = 0 status = <value optimized out> argval = <value optimized out> spawn_flag = true display_version = false flag = 0 from_child = {4, 5} state = 0x66bb40 autofree = 0x2264060 A debugging session is active. -- .:.Sebastian Hagedorn - Weyertal 121 (Gebäude 133), Zimmer 2.02.:. .:.Regionales Rechenzentrum (RRZK).:. .:.Universität zu Köln / Cologne University - ✆ +49-221-470-89578.:.
--On 18. November 2015 um 09:52:51 -0500 Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
I'm willing to test anything you suggest. Meanwhile here's a new back trace:
Could you install the libtalloc debug package as well.
Done. Now we'll have to wait. -- .:.Sebastian Hagedorn - Weyertal 121 (Gebäude 133), Zimmer 2.02.:. .:.Regionales Rechenzentrum (RRZK).:. .:.Universität zu Köln / Cologne University - ✆ +49-221-470-89578.:.
On 18 Nov 2015, at 10:20, Sebastian Hagedorn <Hagedorn@uni-koeln.de> wrote:
--On 18. November 2015 um 09:52:51 -0500 Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
I'm willing to test anything you suggest. Meanwhile here's a new back trace:
Could you install the libtalloc debug package as well.
Done. Now we'll have to wait.
Pushed some fixes to v3.0.x. -Arran Arran Cudbard-Bell <a.cudbardb@freeradius.org> FreeRADIUS development team FD31 3077 42EC 7FCD 32FE 5EE2 56CF 27F9 30A8 CAA2
--On 18. November 2015 um 11:51:50 -0500 Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
On 18 Nov 2015, at 10:20, Sebastian Hagedorn <Hagedorn@uni-koeln.de> wrote:
--On 18. November 2015 um 09:52:51 -0500 Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
I'm willing to test anything you suggest. Meanwhile here's a new back trace:
Could you install the libtalloc debug package as well.
Done. Now we'll have to wait.
Pushed some fixes to v3.0.x.
Thanks, but that actually made it worse ;-) This change to rlm_eap.c is buggy: if (!request->proxy_reply) return RLM_MODULE_NOOP; + if (handler->type != PW_EAP_LEAP) return RLM_MODULE_NOOP; It's outside the scope of the if (handler != NULL) { block, and crashes when handler is NULL. -- .:.Sebastian Hagedorn - Weyertal 121 (Gebäude 133), Zimmer 2.02.:. .:.Regionales Rechenzentrum (RRZK).:. .:.Universität zu Köln / Cologne University - ✆ +49-221-470-89578.:.
On 20 Nov 2015, at 08:19, Sebastian Hagedorn <Hagedorn@uni-koeln.de> wrote:
--On 18. November 2015 um 11:51:50 -0500 Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
On 18 Nov 2015, at 10:20, Sebastian Hagedorn <Hagedorn@uni-koeln.de> wrote:
--On 18. November 2015 um 09:52:51 -0500 Arran Cudbard-Bell <a.cudbardb@freeradius.org> wrote:
I'm willing to test anything you suggest. Meanwhile here's a new back trace:
Could you install the libtalloc debug package as well.
Done. Now we'll have to wait.
Pushed some fixes to v3.0.x.
Thanks, but that actually made it worse ;-)
Yeah reverted it... The length fixes might still help. -Arran
participants (3)
-
Alan DeKok -
Arran Cudbard-Bell -
Sebastian Hagedorn