Different behavior when run with -X and not
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.
This archive was generated by a fusion of
Pipermail (Mailman edition) and
MHonArc.