I did some more testing. It happens only on Access-Reject. No problem when sending Access-Accept. I ran it as "radiusd -fxxyz -l stdout", which is only one difference(spawn child processes) from "radiusd -X". In the following log, it finished processing the request and waited for about 15 second to send out the reject packets. Please help me to solve the problem. Thanks. Exec-Program output: h323-return-code=3 Exec-Program-Wait: value-pairs: h323-return-code=3 Exec-Program: returned: 1 Delaying request 2 for 1 seconds Finished request 2 Going to the next request Thread 3 waiting to be assigned a request ======================================================================= ========================= about 15 seconds later======================= ======================================================================= rad_recv: Access-Request packet from host 10.1.2.182:1812, id=82, length=108 Sending Access-Reject of id 82 to 10.1.2.182 port 1812 --- Walking the entire request list --- freeradius-users-bounces+hwang=i-fone.net@lists.freeradius.org wrote:
I'm running FreeRADIUS 1.1.6 on a CentOS 3 box. I'm using Exec-Program-Wait to call my external program. When I run it in debug mode with "radiusd -X", the process goes fine. But when I run it in normal mode, the server didn't response the first time. It responses when the NAS timed out and send the access request again (I can see it with Ethereal). My external program will output debug info and I can see it has processed the request the first time. When NAS re-sending the request the RADIUS is responding with "cached" result because my program only run once. I was running version 1.0.1 and I thought it might be the server so I upgrade to 1.1.6 but no luck here. Below is the "radiusd -X" log(which is OK) because I don't know how to get the same log in non-debug mode, the one that have problem is second access-request(request 2). Please tell me how can I find where the problem is and fix it. Thanks for your help.
Chih-Chen Hwang
ps. I only modified users, acct_user and clients.conf after installation.
Starting - reading configuration files ... reread_config: reading radiusd.conf Config: including file: /usr/local/freeradius-1.1.6/etc/raddb/proxy.conf Config: including file: /usr/local/freeradius-1.1.6/etc/raddb/clients.conf Config: including file: /usr/local/freeradius-1.1.6/etc/raddb/snmp.conf Config: including file: /usr/local/freeradius-1.1.6/etc/raddb/eap.conf Config: including file: /usr/local/freeradius-1.1.6/etc/raddb/sql.conf main: prefix = "/usr/local/freeradius-1.1.6" main: localstatedir = "/usr/local/freeradius-1.1.6/var" main: logdir = "/usr/local/freeradius-1.1.6/var/log/radius" main: libdir = "/usr/local/freeradius-1.1.6/lib" main: radacctdir = "/usr/local/freeradius-1.1.6/var/log/radius/radacct" main: hostname_lookups = no main: snmp = no main: max_request_time = 30 main: cleanup_delay = 5 main: max_requests = 1024 main: delete_blocked_requests = 0 main: port = 0 main: allow_core_dumps = no main: log_stripped_names = no main: log_file = "/usr/local/freeradius-1.1.6/var/log/radius/radius.log" main: log_auth = no main: log_auth_badpass = no main: log_auth_goodpass = no main: pidfile = "/usr/local/freeradius-1.1.6/var/run/radiusd/radiusd.pid" main: user = "(null)" main: group = "(null)" main: usercollide = no main: lower_user = "no" main: lower_pass = "no" main: nospace_user = "no" main: nospace_pass = "no" main: checkrad = "/usr/local/freeradius-1.1.6/sbin/checkrad" main: proxy_requests = yes proxy: retry_delay = 5 proxy: retry_count = 3 proxy: synchronous = no proxy: default_fallback = yes proxy: dead_time = 120 proxy: post_proxy_authorize = no proxy: wake_all_if_all_dead = no security: max_attributes = 200 security: reject_delay = 1 security: status_server = no main: debug_level = 0 read_config_files: reading dictionary read_config_files: reading naslist Using deprecated naslist file. Support for this will go away soon. read_config_files: reading clients read_config_files: reading realms radiusd: entering modules setup Module: Library search path is /usr/local/freeradius-1.1.6/lib Module: Loaded exec exec: wait = yes exec: program = "(null)" exec: input_pairs = "request" exec: output_pairs = "(null)" exec: packet_type = "(null)" rlm_exec: Wait=yes but no output defined. Did you mean output=none? Module: Instantiated exec (exec) Module: Loaded expr Module: Instantiated expr (expr) Module: Loaded PAP pap: encryption_scheme = "crypt" pap: auto_header = yes Module: Instantiated pap (pap) Module: Loaded CHAP Module: Instantiated chap (chap) Module: Loaded MS-CHAP mschap: use_mppe = yes mschap: require_encryption = no mschap: require_strong = no mschap: with_ntdomain_hack = no mschap: passwd = "(null)" mschap: ntlm_auth = "(null)" Module: Instantiated mschap (mschap) Module: Loaded System unix: cache = no unix: passwd = "(null)" unix: shadow = "(null)" unix: group = "(null)" unix: radwtmp = "/usr/local/freeradius-1.1.6/var/log/radius/radwtmp" unix: usegroup = no unix: cache_reload = 600 Module: Instantiated unix (unix) Module: Loaded eap eap: default_eap_type = "md5" eap: timer_expire = 60 eap: ignore_unknown_eap_types = no eap: cisco_accounting_username_bug = no rlm_eap: Loaded and initialized type md5 rlm_eap: Loaded and initialized type leap gtc: challenge = "Password: " gtc: auth_type = "PAP" rlm_eap: Loaded and initialized type gtc mschapv2: with_ntdomain_hack = no rlm_eap: Loaded and initialized type mschapv2 Module: Instantiated eap (eap) Module: Loaded preprocess preprocess: huntgroups = "/usr/local/freeradius-1.1.6/etc/raddb/huntgroups" preprocess: hints = "/usr/local/freeradius-1.1.6/etc/raddb/hints" preprocess: with_ascend_hack = no preprocess: ascend_channels_per_line = 23 preprocess: with_ntdomain_hack = no preprocess: with_specialix_jetstream_hack = no preprocess: with_cisco_vsa_hack = no preprocess: with_alvarion_vsa_hack = no Module: Instantiated preprocess (preprocess) Module: Loaded realm realm: format = "suffix" realm: delimiter = "@" realm: ignore_default = no realm: ignore_null = no Module: Instantiated realm (suffix) Module: Loaded files files: usersfile = "/usr/local/freeradius-1.1.6/etc/raddb/users" files: acctusersfile = "/usr/local/freeradius-1.1.6/etc/raddb/acct_users" files: preproxy_usersfile = "/usr/local/freeradius-1.1.6/etc/raddb/preproxy_users" files: compat = "no" Module: Instantiated files (files) Module: Loaded Acct-Unique-Session-Id acct_unique: key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port" Module: Instantiated acct_unique (acct_unique) Module: Loaded detail detail: detailfile = "/usr/local/freeradius-1.1.6/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d" detail: detailperm = 384 detail: dirperm = 493 detail: locking = no Module: Instantiated detail (detail) Module: Loaded radutmp radutmp: filename = "/usr/local/freeradius-1.1.6/var/log/radius/radutmp" radutmp: username = "%{User-Name}" radutmp: case_sensitive = yes radutmp: check_with_nas = yes radutmp: perm = 384 radutmp: callerid = yes Module: Instantiated radutmp (radutmp) Listening on authentication *:1812 Listening on accounting *:1813 Ready to process requests. rad_recv: Accounting-Request packet from host 10.1.2.182:1813, id=91, length=198 NAS-IP-Address = 10.1.2.182 NAS-Port-Type = Async User-Name = "111" Called-Station-Id = "0227130985" Calling-Station-Id = "886227130985" Acct-Status-Type = Start Service-Type = Dialout-Framed-User h323-gw-id = "111" h323-conf-id = "3023024-20070523144854" h323-call-origin = "answer" h323-call-type = "VOIP" h323-setup-time = "06:48:54.912 UTC Wed May 23 2007" Acct-Session-Id = "00000024" Acct-Delay-Time = 0 Processing the preacct section of radiusd.conf modcall: entering group preacct for request 0 modcall[preacct]: module "preprocess" returns noop for request 0 rlm_acct_unique: WARNING: Attribute NAS-Port was not found in request, unique ID MAY be inconsistent rlm_acct_unique: Hashing ',Client-IP-Address = 10.1.2.182,NAS-IP-Address = 10.1.2.182,Acct-Session-Id = "00000024",User-Name = "111"' rlm_acct_unique: Acct-Unique-Session-ID = "f5de261a872f9626". modcall[preacct]: module "acct_unique" returns ok for request 0 rlm_realm: No '@' in User-Name = "111", looking up realm NULL rlm_realm: No such realm "NULL" modcall[preacct]: module "suffix" returns noop for request 0 acct_users: Matched entry DEFAULT at line 19 modcall[preacct]: module "files" returns ok for request 0 modcall: leaving group preacct (returns ok) for request 0 Processing the accounting section of radiusd.conf modcall: entering group accounting for request 0 radius_xlat: '/usr/local/freeradius-1.1.6/var/log/radius/radacct/10.1.2.182/detail-20070523' rlm_detail: /usr/local/freeradius-1.1.6/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /usr/local/freeradius-1.1.6/var/log/radius/radacct/10.1.2.182/detail-20070523 modcall[accounting]: module "detail" returns ok for request 0 modcall[accounting]: module "unix" returns noop for request 0 radius_xlat: '/usr/local/freeradius-1.1.6/var/log/radius/radutmp' radius_xlat: '111' rlm_radutmp: No NAS-Port seen. Cannot do anything. rlm_radumtp: WARNING: checkrad will probably not work! modcall[accounting]: module "radutmp" returns noop for request 0 modcall: leaving group accounting (returns ok) for request 0 Exec-Program output: Exec-Program: returned: 0 Sending Accounting-Response of id 91 to 10.1.2.182 port 1813 Finished request 0 Going to the next request --- Walking the entire request list --- Waking up in 6 seconds... rad_recv: Access-Request packet from host 10.1.2.182:1816, id=92, length=106 NAS-IP-Address = 10.1.2.182 NAS-Port-Type = Async Service-Type = Authenticate-Only User-Name = "A001" h323-conf-id = "3023024-20070523144854" Calling-Station-Id = "886227130985" User-Password = "111" Processing the authorize section of radiusd.conf modcall: entering group authorize for request 1 modcall[authorize]: module "preprocess" returns ok for request 1 modcall[authorize]: module "chap" returns noop for request 1 modcall[authorize]: module "mschap" returns noop for request 1 rlm_realm: No '@' in User-Name = "A001", looking up realm NULL rlm_realm: No such realm "NULL" modcall[authorize]: module "suffix" returns noop for request 1 rlm_eap: No EAP-Message, not doing EAP modcall[authorize]: module "eap" returns noop for request 1 users: Matched entry DEFAULT at line 53 modcall[authorize]: module "files" returns ok for request 1 rlm_pap: Found existing Auth-Type, not changing it. modcall[authorize]: module "pap" returns noop for request 1 modcall: leaving group authorize (returns ok) for request 1 rad_check_password: Found Auth-Type Accept rad_check_password: Auth-Type = Accept, accepting the user Exec-Program output: h323-return-code=0, h323-billing-model=1, h323-credit-amount=10.30 Exec-Program-Wait: value-pairs: h323-return-code=0, h323-billing-model=1, h323-credit-amount=10.30 Exec-Program: returned: 0 Sending Access-Accept of id 92 to 10.1.2.182 port 1816 h323-return-code = "0" h323-billing-model = "1" h323-credit-amount = "10.30" Finished request 1 Going to the next request --- Walking the entire request list --- Waking up in 5 seconds... --- Walking the entire request list --- Cleaning up request 0 ID 91 with timestamp 4653e3d6 Waking up in 1 seconds... --- Walking the entire request list --- Cleaning up request 1 ID 92 with timestamp 4653e3d7 Nothing to do. Sleeping until we see a request. rad_recv: Access-Request packet from host 10.1.2.182:1812, id=93, length=104 NAS-IP-Address = 10.1.2.182 NAS-Port-Type = Async User-Name = "A001" h323-conf-id = "3023024-20070523144854" Called-Station-Id = "80" Calling-Station-Id = "886227130985" User-Password = "111" Processing the authorize section of radiusd.conf modcall: entering group authorize for request 2 modcall[authorize]: module "preprocess" returns ok for request 2 modcall[authorize]: module "chap" returns noop for request 2 modcall[authorize]: module "mschap" returns noop for request 2 rlm_realm: No '@' in User-Name = "A001", looking up realm NULL rlm_realm: No such realm "NULL" modcall[authorize]: module "suffix" returns noop for request 2 rlm_eap: No EAP-Message, not doing EAP modcall[authorize]: module "eap" returns noop for request 2 users: Matched entry DEFAULT at line 53 modcall[authorize]: module "files" returns ok for request 2 rlm_pap: Found existing Auth-Type, not changing it. modcall[authorize]: module "pap" returns noop for request 2 modcall: leaving group authorize (returns ok) for request 2 rad_check_password: Found Auth-Type Accept rad_check_password: Auth-Type = Accept, accepting the user Exec-Program output: h323-return-code=5, Exec-Program-Wait: value-pairs: h323-return-code=5, Exec-Program: returned: 1 Delaying request 2 for 1 seconds Finished request 2 Going to the next request --- Walking the entire request list --- Waking up in 1 seconds... --- Walking the entire request list --- Waking up in 1 seconds... --- Walking the entire request list --- Sending Access-Reject of id 93 to 10.1.2.182 port 1812 Waking up in 4 seconds... rad_recv: Accounting-Request packet from host 10.1.2.182:1813, id=94, length=345 NAS-IP-Address = 10.1.2.182 NAS-Port-Type = Async User-Name = "A001" Called-Station-Id = "0227130985" Calling-Station-Id = "886227130985" Acct-Status-Type = Stop Service-Type = Dialout-Framed-User h323-gw-id = "111" h323-conf-id = "3023024-20070523144854" h323-call-origin = "answer" h323-call-type = "VOIP" h323-setup-time = "06:48:54.912 UTC Wed May 23 2007" h323-connect-time = "06:48:54.912 UTC Wed May 23 2007" h323-disconnect-time = "06:49:06.819 UTC Wed May 23 2007" h323-disconnect-cause = "16" h323-voice-quality = "0" h323-remote-address = "10.1.5.67" Acct-Session-Id = "00000024" Acct-Input-Octets = 0 Acct-Output-Octets = 0 Acct-Input-Packets = 0 Acct-Output-Packets = 0 Acct-Session-Time = 12 Acct-Delay-Time = 0 Processing the preacct section of radiusd.conf modcall: entering group preacct for request 3 modcall[preacct]: module "preprocess" returns noop for request 3 rlm_acct_unique: WARNING: Attribute NAS-Port was not found in request, unique ID MAY be inconsistent rlm_acct_unique: Hashing ',Client-IP-Address = 10.1.2.182,NAS-IP-Address = 10.1.2.182,Acct-Session-Id = "00000024",User-Name = "A001"' rlm_acct_unique: Acct-Unique-Session-ID = "01924388eb093203". modcall[preacct]: module "acct_unique" returns ok for request 3 rlm_realm: No '@' in User-Name = "A001", looking up realm NULL rlm_realm: No such realm "NULL" modcall[preacct]: module "suffix" returns noop for request 3 acct_users: Matched entry DEFAULT at line 19 modcall[preacct]: module "files" returns ok for request 3 modcall: leaving group preacct (returns ok) for request 3 Processing the accounting section of radiusd.conf modcall: entering group accounting for request 3 radius_xlat: '/usr/local/freeradius-1.1.6/var/log/radius/radacct/10.1.2.182/detail-20070523' rlm_detail: /usr/local/freeradius-1.1.6/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d expands to /usr/local/freeradius-1.1.6/var/log/radius/radacct/10.1.2.182/detail-20070523 modcall[accounting]: module "detail" returns ok for request 3 modcall[accounting]: module "unix" returns noop for request 3 radius_xlat: '/usr/local/freeradius-1.1.6/var/log/radius/radutmp' radius_xlat: 'A001' rlm_radutmp: No NAS-Port seen. Cannot do anything. rlm_radumtp: WARNING: checkrad will probably not work! modcall[accounting]: module "radutmp" returns noop for request 3 modcall: leaving group accounting (returns ok) for request 3 Exec-Program output: Exec-Program: returned: 0 Sending Accounting-Response of id 94 to 10.1.2.182 port 1813 Finished request 3 Going to the next request --- Walking the entire request list --- Waking up in 2 seconds... --- Walking the entire request list --- Cleaning up request 2 ID 93 with timestamp 4653e3de Waking up in 4 seconds... --- Walking the entire request list --- Cleaning up request 3 ID 94 with timestamp 4653e3e2 Nothing to do. Sleeping until we see a request.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html