(Bump) - Nathan Miller
-----Original Message----- From: [EMAIL PROTECTED] [mailto:[EMAIL PROTECTED] On Behalf Of Nate M Sent: Tuesday, October 12, 2004 12:34 PM To: [EMAIL PROTECTED] Subject: Exec-Program-Wait & Unresponsive Child Errors Good morning. I've got some weirdness with freeradius 1.0.1 (same results in previous versions). Test systems are x86_64 and i386 Fedora Core 2 machines (2.6.8.1). Same tests on older redhat9 machine (2.6.4) do not have the same issue. My users entry looks like: DEFAULT Auth-Type := Accept Exec-Program-Wait = "/etc/raddb/scripts/pre_auth.sh", Fall-Through = Yes There are no other authentication mechanisms enabled, all requests go to pre_auth.sh. The script is configured to only exit 0 (although I get identical results when rejecting requests with exit 1) and pass attributes. Same results w/o attributes. This issue only happens when running in standard mode, in debug -x or debug -xx mode. The problem can be duplicated over and over on various platforms. The problem does not happen in -X debug mode. Problem also does not happen in single thread mode. When sending test radius packets it will authenticate the first always, then depending on the frequency of the incoming packets it will hang usually once they are sent at a rate of apx 1+/second. Sending packets continuously at 1 each 2 seconds it will never have any problem. It appears to be in the following entry that it is hanging right before it gets to the "Exec-Program: returned: 0" section. Almost as if it's not catching the return value of the external program. Later (10-15 seconds) it drops that client as unresponsive. Attaching 2 -xx debug reports, the first is the request which bombs, the 2nd is a good request. Any help in further debugging or solving this issue is greatly appreciated. ###### REQUEST WHICH BOMBS ###### Going to the next request Thread 7 waiting to be assigned a request rad_recv: Access-Request packet from host 63.228.227.6:2300, id=67, length=53 Waking up in 2 seconds... Thread 8 got semaphore Thread 8 handling request 6, (1 handled so far) User-Name = "[EMAIL PROTECTED]" User-Password = "xxxxx" rad_rmspace_pair: User-Name now '[EMAIL PROTECTED]' Processing the authorize section of radiusd.conf modcall: entering group authorize for request 6 modcall[authorize]: module "preprocess" returns ok for request 6 modcall[authorize]: module "attr_filter" returns noop for request 6 rlm_realm: No '#' in User-Name = "[EMAIL PROTECTED]", looking up realm NULL rlm_realm: No such realm "NULL" modcall[authorize]: module "prefix" returns noop for request 6 rlm_realm: Looking up realm "visp.net" for User-Name = "[EMAIL PROTECTED]" rlm_realm: No such realm "visp.net" modcall[authorize]: module "suffix" returns noop for request 6 users: Matched DEFAULT at 36 modcall[authorize]: module "files" returns ok for request 6 modcall: group authorize returns ok for request 6 rad_check_password: Found Auth-Type Accept rad_check_password: Auth-Type = Accept, accepting the user radius_xlat: '/etc/raddb/scripts/pre_auth.sh' Exec-Program: /etc/raddb/scripts/pre_auth.sh Re-wait 2 Exec-Program output: Idle-Timeout = 1140, Session-Timeout = 28800, Service-Type = Framed-User, Framed-IP-Address = 255.255.255.254, Framed-Protocol = PPP, Simultaneous-Use = 1, Exec-Program-Wait: value-pairs: Idle-Timeout = 1140, Session-Timeout = 28800, Service-Type = Framed-User, Framed-IP-Address = 255.255.255.254, Framed-Protocol = PPP, Simultaneous-Use = 1, --- Walking the entire request list --- Cleaning up request 0 ID 61 with timestamp 416c1c9c Cleaning up request 1 ID 62 with timestamp 416c1c9c Cleaning up request 2 ID 63 with timestamp 416c1c9c Waking up in 1 seconds... Threads: total/active/spare threads = 15/1/14 --- Walking the entire request list --- Cleaning up request 3 ID 64 with timestamp 416c1c9d Cleaning up request 4 ID 65 with timestamp 416c1c9d Cleaning up request 5 ID 66 with timestamp 416c1c9d Waking up in 5 seconds... --- Walking the entire request list --- Waking up in 5 seconds... --- Walking the entire request list --- Waking up in 5 seconds... --- Walking the entire request list --- WARNING: Unresponsive child (id 1145158576) for request 6 Server rejecting request 6. Sending Access-Reject of id 67 to 63.228.227.6:2300 Waking up in 5 seconds... --- Walking the entire request list --- #### STRACE OUTPUT at time of error #### radius_xlat: '/etc/raddb/scripts/pre_auth.sh' Exec-Program: /etc/raddb/scripts/pre_auth.sh Exec-Program output: Idle-Timeout = 1140, Session-Timeout = 28800, Service-Type = Framed-User, Framed-IP-Address = 255.255.255.254, Framed-Protocol = PPP, Simultaneous-Use = 1, Exec-Program-Wait: value-pairs: Idle-Timeout = 1140, Session-Timeout = 28800, Service-Type = Framed-User, Framed-IP-Address = 255.255.255.254, Framed-Protocol = PPP, Simultaneous-Use = 1, ) = 0 (Timeout) time(NULL) = 1097605809 time(NULL) = 1097605809 write(1, "--- Walking the entire request l"..., 40--- Walking the entire request list --- ) = 40 ###### REQUEST WHICH WORKS PROPERLY ###### Thread 6 waiting to be assigned a request Re-wait 2 rad_recv: Access-Request packet from host 63.228.227.6:2299, id=66, length=53 Waking up in 2 seconds... Thread 7 got semaphore Thread 7 handling request 5, (1 handled so far) User-Name = "[EMAIL PROTECTED]" User-Password = "xxxxx" rad_rmspace_pair: User-Name now '[EMAIL PROTECTED]' Processing the authorize section of radiusd.conf modcall: entering group authorize for request 5 modcall[authorize]: module "preprocess" returns ok for request 5 modcall[authorize]: module "attr_filter" returns noop for request 5 rlm_realm: No '#' in User-Name = "[EMAIL PROTECTED]", looking up realm NULL rlm_realm: No such realm "NULL" modcall[authorize]: module "prefix" returns noop for request 5 rlm_realm: Looking up realm "visp.net" for User-Name = "[EMAIL PROTECTED]" rlm_realm: No such realm "visp.net" modcall[authorize]: module "suffix" returns noop for request 5 users: Matched DEFAULT at 36 modcall[authorize]: module "files" returns ok for request 5 modcall: group authorize returns ok for request 5 rad_check_password: Found Auth-Type Accept rad_check_password: Auth-Type = Accept, accepting the user radius_xlat: '/etc/raddb/scripts/pre_auth.sh' Exec-Program: /etc/raddb/scripts/pre_auth.sh Exec-Program output: Idle-Timeout = 1140, Session-Timeout = 28800, Service-Type = Framed-User, Framed-IP-Address = 255.255.255.254, Framed-Protocol = PPP, Simultaneous-Use = 1, Exec-Program-Wait: value-pairs: Idle-Timeout = 1140, Session-Timeout = 28800, Service-Type = Framed-User, Framed-IP-Address = 255.255.255.254, Framed-Protocol = PPP, Simultaneous-Use = 1, Exec-Program: returned: 0 Login OK: [EMAIL PROTECTED]/xxxxx] (from client natewkstation port 0) Sending Access-Accept of id 66 to 63.228.227.6:2299 Idle-Timeout = 1140 Session-Timeout = 28800 Service-Type = Framed-User Framed-IP-Address = 255.255.255.254 Framed-Protocol = PPP Finished request 5 ---------------------------------- Nathan Miller - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html