3.0.6 strange bug causing infinite loop on "Ready to process requests" message

[Nick Rogers]

On Tue, Jan 6, 2015 at 4:20 PM, Arran Cudbard-Bell <
a.cudbardb at freeradius.org> wrote:

>
> > On 6 Jan 2015, at 19:11, Alan DeKok <aland at deployingradius.com> wrote:
> >
> > On Jan 6, 2015, at 7:00 PM, Nick Rogers <ncrogers at gmail.com> wrote:
> >> Yeah, that has been my gut feeling as well after seeing the kqueue
> addition in the changelog. I've definitely experienced kqueue related
> issues with other daemons under FreeBSD.
> >>
> >> Here's the thread backtrace
> >>
> >> Starting program: /usr/local/sbin/radiusd -fxx
> >> (no debugging symbols found)...(no debugging symbols found)...(no
> debugging symbols found)...(no debugging symbols found)...(no debugging
> symbols found)...(no debugging symbols found)...(no debugging symbols
> found)...(no debugging symbols found)...[New LWP 100270]
> >
> >  PLEASE build with debugging symbols.  Otherwise the backtrace is
> useless.
>
> To do that either:
>
> ./configure --enable-developer
>
> Or edit Make.inc, remove -O2 add -g3
>

Sorry, I had enabled developer option but also had to set WITH_DEBUG in the
FreeBSD port.

Here's the backtrace. Hope it is useful.

Starting program: /usr/local/sbin/radiusd -fxx
[New LWP 100455]
[New Thread 803406400 (LWP 100455/radiusd)]
[New Thread 80f1f9c00 (LWP 100595/radiusd)]

Program received signal SIGINT, Interrupt.
[Switching to Thread 80f1f9c00 (LWP 100595/radiusd)]
0x000000080208d448 in _umtx_op () from /lib/libc.so.7
* 3 Thread 80f1f9c00 (LWP 100595/radiusd)  0x000000080208d448 in _umtx_op
() from /lib/libc.so.7
  2 Thread 803406400 (LWP 100455/radiusd)  0x0000000802164bda in write ()
from /lib/libc.so.7

Thread 3 (Thread 80f1f9c00 (LWP 100595/radiusd)):
#0  0x000000080208d448 in _umtx_op () from /lib/libc.so.7
No symbol table info available.
#1  0x000000080207cc24 in sem_timedwait () from /lib/libc.so.7
No symbol table info available.
#2  0x000000000043d61e in request_handler_thread (arg=0x80f2a7300) at
src/main/threads.c:609
self = (THREAD_HANDLE *) 0x80f2a7300
#3  0x00000008019a14f5 in pthread_create () from /lib/libthr.so.3
No symbol table info available.
#4  0x0000000000000000 in ?? ()
No symbol table info available.

Thread 2 (Thread 803406400 (LWP 100455/radiusd)):
#0  0x0000000802164bda in write () from /lib/libc.so.7
No symbol table info available.
#1  0x00000008019a3ef6 in write () from /lib/libthr.so.3
No symbol table info available.
#2  0x00000008008ab5f7 in vradlog (type=L_INFO, fmt=0x46c5a0 "Ready to
process requests", ap=0x7fffffffe8b0)
    at src/main/log.c:464
p = (unsigned char *) 0x7fffffffbf19 "\n"
buffer = "Ready to process
requests\n\000\017\b\000\000\000\001\000\000\000\000\000\000\000`H\214\000\b\000\000\000??F\000\000\000\000\000\200\200\200\200\200\200\200\200\200????\177\000\000??X\001\000\000\000\0001\000\000\000\000\000\000\000]\227???\177\000\000\000????\177\000\000\213K\214\000\b\000\000\000\020\000\000\000\016\000\000\000???\230$?\b?0????\177\000\000\016\v\212\000\b\000\000\000#\n\000\003\b\000\000\000???\000\016\000\000\000\213K\214\000\b\000\000\000\001\000\000\000\000\000\000\000`H\214\000\b\000\000\000?5F\000\000\000\000\000\025\a\000\000\000\000\000\000"...
unsan = 0x7fffffffbf00 "Ready to process requests\n"
len = 25
colourise = 0
#3  0x00000008008ab83e in radlog (type=L_INFO, msg=0x46c5a0 "Ready to
process requests") at src/main/log.c:485
ap = {{gp_offset = 16, fp_offset = 48, overflow_arg_area = 0x7fffffffe8f0,
    reg_save_area = 0x7fffffffe7f0}}
r = 0
#4  0x00000000004428a5 in event_status (wake=0x0) at src/main/process.c:4334
No locals.
#5  0x0000000800b0cd44 in fr_event_loop (el=0x80365e060) at
src/lib/event.c:577
i = 1
rcode = 1
when = {tv_sec = 0, tv_usec = 0}
wake = (struct timeval *) 0x0
ts_when = {tv_sec = 34614206240, tv_nsec = 34614206240}
ts_wake = (struct timespec *) 0x0
#6  0x0000000000443541 in radius_event_process () at src/main/process.c:5186
No locals.
#7  0x00000000004332d6 in main (argc=2, argv=0x7fffffffeb90) at
src/main/radiusd.c:574
rcode = 0
status = 6801456
argval = -1
spawn_flag = true
write_pid = false
display_version = false
flag = 0
from_child = {-1, -1}
autofree = (void *) 0x8034170e0
#0  0x000000080208d448 in _umtx_op () from /lib/libc.so.7
The program is running.  Exit anyway? (y or n)



> >> I was working on trying to disable kqueue somehow and test. Any
> suggestions on the best way of doing that? There does not appear to be a
> configure flag for it, unless I am missing it.
> >
> >  After the “configure” script runs, edit src/include/autoconf.h.  Look
> for:
> >
> > /* Define to 1 if you have the `kqueue' function. */
> > #define HAVE_KQUEUE 1
> >
> >  And delete it.  Then, “make” as normal.
>
> Yep that'd be a good test.
>

Removing kqueue definitely fixes the problem I'm having. I ended up
removing the kqueue line from the "for ac_func in \" loop in configure
script, but it had the same affect. I am able to handle requests after
rebuilding without kqueue and there is no more infinite loop.


>
> -Arran
> -
> List info/subscribe/unsubscribe? See
> http://www.freeradius.org/list/users.html
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20150106/014d5865/attachment.html>