Hi All (warning, big/verbose email below),
First of all, quick summary of setup:
- Stock Debian Sarge
- Clean freeradius 1.1.1 package downloaded yesterday. Built using standard
dpkg-buildpackage from source.
- Stock config files, with appropriate SQL bits uncommented for
freeradius-mysql to work (see bottom of email).
So, generally, it works fine - However, I'm experiencing a problem where
whenever an Access-Reject is sent, the response is VERY slow (ie: >30
seconds). This happens if it's a formal Access-Reject via radgroupcheck or
just wrong password or whatever (anything that would result in an
Access-Reject).
Access-Accept is instant/perfect, it's only any Access-Reject. And yes,
reject_delay is on its standard setting of 1.
Now, the bit that baffled me was I couldn't replicate it in debug mode
(freeradius -X). At least, until I worked out it only occurs when freeradius
is run normally. If you pass the -s flag (Do not spawn child processes), it
works perfectly with a 1 second Access-Reject delay; if you set it to spawn
child processes, it appears the reject only gets sent when the request times
out (or something).
See below for full output of a working and non-working example:
Run without child processes:
--------------Working----------------
/usr/sbin/freeradius -sfxxyz
Starting - reading configuration files ...
reread_config: reading radiusd.conf
Config: including file: /etc/freeradius/proxy.conf
Config: including file: /etc/freeradius/clients.conf
Config: including file: /etc/freeradius/snmp.conf
Config: including file: /etc/freeradius/eap.conf
Config: including file: /etc/freeradius/sql.conf
main: prefix = "/usr"
main: localstatedir = "/var"
main: logdir = "/var/log/freeradius"
main: libdir = "/usr/lib/freeradius"
main: radacctdir = "/var/log/freeradius/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 = "/var/log/freeradius/radius.log"
main: log_auth = yes
main: log_auth_badpass = yes
main: log_auth_goodpass = no
main: pidfile = "/var/run/freeradius/freeradius.pid"
main: user = "freerad"
main: group = "freerad"
main: usercollide = no
main: lower_user = "no"
main: lower_pass = "no"
main: nospace_user = "no"
main: nospace_pass = "no"
main: checkrad = "/usr/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/lib/freeradius
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 = "clear"
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: authtype = "MS-CHAP"
mschap: ntlm_auth = "(null)"
Module: Instantiated mschap (mschap)
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 = "/etc/freeradius/huntgroups"
preprocess: hints = "/etc/freeradius/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
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 SQL
sql: driver = "rlm_sql_mysql"
sql: server = "localhost"
sql: port = ""
sql: login = "freeradius"
sql: password = "xxxxxx"
sql: radius_db = "freeradius"
sql: acct_table = "radacct"
sql: acct_table2 = "radacct"
sql: authcheck_table = "radcheck"
sql: authreply_table = "radreply"
sql: groupcheck_table = "radgroupcheck"
sql: groupreply_table = "radgroupreply"
sql: usergroup_table = "usergroup"
sql: nas_table = "nas"
sql: dict_table = "dictionary"
sql: sqltrace = no
sql: sqltracefile = "/var/log/freeradius/sqltrace.sql"
sql: readclients = yes
sql: deletestalesessions = yes
sql: num_sql_socks = 5
sql: sql_user_name = "%{User-Name}"
sql: default_user_profile = ""
sql: query_on_not_found = no
sql: authorize_check_query = "SELECT id, UserName, Attribute, Value, op
FROM radcheck WHERE Username = '%{SQL-User-Name}' ORDER
BY id"
sql: authorize_reply_query = "SELECT id, UserName, Attribute, Value, op
FROM radreply WHERE Username = '%{SQL-User-Name}' ORDER
BY id"
sql: authorize_group_check_query = "SELECT
radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupche
ck.Value,radgroupcheck.op FROM radgroupcheck,usergroup WHERE
usergroup.Username = '%{SQL-User-Name}' AND usergroup.GroupName =
radgroupcheck.GroupName ORDER BY radgroupcheck.id"
sql: authorize_group_reply_query = "SELECT
radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgrouprep
ly.Value,radgroupreply.op FROM radgroupreply,usergroup WHERE
usergroup.Username = '%{SQL-User-Name}' AND usergroup.GroupName =
radgroupreply.GroupName ORDER BY radgroupreply.id"
sql: accounting_onoff_query = "UPDATE radacct SET AcctStopTime='%S',
AcctSessionTime=unix_timestamp('%S') - unix_timestamp(AcctStartTime),
AcctTerminateCause='%{Acct-Terminate-Cause}', AcctStopDelay =
'%{Acct-Delay-Time}' WHERE AcctSessionTime=0 AND AcctStopTime=0 AND
NASIPAddress= '%{NAS-IP-Address}' AND AcctStartTime <= '%S'"
sql: accounting_update_query = "UPDATE radacct SET
FramedIPAddress = '%{Framed-IP-Address}', AcctSessionTime =
'%{Acct-Session-Time}', AcctInputOctets = '%{Acct-Input-Octets}',
AcctOutputOctets = '%{Acct-Output-Octets}' WHERE AcctSessionId =
'%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}'
AND NASIPAddress= '%{NAS-IP-Address}'"
sql: accounting_update_query_alt = "INSERT into radacct (AcctSessionId,
AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType,
AcctStartTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start,
AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId,
ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay)
values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}',
'%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}',
'%{NAS-Port-Type}', DATE_SUB('%S',INTERVAL (%{Acct-Session-Time:-0} +
%{Acct-Delay-Time:-0}) SECOND), '%{Acct-Session-Time}', '%{Acct-Authentic}',
'', '%{Acct-Input-Octets}', '%{Acct-Output-Octets}', '%{Called-Station-Id}',
'%{Calling-Station-Id}', '%{Service-Type}', '%{Framed-Protocol}',
'%{Framed-IP-Address}', '0')"
sql: accounting_start_query = "INSERT into radacct (AcctSessionId,
AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType,
AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic,
ConnectInfo_start, ConnectInfo_stop, AcctInputOctets, AcctOutputOctets,
CalledStationId, CallingStationId, AcctTerminateCause, ServiceType,
FramedProtocol, FramedIPAddress, AcctStartDelay, AcctStopDelay)
values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}',
'%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}',
'%{NAS-Port-Type}', '%S', '0', '0', '%{Acct-Authentic}', '%{Connect-Info}',
'', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '',
'%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}',
'%{Acct-Delay-Time}', '0')"
sql: accounting_start_query_alt = "UPDATE radacct SET AcctStartTime = '%S',
AcctStartDelay = '%{Acct-Delay-Time}', ConnectInfo_start = '%{Connect-Info}'
WHERE AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}'
AND NASIPAddress = '%{NAS-IP-Address}'"
sql: accounting_stop_query = "UPDATE radacct SET AcctStopTime = '%S',
AcctSessionTime = '%{Acct-Session-Time}', AcctInputOctets =
'%{Acct-Input-Octets}', AcctOutputOctets = '%{Acct-Output-Octets}',
AcctTerminateCause = '%{Acct-Terminate-Cause}', AcctStopDelay =
'%{Acct-Delay-Time}', ConnectInfo_stop = '%{Connect-Info}' WHERE
AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' AND
NASIPAddress = '%{NAS-IP-Address}'"
sql: accounting_stop_query_alt = "INSERT into radacct (AcctSessionId,
AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType,
AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic,
ConnectInfo_start, ConnectInfo_stop, AcctInputOctets, AcctOutputOctets,
CalledStationId, CallingStationId, AcctTerminateCause, ServiceType,
FramedProtocol, FramedIPAddress, AcctStartDelay, AcctStopDelay)
values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}',
'%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}',
'%{NAS-Port-Type}', DATE_SUB('%S', INTERVAL (%{Acct-Session-Time:-0} +
%{Acct-Delay-Time:-0}) SECOND), '%S', '%{Acct-Session-Time}',
'%{Acct-Authentic}', '', '%{Connect-Info}', '%{Acct-Input-Octets}',
'%{Acct-Output-Octets}', '%{Called-Station-Id}', '%{Calling-Station-Id}',
'%{Acct-Terminate-Cause}', '%{Service-Type}', '%{Framed-Protocol}',
'%{Framed-IP-Address}', '0', '%{Acct-Delay-Time}')"
sql: group_membership_query = "SELECT GroupName FROM usergroup WHERE
UserName='%{SQL-User-Name}'"
sql: connect_failure_retry_delay = 60
sql: simul_count_query = "SELECT COUNT(*) FROM radacct WHERE
UserName='%{SQL-User-Name}' AND AcctStopTime = 0"
sql: simul_verify_query = "SELECT RadAcctId, AcctSessionId, UserName,
NASIPAddress, NASPortId, FramedIPAddress, CallingStationId, FramedProtocol
FROM radacct WHERE UserName='%{SQL-User-Name}' AND AcctStopTime = 0"
sql: postauth_table = "radpostauth"
sql: postauth_query = "INSERT into radpostauth (id, user, pass, reply,
date) values ('', '%{User-Name}', '%{User-Password:-Chap-Password}',
'%{reply:Packet-Type}', NOW())"
sql: safe-characters =
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked
rlm_sql (sql): Attempting to connect to freeradius@localhost:/freeradius
rlm_sql (sql): starting 0
rlm_sql (sql): Attempting to connect rlm_sql_mysql #0
rlm_sql_mysql: Starting connect to MySQL server for #0
rlm_sql (sql): Connected new DB handle, #0
rlm_sql (sql): starting 1
rlm_sql (sql): Attempting to connect rlm_sql_mysql #1
rlm_sql_mysql: Starting connect to MySQL server for #1
rlm_sql (sql): Connected new DB handle, #1
rlm_sql (sql): starting 2
rlm_sql (sql): Attempting to connect rlm_sql_mysql #2
rlm_sql_mysql: Starting connect to MySQL server for #2
rlm_sql (sql): Connected new DB handle, #2
rlm_sql (sql): starting 3
rlm_sql (sql): Attempting to connect rlm_sql_mysql #3
rlm_sql_mysql: Starting connect to MySQL server for #3
rlm_sql (sql): Connected new DB handle, #3
rlm_sql (sql): starting 4
rlm_sql (sql): Attempting to connect rlm_sql_mysql #4
rlm_sql_mysql: Starting connect to MySQL server for #4
rlm_sql (sql): Connected new DB handle, #4
rlm_sql (sql): - generate_sql_clients
rlm_sql (sql): Query: SELECT * FROM nas
rlm_sql (sql): Reserving sql socket id: 4
rlm_sql (sql): Read entry
nasname=office.xxxx.com.au,shortname=office-nas,secret=xxxxxx
rlm_sql (sql): Adding client 218.xxx.xxx.xxx (office-nas) to clients list
rlm_sql (sql): Released sql socket id: 4
Module: Instantiated sql (sql)
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 files
files: usersfile = "/etc/freeradius/users"
files: acctusersfile = "/etc/freeradius/acct_users"
files: preproxy_usersfile = "/etc/freeradius/preproxy_users"
files: compat = "no"
Module: Instantiated files (files)
Module: Loaded detail
detail: detailfile =
"/var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d"
detail: detailperm = 384
detail: dirperm = 493
detail: locking = no
Module: Instantiated detail (detail)
Module: Loaded System
unix: cache = no
unix: passwd = "(null)"
unix: shadow = "/etc/shadow"
unix: group = "(null)"
unix: radwtmp = "/var/log/freeradius/radwtmp"
unix: usegroup = no
unix: cache_reload = 600
Module: Instantiated unix (unix)
Module: Loaded radutmp
radutmp: filename = "/var/log/freeradius/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: Access-Request packet from host 218.xxx.xxx.xxx:2011, id=102,
length=69
User-Name = "johnsmith(a)xxxx.com.au"
User-Password = "xxxxxx"
Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 0
modcall[authorize]: module "preprocess" returns ok for request 0
modcall[authorize]: module "chap" returns noop for request 0
modcall[authorize]: module "mschap" returns noop for request 0
rlm_realm: Looking up realm "xxxx.com.au" for User-Name =
"johnsmith(a)xxxx.com.au"
rlm_realm: No such realm "xxxx.com.au"
modcall[authorize]: module "suffix" returns noop for request 0
rlm_eap: No EAP-Message, not doing EAP
modcall[authorize]: module "eap" returns noop for request 0
radius_xlat: 'johnsmith(a)xxxx.com.au'
rlm_sql (sql): sql_set_user escaped user --> 'johnsmith(a)xxxx.com.au'
radius_xlat: 'SELECT id, UserName, Attribute, Value, op FROM
radcheck WHERE Username = 'johnsmith(a)xxxx.com.au' ORDER
BY id'
rlm_sql (sql): Reserving sql socket id: 3
radius_xlat: 'SELECT
radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupche
ck.Value,radgroupcheck.op FROM radgroupcheck,usergroup WHERE
usergroup.Username = 'johnsmith(a)xxxx.com.au' AND usergroup.GroupName =
radgroupcheck.GroupName ORDER BY radgroupcheck.id'
radius_xlat: 'SELECT id, UserName, Attribute, Value, op FROM
radreply WHERE Username = 'johnsmith(a)xxxx.com.au' ORDER
BY id'
radius_xlat: 'SELECT
radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgrouprep
ly.Value,radgroupreply.op FROM radgroupreply,usergroup WHERE
usergroup.Username = 'johnsmith(a)xxxx.com.au' AND usergroup.GroupName =
radgroupreply.GroupName ORDER BY radgroupreply.id'
rlm_sql (sql): Released sql socket id: 3
modcall[authorize]: module "sql" returns ok for request 0
modcall: leaving group authorize (returns ok) for request 0
rad_check_password: Found Auth-Type Reject
rad_check_password: Auth-Type = Reject, rejecting user
auth: Failed to validate the user.
Login incorrect: [johnsmith(a)xxxx.com.au/xxxxxx] (from client office-nas port
0)
Delaying request 0 for 1 seconds
Finished request 0
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 102 to 218.xxx.xxx.xxx port 2011
Reply-Message := "Account Suspended"
Waking up in 4 seconds...
-------------------------------------
Run WITH child processes:
--------------Broken-----------------
/usr/sbin/freeradius -fxxyz
Starting - reading configuration files ...
reread_config: reading radiusd.conf
Config: including file: /etc/freeradius/proxy.conf
Config: including file: /etc/freeradius/clients.conf
Config: including file: /etc/freeradius/snmp.conf
Config: including file: /etc/freeradius/eap.conf
Config: including file: /etc/freeradius/sql.conf
main: prefix = "/usr"
main: localstatedir = "/var"
main: logdir = "/var/log/freeradius"
main: libdir = "/usr/lib/freeradius"
main: radacctdir = "/var/log/freeradius/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 = "/var/log/freeradius/radius.log"
main: log_auth = yes
main: log_auth_badpass = yes
main: log_auth_goodpass = no
main: pidfile = "/var/run/freeradius/freeradius.pid"
main: user = "freerad"
main: group = "freerad"
main: usercollide = no
main: lower_user = "no"
main: lower_pass = "no"
main: nospace_user = "no"
main: nospace_pass = "no"
main: checkrad = "/usr/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/lib/freeradius
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 = "clear"
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: authtype = "MS-CHAP"
mschap: ntlm_auth = "(null)"
Module: Instantiated mschap (mschap)
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 = "/etc/freeradius/huntgroups"
preprocess: hints = "/etc/freeradius/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
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 SQL
sql: driver = "rlm_sql_mysql"
sql: server = "localhost"
sql: port = ""
sql: login = "freeradius"
sql: password = "xxxxxx"
sql: radius_db = "freeradius"
sql: acct_table = "radacct"
sql: acct_table2 = "radacct"
sql: authcheck_table = "radcheck"
sql: authreply_table = "radreply"
sql: groupcheck_table = "radgroupcheck"
sql: groupreply_table = "radgroupreply"
sql: usergroup_table = "usergroup"
sql: nas_table = "nas"
sql: dict_table = "dictionary"
sql: sqltrace = no
sql: sqltracefile = "/var/log/freeradius/sqltrace.sql"
sql: readclients = yes
sql: deletestalesessions = yes
sql: num_sql_socks = 5
sql: sql_user_name = "%{User-Name}"
sql: default_user_profile = ""
sql: query_on_not_found = no
sql: authorize_check_query = "SELECT id, UserName, Attribute, Value, op
FROM radcheck WHERE Username = '%{SQL-User-Name}' ORDER
BY id"
sql: authorize_reply_query = "SELECT id, UserName, Attribute, Value, op
FROM radreply WHERE Username = '%{SQL-User-Name}' ORDER
BY id"
sql: authorize_group_check_query = "SELECT
radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupche
ck.Value,radgroupcheck.op FROM radgroupcheck,usergroup WHERE
usergroup.Username = '%{SQL-User-Name}' AND usergroup.GroupName =
radgroupcheck.GroupName ORDER BY radgroupcheck.id"
sql: authorize_group_reply_query = "SELECT
radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgrouprep
ly.Value,radgroupreply.op FROM radgroupreply,usergroup WHERE
usergroup.Username = '%{SQL-User-Name}' AND usergroup.GroupName =
radgroupreply.GroupName ORDER BY radgroupreply.id"
sql: accounting_onoff_query = "UPDATE radacct SET AcctStopTime='%S',
AcctSessionTime=unix_timestamp('%S') - unix_timestamp(AcctStartTime),
AcctTerminateCause='%{Acct-Terminate-Cause}', AcctStopDelay =
'%{Acct-Delay-Time}' WHERE AcctSessionTime=0 AND AcctStopTime=0 AND
NASIPAddress= '%{NAS-IP-Address}' AND AcctStartTime <= '%S'"
sql: accounting_update_query = "UPDATE radacct SET
FramedIPAddress = '%{Framed-IP-Address}', AcctSessionTime =
'%{Acct-Session-Time}', AcctInputOctets = '%{Acct-Input-Octets}',
AcctOutputOctets = '%{Acct-Output-Octets}' WHERE AcctSessionId =
'%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}'
AND NASIPAddress= '%{NAS-IP-Address}'"
sql: accounting_update_query_alt = "INSERT into radacct (AcctSessionId,
AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType,
AcctStartTime, AcctSessionTime, AcctAuthentic, ConnectInfo_start,
AcctInputOctets, AcctOutputOctets, CalledStationId, CallingStationId,
ServiceType, FramedProtocol, FramedIPAddress, AcctStartDelay)
values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}',
'%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}',
'%{NAS-Port-Type}', DATE_SUB('%S',INTERVAL (%{Acct-Session-Time:-0} +
%{Acct-Delay-Time:-0}) SECOND), '%{Acct-Session-Time}', '%{Acct-Authentic}',
'', '%{Acct-Input-Octets}', '%{Acct-Output-Octets}', '%{Called-Station-Id}',
'%{Calling-Station-Id}', '%{Service-Type}', '%{Framed-Protocol}',
'%{Framed-IP-Address}', '0')"
sql: accounting_start_query = "INSERT into radacct (AcctSessionId,
AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType,
AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic,
ConnectInfo_start, ConnectInfo_stop, AcctInputOctets, AcctOutputOctets,
CalledStationId, CallingStationId, AcctTerminateCause, ServiceType,
FramedProtocol, FramedIPAddress, AcctStartDelay, AcctStopDelay)
values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}',
'%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}',
'%{NAS-Port-Type}', '%S', '0', '0', '%{Acct-Authentic}', '%{Connect-Info}',
'', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '',
'%{Service-Type}', '%{Framed-Protocol}', '%{Framed-IP-Address}',
'%{Acct-Delay-Time}', '0')"
sql: accounting_start_query_alt = "UPDATE radacct SET AcctStartTime = '%S',
AcctStartDelay = '%{Acct-Delay-Time}', ConnectInfo_start = '%{Connect-Info}'
WHERE AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}'
AND NASIPAddress = '%{NAS-IP-Address}'"
sql: accounting_stop_query = "UPDATE radacct SET AcctStopTime = '%S',
AcctSessionTime = '%{Acct-Session-Time}', AcctInputOctets =
'%{Acct-Input-Octets}', AcctOutputOctets = '%{Acct-Output-Octets}',
AcctTerminateCause = '%{Acct-Terminate-Cause}', AcctStopDelay =
'%{Acct-Delay-Time}', ConnectInfo_stop = '%{Connect-Info}' WHERE
AcctSessionId = '%{Acct-Session-Id}' AND UserName = '%{SQL-User-Name}' AND
NASIPAddress = '%{NAS-IP-Address}'"
sql: accounting_stop_query_alt = "INSERT into radacct (AcctSessionId,
AcctUniqueId, UserName, Realm, NASIPAddress, NASPortId, NASPortType,
AcctStartTime, AcctStopTime, AcctSessionTime, AcctAuthentic,
ConnectInfo_start, ConnectInfo_stop, AcctInputOctets, AcctOutputOctets,
CalledStationId, CallingStationId, AcctTerminateCause, ServiceType,
FramedProtocol, FramedIPAddress, AcctStartDelay, AcctStopDelay)
values('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}',
'%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}',
'%{NAS-Port-Type}', DATE_SUB('%S', INTERVAL (%{Acct-Session-Time:-0} +
%{Acct-Delay-Time:-0}) SECOND), '%S', '%{Acct-Session-Time}',
'%{Acct-Authentic}', '', '%{Connect-Info}', '%{Acct-Input-Octets}',
'%{Acct-Output-Octets}', '%{Called-Station-Id}', '%{Calling-Station-Id}',
'%{Acct-Terminate-Cause}', '%{Service-Type}', '%{Framed-Protocol}',
'%{Framed-IP-Address}', '0', '%{Acct-Delay-Time}')"
sql: group_membership_query = "SELECT GroupName FROM usergroup WHERE
UserName='%{SQL-User-Name}'"
sql: connect_failure_retry_delay = 60
sql: simul_count_query = "SELECT COUNT(*) FROM radacct WHERE
UserName='%{SQL-User-Name}' AND AcctStopTime = 0"
sql: simul_verify_query = "SELECT RadAcctId, AcctSessionId, UserName,
NASIPAddress, NASPortId, FramedIPAddress, CallingStationId, FramedProtocol
FROM radacct WHERE UserName='%{SQL-User-Name}' AND AcctStopTime = 0"
sql: postauth_table = "radpostauth"
sql: postauth_query = "INSERT into radpostauth (id, user, pass, reply,
date) values ('', '%{User-Name}', '%{User-Password:-Chap-Password}',
'%{reply:Packet-Type}', NOW())"
sql: safe-characters =
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked
rlm_sql (sql): Attempting to connect to freeradius@localhost:/freeradius
rlm_sql (sql): starting 0
rlm_sql (sql): Attempting to connect rlm_sql_mysql #0
rlm_sql_mysql: Starting connect to MySQL server for #0
rlm_sql (sql): Connected new DB handle, #0
rlm_sql (sql): starting 1
rlm_sql (sql): Attempting to connect rlm_sql_mysql #1
rlm_sql_mysql: Starting connect to MySQL server for #1
rlm_sql (sql): Connected new DB handle, #1
rlm_sql (sql): starting 2
rlm_sql (sql): Attempting to connect rlm_sql_mysql #2
rlm_sql_mysql: Starting connect to MySQL server for #2
rlm_sql (sql): Connected new DB handle, #2
rlm_sql (sql): starting 3
rlm_sql (sql): Attempting to connect rlm_sql_mysql #3
rlm_sql_mysql: Starting connect to MySQL server for #3
rlm_sql (sql): Connected new DB handle, #3
rlm_sql (sql): starting 4
rlm_sql (sql): Attempting to connect rlm_sql_mysql #4
rlm_sql_mysql: Starting connect to MySQL server for #4
rlm_sql (sql): Connected new DB handle, #4
rlm_sql (sql): - generate_sql_clients
rlm_sql (sql): Query: SELECT * FROM nas
rlm_sql (sql): Reserving sql socket id: 4
rlm_sql (sql): Read entry
nasname=office.xxxx.com.au,shortname=office-nas,secret=xxxxxx
rlm_sql (sql): Adding client 218.xxx.xxx.xxx (office-nas) to clients list
rlm_sql (sql): Released sql socket id: 4
Module: Instantiated sql (sql)
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 files
files: usersfile = "/etc/freeradius/users"
files: acctusersfile = "/etc/freeradius/acct_users"
files: preproxy_usersfile = "/etc/freeradius/preproxy_users"
files: compat = "no"
Module: Instantiated files (files)
Module: Loaded detail
detail: detailfile =
"/var/log/freeradius/radacct/%{Client-IP-Address}/detail-%Y%m%d"
detail: detailperm = 384
detail: dirperm = 493
detail: locking = no
Module: Instantiated detail (detail)
Module: Loaded System
unix: cache = no
unix: passwd = "(null)"
unix: shadow = "/etc/shadow"
unix: group = "(null)"
unix: radwtmp = "/var/log/freeradius/radwtmp"
unix: usegroup = no
unix: cache_reload = 600
Module: Instantiated unix (unix)
Module: Loaded radutmp
radutmp: filename = "/var/log/freeradius/radutmp"
radutmp: username = "%{User-Name}"
radutmp: case_sensitive = yes
radutmp: check_with_nas = yes
radutmp: perm = 384
radutmp: callerid = yes
Module: Instantiated radutmp (radutmp)
Initializing the thread pool...
thread: start_servers = 5
thread: max_servers = 32
thread: min_spare_servers = 3
thread: max_spare_servers = 10
thread: max_requests_per_server = 0
thread: cleanup_delay = 5
Thread spawned new child 1. Total threads in pool: 1
Thread spawned new child 2. Total threads in pool: 2
Thread spawned new child 3. Total threads in pool: 3
Thread spawned new child 4. Total threads in pool: 4
Thread spawned new child 5. Total threads in pool: 5
Thread pool initialized
Listening on authentication *:1812
Listening on accounting *:1813
Ready to process requests.
Thread 1 waiting to be assigned a request
Thread 2 waiting to be assigned a request
Thread 3 waiting to be assigned a request
Thread 4 waiting to be assigned a request
Thread 5 waiting to be assigned a request
rad_recv: Access-Request packet from host 218.xxx.xxx.xxx:2006, id=101,
length=69
--- Walking the entire request list ---
Waking up in 31 seconds...
Threads: total/active/spare threads = 5/0/5
Thread 1 got semaphore
Thread 1 handling request 0, (1 handled so far)
User-Name = "johnsmith(a)xxxx.com.au"
User-Password = "xxxxxx"
Processing the authorize section of radiusd.conf
modcall: entering group authorize for request 0
modcall[authorize]: module "preprocess" returns ok for request 0
modcall[authorize]: module "chap" returns noop for request 0
modcall[authorize]: module "mschap" returns noop for request 0
rlm_realm: Looking up realm "xxxx.com.au" for User-Name =
"johnsmith(a)xxxx.com.au"
rlm_realm: No such realm "xxxx.com.au"
modcall[authorize]: module "suffix" returns noop for request 0
rlm_eap: No EAP-Message, not doing EAP
modcall[authorize]: module "eap" returns noop for request 0
radius_xlat: 'johnsmith(a)xxxx.com.au'
rlm_sql (sql): sql_set_user escaped user --> 'johnsmith(a)xxxx.com.au'
radius_xlat: 'SELECT id, UserName, Attribute, Value, op FROM
radcheck WHERE Username = 'johnsmith(a)xxxx.com.au' ORDER
BY id'
rlm_sql (sql): Reserving sql socket id: 3
radius_xlat: 'SELECT
radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupche
ck.Value,radgroupcheck.op FROM radgroupcheck,usergroup WHERE
usergroup.Username = 'johnsmith(a)xxxx.com.au' AND usergroup.GroupName =
radgroupcheck.GroupName ORDER BY radgroupcheck.id'
radius_xlat: 'SELECT id, UserName, Attribute, Value, op FROM
radreply WHERE Username = 'johnsmith(a)xxxx.com.au' ORDER
BY id'
radius_xlat: 'SELECT
radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgrouprep
ly.Value,radgroupreply.op FROM radgroupreply,usergroup WHERE
usergroup.Username = 'johnsmith(a)xxxx.com.au' AND usergroup.GroupName =
radgroupreply.GroupName ORDER BY radgroupreply.id'
rlm_sql (sql): Released sql socket id: 3
modcall[authorize]: module "sql" returns ok for request 0
modcall: leaving group authorize (returns ok) for request 0
rad_check_password: Found Auth-Type Reject
rad_check_password: Auth-Type = Reject, rejecting user
auth: Failed to validate the user.
Login incorrect: [johnsmith(a)xxxx.com.au/xxxxxx] (from client office-nas port
0)
Delaying request 0 for 1 seconds
Finished request 0
Going to the next request
Thread 1 waiting to be assigned a request
<<Nothing happens for ~30 seconds here>>
--- Walking the entire request list ---
Sending Access-Reject of id 101 to 218.xxx.xxx.xxx port 2006
Reply-Message := "Account Suspended"
Cleaning up request 0 ID 101 with timestamp 442253f9
Nothing to do. Sleeping until we see a request.
-------------------------------------
-----------------Config--------------
cat /etc/freeradius/radiusd.conf | grep -v '#'
prefix = /usr
exec_prefix = /usr
sysconfdir = /etc
localstatedir = /var
sbindir = ${exec_prefix}/sbin
logdir = /var/log/freeradius
raddbdir = /etc/freeradius
radacctdir = ${logdir}/radacct
confdir = ${raddbdir}
run_dir = ${localstatedir}/run/freeradius
log_file = ${logdir}/radius.log
libdir = /usr/lib/freeradius
pidfile = ${run_dir}/freeradius.pid
user = freerad
group = freerad
max_request_time = 30
delete_blocked_requests = no
cleanup_delay = 5
max_requests = 1024
bind_address = *
port = 0
hostname_lookups = no
allow_core_dumps = no
regular_expressions = yes
extended_expressions = yes
log_stripped_names = no
log_auth = yes
log_auth_badpass = yes
log_auth_goodpass = no
usercollide = no
lower_user = no
lower_pass = no
nospace_user = no
nospace_pass = no
checkrad = ${sbindir}/checkrad
security {
max_attributes = 200
reject_delay = 1
status_server = no
}
proxy_requests = yes
$INCLUDE ${confdir}/proxy.conf
$INCLUDE ${confdir}/clients.conf
snmp = no
$INCLUDE ${confdir}/snmp.conf
thread pool {
start_servers = 5
max_servers = 32
min_spare_servers = 3
max_spare_servers = 10
max_requests_per_server = 0
}
modules {
pap {
encryption_scheme = clear
}
chap {
authtype = CHAP
}
pam {
pam_auth = radiusd
}
unix {
cache = no
cache_reload = 600
shadow = /etc/shadow
radwtmp = ${logdir}/radwtmp
}
$INCLUDE ${confdir}/eap.conf
mschap {
authtype = MS-CHAP
}
ldap {
server = "ldap.your.domain"
basedn = "o=My Org,c=UA"
filter = "(uid=%{Stripped-User-Name:-%{User-Name}})"
start_tls = no
access_attr = "dialupAccess"
dictionary_mapping = ${raddbdir}/ldap.attrmap
ldap_connections_number = 5
timeout = 4
timelimit = 3
net_timeout = 1
}
realm IPASS {
format = prefix
delimiter = "/"
ignore_default = no
ignore_null = no
}
realm suffix {
format = suffix
delimiter = "@"
ignore_default = no
ignore_null = no
}
realm realmpercent {
format = suffix
delimiter = "%"
ignore_default = no
ignore_null = no
}
realm ntdomain {
format = prefix
delimiter = "\\"
ignore_default = no
ignore_null = no
}
checkval {
item-name = Calling-Station-Id
check-name = Calling-Station-Id
data-type = string
}
preprocess {
huntgroups = ${confdir}/huntgroups
hints = ${confdir}/hints
with_ascend_hack = no
ascend_channels_per_line = 23
with_ntdomain_hack = no
with_specialix_jetstream_hack = no
with_cisco_vsa_hack = no
}
files {
usersfile = ${confdir}/users
acctusersfile = ${confdir}/acct_users
preproxy_usersfile = ${confdir}/preproxy_users
compat = no
}
detail {
detailfile =
${radacctdir}/%{Client-IP-Address}/detail-%Y%m%d
detailperm = 0600
}
acct_unique {
key = "User-Name, Acct-Session-Id, NAS-IP-Address,
Client-IP-Address, NAS-Port"
}
$INCLUDE ${confdir}/sql.conf
radutmp {
filename = ${logdir}/radutmp
username = %{User-Name}
case_sensitive = yes
check_with_nas = yes
perm = 0600
callerid = "yes"
}
radutmp sradutmp {
filename = ${logdir}/sradutmp
perm = 0644
callerid = "no"
}
attr_filter {
attrsfile = ${confdir}/attrs
}
counter daily {
filename = ${raddbdir}/db.daily
key = User-Name
count-attribute = Acct-Session-Time
reset = daily
counter-name = Daily-Session-Time
check-name = Max-Daily-Session
allowed-servicetype = Framed-User
cache-size = 5000
}
sqlcounter dailycounter {
counter-name = Daily-Session-Time
check-name = Max-Daily-Session
sqlmod-inst = sql
key = User-Name
reset = daily
query = "SELECT SUM(AcctSessionTime - \
GREATEST((%b - UNIX_TIMESTAMP(AcctStartTime)), 0)) \
FROM radacct WHERE UserName='%{%k}' AND \
UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '%b'"
}
sqlcounter monthlycounter {
counter-name = Monthly-Session-Time
check-name = Max-Monthly-Session
sqlmod-inst = sql
key = User-Name
reset = monthly
query = "SELECT SUM(AcctSessionTime - \
GREATEST((%b - UNIX_TIMESTAMP(AcctStartTime)), 0)) \
FROM radacct WHERE UserName='%{%k}' AND \
UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime > '%b'"
}
always fail {
rcode = fail
}
always reject {
rcode = reject
}
always ok {
rcode = ok
simulcount = 0
mpp = no
}
expr {
}
digest {
}
exec {
wait = yes
input_pairs = request
}
exec echo {
wait = yes
program = "/bin/echo %{User-Name}"
input_pairs = request
output_pairs = reply
}
ippool main_pool {
range-start = 192.168.1.1
range-stop = 192.168.3.254
netmask = 255.255.255.0
cache-size = 800
session-db = ${raddbdir}/db.ippool
ip-index = ${raddbdir}/db.ipindex
override = no
maximum-timeout = 0
}
}
instantiate {
exec
expr
}
authorize {
preprocess
chap
mschap
suffix
eap
sql
}
authenticate {
Auth-Type PAP {
pap
}
Auth-Type CHAP {
chap
}
Auth-Type MS-CHAP {
mschap
}
eap
}
preacct {
preprocess
acct_unique
suffix
files
}
accounting {
detail
unix
radutmp
sql
}
session {
sql
}
post-auth {
}
pre-proxy {
}
post-proxy {
eap
}
-------------------------------------
Any suggestions/help as to what would be causing this very slow reject time
(which breaks most clients as they time out) would be most welcome.
Thanks,
Fenn.
