Hi list
I'm in the process of setting up my first radius server. Radius starts ok and
auths with radtest but from cisco it does not. I'm running Fedora Core 2 with
freeradius ver 1.0.1 using cisco 1601 (testing)
here is the cisco setup followed by radius radiusd -fxxxx startup then when I
try and authenticate in debug mode.
---------------------------------------------------------------------------------------------
aaa new-model
aaa authentication login default group radius none
aaa authentication login none none
aaa authentication login unilynx local
aaa authentication login consoleport none
aaa authentication ppp default group radius none
aaa authentication ppp unilynx-radius group radius local
aaa authentication ppp radppp if-needed group radius
aaa authorization network default group radius
aaa accounting update newinfo
aaa accounting network default wait-start group radius
ip radius source-interface Loopback0
snmp-server engineID local 000000090200000142062DED
snmp-server community public RO 97
radius-server host 192.168.2.254 auth-port 1812 acct-port 1813 non-standard
radius-server retransmit 2
radius-server timeout 8
radius-server deadtime 2
radius-server key password
---------------------------------------------------------------------------------------------------
Fri Dec 3 10:38:47 2004 : Info: Starting - reading configuration files ...
Fri Dec 3 10:38:47 2004 : Debug: reread_config: reading radiusd.conf
Fri Dec 3 10:38:47 2004 : Debug: Config: including
file: /usr/local/etc/raddb/proxy.conf
Fri Dec 3 10:38:47 2004 : Debug: Config: including
file: /usr/local/etc/raddb/clients.conf
Fri Dec 3 10:38:47 2004 : Debug: Config: including
file: /usr/local/etc/raddb/snmp.conf
Fri Dec 3 10:38:47 2004 : Debug: Config: including
file: /usr/local/etc/raddb/sql.conf
Fri Dec 3 10:38:47 2004 : Debug: main: prefix = "/usr/local"
Fri Dec 3 10:38:47 2004 : Debug: main: localstatedir = "/usr/local/var"
Fri Dec 3 10:38:47 2004 : Debug: main: logdir = "/usr/local/var/log/radius"
Fri Dec 3 10:38:47 2004 : Debug: main: libdir =
"/home/temp/freeradius/freeradius-1.0.1/src/modules"
Fri Dec 3 10:38:47 2004 : Debug: main: radacctdir =
"/usr/local/var/log/radius/radacct"
Fri Dec 3 10:38:47 2004 : Debug: main: hostname_lookups = no
Fri Dec 3 10:38:47 2004 : Debug: main: max_request_time = 30
Fri Dec 3 10:38:47 2004 : Debug: main: cleanup_delay = 5
Fri Dec 3 10:38:47 2004 : Debug: main: max_requests = 1024
Fri Dec 3 10:38:47 2004 : Debug: main: delete_blocked_requests = 0
Fri Dec 3 10:38:47 2004 : Debug: main: port = 0
Fri Dec 3 10:38:47 2004 : Debug: main: allow_core_dumps = no
Fri Dec 3 10:38:47 2004 : Debug: main: log_stripped_names = no
Fri Dec 3 10:38:47 2004 : Debug: main: log_file =
"/usr/local/var/log/radius/radius.log"
Fri Dec 3 10:38:47 2004 : Debug: main: log_auth = no
Fri Dec 3 10:38:47 2004 : Debug: main: log_auth_badpass = no
Fri Dec 3 10:38:47 2004 : Debug: main: log_auth_goodpass = no
Fri Dec 3 10:38:47 2004 : Debug: main: pidfile =
"/usr/local/var/run/radiusd/radiusd.pid"
Fri Dec 3 10:38:47 2004 : Debug: main: user = "(null)"
Fri Dec 3 10:38:47 2004 : Debug: main: group = "(null)"
Fri Dec 3 10:38:47 2004 : Debug: main: usercollide = no
Fri Dec 3 10:38:47 2004 : Debug: main: lower_user = "no"
Fri Dec 3 10:38:47 2004 : Debug: main: lower_pass = "no"
Fri Dec 3 10:38:47 2004 : Debug: main: nospace_user = "no"
Fri Dec 3 10:38:47 2004 : Debug: main: nospace_pass = "no"
Fri Dec 3 10:38:47 2004 : Debug: main: checkrad = "/usr/local/sbin/checkrad"
Fri Dec 3 10:38:47 2004 : Debug: main: proxy_requests = yes
Fri Dec 3 10:38:47 2004 : Debug: proxy: retry_delay = 5
Fri Dec 3 10:38:47 2004 : Debug: proxy: retry_count = 3
Fri Dec 3 10:38:47 2004 : Debug: proxy: synchronous = no
Fri Dec 3 10:38:47 2004 : Debug: proxy: default_fallback = no
Fri Dec 3 10:38:47 2004 : Debug: proxy: dead_time = 120
Fri Dec 3 10:38:47 2004 : Debug: proxy: post_proxy_authorize = no
Fri Dec 3 10:38:47 2004 : Debug: proxy: wake_all_if_all_dead = no
Fri Dec 3 10:38:47 2004 : Debug: security: max_attributes = 200
Fri Dec 3 10:38:47 2004 : Debug: security: reject_delay = 1
Fri Dec 3 10:38:47 2004 : Debug: security: status_server = no
Fri Dec 3 10:38:47 2004 : Debug: main: debug_level = 0
Fri Dec 3 10:38:47 2004 : Debug: read_config_files: reading dictionary
Fri Dec 3 10:38:47 2004 : Debug: read_config_files: reading naslist
Fri Dec 3 10:38:47 2004 : Info: Using deprecated naslist file. Support for
this will go away soon.
Fri Dec 3 10:38:47 2004 : Debug: read_config_files: reading clients
Fri Dec 3 10:38:47 2004 : Info: Using deprecated clients file. Support for
this will go away soon.
Fri Dec 3 10:38:47 2004 : Debug: read_config_files: reading realms
Fri Dec 3 10:38:47 2004 : Info: Using deprecated realms file. Support for
this will go away soon.
Fri Dec 3 10:38:47 2004 : Debug: radiusd: entering modules setup
Fri Dec 3 10:38:47 2004 : Debug: Module: Library search path
is /home/temp/freeradius/freeradius-1.0.1/src/modules
Fri Dec 3 10:38:47 2004 : Debug: Module: Loaded exec
Fri Dec 3 10:38:47 2004 : Debug: exec: wait = yes
Fri Dec 3 10:38:47 2004 : Debug: exec: program = "(null)"
Fri Dec 3 10:38:47 2004 : Debug: exec: input_pairs = "request"
Fri Dec 3 10:38:47 2004 : Debug: exec: output_pairs = "(null)"
Fri Dec 3 10:38:47 2004 : Debug: exec: packet_type = "(null)"
Fri Dec 3 10:38:47 2004 : Info: rlm_exec: Wait=yes but no output defined. Did
you mean output=none?
Fri Dec 3 10:38:47 2004 : Debug: Module: Instantiated exec (exec)
Fri Dec 3 10:38:47 2004 : Debug: Module: Loaded expr
Fri Dec 3 10:38:47 2004 : Debug: Module: Instantiated expr (expr)
Fri Dec 3 10:38:47 2004 : Debug: Module: Loaded PAP
Fri Dec 3 10:38:47 2004 : Debug: pap: encryption_scheme = "crypt"
Fri Dec 3 10:38:47 2004 : Debug: Module: Instantiated pap (pap)
Fri Dec 3 10:38:47 2004 : Debug: Module: Loaded CHAP
Fri Dec 3 10:38:47 2004 : Debug: Module: Instantiated chap (chap)
Fri Dec 3 10:38:47 2004 : Debug: Module: Loaded MS-CHAP
Fri Dec 3 10:38:47 2004 : Debug: mschap: use_mppe = yes
Fri Dec 3 10:38:47 2004 : Debug: mschap: require_encryption = no
Fri Dec 3 10:38:47 2004 : Debug: mschap: require_strong = no
Fri Dec 3 10:38:47 2004 : Debug: mschap: passwd = "(null)"
Fri Dec 3 10:38:47 2004 : Debug: mschap: authtype = "MS-CHAP"
Fri Dec 3 10:38:47 2004 : Debug: Module: Instantiated mschap (mschap)
Fri Dec 3 10:38:47 2004 : Debug: Module: Loaded System
Fri Dec 3 10:38:47 2004 : Debug: unix: cache = no
Fri Dec 3 10:38:47 2004 : Debug: unix: passwd = "(null)"
Fri Dec 3 10:38:47 2004 : Debug: unix: shadow = "(null)"
Fri Dec 3 10:38:47 2004 : Debug: unix: group = "(null)"
Fri Dec 3 10:38:47 2004 : Debug: unix: radwtmp =
"/usr/local/var/log/radius/radwtmp"
Fri Dec 3 10:38:47 2004 : Debug: unix: usegroup = no
Fri Dec 3 10:38:47 2004 : Debug: unix: cache_reload = 600
Fri Dec 3 10:38:47 2004 : Debug: Module: Instantiated unix (unix)
Fri Dec 3 10:38:47 2004 : Debug: Module: Loaded preprocess
Fri Dec 3 10:38:47 2004 : Debug: preprocess: huntgroups =
"/usr/local/etc/raddb/huntgroups"
Fri Dec 3 10:38:47 2004 : Debug: preprocess: hints =
"/usr/local/etc/raddb/hints"
Fri Dec 3 10:38:47 2004 : Debug: preprocess: with_ascend_hack = no
Fri Dec 3 10:38:47 2004 : Debug: preprocess: ascend_channels_per_line = 23
Fri Dec 3 10:38:47 2004 : Debug: preprocess: with_ntdomain_hack = no
Fri Dec 3 10:38:47 2004 : Debug: preprocess: with_specialix_jetstream_hack =
no
Fri Dec 3 10:38:47 2004 : Debug: preprocess: with_cisco_vsa_hack = yes
Fri Dec 3 10:38:47 2004 : Debug: Module: Instantiated preprocess (preprocess)
Fri Dec 3 10:38:47 2004 : Debug: Module: Loaded realm
Fri Dec 3 10:38:47 2004 : Debug: realm: format = "suffix"
Fri Dec 3 10:38:47 2004 : Debug: realm: delimiter = "@"
Fri Dec 3 10:38:47 2004 : Debug: Module: Instantiated realm (suffix)
Fri Dec 3 10:38:47 2004 : Debug: Module: Loaded files
Fri Dec 3 10:38:47 2004 : Debug: files: usersfile =
"/usr/local/etc/raddb/users"
Fri Dec 3 10:38:47 2004 : Debug: files: acctusersfile =
"/usr/local/etc/raddb/acct_users"
Fri Dec 3 10:38:47 2004 : Debug: files: preproxy_usersfile =
"/usr/local/etc/raddb/preproxy_users"
Fri Dec 3 10:38:47 2004 : Debug: files: compat = "no"
Fri Dec 3 10:38:47 2004 : Debug: Module: Instantiated files (files)
Fri Dec 3 10:38:47 2004 : Debug: Module: Loaded SQL
Fri Dec 3 10:38:47 2004 : Debug: sql: driver = "rlm_sql_mysql"
Fri Dec 3 10:38:47 2004 : Debug: sql: server = "localhost"
Fri Dec 3 10:38:47 2004 : Debug: sql: port = ""
Fri Dec 3 10:38:47 2004 : Debug: sql: login = "root"
Fri Dec 3 10:38:47 2004 : Debug: sql: password = "password"
Fri Dec 3 10:38:47 2004 : Debug: sql: radius_db = "radius"
Fri Dec 3 10:38:47 2004 : Debug: sql: acct_table = "radacct"
Fri Dec 3 10:38:47 2004 : Debug: sql: acct_table2 = "radacct"
Fri Dec 3 10:38:47 2004 : Debug: sql: authcheck_table = "radcheck"
Fri Dec 3 10:38:47 2004 : Debug: sql: authreply_table = "radreply"
Fri Dec 3 10:38:47 2004 : Debug: sql: groupcheck_table = "radgroupcheck"
Fri Dec 3 10:38:47 2004 : Debug: sql: groupreply_table = "radgroupreply"
Fri Dec 3 10:38:47 2004 : Debug: sql: usergroup_table = "usergroup"
Fri Dec 3 10:38:47 2004 : Debug: sql: nas_table = "nas"
Fri Dec 3 10:38:47 2004 : Debug: sql: dict_table = "dictionary"
Fri Dec 3 10:38:47 2004 : Debug: sql: sqltrace = yes
Fri Dec 3 10:38:47 2004 : Debug: sql: sqltracefile =
"/var/log/radius/sqltrace.sql"
Fri Dec 3 10:38:47 2004 : Debug: sql: deletestalesessions = yes
Fri Dec 3 10:38:47 2004 : Debug: sql: num_sql_socks = 5
Fri Dec 3 10:38:47 2004 : Debug: sql: sql_user_name = "%{User-Name}"
Fri Dec 3 10:38:47 2004 : Debug: sql: default_user_profile = ""
Fri Dec 3 10:38:47 2004 : Debug: sql: query_on_not_found = no
Fri Dec 3 10:38:47 2004 : Debug: sql: authorize_check_query = "SELECT
id,UserName,Attribute,Value,op FROM radcheck WHERE Username =
'%{SQL-User-Name}' ORDER BY id"
Fri Dec 3 10:38:47 2004 : Debug: sql: authorize_reply_query = "SELECT
id,UserName,Attribute,Value,op FROM radreply WHERE Username =
'%{SQL-User-Name}' ORDER BY id"
Fri Dec 3 10:38:47 2004 : Debug: sql: authorize_group_check_query = "SELECT
radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op
FROM radgroupcheck,usergroup WHERE usergroup.Username = '%{SQL-User-Name}'
AND usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id"
Fri Dec 3 10:38:47 2004 : Debug: sql: authorize_group_reply_query = "SELECT
radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op
FROM radgroupreply,usergroup WHERE usergroup.Username = '%{SQL-User-Name}'
AND usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id"
Fri Dec 3 10:38:47 2004 : Debug: 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'"
Fri Dec 3 10:38:47 2004 : Debug: 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}'"
Fri Dec 3 10:38:47 2004 : Debug: 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')"
Fri Dec 3 10:38:47 2004 : Debug: 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}'"
Fri Dec 3 10:38:47 2004 : Debug: 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')"
Fri Dec 3 10:38:47 2004 : Debug: 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}'"
Fri Dec 3 10:38:47 2004 : Debug: 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}'"
Fri Dec 3 10:38:47 2004 : Debug: 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}')"
Fri Dec 3 10:38:47 2004 : Debug: sql: group_membership_query = "SELECT
GroupName FROM usergroup WHERE UserName='%{SQL-User-Name}'"
Fri Dec 3 10:38:47 2004 : Debug: sql: connect_failure_retry_delay = 60
Fri Dec 3 10:38:47 2004 : Debug: sql: simul_count_query = ""
Fri Dec 3 10:38:47 2004 : Debug: sql: simul_verify_query = "SELECT
RadAcctId, AcctSessionId, UserName, NASIPAddress, NASPortId, FramedIPAddress,
CallingStationId, FramedProtocol FROM radacct WHERE
UserName='%{SQL-User-Name}' AND AcctStopTime = 0"Fri Dec 3 10:38:47 2004 :
Info: rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and
linked
Fri Dec 3 10:38:47 2004 : Info: rlm_sql (sql): Attempting to connect to
[EMAIL PROTECTED]:/radius
Fri Dec 3 10:38:47 2004 : Debug: rlm_sql (sql): starting 0
Fri Dec 3 10:38:47 2004 : Debug: rlm_sql (sql): Attempting to connect
rlm_sql_mysql #0
Fri Dec 3 10:38:47 2004 : Info: rlm_sql_mysql: Starting connect to MySQL
server for #0
Fri Dec 3 10:38:47 2004 : Debug: rlm_sql (sql): Connected new DB handle, #0
Fri Dec 3 10:38:47 2004 : Debug: rlm_sql (sql): starting 1
Fri Dec 3 10:38:47 2004 : Debug: rlm_sql (sql): Attempting to connect
rlm_sql_mysql #1
Fri Dec 3 10:38:47 2004 : Info: rlm_sql_mysql: Starting connect to MySQL
server for #1
Fri Dec 3 10:38:47 2004 : Debug: rlm_sql (sql): Connected new DB handle, #1
Fri Dec 3 10:38:47 2004 : Debug: rlm_sql (sql): starting 2
Fri Dec 3 10:38:47 2004 : Debug: rlm_sql (sql): Attempting to connect
rlm_sql_mysql #2
Fri Dec 3 10:38:47 2004 : Info: rlm_sql_mysql: Starting connect to MySQL
server for #2
Fri Dec 3 10:38:47 2004 : Debug: rlm_sql (sql): Connected new DB handle, #2
Fri Dec 3 10:38:47 2004 : Debug: rlm_sql (sql): starting 3
Fri Dec 3 10:38:47 2004 : Debug: rlm_sql (sql): Attempting to connect
rlm_sql_mysql #3
Fri Dec 3 10:38:47 2004 : Info: rlm_sql_mysql: Starting connect to MySQL
server for #3
Fri Dec 3 10:38:47 2004 : Debug: rlm_sql (sql): Connected new DB handle, #3
Fri Dec 3 10:38:47 2004 : Debug: rlm_sql (sql): starting 4
Fri Dec 3 10:38:47 2004 : Debug: rlm_sql (sql): Attempting to connect
rlm_sql_mysql #4
Fri Dec 3 10:38:47 2004 : Info: rlm_sql_mysql: Starting connect to MySQL
server for #4
Fri Dec 3 10:38:47 2004 : Debug: rlm_sql (sql): Connected new DB handle, #4
Fri Dec 3 10:38:47 2004 : Debug: Module: Instantiated sql (sql)
Fri Dec 3 10:38:47 2004 : Debug: Module: Loaded Acct-Unique-Session-Id
Fri Dec 3 10:38:47 2004 : Debug: acct_unique: key = "User-Name,
Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port"
Fri Dec 3 10:38:47 2004 : Debug: Module: Instantiated acct_unique
(acct_unique)
Fri Dec 3 10:38:47 2004 : Debug: Module: Loaded detail
Fri Dec 3 10:38:47 2004 : Debug: detail: detailfile =
"/usr/local/var/log/radius/radacct/%{Client-IP-Address}/detail-%Y%m%d"
Fri Dec 3 10:38:47 2004 : Debug: detail: detailperm = 384
Fri Dec 3 10:38:47 2004 : Debug: detail: dirperm = 493
Fri Dec 3 10:38:47 2004 : Debug: detail: locking = no
Fri Dec 3 10:38:47 2004 : Debug: Module: Instantiated detail (detail)
Fri Dec 3 10:38:47 2004 : Debug: Module: Loaded radutmp
Fri Dec 3 10:38:47 2004 : Debug: radutmp: filename =
"/usr/local/var/log/radius/radutmp"
Fri Dec 3 10:38:47 2004 : Debug: radutmp: username = "%{User-Name}"
Fri Dec 3 10:38:47 2004 : Debug: radutmp: case_sensitive = yes
Fri Dec 3 10:38:47 2004 : Debug: radutmp: check_with_nas = yes
Fri Dec 3 10:38:47 2004 : Debug: radutmp: perm = 384
Fri Dec 3 10:38:47 2004 : Debug: radutmp: callerid = yes
Fri Dec 3 10:38:47 2004 : Debug: Module: Instantiated radutmp (radutmp)
Fri Dec 3 10:38:47 2004 : Debug: Initializing the thread pool...
Fri Dec 3 10:38:47 2004 : Debug: thread: start_servers = 5
Fri Dec 3 10:38:47 2004 : Debug: thread: max_servers = 32
Fri Dec 3 10:38:47 2004 : Debug: thread: min_spare_servers = 3
Fri Dec 3 10:38:47 2004 : Debug: thread: max_spare_servers = 10
Fri Dec 3 10:38:47 2004 : Debug: thread: max_requests_per_server = 0
Fri Dec 3 10:38:47 2004 : Debug: thread: cleanup_delay = 5
Fri Dec 3 10:38:47 2004 : Debug: Thread 1 waiting to be assigned a request
Fri Dec 3 10:38:47 2004 : Debug: Thread spawned new child 1. Total threads in
pool: 1
Fri Dec 3 10:38:47 2004 : Debug: Thread 2 waiting to be assigned a request
Fri Dec 3 10:38:47 2004 : Debug: Thread spawned new child 2. Total threads in
pool: 2
Fri Dec 3 10:38:47 2004 : Debug: Thread 3 waiting to be assigned a request
Fri Dec 3 10:38:47 2004 : Debug: Thread spawned new child 3. Total threads in
pool: 3
Fri Dec 3 10:38:47 2004 : Debug: Thread 4 waiting to be assigned a request
Fri Dec 3 10:38:47 2004 : Debug: Thread spawned new child 4. Total threads in
pool: 4
Fri Dec 3 10:38:47 2004 : Debug: Thread 5 waiting to be assigned a request
Fri Dec 3 10:38:47 2004 : Debug: Thread spawned new child 5. Total threads in
pool: 5
Fri Dec 3 10:38:47 2004 : Info: Listening on IP address *, ports 1812/udp and
1813/udp, with proxy on 1814/udp.
Fri Dec 3 10:38:47 2004 : Info: Ready to process requests.
---------------------------------------------------------------------------------------------------
NAS-IP-Address = 192.168.0.250
NAS-Port = 2
NAS-Port-Type = Virtual
User-Name = "unilynx"
Calling-Station-Id = "192.168.2.177"
User-Password = "password"
Fri Dec 3 10:30:25 2004 : Debug: modcall: entering group authorize for
request 12
Fri Dec 3 10:30:25 2004 : Debug: modsingle[authorize]: calling preprocess
(rlm_preprocess) for request 12
Fri Dec 3 10:30:25 2004 : Debug: modsingle[authorize]: returned from
preprocess (rlm_preprocess) for request 12
Fri Dec 3 10:30:25 2004 : Debug: modcall[authorize]: module "preprocess"
returns ok for request 12
Fri Dec 3 10:30:25 2004 : Debug: modsingle[authorize]: calling chap
(rlm_chap) for request 12
Fri Dec 3 10:30:25 2004 : Debug: modsingle[authorize]: returned from chap
(rlm_chap) for request 12
Fri Dec 3 10:30:25 2004 : Debug: modcall[authorize]: module "chap" returns
noop for request 12
Fri Dec 3 10:30:25 2004 : Debug: modsingle[authorize]: calling mschap
(rlm_mschap) for request 12
Fri Dec 3 10:30:25 2004 : Debug: modsingle[authorize]: returned from mschap
(rlm_mschap) for request 12
Fri Dec 3 10:30:25 2004 : Debug: modcall[authorize]: module "mschap"
returns noop for request 12
Fri Dec 3 10:30:25 2004 : Debug: modsingle[authorize]: calling suffix
(rlm_realm) for request 12
Fri Dec 3 10:30:25 2004 : Debug: rlm_realm: No '@' in User-Name =
"unilynx", looking up realm NULL
Fri Dec 3 10:30:25 2004 : Debug: rlm_realm: No such realm "NULL"
Fri Dec 3 10:30:25 2004 : Debug: modsingle[authorize]: returned from suffix
(rlm_realm) for request 12
Fri Dec 3 10:30:25 2004 : Debug: modcall[authorize]: module "suffix"
returns noop for request 12
Fri Dec 3 10:30:25 2004 : Debug: modsingle[authorize]: calling files
(rlm_files) for request 12
Fri Dec 3 10:30:25 2004 : Debug: modsingle[authorize]: returned from files
(rlm_files) for request 12
Fri Dec 3 10:30:25 2004 : Debug: modcall[authorize]: module "files" returns
notfound for request 12
Fri Dec 3 10:30:25 2004 : Debug: modsingle[authorize]: calling sql
(rlm_sql) for request 12
Fri Dec 3 10:30:25 2004 : Debug: radius_xlat: 'unilynx'
Fri Dec 3 10:30:25 2004 : Debug: rlm_sql (sql): sql_set_user escaped user -->
'unilynx'
Fri Dec 3 10:30:25 2004 : Debug: radius_xlat: 'SELECT
id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'unilynx' ORDER
BY id'
Fri Dec 3 10:30:25 2004 : Debug: rlm_sql (sql): Reserving sql socket id: 2
Fri Dec 3 10:30:25 2004 : Debug: rlm_sql_mysql: query: SELECT
id,UserName,Attribute,Value,op FROM radcheck WHERE Username = 'unilynx' ORDER
BY id
Fri Dec 3 10:30:25 2004 : Debug: radius_xlat: 'SELECT
radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op
FROM radgroupcheck,usergroup WHERE usergroup.Username = 'unilynx' AND
usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id'
Fri Dec 3 10:30:25 2004 : Debug: rlm_sql_mysql: query: SELECT
radgroupcheck.id,radgroupcheck.GroupName,radgroupcheck.Attribute,radgroupcheck.Value,radgroupcheck.op
FROM radgroupcheck,usergroup WHERE usergroup.Username = 'unilynx' AND
usergroup.GroupName = radgroupcheck.GroupName ORDER BY radgroupcheck.id
Fri Dec 3 10:30:25 2004 : Debug: radius_xlat: 'SELECT
id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'unilynx' ORDER
BY id'
Fri Dec 3 10:30:25 2004 : Debug: rlm_sql_mysql: query: SELECT
id,UserName,Attribute,Value,op FROM radreply WHERE Username = 'unilynx' ORDER
BY id
Fri Dec 3 10:30:25 2004 : Debug: radius_xlat: 'SELECT
radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op
FROM radgroupreply,usergroup WHERE usergroup.Username = 'unilynx' AND
usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id'
Fri Dec 3 10:30:25 2004 : Debug: rlm_sql_mysql: query: SELECT
radgroupreply.id,radgroupreply.GroupName,radgroupreply.Attribute,radgroupreply.Value,radgroupreply.op
FROM radgroupreply,usergroup WHERE usergroup.Username = 'unilynx' AND
usergroup.GroupName = radgroupreply.GroupName ORDER BY radgroupreply.id
Fri Dec 3 10:30:25 2004 : Debug: rlm_sql (sql): Released sql socket id: 2
Fri Dec 3 10:30:25 2004 : Debug: modsingle[authorize]: returned from sql
(rlm_sql) for request 12
Fri Dec 3 10:30:25 2004 : Debug: modcall[authorize]: module "sql" returns
ok for request 12
Fri Dec 3 10:30:25 2004 : Debug: modcall: group authorize returns ok for
request 12
Fri Dec 3 10:30:25 2004 : Debug: auth: type Local
Fri Dec 3 10:30:25 2004 : Debug: auth: user supplied User-Password matches
local User-Password
Sending Access-Accept of id 4 to 192.168.0.250:1645
Fri Dec 3 10:30:25 2004 : Debug: Finished request 12
Fri Dec 3 10:30:25 2004 : Debug: Going to the next request
Fri Dec 3 10:30:25 2004 : Debug: Thread 3 waiting to be assigned a request
Fri Dec 3 10:30:30 2004 : Debug: --- Walking the entire request list ---
Fri Dec 3 10:30:30 2004 : Debug: Threads: total/active/spare threads = 5/0/5
Fri Dec 3 10:30:30 2004 : Debug: Waking up in 1 seconds...
Fri Dec 3 10:30:31 2004 : Debug: --- Walking the entire request list ---
Fri Dec 3 10:30:31 2004 : Debug: Cleaning up request 12 ID 4 with timestamp
41b02421
Fri Dec 3 10:30:31 2004 : Debug: Nothing to do. Sleeping until we see a
request.
---------------------------------------------------------------------------------------------------------------
Sorry about the big logs but I think that it will spark a thought from
somebody who has been through this setup a few times and has trouble shooted
problems with freeradius.
Thanking you in advance
Adam
-
List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
