FreeRadius crashed on loading test.

Konstantin Chekushin koch2 at inbox.lv
Tue Sep 14 16:46:00 CEST 2010 

 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?
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.freeradius.org/pipermail/freeradius-users/attachments/20100914/6d3326e2/attachment.html>

More information about the Freeradius-Users mailing list