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