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

4.0.x - default_log not being initialised when server run in multi-threaded mode. Additionally, calls using fr_log_fp need to be moved to a modern equivalent. #2786

Open
gen2brain opened this issue Jul 12, 2019 · 10 comments

Comments

@gen2brain
Copy link

commented Jul 12, 2019

With debug_level = 2 I can start radiusd via systemd service and everything works. With debug_level = 3 it always segfaults, but that is just if I add that option in radiusd.conf file, when I use radiusd -f -Xxx -d ... it works properly.

I cannot use gdb when I start it via service (or I don't know how) so I cannot send more information. I understand 4.0.x is WIP, and maybe you are aware of the problem, but this looks like something that can pass through tests and go unnoticed.

With debug_level = 3 , every packet received will cause segfault:

Fri Jul 12 14:35:29 2019: Debug : proto_radius_udp - Received Accounting-Request ID 187 length 85 proto_radius_udp server * port 1813
Fri Jul 12 14:35:29 2019: Debug : Network received packet size 85
Fri Jul 12 14:35:29 2019: Debug : Waiting for events 1
Fri Jul 12 14:35:29 2019: Debug :       thread 1 - Got num_events 2
Fri Jul 12 14:35:29 2019: Debug :       thread 1 - servicing events
Fri Jul 12 14:35:29 2019: Debug :       --> data
Fri Jul 12 14:35:29 2019: Debug :       thread 1 - received request 1
Fri Jul 12 14:35:29 2019: Debug :       Worker thread 1 -  checking timeouts
Fri Jul 12 14:35:29 2019: Debug : Worker 1 found request to decode
CAUGHT SIGNAL: Segmentation fault
No panic action set

Thanks,
Milan

@arr2036

This comment has been minimized.

Copy link
Member

commented Jul 12, 2019

Going to need a backtrace for that one.

@arr2036

This comment has been minimized.

Copy link
Member

commented Jul 12, 2019

gdb --args <path to radiusd>/radiusd -l stdout -f -xxx

@arr2036

This comment has been minimized.

Copy link
Member

commented Jul 12, 2019

FWIW I also definitely don't see that here, and I regularly run with debug level 3 or greater, as do the Travis tests.

@gen2brain

This comment has been minimized.

Copy link
Author

commented Jul 12, 2019

If I start from console with radiusd -f -Xxx it works. Only if I put debug_level = 3 in radiusd.conf and start via service (that just exec /usr/sbin/radiusd -d /home/idbox/etc/raddb -f) then it segfaults, that is why it is hard to get gdb, from console and -Xxx it works properly.

@arr2036

This comment has been minimized.

Copy link
Member

commented Jul 12, 2019

I didn't specify -f -Xxx I specified -f -xxx. -Xxx will set the server to single threaded mode, and set the debug level to 4. As this could be related to threading, you need to run the server in multi-threaded mode.

@gen2brain

This comment has been minimized.

Copy link
Author

commented Jul 12, 2019

Ah, sorry, yes, I can start it with -xxx and it will work until I send a packet from other server, here is the gdb output:

(gdb) run radiusd -f -xxx -d /home/idbox/etc/raddb
Starting program: /usr/sbin/radiusd radiusd -f -xxx -d /home/idbox/etc/raddb
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/libthread_db.so.1".
Detaching after fork from child process 33268.
Detaching after fork from child process 33269.
Detaching after fork from child process 33270.
Detaching after fork from child process 33271.
[New Thread 0x7fffec698700 (LWP 33272)]
[New Thread 0x7fffebe97700 (LWP 33273)]
[New Thread 0x7fffeb696700 (LWP 33274)]
[New Thread 0x7fffeae95700 (LWP 33275)]
[New Thread 0x7fffea694700 (LWP 33276)]
[New Thread 0x7fffe9e93700 (LWP 33277)]
[New Thread 0x7fffe9692700 (LWP 33278)]
[New Thread 0x7fffe8e91700 (LWP 33279)]
[New Thread 0x7fffcbfff700 (LWP 33280)]
[New Thread 0x7fffcb7fe700 (LWP 33281)]

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7fffeae95700 (LWP 33275)]
0x00007ffff51844cb in __fprintf_chk () from /lib64/libc.so.6
Missing separate debuginfos, use: debuginfo-install freeradius-4.0.0-15.el7.x86_64
(gdb) bt
#0  0x00007ffff51844cb in __fprintf_chk () from /lib64/libc.so.6
#1  0x00007ffff17b5fc5 in fprintf (__fmt=0x7ffff17bc6b0 "  Code:\t\t%s\n", __stream=0x0) at /usr/include/bits/stdio2.h:97
#2  fr_radius_print_hex (fp=0x0, packet=packet@entry=0x7fffdc346d10 "\004G", packet_len=packet_len@entry=85) at src/protocols/radius/base.c:1137
#3  0x00007ffff19c834b in mod_decode (instance=0x555555eb7f80, request=0x7fffd405d4e0, data=0x7fffdc346d10 "\004G", data_len=85)
    at src/modules/proto_radius/proto_radius.c:287
#4  0x00007ffff74c3176 in fr_worker_get_request (now=9253598195, worker=0x7fffd4009f30) at src/lib/io/worker.c:836
#5  fr_worker_post_event (el=<optimized out>, when=<optimized out>, uctx=0x7fffd4009f30) at src/lib/io/worker.c:1435
#6  0x00007ffff727d63a in fr_event_service (el=0x7fffd4001aa0) at src/lib/util/event.c:1732
#7  0x00007ffff74c3d10 in fr_worker (worker=0x7fffd4009f30) at src/lib/io/worker.c:1489
#8  0x00007ffff74c42aa in fr_schedule_worker_thread (arg=0x555556169840) at src/lib/io/schedule.c:217
#9  0x00007ffff58badd5 in start_thread () from /lib64/libpthread.so.0
#10 0x00007ffff516cead in clone () from /lib64/libc.so.6
(gdb) 

You are right, with -Xxxx it works, but with just -xxx it segfaults when it receives packet. Thanks, didn't realize -X involves single thread.

@arr2036 arr2036 changed the title 4.0.x - segfaults with debug_level > 2 in radiusd.conf 4.0.x - default_log not being initialised when server run in multi-threaded mode. Additionally, calls using fr_log_fp need to be moved to a modern equivalent. Jul 12, 2019

@arr2036 arr2036 self-assigned this Jul 12, 2019

@alandekok

This comment has been minimized.

Copy link
Member

commented Jul 13, 2019

Arran pushed some fixes. It shouldn't hang any more.

The downside is that it no longer prints out the packets as hex any more. I'll take a look.

@gen2brain

This comment has been minimized.

Copy link
Author

commented Jul 13, 2019

I just tested and it works properly now. Thanks!

@arr2036

This comment has been minimized.

Copy link
Member

commented Jul 13, 2019

@arr2036

This comment has been minimized.

Copy link
Member

commented Jul 16, 2019

Between Alan and myself we've fixed most of this, and removed much of the original fr_log_fp code that caused the original issue. Just need to figure out why the default_log is not being initialised in foreground mode, and we should be good to close this.

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