(long) I have been running radiusd cvs 9/29 + local mods for some time. (mostly under gdb with -fxx), to see if I can upgrade all systems to this or something later (plan to recheckpoint as soon as 9/29 is stable for me). As illustrated by previous unrelated posts, this server forks a lot (for every accounting which is confed for 5 minute updates per logged in user on the nas) to implement a ddns scheme. One issue that appears to be cropping up is where debug output and the server appears to freeze up. ===================================================== thread apply all bt shows this : Thread 11 (Thread -1290798160 (LWP 7382)): #0 0xb7ca438f in fork () from /lib/tls/libc.so.6 #1 0xb7f73064 in fork () from /lib/tls/libpthread.so.0 #2 0x08058a03 in rad_fork (exec_wait=0) at threads.c:1114 #3 0xb7fa8205 in radius_exec_program () from /usr/lib/freeradius/rlm_exec-1.1.0-pre0.so #4 0xb7fa8d8c in radius_exec_program () from /usr/lib/freeradius/rlm_exec-1.1.0-pre0.so #5 0x08054d26 in modcall (component=3, c=0x81b1188, request=0xb51033c8) at modcall.c:254 #6 0x080552d9 in call_one (component=Variable "component" is not available. ) at modcall.c:287 #7 0x08054eb5 in modcall (component=3, c=0x81afa08, request=0xb51033c8) at modcall.c:342 #8 0x08053f5f in indexed_modcall (comp=3, idx=Variable "idx" is not available. ) at modules.c:428 #9 0x0804f009 in rad_accounting (request=0xb51033c8) at acct.c:65 #10 0x08060f32 in rad_respond (request=0xb51033c8, fun=0x804efa0 <rad_accounting>) at request_process.c:456 #11 0x08057dba in request_handler_thread (arg=0x81b5828) at threads.c:585 #12 0xb7f6cccd in start_thread () from /lib/tls/libpthread.so.0 #13 0xb7ce3b0e in clone () from /lib/tls/libc.so.6 <the rest of the threads are at sem_wait> Thread 1 (Thread -1212102976 (LWP 27527)): #0 0xb7cf0d69 in pthread_setcanceltype () from /lib/tls/libc.so.6 #1 0xb7c7ac05 in malloc () from /lib/tls/libc.so.6 #2 0xb7f5a744 in rad_recv (fd=8) at radius.c:1063 #3 0x0805ec18 in proxy_socket_recv (listener=0xfffffffc, pfun=0xfffffffc, prequest=0xfffffffc) at listen.c:802 #4 0x0804d3c1 in main (argc=2, argv=0xbfabde44) at radiusd.c:665 ============================================ This tentatively appears to occur with -fxx NOT under gdb, normal is not currently known. cvs 3/16 does not have this issue when running normally. The only change I could detect as being obviously relevant is an added call to reap_children() in rad_fork() Now reap_children implements some magic voodoo tail head queue scheme that I havent managed to wrap my head around yet. debug output shows that radutmp (which is before the ddns exec module) is the last module to returns normally before. So I have added copious debug output. And I am having trouble understanding what I am seeing (nothing new there). In reap_children I have added some calls like this: ================================== --- /home/joe/download/radius/cvs/cvs-20050929/radiusd/src/main/threads.c 2005-09-14 21:21:14.000000000 -0400 +++ src/main/threads.c 2005-10-27 22:45:28.000000000 -0400 @@ -246,8 +248,10 @@ { if (thread_pool.wait_head != thread_pool.wait_tail) { int num; + int rval; pthread_mutex_lock(&thread_pool.wait_mutex); + FUNC_LINE_FILE(" mutex locked"); for (num = ((thread_pool.wait_tail + MAX_WAITERS) - thread_pool.wait_head) % MAX_WAITERS; num != 0; num--) { @@ -259,18 +263,35 @@ /* * Child is still alive: move it to the tail. */ - if (waitpid(pid, NULL, WNOHANG) == 0) { + FUNC_LINE_FILE(" wait for %d", pid); + if (waitpid(pid, &rval, WNOHANG) == 0) { if (((thread_pool.wait_tail + 1) % MAX_WAITERS) == thread_pool.wait_head) { rad_assert(0 == 1); } + FUNC_LINE_FILE(" wait for %d returned val\n" + " WIFEXITED(%d)" + " WEXITSTATUS(%d)" + " WIFSIGNALED(%d)" + " WTERMSIG(%d)" + " WIFSTOPPED(%d)" + " WSTOPSIG(%d)" + , pid, WIFEXITED(rval), + WIFEXITED(rval) ? WEXITSTATUS(rval) : 0, + WIFSIGNALED(rval), + WIFSIGNALED(rval) ? WTERMSIG(rval) : 0, + WIFSTOPPED(rval), + WIFSTOPPED(rval) ? WSTOPSIG(rval) : 0 + ); thread_pool.wait[thread_pool.wait_tail] = pid; thread_pool.wait_tail++; thread_pool.wait_tail %= MAX_WAITERS; } /* else no child, or was already reaped */ + else FUNC_LINE_FILE(" wait for %d returned noval", pid); } pthread_mutex_unlock(&thread_pool.wait_mutex); + FUNC_LINE_FILE(" mutex unlocked"); } } =============================================================== A sample of the output looks like this: ================================================================ reap_children() threads.c:254 mutex locked reap_children() threads.c:266 wait for 9240 reap_children() threads.c:285 wait for 9240 returned val WIFEXITED(0) WEXITSTATUS(0) WIFSIGNALED(1) WTERMSIG(84) WIFSTOPPED(0) WSTOPSIG(0) reap_children() threads.c:266 wait for 9241 reap_children() threads.c:285 wait for 9241 returned val WIFEXITED(0) WEXITSTATUS(0) WIFSIGNALED(1) WTERMSIG(84) WIFSTOPPED(0) WSTOPSIG(0) reap_children() threads.c:266 wait for 14565 reap_children() threads.c:285 wait for 14565 returned val WIFEXITED(0) WEXITSTATUS(0) WIFSIGNALED(1) WTERMSIG(84) WIFSTOPPED(0) WSTOPSIG(0) reap_children() threads.c:266 wait for 14566 reap_children() threads.c:285 wait for 14566 returned val WIFEXITED(0) WEXITSTATUS(0) WIFSIGNALED(1) WTERMSIG(84) WIFSTOPPED(0) WSTOPSIG(0) reap_children() threads.c:266 wait for 17694 reap_children() threads.c:285 wait for 17694 returned val WIFEXITED(0) WEXITSTATUS(0) WIFSIGNALED(1) WTERMSIG(84) WIFSTOPPED(0) WSTOPSIG(0) reap_children() threads.c:266 wait for 19290 reap_children() threads.c:285 wait for 19290 returned val WIFEXITED(0) WEXITSTATUS(0) WIFSIGNALED(1) WTERMSIG(84) WIFSTOPPED(0) WSTOPSIG(0) reap_children() threads.c:266 wait for 19291 reap_children() threads.c:285 wait for 19291 returned val WIFEXITED(0) WEXITSTATUS(0) WIFSIGNALED(1) WTERMSIG(84) WIFSTOPPED(0) WSTOPSIG(0) reap_children() threads.c:266 wait for 20399 reap_children() threads.c:285 wait for 20399 returned val WIFEXITED(0) WEXITSTATUS(0) WIFSIGNALED(1) WTERMSIG(84) WIFSTOPPED(0) WSTOPSIG(0) reap_children() threads.c:294 mutex unlocked ======================================================================== Question 1: Signal 84? Question 2: Appears that reap_children waits for thread pids, in addition to forked children? (see 9241 and 9240 and 20399..... below) ====================================================== freerad 6760 32641 6760 0 7 22:45 pts/15 00:00:00 src/main/.libs/radiusd -fxx freerad 6760 32641 6791 0 7 22:45 pts/15 00:00:00 src/main/.libs/radiusd -fxx freerad 6760 32641 6792 0 7 22:45 pts/15 00:00:00 src/main/.libs/radiusd -fxx freerad 6760 32641 6793 0 7 22:45 pts/15 00:00:00 src/main/.libs/radiusd -fxx freerad 6760 32641 6794 0 7 22:45 pts/15 00:00:00 src/main/.libs/radiusd -fxx freerad 6760 32641 6795 0 7 22:45 pts/15 00:00:00 src/main/.libs/radiusd -fxx freerad 6760 32641 19287 0 7 22:58 pts/15 00:00:00 src/main/.libs/radiusd -fxx freerad 9240 6760 9240 0 1 22:48 pts/15 00:00:00 src/main/.libs/radiusd -fxx freerad 9241 6760 9241 0 1 22:48 pts/15 00:00:00 src/main/.libs/radiusd -fxx freerad 14565 6760 14565 0 1 22:53 pts/15 00:00:00 src/main/.libs/radiusd -fxx freerad 14566 6760 14566 0 1 22:53 pts/15 00:00:00 src/main/.libs/radiusd -fxx freerad 17694 6760 17694 0 1 22:56 pts/15 00:00:00 src/main/.libs/radiusd -fxx freerad 19290 6760 19290 0 1 22:58 pts/15 00:00:00 src/main/.libs/radiusd -fxx freerad 19291 6760 19291 0 1 22:58 pts/15 00:00:00 src/main/.libs/radiusd -fxx freerad 20399 6760 20399 0 1 22:59 pts/15 00:00:00 src/main/.libs/radiusd -fxx freerad 22467 6760 22467 0 1 23:01 pts/15 00:00:00 src/main/.libs/radiusd -fxx ============================================================= How this has anything todo with my possible issue, I am not quite certain. misc: FUNC_LINE_FILE() is a local debug modification looks like this: #define FUNC_LINE_FILE(format, ...) do {\ printf("%s() %s:%d" format "\n",__func__,__FILE__,__LINE__, ## __VA_ARGS__);\ } while (0); (yes its missing a mutex lock, but since I put it into libradius.h I couldnt easily use DEBUG2) If anyone has any tips I would appreciate it. Joe