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?