Hi Milan, Sorry~ I don't describ my architecture more detail. NAS (Aptilo) --- FreeRADIUS --- JuniperSBR (Funk) (FreeRadius proxy to JuniperSBR) The error message occurred between FreeRADIUS and JuniperSBR. In my thinking, there is no secret error in Accounting-Request why I got the secret error in Accounting-Response. Rio 2007/5/23, Milan Holub <holub@thenet.ch>:

Hi Rio,

what type of NAS are you using? I've experienced similar behaviour with nocat software.

The problem was that the NAS did not generate correct packet signature according to rfc.

I have a simple patch to freeradius to bypass checking of signature of accounting packets. Although the correct way is to fix your NAS to create the signature according to rfc.

Anyway I can send you the patch for testing if needed.

Regards

Milan Holub holub (at) thenet (dot) ch

-------------------------------------- TheNet-Internet Services AG, im Bernertechnopark, Morgenstr. 129 CH-3018, Bern, Switzerland 031 998 4333, Fax 031 998 4330 http://www.thenet.ch http://wlan.thenet.ch --------------------------------------

- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

I have checked all secrets and they are the same. Not all Accounting-Response with invalid signature. This error message occurred in sometime. It's a very strange. Rio 2007/5/23, Alex French <alex@evilal.com>:

On 23/05/07, Rio Yang <rioyang.tw@gmail.com> wrote:

...

NAS (Aptilo) --- FreeRADIUS --- JuniperSBR (Funk)

(FreeRadius proxy to JuniperSBR)

The error message occurred between FreeRADIUS and JuniperSBR.

But then you need to set the same shared secret on the FreeRadius server and the JuniperSBR, nothing to do with the NAS.

Alex - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html

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

Hi Alan, Thanks for your explanation. Do you know when will it happen ? Rio 2007/5/25, Alan Dekok <aland@deployingradius.com>:

...

I got the following message from my radius.log.

Wed May 23 16:39:11 2007 : Error: Received Accounting-Response packet from 172.16.1.1:1813 with invalid signature (err=2)! (Shared secret is incorrect.) Wed May 23 16:39:11 2007 : Error: Reply from home server 172.16.1.1:1813

Rio Yang wrote: -

...

ID: 180 arrived too late for request 2515449. Try increasing 'retry_delay' or 'max_request_time'

This happens sometimes in versions before 1.1.5. Upgrade.

Alan DeKok. -- http://deployingradius.com - The web site of the book http://deployingradius.com/blog/ - The blog - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html