Different behavior when run with -X and not
hwang at i-fone.net
hwang at i-fone.net
Fri May 25 05:53:52 CEST 2007
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 at 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
>
>
More information about the Freeradius-Users
mailing list