FreeRadius crashed on loading test.
Good day. I want to continue Dinh Pham Cong topic ((FreeRadius crashed on accounting load tests with 1000 concurrent clients - Tue, 10 Nov 2009 01:39:30 -0800 )) I use freeradius 2.1.9 Linux myhost 2.6.26-2-amd64 Some info from radiusd.conf : -------------- max_request_time = 30 cleanup_delay = 5 max_requests = 2048 hostname_lookups = no allow_core_dumps = yes regular_expressions = yes extended_expressions = yes log { destination = files file = ${logdir}/radius.log syslog_facility = daemon stripped_names = no auth = yes auth_badpass = yes auth_goodpass = yes } checkrad = ${sbindir}/checkrad security { max_attributes = 200 reject_delay = 1 status_server = yes } proxy_requests = no $INCLUDE clients.conf thread pool { start_servers = 5 max_servers = 32 min_spare_servers = 3 max_spare_servers = 10 max_requests_per_server = 0 } -------------- I'm using rlm_sql for my own ippool module: database = "mysql" num_sql_socks = 32 I've started ./radius -xxx -f I've prepared huge file with auth requests for sending: Packet-Type = Access-Request NAS-Identifier = "nas1" User-Name = "test" User-Password = "test" NAS-IP-Address = 212.93.99.126 NAS-Port-Type = Virtual Called-Station-Id = "1000" Calling-Station-Id = "37129111111" Service-Type = Framed-User Framed-Protocol = GPRS-PDP-Context Acct-Session-Id = "d45d637e72d54736" Acct-Multi-Session-Id = "d45d637e396391a1" Packet-Type = Access-Request NAS-Identifier = "nas1" User-Name = "test2" User-Password = "test2" NAS-IP-Address = 212.93.99.126 NAS-Port-Type = Virtual Called-Station-Id = "3" Calling-Station-Id = "37126222222" Service-Type = Framed-User Framed-Protocol = GPRS-PDP-Context Acct-Session-Id = "d45d637e5b97ac8e" Acct-Multi-Session-Id = "d45d637e2dc41c4e" and so on then, I've run radclient: cat auth-det.log |/usr/local/freeradius2.1.9/bin/radclient -c 1 -p 500 -q localhost:1812 auth testkey my module process requests too slow (I will discover this problem in few days, this is mysql-db-cluster issues), but this test causes radiusd segmentation fault. I've grabbed the core and look what it shows: Core was generated by `./radiusd -xxx -f'. Program terminated with signal 11, Segmentation fault. [New process 7173] [New process 7180] [New process 7181] [New process 7182] [New process 7183] [New process 7185] [New process 7187] [New process 7188] [New process 7191] [New process 7193] [New process 7196] [New process 7197] [New process 7174] [New process 7199] [New process 7177] [New process 7202] [New process 7203] [New process 7205] [New process 7176] [New process 7175] [New process 7184] [New process 7186] [New process 7189] [New process 7190] [New process 7192] [New process 7194] [New process 7195] [New process 7198] [New process 7200] [New process 7201] [New process 7204] [New process 7206] [New process 7107] #0 request_pre_handler (request=0xb493fc20) at event.c:1769 1769 if (request->packet->dst_port == 0) { (gdb) bt #0 request_pre_handler (request=0xb493fc20) at event.c:1769 #1 0x0806e404 in radius_handle_request (request=0xb493fc20, fun=0x804ef20 <rad_authenticate>) at event.c:3728 #2 0x08066970 in request_handler_thread (arg=0xae9cbf8) at threads.c:493 #3 0xb780e4c0 in start_thread () from /lib/i686/cmov/libpthread.so.0 #4 0xb75b684e in clone () from /lib/i686/cmov/libc.so.6 And here is last breath of my radius (from radius.log) Tue Sep 14 16:44:43 2010 : Info: WARNING: Child is hung for request 16359 in component module . Tue Sep 14 16:44:43 2010 : Info: WARNING: Child is hung for request 16366 in component module . Tue Sep 14 16:44:43 2010 : Info: WARNING: Child is hung for request 16369 in component module . Tue Sep 14 16:44:43 2010 : Info: WARNING: Child is hung for request 16383 in component module . Tue Sep 14 16:44:43 2010 : Debug: Waking up in 0.1 seconds. Tue Sep 14 16:44:43 2010 : Info: Cleaning up request 16169 ID 189 with timestamp +952 Tue Sep 14 16:44:43 2010 : Info: Child is finally responsive for request 14864 Tue Sep 14 16:44:43 2010 : Info: WARNING: Child is hung for request 16165 in component post-auth module lmtsqlippool1. Tue Sep 14 16:44:43 2010 : Info: WARNING: Child is hung for request 16186 in component post-auth module lmtsqlippool1. Tue Sep 14 16:44:43 2010 : Info: WARNING: Child is hung for request 16189 in component post-auth module lmtsqlippool1. *** Tue Sep 14 16:44:43 2010 : Info: WARNING: Child is hung for request 16241 in component post-auth module lmtsqlippool1. Tue Sep 14 16:44:43 2010 : Info: WARNING: Child is hung for request 16243 in component post-auth module lmtsqlippool1. Tue Sep 14 16:44:43 2010 : Debug: Waking up in 0.1 seconds. Tue Sep 14 16:44:43 2010 : Info: Cleaning up request 16223 ID 21 with timestamp +952 Tue Sep 14 16:44:43 2010 : Debug: Waking up in 0.1 seconds. Tue Sep 14 16:44:43 2010 : Info: Cleaning up request 16173 ID 190 with timestamp +952 Tue Sep 14 16:44:43 2010 : Info: WARNING: Child is hung for request 16165 in component post-auth module lmtsqlippool1. Tue Sep 14 16:44:43 2010 : Info: WARNING: Child is hung for request 16186 in component post-auth module lmtsqlippool1. *** Tue Sep 14 16:44:43 2010 : Info: WARNING: Child is hung for request 16241 in component post-auth module lmtsqlippool1. Tue Sep 14 16:44:43 2010 : Info: WARNING: Child is hung for request 16243 in component post-auth module lmtsqlippool1. Tue Sep 14 16:44:43 2010 : Info: Cleaning up request 16174 ID 151 with timestamp +952 Tue Sep 14 16:44:43 2010 : Debug: Waking up in 0.1 seconds. Tue Sep 14 16:44:43 2010 : Info: Cleaning up request 16177 ID 58 with timestamp +952 Tue Sep 14 16:44:44 2010 : Info: Cleaning up request 16181 ID 60 with timestamp +952 Tue Sep 14 16:44:44 2010 : Debug: rlm_sql_mysql: query: COMMIT Tue Sep 14 16:44:44 2010 : Info: [lmtsqlippool1] expand: UPDATE ippool SET active=1, username=%{Calling-Station-Id} WHERE username=0 AND iprange_id IN (2) LIMIT 1 -> UPDATE ippool SET active=1, username=37126333333 WHERE username=0 AND iprange_id IN (2) LIMIT 1 Tue Sep 14 16:44:44 2010 : Debug: rlm_sql_mysql: query: UPDATE ippool SET active=1, username=37126333333 WHERE username=0 AND iprange_id IN (2) LIMIT 1 Tue Sep 14 16:44:44 2010 : Debug: rlm_sql (sql1): Released sql socket id: 19 Tue Sep 14 16:44:44 2010 : Info: ++++[lmtsqlippool1] returns ok Tue Sep 14 16:44:44 2010 : Info: +++- policy redundant returns ok Tue Sep 14 16:44:44 2010 : Info: ++- else else returns ok Tue Sep 14 16:44:44 2010 : Info: } # server localonly Tue Sep 14 16:44:44 2010 : Info: request 16165 was cancelled. Tue Sep 14 16:44:44 2010 : Info: Finished request 16165. Tue Sep 14 16:44:44 2010 : Debug: Going to the next request Tue Sep 14 16:44:44 2010 : Debug: Thread 1 waiting to be assigned a request Tue Sep 14 16:44:44 2010 : Debug: Thread 1 got semaphore Tue Sep 14 16:44:44 2010 : Debug: Thread 1 handling request 16244, (20 handled so far) Looks like a bug, am I right?
Hi,
I'm using rlm_sql for my own ippool module: database = "mysql" num_sql_socks = 32
a while back I pointed out that anything over 10 seems to really kill the system - we found it ticked along okay with 10 sockets per thread anyway.... but then we found, generally, that MySQL sucks for concurrent inserts and updates and queries which RADIUS does tonnes of, so we ditched it for PostgresQL and havent looked back since. alan
Konstantin Chekushin wrote:
Good day. I want to continue Dinh Pham Cong topic ((FreeRadius crashed on accounting load tests with 1000 concurrent clients - Tue, 10 Nov 2009 01:39:30 -0800 ))
I use freeradius 2.1.9
Linux myhost 2.6.26-2-amd64
Some info from radiusd.conf :
<sigh> This isn't requested, and isn't necessary.
I'm using rlm_sql for my own ippool module: database = "mysql" num_sql_socks = 32
And it can't keep up with the load.
I've started ./radius -xxx -f
"radius"? Not "radiusd"? And why not "radiusd -X" as documented *everywhere* ?
I've prepared huge file with auth requests for sending:
Which no one asked for, and isn't necessary.
my module process requests too slow (I will discover this problem in few days, this is mysql-db-cluster issues), but this test causes radiusd segmentation fault. I've grabbed the core and look what it shows:
This should be fixed in 2.1.10. Alan DeKok.
Quoting *Alan DeKok <aland@deployingradius.com>*:
Konstantin Chekushin wrote:
I've started ./radius -xxx -f
"radius"? Not "radiusd"? And why not "radiusd -X" as documented *everywhere* ? -X = -sfxx -l stdout . But, I didn't wanted single mode for my loading test. So I used "./radiusd -xxx -f" (the letter was missed in a previous mail) And I've used -xxx to make my my own debug3 visible with timestamp (without changing your log.c). In fact, your logging architecture logic is rather strange. But this is another topic.
I've prepared huge file with auth requests for sending:
Which no one asked for, and isn't necessary.
my module process requests too slow (I will discover this problem in few days, this is mysql-db-cluster issues), but this test causes radiusd segmentation fault. I've grabbed the core and look what it shows:
This should be fixed in 2.1.10. Good. Thanks for the answer.
participants (3)
-
Alan Buxey -
Alan DeKok -
Konstantin Chekushin