Hi! We're currently testing FR 3.0.1 with RadSec and we're seeing crashes when we turn off an access point. In the log below you can see that the access point sends an accounting stop request before it powers down. FR crashes after closing the socket. I also pasted the GDB stack trace below. BTW, we're also seeing these warnings a lot and we're not sure what they mean or how to prevent them: Debug: (19) Writing to socket 12 Debug: (19) Finished request 19. Debug: Thread 1 waiting to be assigned a request WARNING: WARNING: Socket was closed while processing request 19: Stopping it. Debug: (19) Cleaning up request packet ID 73 with timestamp +1053 Debug: Waking up in 1.1 seconds. Cheers, JB == Log == Sending Accounting-Response of id 1 from 0.0.0.0 port 2083 to XXX.XXX.XXX.XXX port 2159 (0) Finished request 0. Thread 5 waiting to be assigned a request Waking up in 0.3 seconds. Client has closed connection ... closing socket auth+acct from client (XXX.XXX.XXX.XXX, 2159) -> (*, 2083, virtual-server=testserver) Waking up in 0.3 seconds. WARNING: Socket was closed while processing request 0: Stopping it. (0) Cleaning up request packet ID 1 with timestamp +10 talloc: access after free error - first free may be at src/main/listen.c:3287 Bad talloc magic value - access after free Program received signal SIGABRT, Aborted. 0xb7fe1424 in __kernel_vsyscall () == GDB stacktrace == #0 0xb7fe1424 in __kernel_vsyscall () No symbol table info available. #1 0xb7b5d941 in raise () from /lib/i386-linux-gnu/i686/cmov/libc.so.6 No symbol table info available. #2 0xb7b60d72 in abort () from /lib/i386-linux-gnu/i686/cmov/libc.so.6 No symbol table info available. #3 0xb7f2bd99 in talloc_abort () from /usr/local/lib/libtalloc.so.2 No symbol table info available. #4 0xb7f2be50 in talloc_abort_access_after_free () from /usr/local/lib/libtalloc.so.2 No symbol table info available. #5 0xb7f2bedf in talloc_chunk_from_ptr () from /usr/local/lib/libtalloc.so.2 No symbol table info available. #6 0xb7f2dafb in _talloc_free () from /usr/local/lib/libtalloc.so.2 No symbol table info available. #7 0xb7fd2a99 in request_free (request_ptr=0xbffff330) at src/main/util.c:229 request = 0x8293630 #8 0x0807446c in request_done (request=0x8293630, action=2) at src/main/process.c:599 now = {tv_sec = -1073745096, tv_usec = 134690952} when = {tv_sec = 17, tv_usec = 134838992} __FUNCTION__ = "request_done" #9 0x080748dd in request_process_timer (request=0x8293630) at src/main/process.c:753 now = {tv_sec = 136778432, tv_usec = 134553804} when = {tv_sec = 136790696, tv_usec = 136791168} #10 0x08074d1f in request_common (request=0x8293630, action=5) at src/main/process.c:906 buffer = "\250B'\b@\364\377\277\370\363\377\277\004\364\377\277\000\f\376\267\000\f\376\267\000\000\000\000d\364\377\277\250\254\370\267\343\312\370\267d\372\377\267\000\000\000\000\000\000\000\000p\364\377\277(\364\377\277\064\364\377\277\000\f\376\267\000\f\376\267\000\000\000\000\b\364\377\277\274>\n\b\226Q\272\267\370\266\370\267\000\f\376\267\000\000\000\000\377\377\377\377\364\357\377\267\343\312\370\267\005\000\000\000P\364\377\277\026\374\376\267\270\r\376\267" __FUNCTION__ = "request_common" #11 0x08075849 in request_running (request=0x8293630, action=5) at src/main/process.c:1214 __FUNCTION__ = "request_running" #12 0x08073d0e in request_timer (ctx=0x8293630) at src/main/process.c:352 request = 0x8293630 action = 5 #13 0xb7fabe7a in fr_event_run (el=0x82540b0, when=0xbffff608) at src/lib/event.c:219 callback = 0x8073ce4 <request_timer> ctx = 0x8293630 ev = 0x0 #14 0xb7fac4ab in fr_event_loop (el=0x82540b0) at src/lib/event.c:405 i = 4 rcode = 0 maxfd = 16 when = {tv_sec = 1390328421, tv_usec = 338121} wake = 0xbffff608 read_fds = {fds_bits = {0 <repeats 32 times>}} master_fds = {fds_bits = {61440, 0 <repeats 31 times>}} #15 0x0807c34c in radius_event_process () at src/main/process.c:4251 No locals. #16 0x0806b8ef in main (argc=4, argv=0xbffff804) at src/main/radiusd.c:533 rcode = 0 status = -1073744040 argval = -1 spawn_flag = 1 dont_fork = 1 write_pid = 0 flag = 0 from_child = {-1, -1} act = {__sigaction_handler = {sa_handler = 0x806bcf7 <sig_fatal>, sa_sigaction = 0x806bcf7 <sig_fatal>}, sa_mask = {__val = { 0 <repeats 32 times>}}, sa_flags = 0, sa_restorer = 0}
Hello! Can anyone confirm this? Is further information needed to investigate? Thanks, JB JB wrote:
Hi!
We're currently testing FR 3.0.1 with RadSec and we're seeing crashes when we turn off an access point. In the log below you can see that the access point sends an accounting stop request before it powers down. FR crashes after closing the socket. I also pasted the GDB stack trace below.
BTW, we're also seeing these warnings a lot and we're not sure what they mean or how to prevent them:
Debug: (19) Writing to socket 12 Debug: (19) Finished request 19. Debug: Thread 1 waiting to be assigned a request WARNING: WARNING: Socket was closed while processing request 19: Stopping it. Debug: (19) Cleaning up request packet ID 73 with timestamp +1053 Debug: Waking up in 1.1 seconds.
Cheers, JB
== Log ==
Sending Accounting-Response of id 1 from 0.0.0.0 port 2083 to XXX.XXX.XXX.XXX port 2159 (0) Finished request 0. Thread 5 waiting to be assigned a request Waking up in 0.3 seconds. Client has closed connection ... closing socket auth+acct from client (XXX.XXX.XXX.XXX, 2159) -> (*, 2083, virtual-server=testserver) Waking up in 0.3 seconds. WARNING: Socket was closed while processing request 0: Stopping it. (0) Cleaning up request packet ID 1 with timestamp +10 talloc: access after free error - first free may be at src/main/listen.c:3287 Bad talloc magic value - access after free Program received signal SIGABRT, Aborted. 0xb7fe1424 in __kernel_vsyscall ()
== GDB stacktrace ==
#0 0xb7fe1424 in __kernel_vsyscall () No symbol table info available. #1 0xb7b5d941 in raise () from /lib/i386-linux-gnu/i686/cmov/libc.so.6 No symbol table info available. #2 0xb7b60d72 in abort () from /lib/i386-linux-gnu/i686/cmov/libc.so.6 No symbol table info available. #3 0xb7f2bd99 in talloc_abort () from /usr/local/lib/libtalloc.so.2 No symbol table info available. #4 0xb7f2be50 in talloc_abort_access_after_free () from /usr/local/lib/libtalloc.so.2 No symbol table info available. #5 0xb7f2bedf in talloc_chunk_from_ptr () from /usr/local/lib/libtalloc.so.2 No symbol table info available. #6 0xb7f2dafb in _talloc_free () from /usr/local/lib/libtalloc.so.2 No symbol table info available. #7 0xb7fd2a99 in request_free (request_ptr=0xbffff330) at src/main/util.c:229 request = 0x8293630 #8 0x0807446c in request_done (request=0x8293630, action=2) at src/main/process.c:599 now = {tv_sec = -1073745096, tv_usec = 134690952} when = {tv_sec = 17, tv_usec = 134838992} __FUNCTION__ = "request_done" #9 0x080748dd in request_process_timer (request=0x8293630) at src/main/process.c:753 now = {tv_sec = 136778432, tv_usec = 134553804} when = {tv_sec = 136790696, tv_usec = 136791168} #10 0x08074d1f in request_common (request=0x8293630, action=5) at src/main/process.c:906 buffer = "\250B'\b@\364\377\277\370\363\377\277\004\364\377\277\000\f\376\267\000\f\376\267\000\000\000\000d\364\377\277\250\254\370\267\343\312\370\267d\372\377\267\000\000\000\000\000\000\000\000p\364\377\277(\364\377\277\064\364\377\277\000\f\376\267\000\f\376\267\000\000\000\000\b\364\377\277\274>\n\b\226Q\272\267\370\266\370\267\000\f\376\267\000\000\000\000\377\377\377\377\364\357\377\267\343\312\370\267\005\000\000\000P\364\377\277\026\374\376\267\270\r\376\267" __FUNCTION__ = "request_common" #11 0x08075849 in request_running (request=0x8293630, action=5) at src/main/process.c:1214 __FUNCTION__ = "request_running" #12 0x08073d0e in request_timer (ctx=0x8293630) at src/main/process.c:352 request = 0x8293630 action = 5 #13 0xb7fabe7a in fr_event_run (el=0x82540b0, when=0xbffff608) at src/lib/event.c:219 callback = 0x8073ce4 <request_timer> ctx = 0x8293630 ev = 0x0 #14 0xb7fac4ab in fr_event_loop (el=0x82540b0) at src/lib/event.c:405 i = 4 rcode = 0 maxfd = 16 when = {tv_sec = 1390328421, tv_usec = 338121} wake = 0xbffff608 read_fds = {fds_bits = {0 <repeats 32 times>}} master_fds = {fds_bits = {61440, 0 <repeats 31 times>}} #15 0x0807c34c in radius_event_process () at src/main/process.c:4251 No locals. #16 0x0806b8ef in main (argc=4, argv=0xbffff804) at src/main/radiusd.c:533 rcode = 0 status = -1073744040 argval = -1 spawn_flag = 1 dont_fork = 1 write_pid = 0 flag = 0 from_child = {-1, -1} act = {__sigaction_handler = {sa_handler = 0x806bcf7 <sig_fatal>, sa_sigaction = 0x806bcf7 <sig_fatal>}, sa_mask = {__val = { 0 <repeats 32 times>}}, sa_flags = 0, sa_restorer = 0}
JB wrote:
We're currently testing FR 3.0.1 with RadSec and we're seeing crashes when we turn off an access point. In the log below you can see that the access point sends an accounting stop request before it powers down. FR crashes after closing the socket.
Please pull the v3.0.x branch from github. I've pushed a fix. Alan DeKok.
Alan DeKok wrote:
Please pull the v3.0.x branch from github. I've pushed a fix. Alan DeKok.
With the newly built (with --prefix and --enable-developer) v3.0.x branch we're getting SEGFAULTS when an access point is turned off. I've pasted logs and a GDB trace (not from the same occurrence). Please let me know if you need further info from me. Cheers, JB == Log 1 == FATAL SIGNAL: Segmentation fault Backtrace of last 7 frames: /usr/local/freeradius3/lib/libfreeradius-radius.so(+0x6d91) [0xb7712d91] [0xb7767400] /usr/local/freeradius3/sbin/radiusd() [0x807545e] /usr/local/freeradius3/sbin/radiusd() [0x807596c] /usr/local/freeradius3/sbin/radiusd() [0x8071ea9] /lib/i386-linux-gnu/i686/cmov/libpthread.so.0(+0x5c39) [0xb74aac39] /lib/i386-linux-gnu/i686/cmov/libc.so.6(clone+0x5e) [0xb738b78e] No panic action set _EXIT CALLED src/lib/debug.c[262]: 1: == Log 2 == Program received signal SIGSEGV, Segmentation fault. [Switching to Thread 0xb5c35b70 (LWP 9824)] 0xb7cf9e03 in SSL_write () from /usr/lib/i386-linux-gnu/i686/cmov/libssl.so.1.0.0 == GDB == Program received signal SIGSEGV, Segmentation fault. [Switching to Thread 0xb76a2b70 (LWP 9920)] 0x00000000 in ?? () #0 0x00000000 in ?? () No symbol table info available. #1 0x080752ba in request_pre_handler (request=0x82b56c0, action=1) at src/main/process.c:1039 rcode = -1217791151 #2 0x080758ce in request_running (request=0x82b56c0, action=1) at src/main/process.c:1234 __FUNCTION__ = "request_running" #3 0x08071ea9 in request_handler_thread (arg=0x8289648) at src/main/threads.c:696 self = 0x8289648 #4 0xb7d24c39 in start_thread () from /lib/i386-linux-gnu/i686/cmov/libpthread.so.0 No symbol table info available. #5 0xb7c0578e in clone () from /lib/i386-linux-gnu/i686/cmov/libc.so.6 No symbol table info available.
JB wrote:
With the newly built (with --prefix and --enable-developer) v3.0.x branch we're getting SEGFAULTS when an access point is turned off. I've pasted logs and a GDB trace (not from the same occurrence). Please let me know if you need further info from me.
No, that's OK. I'll try to get a test case running. Alan DeKok.
Alan DeKok wrote:
JB wrote:
With the newly built (with --prefix and --enable-developer) v3.0.x branch we're getting SEGFAULTS when an access point is turned off. I've pasted logs and a GDB trace (not from the same occurrence). Please let me know if you need further info from me.
No, that's OK. I'll try to get a test case running.
That'd be great. Just let me know if you need anything from us. Thanks, JB
Alan DeKok wrote:
JB wrote:
That'd be great. Just let me know if you need anything from us.
I pushed some fixes a while ago. Please test.
Looks promising! No crashes or segfaults after first tests. We will continue testing with more clients and post the results. Thanks a lot! JB
participants (2)
-
Alan DeKok -
JB