SQL Accounting problem with 1.0.3 - The maximum number of threads (32) are active
Hi, We seem to be having the "The maximum number of threads (32) are active" with Freeradius 1.0.3. Version 1.0.1 works just fine. I tried to do a valgrind with -xxxx but when radiusd displays that message, you can no longer kill it. I have the debug output from the -xxxx and it shows the accounting processes running, adding info and completing but the thread doesn't seem to release. Example Tue Apr 17 09:49:57 2007 : Debug: rlm_sql (sql1): Reserving sql socket id: 6 Tue Apr 17 09:49:57 2007 : Debug: rlm_sql (sql1): Released sql socket id: 6 Tue Apr 17 09:49:57 2007 : Debug: modsingle[accounting]: returned from sql1 (rlm_sql) for request 48 Tue Apr 17 09:49:57 2007 : Debug: modcall[accounting]: module "sql1" returns ok for request 48 So it appears to be a problem with the mysql driver rather than a problem with a slow database query. Anything else I can provide ? Centos 4.3 Linux version 2.6.9-42.0.10.ELsmp 512 meg of ram Conntecting to a remote DB server over a dedicated gig network running MySQL 5.x Intel(R) Pentium(R) 4 CPU 3.20GHz with hyperthreading enabled. Regards, Rick
Rick Macdougall wrote:
Hi,
We seem to be having the "The maximum number of threads (32) are active" with Freeradius 1.0.3. Version 1.0.1 works just fine.
Upgrade to 1.1.6. It has a whole host of fixes. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
On 4/17/07, Alan DeKok <aland@deployingradius.com> wrote:
Rick Macdougall wrote:
Hi,
We seem to be having the "The maximum number of threads (32) are active" with Freeradius 1.0.3. Version 1.0.1 works just fine.
Upgrade to 1.1.6. It has a whole host of fixes.
Yah, I've already downloaded it in preparation of doing just that. I kind of wanted to stick to an RPM release but it looks like that isn't going to happen. Thanks, Rick
On Tue 17 Apr 2007, Rick Macdougall wrote:
On 4/17/07, Alan DeKok <aland@deployingradius.com> wrote:
Rick Macdougall wrote:
Hi,
We seem to be having the "The maximum number of threads (32) are active" with Freeradius 1.0.3. Version 1.0.1 works just fine.
Upgrade to 1.1.6. It has a whole host of fixes.
Yah, I've already downloaded it in preparation of doing just that. I kind of wanted to stick to an RPM release but it looks like that isn't going to happen.
You mean rpms like the ones maintianed by a member of the FreeRADIUS core team (me) available for Fedora and SUSE at: http://software.opensuse.org/download/network:/aaa/ -- Peter Nixon http://www.peternixon.net/ PGP Key: http://www.peternixon.net/public.asc
On 4/17/07, Alan DeKok <aland@deployingradius.com> wrote:
Rick Macdougall wrote:
Hi,
We seem to be having the "The maximum number of threads (32) are active" with Freeradius 1.0.3. Version 1.0.1 works just fine.
Upgrade to 1.1.6. It has a whole host of fixes.
Hi, Upgraded to 1.1.6 and the problem persists. The maximum number of threads (32) are active, cannot spawn new thread to handle request rad_recv: Access-Request packet from host 206.123.6.28:1645, id=239, length=208 Discarding duplicate request from client aeiusr05:1645 - ID: 239 due to unfinished request 56 $ ./configure --with-gnu-ld --with-threads --with-thread-pool --disable-ltdl-install --with-rlm-sql_mysql-include-dir=/usr/include/mysql --with-mysql-lib-dir=/usr/lib/mysql --with-unixodbc-lib-dir=/usr/lib --with-rlm-dbm-lib-dir=/usr/lib --with-rlm-krb5-include-dir=/usr/kerberos/include --sysconfdir=/etc --prefix=/usr --exec_prefix=/usr --localstatedir=/var --sbindir=/usr/sbin Any other ideas ? Only seems to happen with accounting, no apparent problems with authentication. Regards, Rick
On Wed 18 Apr 2007, Rick Macdougall wrote:
On 4/17/07, Alan DeKok <aland@deployingradius.com> wrote:
Rick Macdougall wrote:
Hi,
We seem to be having the "The maximum number of threads (32) are active" with Freeradius 1.0.3. Version 1.0.1 works just fine.
Upgrade to 1.1.6. It has a whole host of fixes.
Hi,
Upgraded to 1.1.6 and the problem persists.
The maximum number of threads (32) are active, cannot spawn new thread to handle request rad_recv: Access-Request packet from host 206.123.6.28:1645, id=239, length=208 Discarding duplicate request from client aeiusr05:1645 - ID: 239 due to unfinished request 56
$ ./configure --with-gnu-ld --with-threads --with-thread-pool --disable-ltdl-install --with-rlm-sql_mysql-include-dir=/usr/include/mysql --with-mysql-lib-dir=/usr/lib/mysql --with-unixodbc-lib-dir=/usr/lib --with-rlm-dbm-lib-dir=/usr/lib --with-rlm-krb5-include-dir=/usr/kerberos/include --sysconfdir=/etc --prefix=/usr --exec_prefix=/usr --localstatedir=/var --sbindir=/usr/sbin
Any other ideas ?
Only seems to happen with accounting, no apparent problems with authentication.
Yep. Your backend is too slow to keep up. Accounting is inserts and updates... Auth is selects.. BIG difference in speed... Cheers -- Peter Nixon http://www.peternixon.net/ PGP Key: http://www.peternixon.net/public.asc
Yep. Your backend is too slow to keep up. Accounting is inserts and updates... Auth is selects.. BIG difference in speed...
Not a speed issue, the mysql records are inserted within milliseconds of the detail file being written. Running radiusd -xxxxx shows the sql accounting happening almost instantly. And if it was a speed issue, it would affect the older version running on Fedora as well. Just fyi, we are talking about millions of records in the database by month's end, so if it was a slow backend nothing would work, ever. Regards, Rick
Recompiled with --without-threads and it locks up hard on the first accounting request. And when I say locks up hard, I mean not even a kill -9 will stop it, I have to reboot the server. Output from radiusd -xxxx Wed Apr 18 15:43:13 2007 : Debug: radius_xlat: 'INSERT into radacct (RadAcctId, AcctSessionId, AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortT ype, AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic, ConnectInfo_st art, ConnectInfo_stop, AcctInputOctets, AcctOutputOctets, CalledStationId, Calli ngStationId, AcctTerminateCause, ServiceType, FramedProtocol, FramedIPAddress, A cctStartDelay, AcctStopDelay,BellIP,NexxiaName) values('', '51511460', 'f5572cc9 dce0bf42', 'mjbebe@example.com', 'NULL', '206.123.6.24', '787', 'Async', '2007-04-18 15:43:13', '0', '0', 'RADIUS', '', '', '0', '0', '5142842096', '4504613180', '', 'Framed-User', 'PPP', '216.221.44.18', '120', '0','','')' Wed Apr 18 15:43:13 2007 : Debug: rlm_sql (sql1): Reserving sql socket id: 9 Wed Apr 18 15:43:13 2007 : Debug: rlm_sql (sql1): Released sql socket id: 9 Wed Apr 18 15:43:13 2007 : Debug: modsingle[accounting]: returned from sql1 (r lm_sql) for request 15 Wed Apr 18 15:43:13 2007 : Debug: modcall[accounting]: module "sql1" returns o k for request 15 Wed Apr 18 15:43:13 2007 : Debug: modcall: leaving group (returns ok) for reque st 15 Wed Apr 18 15:43:13 2007 : Debug: modsingle[accounting]: calling radutmp (rlm_ radutmp) for request 15 Wed Apr 18 15:43:13 2007 : Debug: radius_xlat: '/var/log/radius/radutmp' Wed Apr 18 15:43:13 2007 : Debug: radius_xlat: 'mjbebe@example.com'
Rick Macdougall wrote:
Recompiled with --without-threads and it locks up hard on the first accounting request. And when I say locks up hard, I mean not even a kill -9 will stop it, I have to reboot the server.
Are you sure your OS isn't buggy? It's a bad problem if "kill -9" doesn't work. Maybe the process had a memory leak, allocated gigs of RAM, and was in the middle of dumping core. For reasons I've never understood, most OS's don't allow core dumping to be interruptible. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
On 4/19/07, Alan DeKok <aland@deployingradius.com> wrote:
Rick Macdougall wrote:
Recompiled with --without-threads and it locks up hard on the first accounting request. And when I say locks up hard, I mean not even a kill -9 will stop it, I have to reboot the server.
Are you sure your OS isn't buggy? It's a bad problem if "kill -9" doesn't work.
Maybe the process had a memory leak, allocated gigs of RAM, and was in the middle of dumping core. For reasons I've never understood, most OS's don't allow core dumping to be interruptible.
Pretty sure it's not the OS, it's a fully updated CentOS 4 distribution running on a Dell 1860 accessing a MySQL server running Fedora Core 3 on Dell 760 (750 maybe ?, not sure. Haven't looked at the MySQL servers in ages). All the other servers accessing the MySQL servers are running the exact same layout, with the same hardware and have no problem accessing MySQL. The same machines were running Fedora Core 3 with FreeRadius 1.0.1 and had no problems connecting. The other servers include vpopmail machines with users stored in MySQL, SpamAssassin machines access bayes and user prefs in MySQL, web machines with php scripts, etc etc. Rick
Ok, I've taken out the SQL accounting completely, left in the SQL authentication and the problem still persists. On accounting packets with threads disabled, the accounting process stops completely after one packet, on accounting packets with threads enabled, the accounts process reports the maximum number of threads has been reached. Attempting to stop radiusd when this situation is reached results in a zombied radiusd. On other thing I noticed running it under strace is that something (perhaps libmysql) is trying to open /etc/my.cnf even though we are using a remote MySQL server. Any ideas now ? Anything else I should be looking at ? Rick
Well, I went through everything in the accounting { } and the problems turns out to be radutmp Any reason this might be a problem. The file gets created but never written to. If I comment it out of the accounting { }, then everything, including mysql records being written, works just fine. Regards, Rick
On Thu 19 Apr 2007, Rick Macdougall wrote:
Well, I went through everything in the accounting { } and the problems turns out to be radutmp
Any reason this might be a problem. The file gets created but never written to. If I comment it out of the accounting { }, then everything, including mysql records being written, works just fine.
Ahh.. Yes. I have seen similar issues long ago with radutmp now that you mention it. I simply delete it by default, so I hadn't noticed it again for years... Cheers -- Peter Nixon http://www.peternixon.net/ PGP Key: http://www.peternixon.net/public.asc
Rick Macdougall wrote:
Well, I went through everything in the accounting { } and the problems turns out to be radutmp
Any reason this might be a problem. The file gets created but never written to. If I comment it out of the accounting { }, then everything, including mysql records being written, works just fine.
Weird. I haven't run into any problems with radutmp on my system. radutmp tries to lock the utmp file, so if one thread gets blocked, it may stop other threads, too. I would double-check the file permissions, etc. on the radutmp file, and on the directory it's in. Or, you may be mounting the radutmp file over NFS. That would explain the process being un-killable when something goes wrong. Most NFS implementations do things like mark the process as being in the kernel when certain NFS operations happen. When NFS blocks, the process can't be killed, because you can't kill the running kernel, right? This is arguably a kernel bug, just like core dumps can't be stopped vi CTRL-C. I've run into both situations in the past. And yes, I've had to reboot my system because some process was using a file over NFS, and something went wrong. The solution is to *not* mount the log directory over NFS. In fact, *all* of the file needed by FreeRADIUS should be on local disk. If they're not, the process may block completely when NFS goes away. During this time, the process will likely be unkillable. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
You are right on with the NFS locking issue. I believe that is exactly the problem, my only concern now is why it happens with CentOS 4.x and not with Fedora Core 3. More info in the morning as I'm currently having a beer (or 4) and watching the Hockey playoffs. Thanks for the help. Regards, Rick PS - If you don't remember who I am check out the old cistron list mailings. On 4/19/07, Alan DeKok <aland@deployingradius.com> wrote:
Rick Macdougall wrote:
Well, I went through everything in the accounting { } and the problems turns out to be radutmp
Any reason this might be a problem. The file gets created but never written to. If I comment it out of the accounting { }, then everything, including mysql records being written, works just fine.
Weird. I haven't run into any problems with radutmp on my system.
radutmp tries to lock the utmp file, so if one thread gets blocked, it may stop other threads, too. I would double-check the file permissions, etc. on the radutmp file, and on the directory it's in.
Or, you may be mounting the radutmp file over NFS. That would explain the process being un-killable when something goes wrong. Most NFS implementations do things like mark the process as being in the kernel when certain NFS operations happen. When NFS blocks, the process can't be killed, because you can't kill the running kernel, right?
This is arguably a kernel bug, just like core dumps can't be stopped vi CTRL-C. I've run into both situations in the past. And yes, I've had to reboot my system because some process was using a file over NFS, and something went wrong.
The solution is to *not* mount the log directory over NFS. In fact, *all* of the file needed by FreeRADIUS should be on local disk. If they're not, the process may block completely when NFS goes away. During this time, the process will likely be unkillable.
Follow up. It is updating/inserting records into the mysql radacct database but it seems that an ACK is not sent back to the remote server and the thread is not released. A minute later the remote server tries again, etc etc until the threds max out at 32. Regards, Rick
Rick Macdougall wrote:
It is updating/inserting records into the mysql radacct database but it seems that an ACK is not sent back to the remote server and the thread is not released. A minute later the remote server tries again, etc etc until the threds max out at 32.
That says that the inserts are *not* succeeding. i.e. they start, but they never stop. This means that the threads handling the requests are blocked, that they never respond to the client, and that new threads get created for new requests until the maximum gets reached. The problem may be that the MySQL libraries are built without threading support, or that they somehow don't work from multiple threads. I would say run it in non-threaded mode (-s) until the problem can be tracked down and fixed. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
participants (3)
-
Alan DeKok -
Peter Nixon -
Rick Macdougall