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?
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html