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