Again: Major impact on authentication!
Hello, Thanks to everyone! I'm using Oracle just for radcheck/radacct and PostgreSQL for radippool only. No, Mr. Peter, no one is using dial-up admin nor anything alike when the problem occurs, just pure auth (without acct). I've disabled the cron.hourly job and the problem appeared again after some hours. A simple radiusd restart solves the problem. As this causes impact, I can't afford to do this all the time just to debug, but I think I gonna run a script to capture all the radiusd -xxx messages, so when the behaviour starts, I can see what's happening. Also, it's important to note that this server is the proxy radius and those error messages appear: Error: Discarding duplicate request from client ERX-1:50000 - ID: 115 due to unfinished request 32 Info: The maximum number of threads (32) are active, cannot spawn new thread to handle request Error: WARNING: Unresponsive child (id 1315006816) for request 105 With acct: Error: rlm_sql (sql) in sql_accounting: stop packet with zero session length. [user 'joe.black@foo.com', nas '10.10.2.1'] Error: Internal error processing module entry Thank you. On 2/6/07, Peter Nixon <listuser@peternixon.net> wrote:
On Mon 05 Feb 2007 13:05, A.L.M.Buxey@lboro.ac.uk wrote:
Hi,
Freeradius 1.1.4 is randomly losing connection to both databases and it's causing total loss in the authentication process:
from a historical perspective you may find that is wasnt the 1.1.4 upgrade that has broken things - your database may have finally become too big and unwieldy. this has certainly been the case in many such cases. I would check how long your database queries/inserts are taking. perhaps vacuum/optimise the tables, move/drop older entries, create better KEYs for the purposes you need.
The _random_ problems don't coincide with a user running a usage report from a web interface by any chance do they??
Regards --
Peter Nixon http://www.peternixon.net/ PGP Key: http://www.peternixon.net/public.asc
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Guilherme Franco wrote:
Also, it's important to note that this server is the proxy radius and those error messages appear:
Error: Discarding duplicate request from client ERX-1:50000 - ID: 115 due to unfinished request 32
Info: The maximum number of threads (32) are active, cannot spawn new thread to handle request
Error: WARNING: Unresponsive child (id 1315006816) for request 105
All of those messages are caused by the same problem: something is preventing the server from working. Find out what it is, and fix the problem.
Error: Internal error processing module entry
It might have helped if you posted that message earlier. Internal errors ALWAYS indicate something bad happening. In this case, you're running 1.1.x, and somehow the data structures in the server have gotten corrupted. That's a VERY likely reason why the server is broken. As yo how to see what's going wrong, run the server under valgrind. Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog
Thanks Mr. DeKok, I've already downloaded valgrind, just need to setup everything in a time where the user won't suffer from the downtime. Mr. Marshall, the only transaction is in rlm_sqlippool. Thanks. On 2/6/07, Alan DeKok <aland@deployingradius.com> wrote:
Guilherme Franco wrote:
Also, it's important to note that this server is the proxy radius and those error messages appear:
Error: Discarding duplicate request from client ERX-1:50000 - ID: 115 due to unfinished request 32
Info: The maximum number of threads (32) are active, cannot spawn new thread to handle request
Error: WARNING: Unresponsive child (id 1315006816) for request 105
All of those messages are caused by the same problem: something is preventing the server from working. Find out what it is, and fix the problem.
Error: Internal error processing module entry
It might have helped if you posted that message earlier. Internal errors ALWAYS indicate something bad happening.
In this case, you're running 1.1.x, and somehow the data structures in the server have gotten corrupted. That's a VERY likely reason why the server is broken.
As yo how to see what's going wrong, run the server under valgrind.
Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Tue 06 Feb 2007 15:27, Alan DeKok wrote:
Guilherme Franco wrote:
Also, it's important to note that this server is the proxy radius and those error messages appear:
Error: Discarding duplicate request from client ERX-1:50000 - ID: 115 due to unfinished request 32
Info: The maximum number of threads (32) are active, cannot spawn new thread to handle request
Error: WARNING: Unresponsive child (id 1315006816) for request 105
Do you by any chance have a "statefull" firewall between your radius server and database?
All of those messages are caused by the same problem: something is preventing the server from working. Find out what it is, and fix the problem.
Error: Internal error processing module entry
It might have helped if you posted that message earlier. Internal errors ALWAYS indicate something bad happening.
In this case, you're running 1.1.x, and somehow the data structures in the server have gotten corrupted. That's a VERY likely reason why the server is broken.
As yo how to see what's going wrong, run the server under valgrind.
There _may_ be a problem with rlm_sqlippool in 1.1.4 (it is marked as an unstable module in 1.1.4) If at all possible please consider updating to CVS head as there has been allot of work on sqlippool and the postgresql driver. In-fact the latest version of sqlippool _should_ work on Oracle (which I remember you wanted to do previously) although I have not tested this functionality. (rlm_sqlippool in 1.1.4 relies on a bug in rlm_sql_postgresql to work, hence the reason it doesn't work properly with other DBs) Alternatively you could backport the cvs head version of sqlippool to 1.1.4 which is something I have been considering for the 1.1.5 release but have yet to find the time to do (but would happily accept donations to do so :-) -- Peter Nixon http://www.peternixon.net/ PGP Key: http://www.peternixon.net/public.asc
Hello Mr. Nixon! No, the radius server and the DB server are connected in the same switch, using gigabit UTP, resulting in 0.090ms RTT. The proxy server is also directly connected to this switch. I've been using CVS builds mainly because the rlm_sqlippool was under development with constant updates done by you. The last one I've used was freeradius-server-snapshot-20070120.tar.bz2 but the same behaviour appeared, then I've switched to 1.1.4. Humm Oracle support would be great! But I remember that in the previous builds, I had to remove the BEGIN from allocate-begin in rlm_sqlippool.c and recompile it because Oracle understands BEGIN as a function/procedure/transaction start and the next steps taken by rlm_sqlippool didn't fit in the correct structure (missing END; and other statements). That way, no errors raised but sqlippool wouldn't recognize the IP queried by the SELECT then. Mr. Peter, also importantly, as we have both static and dynamic ippools, two instances of sqlippool was running, namely sqlippool DYNAMIC and sqlippool STATIC, called in this order by radiusd. The allocate-find was not working correctly, not giving the same static IPs to the user every time, so I've decided to remove one sqlippool instance and I've created the following function: CREATE OR REPLACE FUNCTION FOOBAR(user text, pool text, nas text) RETURNS inet AS $$ declare ip_temp inet := null; BEGIN if pool = 'DYNAMIC' then select framedipaddress into ip_temp from radippool where expiry_time < 'now'::timestamp(0) and pool_name = pool ORDER BY (username <> user), (callingstationid <> nas), expiry_time LIMIT 1 FOR UPDATE; return ip_temp; end if; if pool <> 'DYNAMIC' then select framedipaddress into ip_temp from radippool where username = user and pool_name = pool; if ip_temp is not null then return ip_temp; end if; if ip_temp is null then select framedipaddress into ip_temp from radippool where expiry_time < 'now'::timestamp(0) and username = '' and pool_name = pool LIMIT 1 FOR UPDATE; UPDATE radippool SET username = user where framedipaddress = ip_temp; return ip_temp; end if; END IF; END; $$ LANGUAGE plpgsql; That way, allocate-find became just allocate-find = "select FOOBAR('%{User-Name}','%{check:Pool-Name}','%{Calling-Station-Id}')" No fail-over would occur anymore, the function works in less than 50ms, the static ip of the user is permanently written in the DB so I think it became better this way, at least for me. This setup was running fine since October 2006, until now that things started to freak out. Thank you! On 2/6/07, Peter Nixon <listuser@peternixon.net> wrote:
On Tue 06 Feb 2007 15:27, Alan DeKok wrote:
Guilherme Franco wrote:
Also, it's important to note that this server is the proxy radius and those error messages appear:
Error: Discarding duplicate request from client ERX-1:50000 - ID: 115 due to unfinished request 32
Info: The maximum number of threads (32) are active, cannot spawn new thread to handle request
Error: WARNING: Unresponsive child (id 1315006816) for request 105
Do you by any chance have a "statefull" firewall between your radius server and database?
All of those messages are caused by the same problem: something is preventing the server from working. Find out what it is, and fix the problem.
Error: Internal error processing module entry
It might have helped if you posted that message earlier. Internal errors ALWAYS indicate something bad happening.
In this case, you're running 1.1.x, and somehow the data structures in the server have gotten corrupted. That's a VERY likely reason why the server is broken.
As yo how to see what's going wrong, run the server under valgrind.
There _may_ be a problem with rlm_sqlippool in 1.1.4 (it is marked as an unstable module in 1.1.4) If at all possible please consider updating to CVS head as there has been allot of work on sqlippool and the postgresql driver. In-fact the latest version of sqlippool _should_ work on Oracle (which I remember you wanted to do previously) although I have not tested this functionality. (rlm_sqlippool in 1.1.4 relies on a bug in rlm_sql_postgresql to work, hence the reason it doesn't work properly with other DBs)
Alternatively you could backport the cvs head version of sqlippool to 1.1.4 which is something I have been considering for the 1.1.5 release but have yet to find the time to do (but would happily accept donations to do so :-)
--
Peter Nixon http://www.peternixon.net/ PGP Key: http://www.peternixon.net/public.asc
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Tue 06 Feb 2007 18:40, Guilherme Franco wrote:
Hello Mr. Nixon!
No, the radius server and the DB server are connected in the same switch, using gigabit UTP, resulting in 0.090ms RTT.
The proxy server is also directly connected to this switch.
I've been using CVS builds mainly because the rlm_sqlippool was under development with constant updates done by you. The last one I've used was freeradius-server-snapshot-20070120.tar.bz2 but the same behaviour appeared, then I've switched to 1.1.4.
OK. Well we have added a few more things this week. The last commit was just over an hour ago for: http://bugs.freeradius.org/show_bug.cgi?id=414
Humm Oracle support would be great! But I remember that in the previous builds, I had to remove the BEGIN from allocate-begin in rlm_sqlippool.c and recompile it because Oracle understands BEGIN as a function/procedure/transaction start and the next steps taken by rlm_sqlippool didn't fit in the correct structure (missing END; and other statements). That way, no errors raised but sqlippool wouldn't recognize the IP queried by the SELECT then.
Oh. I had forgotten this issue with oracle. There are 2 different issues that may be causing this. 1) The bug in sqlippool that relied on a bug in the postgresql driver both of which are now fixed. 2) Transactions may either be "BEGIN" and "END" or the newer SQL99 standard of "START TRANSACTION" and "COMMIT". Postgresql (and it seems MySQL from reading the docs) support both forms and for some reason sqlippool starts the transaction with BEGIN and ends it with COMMIT which is actually a mixture of transaction dialects. Can you please confirm whether on not Oracle supports the SQL99 syntax? If so I will change all the "BEGIN"s to "START TRANSACTION". If it does not I will do the opposite.
Mr. Peter, also importantly, as we have both static and dynamic ippools, two instances of sqlippool was running, namely sqlippool DYNAMIC and sqlippool STATIC, called in this order by radiusd.
The allocate-find was not working correctly, not giving the same static IPs to the user every time, so I've decided to remove one sqlippool instance and I've created the following function:
CREATE OR REPLACE FUNCTION FOOBAR(user text, pool text, nas text) RETURNS inet AS $$ declare ip_temp inet := null; BEGIN if pool = 'DYNAMIC' then select framedipaddress into ip_temp from radippool where expiry_time < 'now'::timestamp(0) and pool_name = pool ORDER BY (username <> user), (callingstationid <> nas), expiry_time LIMIT 1 FOR UPDATE; return ip_temp; end if;
if pool <> 'DYNAMIC' then select framedipaddress into ip_temp from radippool where username = user and pool_name = pool;
if ip_temp is not null then return ip_temp; end if;
if ip_temp is null then select framedipaddress into ip_temp from radippool where expiry_time < 'now'::timestamp(0) and username = '' and pool_name = pool LIMIT 1 FOR UPDATE; UPDATE radippool SET username = user where framedipaddress = ip_temp; return ip_temp; end if;
END IF;
END; $$ LANGUAGE plpgsql;
That way, allocate-find became just allocate-find = "select FOOBAR('%{User-Name}','%{check:Pool-Name}','%{Calling-Station-Id}')"
ok.
No fail-over would occur anymore, the function works in less than 50ms, the static ip of the user is permanently written in the DB so I think it became better this way, at least for me.
The patches I committed today and yesterday improved the exit codes which should make failover more flexible.
This setup was running fine since October 2006, until now that things started to freak out.
I am sorry to hear that. I really am not sure what the problem could be... Regards -- Peter Nixon http://www.peternixon.net/ PGP Key: http://www.peternixon.net/public.asc
Mr. Peter, On 2/6/07, Peter Nixon <listuser@peternixon.net> wrote:
OK. Well we have added a few more things this week. The last commit was just over an hour ago for: http://bugs.freeradius.org/show_bug.cgi?id=414
Yes, I've been watching the progress in "Automatic report from sources (radiusd)" in the devel list, thanks.
Can you please confirm whether on not Oracle supports the SQL99 syntax? If so I will change all the "BEGIN"s to "START TRANSACTION". If it does not I will do the opposite.
Oracle automatically treats every changing aspect of the tables as a transaction so there's no "START TRANSACTION" command in it. Every BEGIN needs to have a END; and a dot "." in after END;. Basically you need the Transaction so you can do the FOR UPDATE command to lock that framedipaddress temporally. In Oracle thou need no BEGIN, just do the "select ... for update" and then the COMMIT; in the end.
The patches I committed today and yesterday improved the exit codes which should make failover more flexible.
I don't know if the new CVS will suit for me because with the PostgreSQL function that I've made there's no need to use 2 sqlippool instances. Again, I don't have anything against the module fail-over, I'm just using the function mainly because the native allocate-find didn't fixed the users IP correctly for me (also one module is a bit quicker). A quick valgrind run detected some errors in rlm_sql for the oracle connection. Gonna do a massive debugging after midnight to see if there's something weird going on. Thank you and everyone for the prompt answers!
On Tue 06 Feb 2007 21:35, Guilherme Franco wrote:
Mr. Peter,
On 2/6/07, Peter Nixon <listuser@peternixon.net> wrote:
OK. Well we have added a few more things this week. The last commit was just over an hour ago for: http://bugs.freeradius.org/show_bug.cgi?id=414
Yes, I've been watching the progress in "Automatic report from sources (radiusd)" in the devel list, thanks.
Can you please confirm whether on not Oracle supports the SQL99 syntax? If so I will change all the "BEGIN"s to "START TRANSACTION". If it does not I will do the opposite.
Oracle automatically treats every changing aspect of the tables as a transaction so there's no "START TRANSACTION" command in it. Every BEGIN needs to have a END; and a dot "." in after END;. Basically you need the Transaction so you can do the FOR UPDATE command to lock that framedipaddress temporally. In Oracle thou need no BEGIN, just do the "select ... for update" and then the COMMIT; in the end.
OK. Well, the start and end transaction commands may be overridden in sqlippool.conf in the same manner as the other sql queries. Simply define "allocate-begin" and "allocate-commit" etc. When you have have time could you please sqlippool with oracle and let me know if it works or not?
The patches I committed today and yesterday improved the exit codes which should make failover more flexible.
I don't know if the new CVS will suit for me because with the PostgreSQL function that I've made there's no need to use 2 sqlippool instances. Again, I don't have anything against the module fail-over, I'm just using the function mainly because the native allocate-find didn't fixed the users IP correctly for me (also one module is a bit quicker).
sure. stored procedures rock :-)
A quick valgrind run detected some errors in rlm_sql for the oracle connection. Gonna do a massive debugging after midnight to see if there's something weird going on.
Yeah. the oracle driver really needs to extra love and attention. I have deployed it a couple of times for customers and made some very minor updates to it to support Oracle 10 but an Oracle dev really needs to torture check it all with valgrind and make sure that the reconnect and everything is working correctly.
Thank you and everyone for the prompt answers!
You are welcome. -- Peter Nixon http://www.peternixon.net/ PGP Key: http://www.peternixon.net/public.asc
Hello, Of course, I can test sqlippool with Oracle. I just need to do it after midnight because the earlier problems with Freeradius were so dramatic that I've received orders to remove freeradius and install some commercial software. Also, those tests would need to be synthetic ones, since the default allocate-find does not get nor fix the static IP's for me and the current users would lose their static IPs. With the cron.hourly job to do a "service radiusd restart", the environment flows smooth. Removing the job and letting radiusd working for a few hours creeps everything. Considering this, how come those problems could be related to slow DB, if by simply reloading freeradius things start to work good? Now, even with the cron.hourly job, radiusd hanged sometimes, needing a kill -9 to free it. Some valgrind messages related to the oracle backend in radiusd initialization: ==11562== Conditional jump or move depends on uninitialised value(s) ==11562== at 0x615F6B2: ztvo5ke (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x5EEC3DC: kpu8lgn (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x5EEA628: kpuauthxa (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x5EEA031: kpuauth (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x5E179A0: kpulon (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x5F45A3F: OCILogon (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x5A6B131: sql_init_socket (sql_oracle.c:158) ==11562== by 0x59667B1: connect_single_socket (sql.c:70) ==11562== by 0x5966907: sql_init_socketpool (sql.c:131) ==11562== by 0x5964EC5: rlm_sql_instantiate (rlm_sql.c:695) ==11562== by 0x40C31A: find_module_instance (in /usr/local/sbin/radiusd) ==11562== by 0x40DA4C: (within /usr/local/sbin/radiusd) ==11562== Syscall param write(buf) points to uninitialised byte(s) ==11562== at 0x397270B012: __write_nocancel (in /lib64/tls/libpthread- 2.3.4.so) ==11562== by 0x61FF1A9: snttwrite (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x61FBEBE: nttwr (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x6132971: nsntwrn (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x6138B41: nspsend (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x611A93C: nsdofls (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x611600E: nsdo (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x611543A: nsdosend (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x6151207: nioqrc (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x62BEB4E: ttcdrv (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x6159AD7: nioqwa (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x5F80BA6: upirtrc (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== Address 0x4F0AFE7 is 47 bytes inside a block of size 2,070 alloc'd ==11562== at 0x490631D: calloc (vg_replace_malloc.c:279) ==11562== by 0x61C52C1: nsbGet (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x61C50F8: nsballoc (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x615566C: niotns (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x61D63AA: nigcall (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x615A399: osncon (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x5E168EF: kpuadef (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x5F814E7: upiini (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x5F5E619: upiah0 (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x5E162EF: kpuatch (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x5E17873: kpulon (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x5F45A3F: OCILogon (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== Use of uninitialised value of size 8 ==11562== at 0x61F5CFA: ztceaencbk (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x61F0193: ztcebn (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x61EE024: ztcen (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x61EDE14: ztceenc (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x615F72E: ztvo5ke (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x5EEC3DC: kpu8lgn (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x5EEA628: kpuauthxa (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x5EEA031: kpuauth (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x5E179A0: kpulon (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x5F45A3F: OCILogon (in /usr/local/instantclient_10_2/libclntsh.so.10.1) ==11562== by 0x5A6B131: sql_init_socket (sql_oracle.c:158) ==11562== by 0x59667B1: connect_single_socket (sql.c:70) Thank you!
participants (3)
-
Alan DeKok -
Guilherme Franco -
Peter Nixon