1.1.1: Backtrace of non-responding server
Hi folks, good news (I think): I did the backtrace Alan spoke about, and it seems like it might be an error on the mysql client-library side that ultimately leads to a broken pipe. For your viewing pleasure, here's the bt: (gdb) set args -f (gdb) r Starting program: /usr/local/freeradius-1.1.1/sbin/radiusd -f [New Thread 16384 (LWP 27561)] Thu Apr 6 14:25:38 2006 : Info: Starting - reading configuration files ... [New Thread 32769 (LWP 27562)] [New Thread 16386 (LWP 27563)] [New Thread 32771 (LWP 27564)] [New Thread 49156 (LWP 27565)] [New Thread 65541 (LWP 27566)] [New Thread 81926 (LWP 27567)] [New Thread 98311 (LWP 27568)] [New Thread 114696 (LWP 27569)] [New Thread 131081 (LWP 27570)] [New Thread 147466 (LWP 27571)] [New Thread 163851 (LWP 27572)] Program received signal SIGPIPE, Broken pipe. [Switching to Thread 114696 (LWP 27569)] 0x40056a9b in write () from /lib/libpthread.so.0 (gdb) info threads 12 Thread 163851 (LWP 27572) 0x40116768 in sigsuspend () from /lib/libc.so.6 11 Thread 147466 (LWP 27571) 0x40116768 in sigsuspend () from /lib/libc.so.6 10 Thread 131081 (LWP 27570) 0x40116768 in sigsuspend () from /lib/libc.so.6 * 9 Thread 114696 (LWP 27569) 0x40056a9b in write () from /lib/libpthread.so.0 8 Thread 98311 (LWP 27568) 0x40116768 in sigsuspend () from /lib/libc.so.6 7 Thread 81926 (LWP 27567) 0x40116768 in sigsuspend () from /lib/libc.so.6 6 Thread 65541 (LWP 27566) 0x40116768 in sigsuspend () from /lib/libc.so.6 5 Thread 49156 (LWP 27565) 0x40116768 in sigsuspend () from /lib/libc.so.6 4 Thread 32771 (LWP 27564) 0x40116768 in sigsuspend () from /lib/libc.so.6 3 Thread 16386 (LWP 27563) 0x40116768 in sigsuspend () from /lib/libc.so.6 2 Thread 32769 (LWP 27562) 0x401c65e7 in poll () from /lib/libc.so.6 1 Thread 16384 (LWP 27561) 0x401c8371 in select () from /lib/libc.so.6 (gdb) thread 1 [Switching to thread 1 (Thread 16384 (LWP 27561))]#0 0x401c8371 in select () from /lib/libc.so.6 (gdb) bt #0 0x401c8371 in select () from /lib/libc.so.6 #1 0xbfffcf70 in ?? () #2 0x401028ae in __libc_start_main () from /lib/libc.so.6 (gdb) thread 2 [Switching to thread 2 (Thread 32769 (LWP 27562))]#0 0x401c65e7 in poll () from /lib/libc.so.6 (gdb) bt #0 0x401c65e7 in poll () from /lib/libc.so.6 #1 0x4005096e in __pthread_manager () from /lib/libpthread.so.0 #2 0x40050b67 in __pthread_manager_event () from /lib/libpthread.so.0 (gdb) thread 3 [Switching to thread 3 (Thread 16386 (LWP 27563))]#0 0x40116768 in sigsuspend () from /lib/libc.so.6 (gdb) bt #0 0x40116768 in sigsuspend () from /lib/libc.so.6 #1 0x40053198 in __pthread_wait_for_restart_signal () from /lib/libpthread.so.0 #2 0x4005420b in sem_wait@@GLIBC_2.1 () from /lib/libpthread.so.0 #3 0x08059c7d in request_handler_thread (arg=0x81fd3e0) at threads.c:481 #4 0x40050c60 in pthread_start_thread () from /lib/libpthread.so.0 #5 0x40050cdf in pthread_start_thread_event () from /lib/libpthread.so.0 (gdb) thread 4 [Switching to thread 4 (Thread 32771 (LWP 27564))]#0 0x40116768 in sigsuspend () from /lib/libc.so.6 (gdb) bt #0 0x40116768 in sigsuspend () from /lib/libc.so.6 #1 0x40053198 in __pthread_wait_for_restart_signal () from /lib/libpthread.so.0 #2 0x4005420b in sem_wait@@GLIBC_2.1 () from /lib/libpthread.so.0 #3 0x08059c7d in request_handler_thread (arg=0x81fd478) at threads.c:481 #4 0x40050c60 in pthread_start_thread () from /lib/libpthread.so.0 #5 0x40050cdf in pthread_start_thread_event () from /lib/libpthread.so.0 (gdb) thread 5 [Switching to thread 5 (Thread 49156 (LWP 27565))]#0 0x40116768 in sigsuspend () from /lib/libc.so.6 (gdb) bt #0 0x40116768 in sigsuspend () from /lib/libc.so.6 #1 0x40053198 in __pthread_wait_for_restart_signal () from /lib/libpthread.so.0 #2 0x4005420b in sem_wait@@GLIBC_2.1 () from /lib/libpthread.so.0 #3 0x08059c7d in request_handler_thread (arg=0x82006c0) at threads.c:481 #4 0x40050c60 in pthread_start_thread () from /lib/libpthread.so.0 #5 0x40050cdf in pthread_start_thread_event () from /lib/libpthread.so.0 (gdb) thread 6 [Switching to thread 6 (Thread 65541 (LWP 27566))]#0 0x40116768 in sigsuspend () from /lib/libc.so.6 (gdb) bt #0 0x40116768 in sigsuspend () from /lib/libc.so.6 #1 0x40053198 in __pthread_wait_for_restart_signal () from /lib/libpthread.so.0 #2 0x4005420b in sem_wait@@GLIBC_2.1 () from /lib/libpthread.so.0 #3 0x08059c7d in request_handler_thread (arg=0x82006e8) at threads.c:481 #4 0x40050c60 in pthread_start_thread () from /lib/libpthread.so.0 #5 0x40050cdf in pthread_start_thread_event () from /lib/libpthread.so.0 (gdb) thread 7 [Switching to thread 7 (Thread 81926 (LWP 27567))]#0 0x40116768 in sigsuspend () from /lib/libc.so.6 (gdb) bt #0 0x40116768 in sigsuspend () from /lib/libc.so.6 #1 0x40053198 in __pthread_wait_for_restart_signal () from /lib/libpthread.so.0 #2 0x4005420b in sem_wait@@GLIBC_2.1 () from /lib/libpthread.so.0 #3 0x08059c7d in request_handler_thread (arg=0x8200710) at threads.c:481 #4 0x40050c60 in pthread_start_thread () from /lib/libpthread.so.0 #5 0x40050cdf in pthread_start_thread_event () from /lib/libpthread.so.0 (gdb) thread 8 [Switching to thread 8 (Thread 98311 (LWP 27568))]#0 0x40116768 in sigsuspend () from /lib/libc.so.6 (gdb) bt #0 0x40116768 in sigsuspend () from /lib/libc.so.6 #1 0x40053198 in __pthread_wait_for_restart_signal () from /lib/libpthread.so.0 #2 0x4005420b in sem_wait@@GLIBC_2.1 () from /lib/libpthread.so.0 #3 0x08059c7d in request_handler_thread (arg=0x8200738) at threads.c:481 #4 0x40050c60 in pthread_start_thread () from /lib/libpthread.so.0 #5 0x40050cdf in pthread_start_thread_event () from /lib/libpthread.so.0 (gdb) thread 9 [Switching to thread 9 (Thread 114696 (LWP 27569))]#0 0x40056a9b in write () from /lib/libpthread.so.0 (gdb) bt #0 0x40056a9b in write () from /lib/libpthread.so.0 #1 0x404f3ee0 in days_in_month () from /usr/lib/libmysqlclient_r.so.15 #2 0x403f7b08 in net_real_write () from /usr/lib/libmysqlclient_r.so.15 #3 0x403f75b8 in net_flush () from /usr/lib/libmysqlclient_r.so.15 #4 0x403f7873 in net_write_command () from /usr/lib/libmysqlclient_r.so.15 #5 0x403f1e1f in cli_advanced_command () from /usr/lib/libmysqlclient_r.so.15 #6 0x403f48cf in mysql_send_query () from /usr/lib/libmysqlclient_r.so.15 #7 0x403f4960 in mysql_real_query () from /usr/lib/libmysqlclient_r.so.15 #8 0x403c86a5 in mysql_query () from /usr/lib/libmysqlclient_r.so.15 #9 0x403a8dd2 in sql_query (sqlsocket=0xffffffe0, config=0xffffffe0, querystr=0x262 <Address 0x262 out of bounds>) at sql_mysql.c:161 #10 0x403a4ab0 in rlm_sql_query (sqlsocket=0x819f190, inst=0x81284e0, query=0xbebfe86c "INSERT into radacct_eduroam (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, Connect"...) at sql.c:495 #11 0x403a3508 in rlm_sql_accounting (instance=0x81284e0, request=0x407133d0) at rlm_sql.c:1020 #12 0x08053ca4 in call_modsingle (component=3, sp=0x81ad190, request=0x407133d0, default_result=7) at modcall.c:236 #13 0x08054125 in modcall (component=3, c=0x81ad190, request=0x407133d0) at modcall.c:564 #14 0x08053d70 in call_one (component=3, p=0x81ad190, request=0x407133d0, ---Type <return> to continue, or q <return> to quit--- priority=0xbebff950, result=0xbebff954) at modcall.c:269 #15 0x08053e23 in call_modgroup (component=3, g=0xffffffe0, request=0x407133d0, default_result=135975312) at modcall.c:324 #16 0x080541fb in modcall (component=3, c=0x8185338, request=0x407133d0) at modcall.c:549 #17 0x08053925 in module_accounting (acct_type=32775, request=0x407133d0) at modules.c:917 #18 0x0804bff1 in rad_accounting (request=0x407133d0) at acct.c:91 #19 0x080572f6 in rad_respond (request=0x407133d0, fun=0x804bf60 <rad_accounting>) at radiusd.c:1642 #20 0x08059d72 in request_handler_thread (arg=0x8200760) at threads.c:517 #21 0x40050c60 in pthread_start_thread () from /lib/libpthread.so.0 #22 0x40050cdf in pthread_start_thread_event () from /lib/libpthread.so.0 (gdb) thread 10 [Switching to thread 10 (Thread 131081 (LWP 27570))]#0 0x40116768 in sigsuspend () from /lib/libc.so.6 (gdb) bt #0 0x40116768 in sigsuspend () from /lib/libc.so.6 #1 0x40053198 in __pthread_wait_for_restart_signal () from /lib/libpthread.so.0 #2 0x4005420b in sem_wait@@GLIBC_2.1 () from /lib/libpthread.so.0 #3 0x08059c7d in request_handler_thread (arg=0x8200788) at threads.c:481 #4 0x40050c60 in pthread_start_thread () from /lib/libpthread.so.0 #5 0x40050cdf in pthread_start_thread_event () from /lib/libpthread.so.0 (gdb) thread 11 [Switching to thread 11 (Thread 147466 (LWP 27571))]#0 0x40116768 in sigsuspend () from /lib/libc.so.6 (gdb) bt #0 0x40116768 in sigsuspend () from /lib/libc.so.6 #1 0x40053198 in __pthread_wait_for_restart_signal () from /lib/libpthread.so.0 #2 0x4005420b in sem_wait@@GLIBC_2.1 () from /lib/libpthread.so.0 #3 0x08059c7d in request_handler_thread (arg=0x82007b0) at threads.c:481 #4 0x40050c60 in pthread_start_thread () from /lib/libpthread.so.0 #5 0x40050cdf in pthread_start_thread_event () from /lib/libpthread.so.0 (gdb) thread 12 [Switching to thread 12 (Thread 163851 (LWP 27572))]#0 0x40116768 in sigsuspend () from /lib/libc.so.6 (gdb) bt #0 0x40116768 in sigsuspend () from /lib/libc.so.6 #1 0x40053198 in __pthread_wait_for_restart_signal () from /lib/libpthread.so.0 #2 0x4005420b in sem_wait@@GLIBC_2.1 () from /lib/libpthread.so.0 #3 0x08059c7d in request_handler_thread (arg=0x82007d8) at threads.c:481 #4 0x40050c60 in pthread_start_thread () from /lib/libpthread.so.0 #5 0x40050cdf in pthread_start_thread_event () from /lib/libpthread.so.0 (gdb) thread 13 Thread ID 13 not known. (gdb) quit So, I'm doing my homework now: install the latest and greatest libmysqlclient and hope that that helps. For the record: the error occured with the libmysqlclient from 5.0.15 (MySQL-shared-5.0.15-0.glibc23). I will now update to 5.0.19 and see if that does any good. Greetings, Stefan -- Stefan WINTER Stiftung RESTENA - Réseau Téléinformatique de l'Education Nationale et de la Recherche Ingenieur Forschung & Entwicklung 6, rue Richard Coudenhove-Kalergi L-1359 Luxembourg E-Mail: stefan.winter@restena.lu Tel.: +352 424409-1 http://www.restena.lu Fax: +352 422473
Hi again,
good news (I think)
OTOH, I think it's rather bad news: Thread 9 says:
#9 0x403a8dd2 in sql_query (sqlsocket=0xffffffe0, config=0xffffffe0, querystr=0x262 <Address 0x262 out of bounds>) at sql_mysql.c:161 #10 0x403a4ab0 in rlm_sql_query (sqlsocket=0x819f190, inst=0x81284e0, query=0xbebfe86c "INSERT into radacct_eduroam (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, Connect"...) at sql.c:495 #11 0x403a3508 in rlm_sql_accounting (instance=0x81284e0, request=0x407133d0) at rlm_sql.c:1020
Note the wrong address 0x262 while the code is supposed to give char* query, 0xbebfe86c, as third argument to that function. So maybe it's in the FR code after all. Maybe a race condition between two threads that mixes pointers up? Greetings, Stefan -- Stefan WINTER Stiftung RESTENA - Réseau Téléinformatique de l'Education Nationale et de la Recherche Ingenieur Forschung & Entwicklung 6, rue Richard Coudenhove-Kalergi L-1359 Luxembourg E-Mail: stefan.winter@restena.lu Tel.: +352 424409-1 http://www.restena.lu Fax: +352 422473
Stefan Winter wrote:
OTOH, I think it's rather bad news:
Thread 9 says:
#9 0x403a8dd2 in sql_query (sqlsocket=0xffffffe0, config=0xffffffe0, querystr=0x262 <Address 0x262 out of bounds>) at sql_mysql.c:161 #10 0x403a4ab0 in rlm_sql_query (sqlsocket=0x819f190, inst=0x81284e0, query=0xbebfe86c "INSERT into radacct_eduroam (AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType, AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start, Connect"...) at sql.c:495 #11 0x403a3508 in rlm_sql_accounting (instance=0x81284e0, request=0x407133d0) at rlm_sql.c:1020
Note the wrong address 0x262 while the code is supposed to give char* query, 0xbebfe86c, as third argument to that function.
So maybe it's in the FR code after all. Maybe a race condition between two threads that mixes pointers up?
Just to add something: I am suffering from a deadlocking freeradius too, but I don't use anything related to mysql, just LDAP. (On Debian Sarge, compiled into a DEB using a clean chroot.) After some unknown amount of time or after a (yet) unknown request the daemon locks up using 100% cpu, a strace shows a constant flow of segfaults. I don't know if this is related to the bug you are seeing, but it seems like it. Grüße, Sven. -- Sven Hartge -- professioneller Unix-Geek Meine Gedanken im Netz: http://www.svenhartge.de/ Achtung, neue Mail-Adresse: sven@svenhartge.de
Sven Hartge <sven@svenhartge.de> wrote:
After some unknown amount of time or after a (yet) unknown request the daemon locks up using 100% cpu, a strace shows a constant flow of segfaults.
Constant? Please build it with symbols, and run it under gdb, or look at the core dumps. We should really fix these problems before issuing 1.1.2. Alan DeKok.
Alan DeKok wrote:
Sven Hartge <sven@svenhartge.de> wrote:
After some unknown amount of time or after a (yet) unknown request the daemon locks up using 100% cpu, a strace shows a constant flow of segfaults.
Constant? Please build it with symbols, and run it under gdb, or look at the core dumps.
"Funny" thing is: Until now freeradiusd has been running flawless. Maybe he "feels" I am going to dissect him as soon as he starts to fail again. :) Right now I am using monit to generate an automatic backtrace as soon as the problem occurs again. Grüße, Sven -- Sven Hartge -- professioneller Unix-Geek Meine Gedanken im Netz: http://www.svenhartge.de/ Achtung, neue Mail-Adresse: sven@svenhartge.de
Stefan Winter <stefan.winter@restena.lu> wrote:
OTOH, I think it's rather bad news:
Thread 9 says:
#9 0x403a8dd2 in sql_query (sqlsocket=0xffffffe0, config=0xffffffe0, querystr=0x262 <Address 0x262 out of bounds>) at sql_mysql.c:161 #10 0x403a4ab0 in rlm_sql_query (sqlsocket=0x819f190, inst=0x81284e0, query=0xbebfe86c ...
That usually happens because of a buffer overflow or stack smash. GDB will print the arguments to sql_query *after* the stack was smashed, which explains why they're nonsense.
So maybe it's in the FR code after all. Maybe a race condition between two threads that mixes pointers up?
I don't see how that can happen when one function calls another. My suggestion is to run it using "valgrind --tool=memcheck". The server will be slow as heck, and may not even work in threaded mode due to valgrind issues. If you're using SSL, valgrind will spit our reams of errors. But it *should* print out any buffer overflows resulting from calling the sql_query function. Alan DeKok.
participants (3)
-
Alan DeKok -
Stefan Winter -
Sven Hartge