Error: WARNING: Unresponsive child
Hello all, I am continuously getting this error message on my /var/log/radius/radius.log file: Mon Sep 28 18:26:55 2009 : Error: WARNING: Unresponsive child (id 1094719808) for request 24026 (in component accounting module rlm_exec) In effect, I got a timeout on account start and stop which resulted that even the user is able to authenticate and authorize, accounting side fails. I have attached my /etc/raddb/radiusd.conf for more information. My RADIUS machine has the following information: # cat /etc/redhat-release CentOS release 5.2 (Final) # rpm -qa | grep freeradius freeradius-1.1.7-2 # free -m total used free shared buffers cached Mem: 1536 1388 147 0 166 882 -/+ buffers/cache: 338 1197 Swap: 2008 13 1994 # iostat -x Linux 2.6.18-53.el5xen (radius-1) 09/28/2009 /etc/sysconfig/sysstat.ioconf: Malformed 0 field record: --- avg-cpu: %user %nice %system %iowait %steal %idle 8.04 0.00 13.89 0.00 0.00 78.07 Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util xvda 0.00 6.24 0.00 3.15 0.16 75.15 23.86 0.00 0.24 0.07 0.02 # cat /proc/cpuinfo processor : 0 vendor_id : GenuineIntel cpu family : 6 model : 23 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz stepping : 6 cpu MHz : 1994.999 cache size : 6144 KB physical id : 0 siblings : 1 core id : 0 cpu cores : 1 fpu : yes fpu_exception : yes cpuid level : 10 wp : yes flags : fpu tsc msr pae mce cx8 apic mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm syscall nx lm constant_tsc pni monitor ds_cpl vmx tm2 cx16 xtpr lahf_lm bogomips : 4994.09 clflush size : 64 cache_alignment : 64 address sizes : 38 bits physical, 48 bits virtual power management: processor : 1 vendor_id : GenuineIntel cpu family : 6 model : 23 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz stepping : 6 cpu MHz : 1994.999 cache size : 6144 KB physical id : 1 siblings : 1 core id : 0 cpu cores : 1 fpu : yes fpu_exception : yes cpuid level : 10 wp : yes flags : fpu tsc msr pae mce cx8 apic mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm syscall nx lm constant_tsc pni monitor ds_cpl vmx tm2 cx16 xtpr lahf_lm bogomips : 4994.09 clflush size : 64 cache_alignment : 64 address sizes : 38 bits physical, 48 bits virtual power management: processor : 2 vendor_id : GenuineIntel cpu family : 6 model : 23 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz stepping : 6 cpu MHz : 1994.999 cache size : 6144 KB physical id : 2 siblings : 1 core id : 0 cpu cores : 1 fpu : yes fpu_exception : yes cpuid level : 10 wp : yes flags : fpu tsc msr pae mce cx8 apic mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm syscall nx lm constant_tsc pni monitor ds_cpl vmx tm2 cx16 xtpr lahf_lm bogomips : 4994.09 clflush size : 64 cache_alignment : 64 address sizes : 38 bits physical, 48 bits virtual power management: processor : 3 vendor_id : GenuineIntel cpu family : 6 model : 23 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz stepping : 6 cpu MHz : 1994.999 cache size : 6144 KB physical id : 3 siblings : 1 core id : 0 cpu cores : 1 fpu : yes fpu_exception : yes cpuid level : 10 wp : yes flags : fpu tsc msr pae mce cx8 apic mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm syscall nx lm constant_tsc pni monitor ds_cpl vmx tm2 cx16 xtpr lahf_lm bogomips : 4994.09 clflush size : 64 cache_alignment : 64 address sizes : 38 bits physical, 48 bits virtual power management: On my database machine, I have the following information: # cat /etc/redhat-release CentOS release 5 (Final) # rpm -qa | grep MySQL MySQL-shared-community-5.0.67-0.rhel5 MySQL-client-community-5.0.67-0.rhel5 MySQL-server-community-5.0.67-0.rhel5 # free -m total used free shared buffers cached Mem: 3948 3619 328 0 451 2760 -/+ buffers/cache: 406 3541 Swap: 8189 0 8189 # iostat -x Linux 2.6.18-92.1.6.el5 (database-1) 09/28/2009 /etc/sysconfig/sysstat.ioconf: Malformed 0 field record: --- avg-cpu: %user %nice %system %iowait %steal %idle 0.82 0.00 0.06 0.01 0.00 99.10 Device: rrqm/s wrqm/s r/s w/s rsec/s wsec/s avgrq-sz avgqu-sz await svctm %util sda 0.02 10.52 0.04 3.93 3.30 117.51 30.44 0.00 0.55 0.21 0.08 dm-0 0.00 0.00 0.00 0.00 0.00 0.00 1.12 0.00 1.91 1.85 0.00 dm-1 0.00 0.00 0.05 13.98 3.11 113.82 8.33 0.01 0.95 0.05 0.08 drbd0 0.00 0.00 0.02 12.63 0.87 101.04 8.06 0.09 6.98 0.13 0.16 # cat /proc/cpuinfo processor : 0 vendor_id : GenuineIntel cpu family : 6 model : 23 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz stepping : 6 cpu MHz : 1995.005 cache size : 6144 KB physical id : 0 siblings : 4 core id : 0 cpu cores : 4 fpu : yes fpu_exception : yes cpuid level : 10 wp : yes flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm syscall nx lm constant_tsc pni monitor ds_cpl vmx tm2 cx16 xtpr lahf_lm bogomips : 3992.90 clflush size : 64 cache_alignment : 64 address sizes : 38 bits physical, 48 bits virtual power management: processor : 1 vendor_id : GenuineIntel cpu family : 6 model : 23 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz stepping : 6 cpu MHz : 1995.005 cache size : 6144 KB physical id : 1 siblings : 4 core id : 0 cpu cores : 4 fpu : yes fpu_exception : yes cpuid level : 10 wp : yes flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm syscall nx lm constant_tsc pni monitor ds_cpl vmx tm2 cx16 xtpr lahf_lm bogomips : 3990.02 clflush size : 64 cache_alignment : 64 address sizes : 38 bits physical, 48 bits virtual power management: processor : 2 vendor_id : GenuineIntel cpu family : 6 model : 23 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz stepping : 6 cpu MHz : 1995.005 cache size : 6144 KB physical id : 0 siblings : 4 core id : 2 cpu cores : 4 fpu : yes fpu_exception : yes cpuid level : 10 wp : yes flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm syscall nx lm constant_tsc pni monitor ds_cpl vmx tm2 cx16 xtpr lahf_lm bogomips : 3990.00 clflush size : 64 cache_alignment : 64 address sizes : 38 bits physical, 48 bits virtual power management: processor : 3 vendor_id : GenuineIntel cpu family : 6 model : 23 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz stepping : 6 cpu MHz : 1995.005 cache size : 6144 KB physical id : 1 siblings : 4 core id : 2 cpu cores : 4 fpu : yes fpu_exception : yes cpuid level : 10 wp : yes flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm syscall nx lm constant_tsc pni monitor ds_cpl vmx tm2 cx16 xtpr lahf_lm bogomips : 3990.04 clflush size : 64 cache_alignment : 64 address sizes : 38 bits physical, 48 bits virtual power management: processor : 4 vendor_id : GenuineIntel cpu family : 6 model : 23 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz stepping : 6 cpu MHz : 1995.005 cache size : 6144 KB physical id : 0 siblings : 4 core id : 1 cpu cores : 4 fpu : yes fpu_exception : yes cpuid level : 10 wp : yes flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm syscall nx lm constant_tsc pni monitor ds_cpl vmx tm2 cx16 xtpr lahf_lm bogomips : 3990.06 clflush size : 64 cache_alignment : 64 address sizes : 38 bits physical, 48 bits virtual power management: processor : 5 vendor_id : GenuineIntel cpu family : 6 model : 23 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz stepping : 6 cpu MHz : 1995.005 cache size : 6144 KB physical id : 1 siblings : 4 core id : 1 cpu cores : 4 fpu : yes fpu_exception : yes cpuid level : 10 wp : yes flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm syscall nx lm constant_tsc pni monitor ds_cpl vmx tm2 cx16 xtpr lahf_lm bogomips : 3989.98 clflush size : 64 cache_alignment : 64 address sizes : 38 bits physical, 48 bits virtual power management: processor : 6 vendor_id : GenuineIntel cpu family : 6 model : 23 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz stepping : 6 cpu MHz : 1995.005 cache size : 6144 KB physical id : 0 siblings : 4 core id : 3 cpu cores : 4 fpu : yes fpu_exception : yes cpuid level : 10 wp : yes flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm syscall nx lm constant_tsc pni monitor ds_cpl vmx tm2 cx16 xtpr lahf_lm bogomips : 3990.05 clflush size : 64 cache_alignment : 64 address sizes : 38 bits physical, 48 bits virtual power management: processor : 7 vendor_id : GenuineIntel cpu family : 6 model : 23 model name : Intel(R) Xeon(R) CPU E5405 @ 2.00GHz stepping : 6 cpu MHz : 1995.005 cache size : 6144 KB physical id : 1 siblings : 4 core id : 3 cpu cores : 4 fpu : yes fpu_exception : yes cpuid level : 10 wp : yes flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm syscall nx lm constant_tsc pni monitor ds_cpl vmx tm2 cx16 xtpr lahf_lm bogomips : 3990.02 clflush size : 64 cache_alignment : 64 address sizes : 38 bits physical, 48 bits virtual power management: And the output of my "show full processlist" on my MySQL server and the "lsof -ni -P | grep mysql | wc -l" says I have 100 rows. The header output of my mytop command says: MySQL on 192.168.123.25 (5.0.67-community) up 4+16:02:36 [18:27:02] Queries: 2.9M qps: 8 Slow: 0.0 Se/In/Up/De(%): 11/00/00/00 qps now: 7 Slow qps: 0.0 Threads: 104 ( 2/ 89) 30/00/00/00 Key Efficiency: 99.7% Bps in/out: 0.0/ 0.3 Now in/out: 8.4/ 2.5k Thank you in advance for your time. Regards, Muffin
Hi,
Hello all,
I am continuously getting this error message on my /var/log/radius/radius.log file:
Mon Sep 28 18:26:55 2009 : Error: WARNING: Unresponsive child (id 1094719808) for request 24026 (in component accounting module rlm_exec)
In effect, I got a timeout on account start and stop which resulted that even the user is able to authenticate and authorize, accounting side fails.
I have attached my /etc/raddb/radiusd.conf for more information.
<loads of system tech detail snipped> this sort of message means that the child process is taking ages to do what is asked of it. in this case, its accounting and the accounting config is trying to run some external executable which is taking a while to do its thing. i see you are using PERL - there are known issues with PERL and CentOS/RHEL is regards to process start up time - with rlm_exec you are having to start this up and connect etc everything - you'd be better off using the rlm_perl PERL module to do your work - check out the example.pl - see how to call it for the accounting and then just call 'perl' in your accounting config rather than that rlm_exec method. better still - ditch 1.1.x , move to 2.1.x and use a virtual server for accounting with asynchronous buffered access so that accounting doesnt affect your live authentication etc alan
Hello Alan and all, On Mon, Sep 28, 2009 at 6:43 PM, Alan Buxey <A.L.M.Buxey@lboro.ac.uk> wrote:
this sort of message means that the child process is taking ages to do what is asked of it. in this case, its accounting and the accounting config is trying to run some external executable which is taking a while to do its thing.
Previously, this has been working smoothly. Then we changed some configurations on the following devices which currently we are now facing the problem: On the router's RADIUS Authentication and Accounting configurations: - Retry Count from 3 to 10 - Timeout from 3 to 10 On the FreeRADIUS's /etc/raddb/radiusd.conf: - max_request_time from 30 down to 10 On the MySQL's /etc/my.cnf: [mysqld] wait_timeout=3600 connect_timeout=10 interactive_timeout=120 max_allowed_packet=16M skip-name-resolve max_connections=500 thread_cache=256 thread_concurrency=16 Of all the changes that we made, what could be the culprit that made this problem triggered?
i see you are using PERL - there are known issues with PERL and CentOS/RHEL is regards to process start up time - with rlm_exec you are having to start this up and connect etc everything - you'd be better off using the rlm_perl PERL module to do your work...
Noted.
better still - ditch 1.1.x , move to 2.1.x and use a virtual server for accounting with asynchronous buffered access so that accounting doesnt affect your live authentication etc
Noted. Thank you once again. Regards, Muffin
Hi,
Previously, this has been working smoothly. Then we changed some configurations on the following devices which currently we are now
too many changes made at the same time.
- Retry Count from 3 to 10 - Timeout from 3 to 10
so the router now hits the RADIUS 10 times insteda of 3 but has more casuallnes in timeout
- max_request_time from 30 down to 10
so RADIUS responses need to be done in 10 seconds
Of all the changes that we made, what could be the culprit that made this problem triggered?
new devices added to the mix? total number of clients increased? some new system put into place that logs into routers - eg monitoring? alan
Hello Alan and all, On Mon, Sep 28, 2009 at 10:30 PM, Alan Buxey <A.L.M.Buxey@lboro.ac.uk> wrote:
so the router now hits the RADIUS 10 times insteda of 3 but has more casuallnes in timeout
Basically: Retry Count is the maximum number of times that the router retransmits a RADIUS packet to the RADIUS server. In this case, this has been increased from 3 times to 10 times. Timeout is the interval (in seconds) before the router retransmits a RADIUS packet to the RADIUS server. In this case, this has been increased from 3 seconds to 10 seconds.
so RADIUS responses need to be done in 10 seconds
Yes.
new devices added to the mix? total number of clients increased? some new system put into place that logs into routers - eg monitoring?
Basically, the number of subscribers increased. If we do a maintenance window where we swing back and forth the traffic to the router, all the subscribers will hit the router which eventually push all the RADIUS Requests to the RADIUS server in one shot and on which the MySQL backend is choked during that time. Regards, Muffin
Hi,
Retry Count is the maximum number of times that the router retransmits a RADIUS packet to the RADIUS server. In this case, this has been increased from 3 times to 10 times.
Timeout is the interval (in seconds) before the router retransmits a RADIUS packet to the RADIUS server. In this case, this has been increased from 3 seconds to 10 seconds.
..as I said
Basically, the number of subscribers increased. If we do a maintenance window where we swing back and forth the traffic to the router, all the subscribers will hit the router which eventually push all the RADIUS Requests to the RADIUS server in one shot and on which the MySQL backend is choked during that time.
are you doing authentication and accounting via MySQL? did you perform a benchmark of the RADIUS server + MySQL (eg with dumb temp accounts) to check what the loading could be? in my experience, authentication can be done quickly - its usually the accounting that gives the big hit - I would advise FR 2.1.x with buffered accounting to get such packets out of the way of the live authentication service. alan
Hello Alan, On Mon, Sep 28, 2009 at 11:24 PM, Alan Buxey <A.L.M.Buxey@lboro.ac.uk> wrote:
are you doing authentication and accounting via MySQL? did you perform a benchmark of the RADIUS server + MySQL (eg with dumb temp accounts) to check what the loading could be? in my experience, authentication can be done quickly - its usually the accounting that gives the big hit - I would advise FR 2.1.x with buffered accounting to get such packets out of the way of the live authentication service.
Both for authentication and accounting. I will consider your suggestion. Thank you once again. Regards, Muffin
muffin sk wrote:
Basically, the number of subscribers increased. If we do a maintenance window where we swing back and forth the traffic to the router,
What does that mean? You kick all of the users off, and then allow them back on?
all the subscribers will hit the router which eventually push all the RADIUS Requests to the RADIUS server in one shot and on which the MySQL backend is choked during that time.
Well... if the MySQL server can't handle the traffic, no amount of playing with FreeRADIUS will fix it. Fix MySQL. Alan DeKok.
Hello Alan, On Tue, Sep 29, 2009 at 12:35 AM, Alan DeKok <aland@deployingradius.com> wrote:
What does that mean? You kick all of the users off, and then allow them back on?
Just bypass the router and the RADIUS servers to go straight to the Internet.
Well... if the MySQL server can't handle the traffic, no amount of playing with FreeRADIUS will fix it.
Fix MySQL.
The MySQL is almost IDLE already. So I assume, it's not an issue on the MySQL. Regards, Muffin
Basically, the number of subscribers increased. If we do a maintenance window where we swing back and forth the traffic to the router, all the subscribers will hit the router which eventually push all the RADIUS Requests to the RADIUS server in one shot and on which the MySQL backend is choked during that time.
Try using buffered-sql virtual server to separate accounting from authentication. At busy time accounting will lag behind but it will catch up when rush passes. Ivan Kalik Kalik Informatika ISP
Hello Ivan, On Tue, Sep 29, 2009 at 3:14 AM, Ivan Kalik <tnt@kalik.net> wrote:
Try using buffered-sql virtual server to separate accounting from authentication. At busy time accounting will lag behind but it will catch up when rush passes.
Noted. I will check this out then. Thank you. Regards, Muffin
I am continuously getting this error message on my /var/log/radius/radius.log file:
Mon Sep 28 18:26:55 2009 : Error: WARNING: Unresponsive child (id 1094719808) for request 24026 (in component accounting module rlm_exec)
Your perl script isn't working. Ivan Kalik Kalik Informatika ISP
participants (4)
-
Alan Buxey -
Alan DeKok -
Ivan Kalik -
muffin sk