Odd proxy authentication failures
Michael Schlies
mschlies at 7sigma.com
Mon Oct 12 21:35:20 CEST 2009
Hello all,
I seem to be running into an issue with a RADIUS setup I am doing. I am
setting up a server that hosts 5 radius instances in 1.x and does realm
proxying to 4 of them but uses one realm (realm 'a.com' in this case) as
its default. so if requests for 'b.com', 'c.com', etc come in they get
relayed on to their radius server and that result is relayed back to the
NAS. In 2.0 I want to merge these separate instances into a single
instance using virtual servers. The problem I am running into is I can
see that accounts are being successfully authenticated on the virtual
servers however the home server is returning Access-Reject unless the
user authenticated is one of its local users... Here is what I have come
up with so far...
/etc/freeradius/radiusd.conf:
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
db_dir = $(raddbdir)
libdir = /usr/lib/freeradius
pidfile = ${run_dir}/freeradius.pid
user = freerad
group = freerad
max_request_time = 30
cleanup_delay = 5
max_requests = 1024
listen {
type = auth
ipaddr = *
port = 0
}
listen {
ipaddr = *
port = 0
type = acct
}
hostname_lookups = no
allow_core_dumps = no
regular_expressions = yes
extended_expressions = yes
log {
...
}
checkrad = ${sbindir}/checkrad
security {
max_attributes = 200
reject_delay = 1
status_server = yes
}
proxy_requests = yes
$INCLUDE proxy.conf
snmp = no
thread pool {
start_servers = 5
max_servers = 32
min_spare_servers = 3
max_spare_servers = 10
max_requests_per_server = 0
}
modules {
pap {
auto_header = no
}
chap {
authtype = CHAP
}
$INCLUDE eap.conf
realm IPASS {
format = prefix
delimiter = "/"
ignore_default = yes
ignore_null = yes
}
realm suffix {
format = suffix
delimiter = "@"
ignore_default = yes
ignore_null = yes
}
checkval {
item-name = Calling-Station-Id
check-name = Calling-Station-Id
data-type = string
}
preprocess {
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
header = "%t"
}
detail pre_proxy_log {
detailfile =
${radacctdir}/%{Client-IP-Address}/pre-proxy-detail-%Y%m%d
}
detail post_proxy_log {
detailfile = /tmp/post-proxy-detail
detailperm = 0600
}
acct_unique {
key = "User-Name, Acct-Session-Id, NAS-IP-Address,
Client-IP-Address, NAS-Port"
}
$INCLUDE 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 attr_filter.post-proxy {
attrsfile = ${confdir}/attrs
}
attr_filter attr_filter.pre-proxy {
attrsfile = ${confdir}/attrs.pre-proxy
}
attr_filter attr_filter.access_reject {
key = %{User-Name}
attrsfile = ${confdir}/attrs.access_reject
}
attr_filter attr_filter.accounting_response {
key = %{User-Name}
attrsfile = ${confdir}/attrs.accounting_response
}
always fail {
rcode = fail
}
always reject {
rcode = reject
}
always noop {
rcode = noop
}
always handled {
rcode = handled
}
always updated {
rcode = updated
}
always notfound {
rcode = notfound
}
always ok {
rcode = ok
simulcount = 0
mpp = no
}
expr {
}
digest {
}
expiration {
reply-message = "Password Has Expired\r\n"
}
logintime {
reply-message = "You are calling outside your allowed timespan\r\n"
minimum-timeout = 60
}
exec {
wait = yes
input_pairs = request
shell_escape = yes
output = none
}
exec echo {
wait = yes
program = "/bin/echo %{User-Name}"
input_pairs = request
output_pairs = reply
shell_escape = yes
}
}
instantiate {
exec
expr
expiration
logintime
}
$INCLUDE sites-enabled/
/etc/freeradius/sql-a.conf:
sql sql-a{
database = "mysql"
driver = "rlm_sql_${database}"
server = "192.168.188.3"
login = "radius"
password = "radiuspass"
radius_db = "radius"
acct_table1 = "radacct"
acct_table2 = "radacct"
postauth_table = "radpostauth"
authcheck_table = "radcheck"
authreply_table = "radreply"
groupcheck_table = "radgroupcheck"
groupreply_table = "radgroupreply"
usergroup_table = "usergroup"
deletestalesessions = yes
sqltrace = yes
sqltracefile = /tmp/sqltrace.sql
num_sql_socks = 5
connect_failure_retry_delay = 60
readclients = yes
nas_table = "nas"
$INCLUDE sql/${database}/dialup.conf
}
/etc/freeradius/sql-b.conf:
sql sql-a{
database = "mysql"
driver = "rlm_sql_${database}"
server = "192.168.188.3"
login = "radius"
password = "radiuspass"
radius_db = "radius_b"
acct_table1 = "radacct"
acct_table2 = "radacct"
postauth_table = "radpostauth"
authcheck_table = "radcheck"
authreply_table = "radreply"
groupcheck_table = "radgroupcheck"
groupreply_table = "radgroupreply"
usergroup_table = "usergroup"
deletestalesessions = yes
sqltrace = yes
sqltracefile = /tmp/sqltrace.sql
num_sql_socks = 5
connect_failure_retry_delay = 60
readclients = yes
nas_table = "nas"
$INCLUDE sql/${database}/dialup.conf
}
...
/etc/freeradius/sql-e.conf:
sql sql-a{
database = "mysql"
driver = "rlm_sql_${database}"
server = "192.168.188.3"
login = "radius"
password = "radiuspass"
radius_db = "radius_e"
acct_table1 = "radacct"
acct_table2 = "radacct"
postauth_table = "radpostauth"
authcheck_table = "radcheck"
authreply_table = "radreply"
groupcheck_table = "radgroupcheck"
groupreply_table = "radgroupreply"
usergroup_table = "usergroup"
deletestalesessions = yes
sqltrace = yes
sqltracefile = /tmp/sqltrace.sql
num_sql_socks = 5
connect_failure_retry_delay = 60
readclients = yes
nas_table = "nas"
$INCLUDE sql/${database}/dialup.conf
}
/etc/freeradius/sql/mysql/dialup.conf:
sql_user_name = "%{User-Name}"
default_user_profile = "DEFAULT"
nas_query = "SELECT id, nasname, shortname, type, secret FROM
${nas_table}"
authorize_check_query = "SELECT id, UserName, Attribute, Value, op
FROM ${authcheck_table} WHERE Username = '%{SQL-User-Name}' ORDER BY id"
authorize_reply_query = "SELECT id, UserName, Attribute, Value, op
FROM ${authreply_table} WHERE Username = '%{SQL-User-Name}' ORDER BY id"
authorize_group_check_query = "SELECT ${groupcheck_table}.id,
${groupcheck_table}.GroupName, ${groupcheck_table}.Attribute,
${groupcheck_table}.Value, ${groupcheck_table}.op FROM
${groupcheck_table}, ${usergroup_table} WHERE
${usergroup_table}.Username = '%{SQL-User-Name}' AND
${usergroup_table}.GroupName = ${groupcheck_table}.GroupName AND
${groupcheck_table}.HuntgroupName = '%{Huntgroup-Name}' ORDER BY
${groupcheck_table}.id"
authorize_group_reply_query = "SELECT id, GroupName, Attribute,
Value, op FROM ${groupreply_table} WHERE GroupName = '%{Sql-Group}'
ORDER BY id"
accounting_onoff_query = "UPDATE ${acct_table1} 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'"
accounting_update_query = "UPDATE ${acct_table1} \
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}'"
accounting_update_query_alt = "INSERT into ${acct_table1}
(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')"
accounting_start_query = "INSERT into ${acct_table1}
(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')"
accounting_start_query_alt = "UPDATE ${acct_table1} 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}'"
accounting_stop_query = "UPDATE ${acct_table2} 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}'"
accounting_stop_query_alt = "INSERT into ${acct_table2}
(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}')"
simul_count_query = "SELECT COUNT(*) FROM ${acct_table1} WHERE
UserName='%{SQL-User-Name}' AND AcctStopTime = 0"
simul_verify_query = "SELECT RadAcctId, AcctSessionId, UserName,
NASIPAddress, NASPortId, FramedIPAddress, CallingStationId,
FramedProtocol FROM ${acct_table1} WHERE UserName='%{SQL-User-Name}' AND
AcctStopTime = 0"
group_membership_query = "SELECT GroupName FROM ${usergroup_table}
WHERE UserName = '%{SQL-User-Name}' AND HuntGroupName =
'%{Huntgroup-Name}'"
/etc/freeradius/sites-enabled/virtuals:
server a {
$INCLUDE ${confdir}/sites-available/a
}
server b {
$INCLUDE ${confdir}/sites-available/b
}
server c {
$INCLUDE ${confdir}/sites-available/c
}
server d {
$INCLUDE ${confdir}/sites-available/d
}
server e {
$INCLUDE ${confdir}/sites-available/e
}
/etc/freeradius/sites-enabled/a:
checkrad = ${raddbdir}/checkrad-a
authorize {
preprocess
update request {
Huntgroup-Name := "%{sql-a:SELECT huntgroup FROM nas WHERE
nasname=\"%{NAS-IP-Address}\"}"
}
chap
IPASS {
updated = return
ok = return
}
suffix {
updated = return
ok = return
}
files
sql-a
}
authenticate {
Auth-Type PAP {
pap
}
}
preacct {
preprocess
acct_unique
suffix
files
}
accounting {
sql-a
}
session {
sql-a
}
post-auth {
sql-a
}
pre-proxy {
pre_proxy_log
}
post-proxy {
post_proxy_log
# attr_filter.post-proxy
}
/etc/freeradius/sites-available/b:
checkrad = ${raddbdir}/checkrad-b
authorize {
preprocess
update request {
Huntgroup-Name := "%{sql-b:SELECT huntgroup FROM allnas WHERE
nasname=\"%{NAS-IP-Address}\"}"
}
chap
IPASS {
updated = return
ok = return
}
suffix {
updated = return
ok = return
}
files
sql-b
}
authenticate {
Auth-Type PAP {
pap
}
}
preacct {
preprocess
acct_unique
suffix
files
}
accounting {
sql-b
}
session {
sql-b
}
post-auth {
sql-b
}
pre-proxy {
pre_proxy_log
}
post-proxy {
}
/etc/freeradius/sites-available/c:
checkrad = ${raddbdir}/checkrad-c
authorize {
preprocess
update request {
Huntgroup-Name := "%{sql-c:SELECT huntgroup FROM allnas WHERE
nasname=\"%{NAS-IP-Address}\"}"
}
chap
IPASS {
updated = return
ok = return
}
suffix {
updated = return
ok = return
}
files
sql-c
}
authenticate {
Auth-Type PAP {
pap
}
}
preacct {
preprocess
acct_unique
suffix
files
}
accounting {
sql-c
}
session {
sql-c
}
post-auth {
sql-c
}
pre-proxy {
pre_proxy_log
}
post-proxy {
}
/etc/freeradius/sites-available/d:
checkrad = ${raddbdir}/checkrad-d
authorize {
preprocess
update request {
Huntgroup-Name := "%{sql-d:SELECT huntgroup FROM allnas WHERE
nasname=\"%{NAS-IP-Address}\"}"
}
chap
IPASS {
updated = return
ok = return
}
suffix {
updated = return
ok = return
}
files
sql-d
}
authenticate {
Auth-Type PAP {
pap
}
}
preacct {
preprocess
acct_unique
suffix
files
}
accounting {
sql-d
}
session {
sql-d
}
post-auth {
sql-d
}
pre-proxy {
pre_proxy_log
}
post-proxy {
}
/etc/freeradius/sites-available/e:
checkrad = ${raddbdir}/checkrad-e
authorize {
preprocess
update request {
Huntgroup-Name := "%{sql-e:SELECT huntgroup FROM allnas WHERE
nasname=\"%{NAS-IP-Address}\"}"
}
chap
IPASS {
updated = return
ok = return
}
suffix {
updated = return
ok = return
}
files
sql-e
}
authenticate {
Auth-Type PAP {
pap
}
}
preacct {
preprocess
acct_unique
suffix
files
}
accounting {
sql-e
}
session {
sql-e
}
post-auth {
sql-e
}
pre-proxy {
pre_proxy_log
}
post-proxy {
}
The log messages I am seeing are as follows:
Mon Oct 12 13:39:36 2009 : Info: FreeRADIUS Version 2.0.4, for host
x86_64-pc-linux-gnu, built on Sep 7 2008 at 17:42:33
Mon Oct 12 13:39:36 2009 : Info: Starting - reading configuration files ...
Mon Oct 12 13:39:36 2009 : Debug: including configuration file
/etc/freeradius/radiusd.conf
Mon Oct 12 13:39:36 2009 : Debug: including configuration file
/etc/freeradius/proxy.conf
Mon Oct 12 13:39:36 2009 : Debug: including configuration file
/etc/freeradius/snmp.conf
Mon Oct 12 13:39:36 2009 : Debug: including configuration file
/etc/freeradius/eap.conf
Mon Oct 12 13:39:36 2009 : Debug: including configuration file
/etc/freeradius/sql-a.conf
Mon Oct 12 13:39:36 2009 : Debug: including configuration file
/etc/freeradius/sql/mysql/dialup.conf
Mon Oct 12 13:39:36 2009 : Debug: including configuration file
/etc/freeradius/sql-d.conf
Mon Oct 12 13:39:36 2009 : Debug: including configuration file
/etc/freeradius/sql/mysql/dialup.conf
Mon Oct 12 13:39:36 2009 : Debug: including configuration file
/etc/freeradius/sql-b.conf
Mon Oct 12 13:39:36 2009 : Debug: including configuration file
/etc/freeradius/sql/mysql/dialup.conf
Mon Oct 12 13:39:36 2009 : Debug: including configuration file
/etc/freeradius/sql-c.conf
Mon Oct 12 13:39:36 2009 : Debug: including configuration file
/etc/freeradius/sql/mysql/dialup.conf
Mon Oct 12 13:39:36 2009 : Debug: including configuration file
/etc/freeradius/sql-e.conf
Mon Oct 12 13:39:36 2009 : Debug: including configuration file
/etc/freeradius/sql/mysql/dialup.conf
Mon Oct 12 13:39:36 2009 : Debug: including files in directory
/etc/freeradius/sites-enabled/
Mon Oct 12 13:39:36 2009 : Debug: including configuration file
/etc/freeradius/sites-enabled/a
Mon Oct 12 13:39:36 2009 : Debug: including configuration file
/etc/freeradius/sites-enabled/virtuals
Mon Oct 12 13:39:36 2009 : Debug: including configuration file
/etc/freeradius/sites-available/a
Mon Oct 12 13:39:36 2009 : Debug: including configuration file
/etc/freeradius/sites-available/d
Mon Oct 12 13:39:36 2009 : Debug: including configuration file
/etc/freeradius/sites-available/c
Mon Oct 12 13:39:36 2009 : Debug: including configuration file
/etc/freeradius/sites-available/b
Mon Oct 12 13:39:36 2009 : Debug: including configuration file
/etc/freeradius/sites-available/e
Mon Oct 12 13:39:36 2009 : Debug: including dictionary file
/etc/freeradius/dictionary
Mon Oct 12 13:39:36 2009 : Debug: main {
Mon Oct 12 13:39:36 2009 : Debug: prefix = "/usr"
Mon Oct 12 13:39:36 2009 : Debug: localstatedir = "/var"
Mon Oct 12 13:39:36 2009 : Debug: logdir = "/var/log/freeradius"
Mon Oct 12 13:39:36 2009 : Debug: libdir = "/usr/lib/freeradius"
Mon Oct 12 13:39:36 2009 : Debug: radacctdir =
"/var/log/freeradius/radacct"
Mon Oct 12 13:39:36 2009 : Debug: hostname_lookups = no
Mon Oct 12 13:39:36 2009 : Debug: max_request_time = 30
Mon Oct 12 13:39:36 2009 : Debug: cleanup_delay = 5
Mon Oct 12 13:39:36 2009 : Debug: max_requests = 1024
Mon Oct 12 13:39:36 2009 : Debug: allow_core_dumps = no
Mon Oct 12 13:39:36 2009 : Debug: pidfile =
"/var/run/freeradius/freeradius.pid"
Mon Oct 12 13:39:36 2009 : Debug: user = "freerad"
Mon Oct 12 13:39:36 2009 : Debug: group = "freerad"
Mon Oct 12 13:39:36 2009 : Debug: checkrad = "/usr/sbin/checkrad"
Mon Oct 12 13:39:36 2009 : Debug: debug_level = 0
Mon Oct 12 13:39:36 2009 : Debug: proxy_requests = yes
Mon Oct 12 13:39:36 2009 : Debug: security {
Mon Oct 12 13:39:36 2009 : Debug: max_attributes = 200
Mon Oct 12 13:39:36 2009 : Debug: reject_delay = 1
Mon Oct 12 13:39:36 2009 : Debug: status_server = yes
Mon Oct 12 13:39:36 2009 : Debug: }
Mon Oct 12 13:39:36 2009 : Debug: }
Mon Oct 12 13:39:36 2009 : Debug: radiusd: #### Loading Realms and Home
Servers ####
Mon Oct 12 13:39:36 2009 : Debug: proxy server {
Mon Oct 12 13:39:36 2009 : Debug: retry_delay = 5
Mon Oct 12 13:39:36 2009 : Debug: retry_count = 3
Mon Oct 12 13:39:36 2009 : Debug: default_fallback = no
Mon Oct 12 13:39:36 2009 : Debug: dead_time = 120
Mon Oct 12 13:39:36 2009 : Debug: wake_all_if_all_dead = no
Mon Oct 12 13:39:36 2009 : Debug: }
Mon Oct 12 13:39:36 2009 : Debug: realm example.com {
Mon Oct 12 13:39:36 2009 : Debug: }
Mon Oct 12 13:39:36 2009 : Debug: realm NULL {
Mon Oct 12 13:39:36 2009 : Debug: }
Mon Oct 12 13:39:36 2009 : Debug: realm DEFAULT {
Mon Oct 12 13:39:36 2009 : Debug: }
Mon Oct 12 13:39:36 2009 : Debug: realm a.com {
Mon Oct 12 13:39:36 2009 : Debug: virtual_server = a
Mon Oct 12 13:39:36 2009 : Debug: }
Mon Oct 12 13:39:36 2009 : Debug: realm b.com {
Mon Oct 12 13:39:36 2009 : Debug: virtual_server = b
Mon Oct 12 13:39:36 2009 : Debug: }
Mon Oct 12 13:39:36 2009 : Debug: realm c.com {
Mon Oct 12 13:39:36 2009 : Debug: virtual_server = c
Mon Oct 12 13:39:36 2009 : Debug: }
Mon Oct 12 13:39:36 2009 : Debug: realm d.com {
Mon Oct 12 13:39:36 2009 : Debug: virtual_server = d
Mon Oct 12 13:39:36 2009 : Debug: }
Mon Oct 12 13:39:36 2009 : Debug: realm e.com {
Mon Oct 12 13:39:36 2009 : Debug: virtual_server = e
Mon Oct 12 13:39:36 2009 : Debug: }
Mon Oct 12 13:39:36 2009 : Debug: radiusd: #### Instantiating modules ####
Mon Oct 12 13:39:36 2009 : Debug: instantiate {
Mon Oct 12 13:39:36 2009 : Debug: (Loaded rlm_exec, checking if it's
valid)
Mon Oct 12 13:39:36 2009 : Debug: Module: Linked to module rlm_exec
Mon Oct 12 13:39:36 2009 : Debug: Module: Instantiating exec
Mon Oct 12 13:39:36 2009 : Debug: exec {
Mon Oct 12 13:39:36 2009 : Debug: wait = yes
Mon Oct 12 13:39:36 2009 : Debug: input_pairs = "request"
Mon Oct 12 13:39:36 2009 : Debug: shell_escape = yes
Mon Oct 12 13:39:36 2009 : Debug: }
Mon Oct 12 13:39:36 2009 : Debug: (Loaded rlm_expr, checking if it's
valid)
Mon Oct 12 13:39:36 2009 : Debug: Module: Linked to module rlm_expr
Mon Oct 12 13:39:36 2009 : Debug: Module: Instantiating expr
Mon Oct 12 13:39:36 2009 : Debug: (Loaded rlm_expiration, checking
if it's valid)
Mon Oct 12 13:39:36 2009 : Debug: Module: Linked to module rlm_expiration
Mon Oct 12 13:39:36 2009 : Debug: Module: Instantiating expiration
Mon Oct 12 13:39:36 2009 : Debug: expiration {
Mon Oct 12 13:39:36 2009 : Debug: reply-message = "Password Has
Expired "
Mon Oct 12 13:39:36 2009 : Debug: }
Mon Oct 12 13:39:36 2009 : Debug: (Loaded rlm_logintime, checking if
it's valid)
Mon Oct 12 13:39:36 2009 : Debug: Module: Linked to module rlm_logintime
Mon Oct 12 13:39:36 2009 : Debug: Module: Instantiating logintime
Mon Oct 12 13:39:36 2009 : Debug: logintime {
Mon Oct 12 13:39:36 2009 : Debug: reply-message = "You are calling
outside your allowed timespan "
Mon Oct 12 13:39:36 2009 : Debug: minimum-timeout = 60
Mon Oct 12 13:39:36 2009 : Debug: }
Mon Oct 12 13:39:36 2009 : Debug: }
Mon Oct 12 13:39:36 2009 : Debug: radiusd: #### Loading Virtual Servers
####
Mon Oct 12 13:39:36 2009 : Debug: server a {
Mon Oct 12 13:39:36 2009 : Debug: modules {
Mon Oct 12 13:39:36 2009 : Debug: Module: Checking authenticate {...}
for more modules to load
Mon Oct 12 13:39:36 2009 : Debug: (Loaded rlm_pap, checking if it's
valid)
Mon Oct 12 13:39:36 2009 : Debug: Module: Linked to module rlm_pap
Mon Oct 12 13:39:36 2009 : Debug: Module: Instantiating pap
Mon Oct 12 13:39:36 2009 : Debug: pap {
Mon Oct 12 13:39:36 2009 : Debug: encryption_scheme = "auto"
Mon Oct 12 13:39:36 2009 : Debug: auto_header = no
Mon Oct 12 13:39:36 2009 : Debug: }
Mon Oct 12 13:39:36 2009 : Debug: Module: Checking authorize {...} for
more modules to load
Mon Oct 12 13:39:36 2009 : Debug: (Loaded rlm_preprocess, checking
if it's valid)
Mon Oct 12 13:39:36 2009 : Debug: Module: Linked to module rlm_preprocess
Mon Oct 12 13:39:36 2009 : Debug: Module: Instantiating preprocess
Mon Oct 12 13:39:36 2009 : Debug: preprocess {
Mon Oct 12 13:39:36 2009 : Debug: huntgroups =
"/etc/freeradius/huntgroups"
Mon Oct 12 13:39:36 2009 : Debug: hints = "/etc/freeradius/hints"
Mon Oct 12 13:39:36 2009 : Debug: with_ascend_hack = no
Mon Oct 12 13:39:36 2009 : Debug: ascend_channels_per_line = 23
Mon Oct 12 13:39:36 2009 : Debug: with_ntdomain_hack = no
Mon Oct 12 13:39:36 2009 : Debug: with_specialix_jetstream_hack = no
Mon Oct 12 13:39:36 2009 : Debug: with_cisco_vsa_hack = no
Mon Oct 12 13:39:36 2009 : Debug: with_alvarion_vsa_hack = no
Mon Oct 12 13:39:36 2009 : Debug: }
Mon Oct 12 13:39:36 2009 : Debug: (Loaded rlm_chap, checking if it's
valid)
Mon Oct 12 13:39:36 2009 : Debug: Module: Linked to module rlm_chap
Mon Oct 12 13:39:36 2009 : Debug: Module: Instantiating chap
Mon Oct 12 13:39:36 2009 : Debug: (Loaded rlm_realm, checking if
it's valid)
Mon Oct 12 13:39:36 2009 : Debug: Module: Linked to module rlm_realm
Mon Oct 12 13:39:36 2009 : Debug: Module: Instantiating IPASS
Mon Oct 12 13:39:36 2009 : Debug: realm IPASS {
Mon Oct 12 13:39:36 2009 : Debug: format = "prefix"
Mon Oct 12 13:39:36 2009 : Debug: delimiter = "/"
Mon Oct 12 13:39:36 2009 : Debug: ignore_default = yes
Mon Oct 12 13:39:36 2009 : Debug: ignore_null = yes
Mon Oct 12 13:39:36 2009 : Debug: }
Mon Oct 12 13:39:36 2009 : Debug: Module: Instantiating suffix
Mon Oct 12 13:39:36 2009 : Debug: realm suffix {
Mon Oct 12 13:39:36 2009 : Debug: format = "suffix"
Mon Oct 12 13:39:36 2009 : Debug: delimiter = "@"
Mon Oct 12 13:39:36 2009 : Debug: ignore_default = yes
Mon Oct 12 13:39:36 2009 : Debug: ignore_null = yes
Mon Oct 12 13:39:36 2009 : Debug: }
Mon Oct 12 13:39:36 2009 : Debug: (Loaded rlm_files, checking if
it's valid)
Mon Oct 12 13:39:36 2009 : Debug: Module: Linked to module rlm_files
Mon Oct 12 13:39:36 2009 : Debug: Module: Instantiating files
Mon Oct 12 13:39:36 2009 : Debug: files {
Mon Oct 12 13:39:36 2009 : Debug: acctusersfile =
"/etc/freeradius/acct_users"
Mon Oct 12 13:39:36 2009 : Debug: preproxy_usersfile =
"/etc/freeradius/preproxy_users"
Mon Oct 12 13:39:36 2009 : Debug: compat = "no"
Mon Oct 12 13:39:36 2009 : Debug: }
Mon Oct 12 13:39:36 2009 : Debug: (Loaded rlm_sql, checking if it's
valid)
Mon Oct 12 13:39:36 2009 : Debug: Module: Linked to module rlm_sql
Mon Oct 12 13:39:36 2009 : Debug: Module: Instantiating sql-a
Mon Oct 12 13:39:36 2009 : Debug: sql sql-a {
Mon Oct 12 13:39:36 2009 : Debug: driver = "rlm_sql_mysql"
Mon Oct 12 13:39:36 2009 : Debug: server = "192.168.188.3"
Mon Oct 12 13:39:36 2009 : Debug: port = ""
Mon Oct 12 13:39:36 2009 : Debug: login = "radius"
Mon Oct 12 13:39:36 2009 : Debug: password = "radiuspass"
Mon Oct 12 13:39:36 2009 : Debug: radius_db = "radius"
Mon Oct 12 13:39:36 2009 : Debug: read_groups = yes
Mon Oct 12 13:39:36 2009 : Debug: sqltrace = yes
Mon Oct 12 13:39:36 2009 : Debug: sqltracefile = "/tmp/sqltrace.sql"
Mon Oct 12 13:39:36 2009 : Debug: readclients = yes
Mon Oct 12 13:39:36 2009 : Debug: deletestalesessions = yes
Mon Oct 12 13:39:36 2009 : Debug: num_sql_socks = 5
Mon Oct 12 13:39:36 2009 : Debug: sql_user_name = "%{User-Name}"
Mon Oct 12 13:39:36 2009 : Debug: default_user_profile = "DEFAULT"
Mon Oct 12 13:39:36 2009 : Debug: nas_query = "SELECT id, nasname,
shortname, type, secret FROM nas"
Mon Oct 12 13:39:36 2009 : Debug: authorize_check_query = "SELECT
id, UserName, Attribute, Value, op FROM radcheck WHERE Username =
'%{SQL-User-Name}' ORDER BY id"
Mon Oct 12 13:39:36 2009 : Debug: authorize_reply_query = "SELECT
id, UserName, Attribute, Value, op FROM radreply WHERE Username =
'%{SQL-User-Name}' ORDER BY id"
Mon Oct 12 13:39:36 2009 : Debug: 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 AND
radgroupcheck.HuntgroupName = '%{Huntgroup-Name}' ORDER BY
radgroupcheck.id"
Mon Oct 12 13:39:36 2009 : Debug: authorize_group_reply_query =
"SELECT id, GroupName, Attribute, Value, op FROM radgroupreply WHERE
GroupName = '%{Sql-Group}' ORDER BY id"
Mon Oct 12 13:39:36 2009 : Debug: 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'"
Mon Oct 12 13:39:36 2009 : Debug: 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}'"
Mon Oct 12 13:39:36 2009 : Debug: 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')"
Mon Oct 12 13:39:36 2009 : Debug: 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')"
Mon Oct 12 13:39:36 2009 : Debug: 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}'"
Mon Oct 12 13:39:36 2009 : Debug: 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}'"
Mon Oct 12 13:39:36 2009 : Debug: 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}')"
Mon Oct 12 13:39:36 2009 : Debug: group_membership_query = "SELECT
GroupName FROM usergroup WHERE UserName = '%{SQL-User-Name}' AND
HuntGroupName = '%{Huntgroup-Name}'"
Mon Oct 12 13:39:36 2009 : Debug: connect_failure_retry_delay = 60
Mon Oct 12 13:39:36 2009 : Debug: simul_count_query = "SELECT
COUNT(*) FROM radacct WHERE UserName='%{SQL-User-Name}' AND AcctStopTime
= 0"
Mon Oct 12 13:39:36 2009 : Debug: simul_verify_query = "SELECT
RadAcctId, AcctSessionId, UserName, NASIPAddress, NASPortId,
FramedIPAddress, CallingStationId, FramedProtocol FROM radacct WHERE
UserName='%{SQL-User-Name}' AND AcctStopTime = 0"
Mon Oct 12 13:39:36 2009 : Debug: postauth_query = ""
Mon Oct 12 13:39:36 2009 : Debug: safe-characters =
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
Mon Oct 12 13:39:36 2009 : Debug: }
Mon Oct 12 13:39:36 2009 : Info: rlm_sql (sql-a): Driver rlm_sql_mysql
(module rlm_sql_mysql) loaded and linked
Mon Oct 12 13:39:36 2009 : Info: rlm_sql (sql-a): Attempting to connect
to radius at 192.168.188.3:/radius
Mon Oct 12 13:39:36 2009 : Debug: rlm_sql (sql-a): starting 0
Mon Oct 12 13:39:36 2009 : Debug: rlm_sql (sql-a): Attempting to connect
rlm_sql_mysql #0
Mon Oct 12 13:39:36 2009 : Info: rlm_sql_mysql: Starting connect to
MySQL server for #0
Mon Oct 12 13:39:36 2009 : Debug: rlm_sql (sql-a): Connected new DB
handle, #0
...
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-a): starting 4
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-a): Attempting to connect
rlm_sql_mysql #4
Mon Oct 12 13:39:37 2009 : Info: rlm_sql_mysql: Starting connect to
MySQL server for #4
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-a): Connected new DB
handle, #4
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-a): Processing
generate_sql_clients
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-a) in
generate_sql_clients: query is SELECT id, nasname, shortname, type,
secret FROM nas
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-a): Reserving sql socket
id: 4
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql_mysql: query: SELECT id,
nasname, shortname, type, secret FROM nas
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-a): Read entry
nasname=127.0.0.1,shortname=Mike Test,secret=secret
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-a): Adding client
127.0.0.1 (Mike Test, server=<none>) to clients list
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-a): Released sql socket
id: 4
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking preacct {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: (Loaded rlm_acct_unique, checking
if it's valid)
Mon Oct 12 13:39:37 2009 : Debug: Module: Linked to module rlm_acct_unique
Mon Oct 12 13:39:37 2009 : Debug: Module: Instantiating acct_unique
Mon Oct 12 13:39:37 2009 : Debug: acct_unique {
Mon Oct 12 13:39:37 2009 : Debug: key = "User-Name, Acct-Session-Id,
NAS-IP-Address, Client-IP-Address, NAS-Port"
Mon Oct 12 13:39:37 2009 : Debug: }
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking accounting {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking session {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking pre-proxy {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: (Loaded rlm_detail, checking if
it's valid)
Mon Oct 12 13:39:37 2009 : Debug: Module: Linked to module rlm_detail
Mon Oct 12 13:39:37 2009 : Debug: Module: Instantiating pre_proxy_log
Mon Oct 12 13:39:37 2009 : Debug: detail pre_proxy_log {
Mon Oct 12 13:39:37 2009 : Debug: detailfile =
"/var/log/freeradius/radacct/%{Client-IP-Address}/pre-proxy-detail-%Y%m%d"
Mon Oct 12 13:39:37 2009 : Debug: header = "%t"
Mon Oct 12 13:39:37 2009 : Debug: detailperm = 384
Mon Oct 12 13:39:37 2009 : Debug: dirperm = 493
Mon Oct 12 13:39:37 2009 : Debug: locking = no
Mon Oct 12 13:39:37 2009 : Debug: log_packet_header = no
Mon Oct 12 13:39:37 2009 : Debug: }
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking post-proxy {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Instantiating post_proxy_log
Mon Oct 12 13:39:37 2009 : Debug: detail post_proxy_log {
Mon Oct 12 13:39:37 2009 : Debug: detailfile = "/tmp/post-proxy-detail"
Mon Oct 12 13:39:37 2009 : Debug: header = "%t"
Mon Oct 12 13:39:37 2009 : Debug: detailperm = 384
Mon Oct 12 13:39:37 2009 : Debug: dirperm = 493
Mon Oct 12 13:39:37 2009 : Debug: locking = no
Mon Oct 12 13:39:37 2009 : Debug: log_packet_header = no
Mon Oct 12 13:39:37 2009 : Debug: }
Mon Oct 12 13:39:37 2009 : Debug: (Loaded rlm_attr_filter, checking
if it's valid)
Mon Oct 12 13:39:37 2009 : Debug: Module: Linked to module rlm_attr_filter
Mon Oct 12 13:39:37 2009 : Debug: Module: Instantiating
attr_filter.post-proxy
Mon Oct 12 13:39:37 2009 : Debug: attr_filter attr_filter.post-proxy {
Mon Oct 12 13:39:37 2009 : Debug: attrsfile = "/etc/freeradius/attrs"
Mon Oct 12 13:39:37 2009 : Debug: key = "%{Realm}"
Mon Oct 12 13:39:37 2009 : Debug: }
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking post-auth {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: }
Mon Oct 12 13:39:37 2009 : Debug: }
Mon Oct 12 13:39:37 2009 : Debug: server d {
Mon Oct 12 13:39:37 2009 : Debug: modules {
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking authenticate {...}
for more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking authorize {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Instantiating sql-d
Mon Oct 12 13:39:37 2009 : Debug: sql sql-d {
Mon Oct 12 13:39:37 2009 : Debug: driver = "rlm_sql_mysql"
Mon Oct 12 13:39:37 2009 : Debug: server = "192.168.188.3"
Mon Oct 12 13:39:37 2009 : Debug: port = ""
Mon Oct 12 13:39:37 2009 : Debug: login = "radius"
Mon Oct 12 13:39:37 2009 : Debug: password = "radiuspass"
Mon Oct 12 13:39:37 2009 : Debug: radius_db = "radius_d"
Mon Oct 12 13:39:37 2009 : Debug: read_groups = yes
Mon Oct 12 13:39:37 2009 : Debug: sqltrace = yes
Mon Oct 12 13:39:37 2009 : Debug: sqltracefile = "/tmp/sqltrace.sql"
Mon Oct 12 13:39:37 2009 : Debug: readclients = yes
Mon Oct 12 13:39:37 2009 : Debug: deletestalesessions = yes
Mon Oct 12 13:39:37 2009 : Debug: num_sql_socks = 5
Mon Oct 12 13:39:37 2009 : Debug: sql_user_name = "%{User-Name}"
Mon Oct 12 13:39:37 2009 : Debug: default_user_profile = "DEFAULT"
Mon Oct 12 13:39:37 2009 : Debug: nas_query = "SELECT id, nasname,
shortname, type, secret FROM nas"
Mon Oct 12 13:39:37 2009 : Debug: authorize_check_query = "SELECT
id, UserName, Attribute, Value, op FROM radcheck WHERE Username =
'%{SQL-User-Name}' ORDER BY id"
Mon Oct 12 13:39:37 2009 : Debug: authorize_reply_query = "SELECT
id, UserName, Attribute, Value, op FROM radreply WHERE Username =
'%{SQL-User-Name}' ORDER BY id"
Mon Oct 12 13:39:37 2009 : Debug: 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 AND
radgroupcheck.HuntgroupName = '%{Huntgroup-Name}' ORDER BY
radgroupcheck.id"
Mon Oct 12 13:39:37 2009 : Debug: authorize_group_reply_query =
"SELECT id, GroupName, Attribute, Value, op FROM radgroupreply WHERE
GroupName = '%{Sql-Group}' ORDER BY id"
Mon Oct 12 13:39:37 2009 : Debug: 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'"
Mon Oct 12 13:39:37 2009 : Debug: 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}'"
Mon Oct 12 13:39:37 2009 : Debug: 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')"
Mon Oct 12 13:39:37 2009 : Debug: 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')"
Mon Oct 12 13:39:37 2009 : Debug: 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}'"
Mon Oct 12 13:39:37 2009 : Debug: 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}'"
Mon Oct 12 13:39:37 2009 : Debug: 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}')"
Mon Oct 12 13:39:37 2009 : Debug: group_membership_query = "SELECT
GroupName FROM usergroup WHERE UserName = '%{SQL-User-Name}' AND
HuntGroupName = '%{Huntgroup-Name}'"
Mon Oct 12 13:39:37 2009 : Debug: connect_failure_retry_delay = 60
Mon Oct 12 13:39:37 2009 : Debug: simul_count_query = "SELECT
COUNT(*) FROM radacct WHERE UserName='%{SQL-User-Name}' AND AcctStopTime
= 0"
Mon Oct 12 13:39:37 2009 : Debug: simul_verify_query = "SELECT
RadAcctId, AcctSessionId, UserName, NASIPAddress, NASPortId,
FramedIPAddress, CallingStationId, FramedProtocol FROM radacct WHERE
UserName='%{SQL-User-Name}' AND AcctStopTime = 0"
Mon Oct 12 13:39:37 2009 : Debug: postauth_query = ""
Mon Oct 12 13:39:37 2009 : Debug: safe-characters =
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
Mon Oct 12 13:39:37 2009 : Debug: }
Mon Oct 12 13:39:37 2009 : Info: rlm_sql (sql-d): Driver rlm_sql_mysql
(module rlm_sql_mysql) loaded and linked
Mon Oct 12 13:39:37 2009 : Info: rlm_sql (sql-d): Attempting to connect
to radius at 192.168.188.3:/radius_d
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-d): starting 0
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-d): Attempting to connect
rlm_sql_mysql #0
Mon Oct 12 13:39:37 2009 : Info: rlm_sql_mysql: Starting connect to
MySQL server for #0
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-d): Connected new DB
handle, #0
...
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-d): starting 4
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-d): Attempting to connect
rlm_sql_mysql #4
Mon Oct 12 13:39:37 2009 : Info: rlm_sql_mysql: Starting connect to
MySQL server for #4
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-d): Connected new DB
handle, #4
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-d): Processing
generate_sql_clients
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-d) in
generate_sql_clients: query is SELECT id, nasname, shortname, type,
secret FROM nas
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-d): Reserving sql socket
id: 4
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql_mysql: query: SELECT id,
nasname, shortname, type, secret FROM nas
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-d): Released sql socket
id: 4
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking preacct {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking accounting {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking session {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking pre-proxy {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking post-auth {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: }
Mon Oct 12 13:39:37 2009 : Debug: }
Mon Oct 12 13:39:37 2009 : Debug: server c {
Mon Oct 12 13:39:37 2009 : Debug: modules {
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking authenticate {...}
for more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking authorize {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Instantiating sql-c
Mon Oct 12 13:39:37 2009 : Debug: sql sql-c {
Mon Oct 12 13:39:37 2009 : Debug: driver = "rlm_sql_mysql"
Mon Oct 12 13:39:37 2009 : Debug: server = "192.168.188.3"
Mon Oct 12 13:39:37 2009 : Debug: port = ""
Mon Oct 12 13:39:37 2009 : Debug: login = "radius"
Mon Oct 12 13:39:37 2009 : Debug: password = "radiuspass"
Mon Oct 12 13:39:37 2009 : Debug: radius_db = "radius_c"
Mon Oct 12 13:39:37 2009 : Debug: read_groups = yes
Mon Oct 12 13:39:37 2009 : Debug: sqltrace = yes
Mon Oct 12 13:39:37 2009 : Debug: sqltracefile = "/tmp/sqltrace.sql"
Mon Oct 12 13:39:37 2009 : Debug: readclients = yes
Mon Oct 12 13:39:37 2009 : Debug: deletestalesessions = yes
Mon Oct 12 13:39:37 2009 : Debug: num_sql_socks = 5
Mon Oct 12 13:39:37 2009 : Debug: sql_user_name = "%{User-Name}"
Mon Oct 12 13:39:37 2009 : Debug: default_user_profile = "DEFAULT"
Mon Oct 12 13:39:37 2009 : Debug: nas_query = "SELECT id, nasname,
shortname, type, secret FROM nas"
Mon Oct 12 13:39:37 2009 : Debug: authorize_check_query = "SELECT
id, UserName, Attribute, Value, op FROM radcheck WHERE Username =
'%{SQL-User-Name}' ORDER BY id"
Mon Oct 12 13:39:37 2009 : Debug: authorize_reply_query = "SELECT
id, UserName, Attribute, Value, op FROM radreply WHERE Username =
'%{SQL-User-Name}' ORDER BY id"
Mon Oct 12 13:39:37 2009 : Debug: 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 AND
radgroupcheck.HuntgroupName = '%{Huntgroup-Name}' ORDER BY
radgroupcheck.id"
Mon Oct 12 13:39:37 2009 : Debug: authorize_group_reply_query =
"SELECT id, GroupName, Attribute, Value, op FROM radgroupreply WHERE
GroupName = '%{Sql-Group}' ORDER BY id"
Mon Oct 12 13:39:37 2009 : Debug: 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'"
Mon Oct 12 13:39:37 2009 : Debug: 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}'"
Mon Oct 12 13:39:37 2009 : Debug: 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')"
Mon Oct 12 13:39:37 2009 : Debug: 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')"
Mon Oct 12 13:39:37 2009 : Debug: 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}'"
Mon Oct 12 13:39:37 2009 : Debug: 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}'"
Mon Oct 12 13:39:37 2009 : Debug: 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}')"
Mon Oct 12 13:39:37 2009 : Debug: group_membership_query = "SELECT
GroupName FROM usergroup WHERE UserName = '%{SQL-User-Name}' AND
HuntGroupName = '%{Huntgroup-Name}'"
Mon Oct 12 13:39:37 2009 : Debug: connect_failure_retry_delay = 60
Mon Oct 12 13:39:37 2009 : Debug: simul_count_query = "SELECT
COUNT(*) FROM radacct WHERE UserName='%{SQL-User-Name}' AND AcctStopTime
= 0"
Mon Oct 12 13:39:37 2009 : Debug: simul_verify_query = "SELECT
RadAcctId, AcctSessionId, UserName, NASIPAddress, NASPortId,
FramedIPAddress, CallingStationId, FramedProtocol FROM radacct WHERE
UserName='%{SQL-User-Name}' AND AcctStopTime = 0"
Mon Oct 12 13:39:37 2009 : Debug: postauth_query = ""
Mon Oct 12 13:39:37 2009 : Debug: safe-characters =
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
Mon Oct 12 13:39:37 2009 : Debug: }
Mon Oct 12 13:39:37 2009 : Info: rlm_sql (sql-c): Driver rlm_sql_mysql
(module rlm_sql_mysql) loaded and linked
Mon Oct 12 13:39:37 2009 : Info: rlm_sql (sql-c): Attempting to connect
to radius at 192.168.188.3:/radius_c
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-c): starting 0
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-c): Attempting to connect
rlm_sql_mysql #0
Mon Oct 12 13:39:37 2009 : Info: rlm_sql_mysql: Starting connect to
MySQL server for #0
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-c): Connected new DB
handle, #0
...
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-c): starting 4
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-c): Attempting to connect
rlm_sql_mysql #4
Mon Oct 12 13:39:37 2009 : Info: rlm_sql_mysql: Starting connect to
MySQL server for #4
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-c): Connected new DB
handle, #4
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-c): Processing
generate_sql_clients
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-c) in
generate_sql_clients: query is SELECT id, nasname, shortname, type,
secret FROM nas
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-c): Reserving sql socket
id: 4
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql_mysql: query: SELECT id,
nasname, shortname, type, secret FROM nas
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-c): Released sql socket
id: 4
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking preacct {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking accounting {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking session {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking pre-proxy {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking post-auth {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: }
Mon Oct 12 13:39:37 2009 : Debug: }
Mon Oct 12 13:39:37 2009 : Debug: server b {
Mon Oct 12 13:39:37 2009 : Debug: modules {
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking authenticate {...}
for more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking authorize {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Instantiating sql-b
Mon Oct 12 13:39:37 2009 : Debug: sql sql-b {
Mon Oct 12 13:39:37 2009 : Debug: driver = "rlm_sql_mysql"
Mon Oct 12 13:39:37 2009 : Debug: server = "192.168.188.3"
Mon Oct 12 13:39:37 2009 : Debug: port = ""
Mon Oct 12 13:39:37 2009 : Debug: login = "radius"
Mon Oct 12 13:39:37 2009 : Debug: password = "radiuspass"
Mon Oct 12 13:39:37 2009 : Debug: radius_db = "radius_b"
Mon Oct 12 13:39:37 2009 : Debug: read_groups = yes
Mon Oct 12 13:39:37 2009 : Debug: sqltrace = yes
Mon Oct 12 13:39:37 2009 : Debug: sqltracefile = "/tmp/sqltrace.sql"
Mon Oct 12 13:39:37 2009 : Debug: readclients = yes
Mon Oct 12 13:39:37 2009 : Debug: deletestalesessions = yes
Mon Oct 12 13:39:37 2009 : Debug: num_sql_socks = 5
Mon Oct 12 13:39:37 2009 : Debug: sql_user_name = "%{User-Name}"
Mon Oct 12 13:39:37 2009 : Debug: default_user_profile = "DEFAULT"
Mon Oct 12 13:39:37 2009 : Debug: nas_query = "SELECT id, nasname,
shortname, type, secret FROM nas"
Mon Oct 12 13:39:37 2009 : Debug: authorize_check_query = "SELECT
id, UserName, Attribute, Value, op FROM radcheck WHERE Username =
'%{SQL-User-Name}' ORDER BY id"
Mon Oct 12 13:39:37 2009 : Debug: authorize_reply_query = "SELECT
id, UserName, Attribute, Value, op FROM radreply WHERE Username =
'%{SQL-User-Name}' ORDER BY id"
Mon Oct 12 13:39:37 2009 : Debug: 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 AND
radgroupcheck.HuntgroupName = '%{Huntgroup-Name}' ORDER BY
radgroupcheck.id"
Mon Oct 12 13:39:37 2009 : Debug: authorize_group_reply_query =
"SELECT id, GroupName, Attribute, Value, op FROM radgroupreply WHERE
GroupName = '%{Sql-Group}' ORDER BY id"
Mon Oct 12 13:39:37 2009 : Debug: 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'"
Mon Oct 12 13:39:37 2009 : Debug: 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}'"
Mon Oct 12 13:39:37 2009 : Debug: 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')"
Mon Oct 12 13:39:37 2009 : Debug: 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')"
Mon Oct 12 13:39:37 2009 : Debug: 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}'"
Mon Oct 12 13:39:37 2009 : Debug: 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}'"
Mon Oct 12 13:39:37 2009 : Debug: 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}')"
Mon Oct 12 13:39:37 2009 : Debug: group_membership_query = "SELECT
GroupName FROM usergroup WHERE UserName = '%{SQL-User-Name}' AND
HuntGroupName = '%{Huntgroup-Name}'"
Mon Oct 12 13:39:37 2009 : Debug: connect_failure_retry_delay = 60
Mon Oct 12 13:39:37 2009 : Debug: simul_count_query = "SELECT
COUNT(*) FROM radacct WHERE UserName='%{SQL-User-Name}' AND AcctStopTime
= 0"
Mon Oct 12 13:39:37 2009 : Debug: simul_verify_query = "SELECT
RadAcctId, AcctSessionId, UserName, NASIPAddress, NASPortId,
FramedIPAddress, CallingStationId, FramedProtocol FROM radacct WHERE
UserName='%{SQL-User-Name}' AND AcctStopTime = 0"
Mon Oct 12 13:39:37 2009 : Debug: postauth_query = ""
Mon Oct 12 13:39:37 2009 : Debug: safe-characters =
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
Mon Oct 12 13:39:37 2009 : Debug: }
Mon Oct 12 13:39:37 2009 : Info: rlm_sql (sql-b): Driver rlm_sql_mysql
(module rlm_sql_mysql) loaded and linked
Mon Oct 12 13:39:37 2009 : Info: rlm_sql (sql-b): Attempting to connect
to radius at 192.168.188.3:/radius_b
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-b): starting 0
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-b): Attempting to connect
rlm_sql_mysql #0
Mon Oct 12 13:39:37 2009 : Info: rlm_sql_mysql: Starting connect to
MySQL server for #0
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-b): Connected new DB
handle, #0
...
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-b): starting 4
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-b): Attempting to connect
rlm_sql_mysql #4
Mon Oct 12 13:39:37 2009 : Info: rlm_sql_mysql: Starting connect to
MySQL server for #4
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-b): Connected new DB
handle, #4
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-b): Processing
generate_sql_clients
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-b) in
generate_sql_clients: query is SELECT id, nasname, shortname, type,
secret FROM nas
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-b): Reserving sql socket
id: 4
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql_mysql: query: SELECT id,
nasname, shortname, type, secret FROM nas
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-b): Released sql socket
id: 4
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking preacct {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking accounting {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking session {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking pre-proxy {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking post-auth {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: }
Mon Oct 12 13:39:37 2009 : Debug: }
Mon Oct 12 13:39:37 2009 : Debug: server e {
Mon Oct 12 13:39:37 2009 : Debug: modules {
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking authenticate {...}
for more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking authorize {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Instantiating sql-e
Mon Oct 12 13:39:37 2009 : Debug: sql sql-e {
Mon Oct 12 13:39:37 2009 : Debug: driver = "rlm_sql_mysql"
Mon Oct 12 13:39:37 2009 : Debug: server = "192.168.188.3"
Mon Oct 12 13:39:37 2009 : Debug: port = ""
Mon Oct 12 13:39:37 2009 : Debug: login = "radius"
Mon Oct 12 13:39:37 2009 : Debug: password = "radiuspass"
Mon Oct 12 13:39:37 2009 : Debug: radius_db = "radius_e"
Mon Oct 12 13:39:37 2009 : Debug: read_groups = yes
Mon Oct 12 13:39:37 2009 : Debug: sqltrace = yes
Mon Oct 12 13:39:37 2009 : Debug: sqltracefile = "/tmp/sqltrace.sql"
Mon Oct 12 13:39:37 2009 : Debug: readclients = yes
Mon Oct 12 13:39:37 2009 : Debug: deletestalesessions = yes
Mon Oct 12 13:39:37 2009 : Debug: num_sql_socks = 5
Mon Oct 12 13:39:37 2009 : Debug: sql_user_name = "%{User-Name}"
Mon Oct 12 13:39:37 2009 : Debug: default_user_profile = "DEFAULT"
Mon Oct 12 13:39:37 2009 : Debug: nas_query = "SELECT id, nasname,
shortname, type, secret FROM nas"
Mon Oct 12 13:39:37 2009 : Debug: authorize_check_query = "SELECT
id, UserName, Attribute, Value, op FROM radcheck WHERE Username =
'%{SQL-User-Name}' ORDER BY id"
Mon Oct 12 13:39:37 2009 : Debug: authorize_reply_query = "SELECT
id, UserName, Attribute, Value, op FROM radreply WHERE Username =
'%{SQL-User-Name}' ORDER BY id"
Mon Oct 12 13:39:37 2009 : Debug: 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 AND
radgroupcheck.HuntgroupName = '%{Huntgroup-Name}' ORDER BY
radgroupcheck.id"
Mon Oct 12 13:39:37 2009 : Debug: authorize_group_reply_query =
"SELECT id, GroupName, Attribute, Value, op FROM radgroupreply WHERE
GroupName = '%{Sql-Group}' ORDER BY id"
Mon Oct 12 13:39:37 2009 : Debug: 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'"
Mon Oct 12 13:39:37 2009 : Debug: 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}'"
Mon Oct 12 13:39:37 2009 : Debug: 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')"
Mon Oct 12 13:39:37 2009 : Debug: 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')"
Mon Oct 12 13:39:37 2009 : Debug: 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}'"
Mon Oct 12 13:39:37 2009 : Debug: 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}'"
Mon Oct 12 13:39:37 2009 : Debug: 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}')"
Mon Oct 12 13:39:37 2009 : Debug: group_membership_query = "SELECT
GroupName FROM usergroup WHERE UserName = '%{SQL-User-Name}' AND
HuntGroupName = '%{Huntgroup-Name}'"
Mon Oct 12 13:39:37 2009 : Debug: connect_failure_retry_delay = 60
Mon Oct 12 13:39:37 2009 : Debug: simul_count_query = "SELECT
COUNT(*) FROM radacct WHERE UserName='%{SQL-User-Name}' AND AcctStopTime
= 0"
Mon Oct 12 13:39:37 2009 : Debug: simul_verify_query = "SELECT
RadAcctId, AcctSessionId, UserName, NASIPAddress, NASPortId,
FramedIPAddress, CallingStationId, FramedProtocol FROM radacct WHERE
UserName='%{SQL-User-Name}' AND AcctStopTime = 0"
Mon Oct 12 13:39:37 2009 : Debug: postauth_query = ""
Mon Oct 12 13:39:37 2009 : Debug: safe-characters =
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
Mon Oct 12 13:39:37 2009 : Debug: }
Mon Oct 12 13:39:37 2009 : Info: rlm_sql (sql-e): Driver rlm_sql_mysql
(module rlm_sql_mysql) loaded and linked
Mon Oct 12 13:39:37 2009 : Info: rlm_sql (sql-e): Attempting to connect
to radius at 192.168.188.3:/radius_e
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-e): starting 0
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-e): Attempting to connect
rlm_sql_mysql #0
Mon Oct 12 13:39:37 2009 : Info: rlm_sql_mysql: Starting connect to
MySQL server for #0
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-e): Connected new DB
handle, #0
...
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-e): starting 4
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-e): Attempting to connect
rlm_sql_mysql #4
Mon Oct 12 13:39:37 2009 : Info: rlm_sql_mysql: Starting connect to
MySQL server for #4
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-e): Connected new DB
handle, #4
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-e): Processing
generate_sql_clients
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-e) in
generate_sql_clients: query is SELECT id, nasname, shortname, type,
secret FROM nas
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-e): Reserving sql socket
id: 4
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql_mysql: query: SELECT id,
nasname, shortname, type, secret FROM nas
Mon Oct 12 13:39:37 2009 : Debug: rlm_sql (sql-e): Released sql socket
id: 4
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking preacct {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking accounting {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking session {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking pre-proxy {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking post-auth {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: }
Mon Oct 12 13:39:37 2009 : Debug: }
Mon Oct 12 13:39:37 2009 : Debug: server {
Mon Oct 12 13:39:37 2009 : Debug: modules {
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking authenticate {...}
for more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking authorize {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking preacct {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking accounting {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking session {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking pre-proxy {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking post-proxy {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: Module: Checking post-auth {...} for
more modules to load
Mon Oct 12 13:39:37 2009 : Debug: }
Mon Oct 12 13:39:37 2009 : Debug: }
Mon Oct 12 13:39:37 2009 : Debug: radiusd: #### Opening IP addresses and
Ports ####
Mon Oct 12 13:39:37 2009 : Debug: listen {
Mon Oct 12 13:39:37 2009 : Debug: type = "auth"
Mon Oct 12 13:39:37 2009 : Debug: ipaddr = *
Mon Oct 12 13:39:37 2009 : Debug: port = 0
Mon Oct 12 13:39:37 2009 : Debug: }
Mon Oct 12 13:39:37 2009 : Debug: listen {
Mon Oct 12 13:39:37 2009 : Debug: type = "acct"
Mon Oct 12 13:39:37 2009 : Debug: ipaddr = *
Mon Oct 12 13:39:37 2009 : Debug: port = 0
Mon Oct 12 13:39:37 2009 : Debug: }
Mon Oct 12 13:39:37 2009 : Debug: main {
Mon Oct 12 13:39:37 2009 : Debug: snmp = no
Mon Oct 12 13:39:37 2009 : Debug: smux_password = ""
Mon Oct 12 13:39:37 2009 : Debug: snmp_write_access = no
Mon Oct 12 13:39:37 2009 : Debug: }
Mon Oct 12 13:39:37 2009 : Debug: Listening on authentication address *
port 1812
Mon Oct 12 13:39:37 2009 : Debug: Listening on accounting address * port
1813
Mon Oct 12 13:39:37 2009 : Debug: Listening on proxy address * port 1814
Mon Oct 12 13:39:37 2009 : Debug: Ready to process requests.
rad_recv: Access-Request packet from host 127.0.0.1 port 33589, id=193,
length=80
User-Name = "test at b.com"
User-Password = "12345"
NAS-IP-Address = 127.0.0.1
NAS-Port = 1
Framed-Protocol = PPP
Mon Oct 12 13:39:45 2009 : Debug: +- entering group authorize
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling
preprocess (rlm_preprocess) for request 0
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from
preprocess (rlm_preprocess) for request 0
Mon Oct 12 13:39:45 2009 : Debug: ++[preprocess] returns ok
Mon Oct 12 13:39:45 2009 : Debug: radius_xlat: Running registered xlat
function of module sql-a for string 'SELECT huntgroup FROM nas WHERE
nasname="%{NAS-IP-Address}"'
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): - sql_xlat
Mon Oct 12 13:39:45 2009 : Debug: expand: %{User-Name} -> test at b.com
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): sql_set_user escaped
user --> 'test at b.com'
Mon Oct 12 13:39:45 2009 : Debug: expand: SELECT huntgroup FROM nas
WHERE nasname="%{NAS-IP-Address}" -> SELECT huntgroup FROM nas WHERE
nasname="127.0.0.1"
Mon Oct 12 13:39:45 2009 : Debug: expand: /tmp/sqltrace.sql ->
/tmp/sqltrace.sql
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): Reserving sql socket
id: 3
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT
huntgroup FROM nas WHERE nasname="127.0.0.1"
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): - sql_xlat finished
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): Released sql socket
id: 3
Mon Oct 12 13:39:45 2009 : Debug: expand: %{sql-a:SELECT huntgroup
FROM nas WHERE nasname="%{NAS-IP-Address}"} -> dialup
Mon Oct 12 13:39:45 2009 : Debug: ::: FROM 1 TO 7 MAX 8
Mon Oct 12 13:39:45 2009 : Debug: ::: Examining Huntgroup-Name
Mon Oct 12 13:39:45 2009 : Debug: ::: APPENDING Huntgroup-Name FROM 0 TO 7
Mon Oct 12 13:39:45 2009 : Debug: ::: TO in 7 out 8
Mon Oct 12 13:39:45 2009 : Debug: ::: to[0] = User-Name
Mon Oct 12 13:39:45 2009 : Debug: ::: to[1] = User-Password
Mon Oct 12 13:39:45 2009 : Debug: ::: to[2] = NAS-IP-Address
Mon Oct 12 13:39:45 2009 : Debug: ::: to[3] = NAS-Port
Mon Oct 12 13:39:45 2009 : Debug: ::: to[4] = Framed-Protocol
Mon Oct 12 13:39:45 2009 : Debug: ::: to[5] = Service-Type
Mon Oct 12 13:39:45 2009 : Debug: ::: to[6] = SQL-User-Name
Mon Oct 12 13:39:45 2009 : Debug: ::: to[7] = Huntgroup-Name
Mon Oct 12 13:39:45 2009 : Debug: ++[request] returns ok
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling chap
(rlm_chap) for request 0
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from
chap (rlm_chap) for request 0
Mon Oct 12 13:39:45 2009 : Debug: ++[chap] returns noop
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling IPASS
(rlm_realm) for request 0
Mon Oct 12 13:39:45 2009 : Debug: rlm_realm: No '/' in User-Name =
"test at b.com", skipping NULL due to config.
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from
IPASS (rlm_realm) for request 0
Mon Oct 12 13:39:45 2009 : Debug: ++[IPASS] returns noop
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling suffix
(rlm_realm) for request 0
Mon Oct 12 13:39:45 2009 : Debug: rlm_realm: Looking up realm
"b.com" for User-Name = "test at b.com"
Mon Oct 12 13:39:45 2009 : Debug: rlm_realm: Found realm "b.com"
Mon Oct 12 13:39:45 2009 : Debug: rlm_realm: Adding
Stripped-User-Name = "test"
Mon Oct 12 13:39:45 2009 : Debug: rlm_realm: Adding Realm = "b.com"
Mon Oct 12 13:39:45 2009 : Debug: rlm_realm: Proxying request from
user test to realm b.com
Mon Oct 12 13:39:45 2009 : Debug: rlm_realm: Preparing to proxy
authentication request to realm "b.com"
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from
suffix (rlm_realm) for request 0
Mon Oct 12 13:39:45 2009 : Debug: ++[suffix] returns updated
Mon Oct 12 13:39:45 2009 : Debug: +- entering group pre-proxy
Mon Oct 12 13:39:45 2009 : Debug: modsingle[pre-proxy]: calling
pre_proxy_log (rlm_detail) for request 0
Mon Oct 12 13:39:45 2009 : Debug: expand:
/var/log/freeradius/radacct/%{Client-IP-Address}/pre-proxy-detail-%Y%m%d
-> /var/log/freeradius/radacct/127.0.0.1/pre-proxy-detail-20091012
Mon Oct 12 13:39:45 2009 : Debug: rlm_detail:
/var/log/freeradius/radacct/%{Client-IP-Address}/pre-proxy-detail-%Y%m%d
expands to /var/log/freeradius/radacct/127.0.0.1/pre-proxy-detail-20091012
Mon Oct 12 13:39:45 2009 : Debug: expand: %t -> Mon Oct 12 13:39:45
2009
Mon Oct 12 13:39:45 2009 : Debug: modsingle[pre-proxy]: returned from
pre_proxy_log (rlm_detail) for request 0
Mon Oct 12 13:39:45 2009 : Debug: ++[pre_proxy_log] returns ok
Mon Oct 12 13:39:45 2009 : Debug: >>> Sending proxied request internally
to virtual server.
Mon Oct 12 13:39:45 2009 : Debug: server b {
Mon Oct 12 13:39:45 2009 : Debug: +- entering group authorize
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling
preprocess (rlm_preprocess) for request 0
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from
preprocess (rlm_preprocess) for request 0
Mon Oct 12 13:39:45 2009 : Debug: ++[preprocess] returns ok
Mon Oct 12 13:39:45 2009 : Debug: radius_xlat: Running registered xlat
function of module sql-b for string 'SELECT huntgroup FROM allnas WHERE
nasname="%{NAS-IP-Address}"'
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): - sql_xlat
Mon Oct 12 13:39:45 2009 : Debug: expand: %{User-Name} -> test
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): sql_set_user escaped
user --> 'test'
Mon Oct 12 13:39:45 2009 : Debug: expand: SELECT huntgroup FROM
allnas WHERE nasname="%{NAS-IP-Address}" -> SELECT huntgroup FROM allnas
WHERE nasname="127.0.0.1"
Mon Oct 12 13:39:45 2009 : Debug: expand: /tmp/sqltrace.sql ->
/tmp/sqltrace.sql
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): Reserving sql socket
id: 3
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT
huntgroup FROM allnas WHERE nasname="127.0.0.1"
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): - sql_xlat finished
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): Released sql socket
id: 3
Mon Oct 12 13:39:45 2009 : Debug: expand: %{sql-b:SELECT huntgroup
FROM allnas WHERE nasname="%{NAS-IP-Address}"} -> dialup
Mon Oct 12 13:39:45 2009 : Debug: ::: FROM 1 TO 12 MAX 13
Mon Oct 12 13:39:45 2009 : Debug: ::: Examining Huntgroup-Name
Mon Oct 12 13:39:45 2009 : Debug: ::: OVERWRITING Huntgroup-Name FROM 0
TO 6
Mon Oct 12 13:39:45 2009 : Debug: ::: TO in 12 out 12
Mon Oct 12 13:39:45 2009 : Debug: ::: to[0] = User-Name
Mon Oct 12 13:39:45 2009 : Debug: ::: to[1] = User-Password
Mon Oct 12 13:39:45 2009 : Debug: ::: to[2] = NAS-IP-Address
Mon Oct 12 13:39:45 2009 : Debug: ::: to[3] = NAS-Port
Mon Oct 12 13:39:45 2009 : Debug: ::: to[4] = Framed-Protocol
Mon Oct 12 13:39:45 2009 : Debug: ::: to[5] = Service-Type
Mon Oct 12 13:39:45 2009 : Debug: ::: to[6] = Huntgroup-Name
Mon Oct 12 13:39:45 2009 : Debug: ::: to[7] = Stripped-User-Name
Mon Oct 12 13:39:45 2009 : Debug: ::: to[8] = Realm
Mon Oct 12 13:39:45 2009 : Debug: ::: to[9] = Realm
Mon Oct 12 13:39:45 2009 : Debug: ::: to[10] = Proxy-State
Mon Oct 12 13:39:45 2009 : Debug: ::: to[11] = SQL-User-Name
Mon Oct 12 13:39:45 2009 : Debug: ++[request] returns ok
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling chap
(rlm_chap) for request 0
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from
chap (rlm_chap) for request 0
Mon Oct 12 13:39:45 2009 : Debug: ++[chap] returns noop
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling IPASS
(rlm_realm) for request 0
Mon Oct 12 13:39:45 2009 : Debug: rlm_realm: Request already
proxied. Ignoring.
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from
IPASS (rlm_realm) for request 0
Mon Oct 12 13:39:45 2009 : Debug: ++[IPASS] returns noop
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling suffix
(rlm_realm) for request 0
Mon Oct 12 13:39:45 2009 : Debug: rlm_realm: Request already
proxied. Ignoring.
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from
suffix (rlm_realm) for request 0
Mon Oct 12 13:39:45 2009 : Debug: ++[suffix] returns noop
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling files
(rlm_files) for request 0
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from
files (rlm_files) for request 0
Mon Oct 12 13:39:45 2009 : Debug: ++[files] returns noop
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling sql-b
(rlm_sql) for request 0
Mon Oct 12 13:39:45 2009 : Debug: expand: %{User-Name} -> test
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): sql_set_user escaped
user --> 'test'
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): Reserving sql socket
id: 2
Mon Oct 12 13:39:45 2009 : Debug: expand: SELECT id, UserName,
Attribute, Value, op FROM radcheck WHERE Username = '%{SQL-User-Name}'
ORDER BY id -> SELECT id, UserName, Attribute, Value, op FROM radcheck
WHERE Username = 'test' ORDER BY id
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT id,
UserName, Attribute, Value, op FROM radcheck WHERE Username = 'test'
ORDER BY id
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): User found in
radcheck table
Mon Oct 12 13:39:45 2009 : Debug: expand: SELECT id, UserName,
Attribute, Value, op FROM radreply WHERE Username = '%{SQL-User-Name}'
ORDER BY id -> SELECT id, UserName, Attribute, Value, op FROM radreply
WHERE Username = 'test' ORDER BY id
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT id,
UserName, Attribute, Value, op FROM radreply WHERE Username = 'test'
ORDER BY id
Mon Oct 12 13:39:45 2009 : Debug: expand: SELECT GroupName FROM
usergroup WHERE UserName = '%{SQL-User-Name}' AND HuntGroupName =
'%{Huntgroup-Name}' -> SELECT GroupName FROM usergroup WHERE UserName =
'test' AND HuntGroupName = 'dialup'
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT
GroupName FROM usergroup WHERE UserName = 'test' AND HuntGroupName =
'dialup'
Mon Oct 12 13:39:45 2009 : Debug: expand: 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
AND radgroupcheck.HuntgroupName = '%{Huntgroup-Name}' ORDER BY
radgroupcheck.id -> SELECT radgroupcheck.id, radgroupcheck.GroupName,
radgroupcheck.Attribute, radgroupcheck.Value, radgroupcheck.op FROM
radgroupcheck, usergroup WHERE usergroup.Username = 'test' AND
usergroup.GroupName = radgroupcheck.GroupName AND
radgroupcheck.HuntgroupName = 'dialup' ORDER BY radgroupcheck.id
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT
radgroupcheck.id, radgroupcheck.GroupName, radgroupcheck.Attribute,
radgroupcheck.Value, radgroupcheck.op FROM radgroupcheck, usergroup
WHERE usergroup.Username = 'test' AND usergroup.GroupName =
radgroupcheck.GroupName AND radgroupcheck.HuntgroupName = 'dialup' ORDER
BY radgroupcheck.id
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): User found in group B
UNLIMITED
Mon Oct 12 13:39:45 2009 : Debug: expand: SELECT id, GroupName,
Attribute, Value, op FROM radgroupreply WHERE GroupName = '%{Sql-Group}'
ORDER BY id -> SELECT id, GroupName, Attribute, Value, op FROM
radgroupreply WHERE GroupName = 'B UNLIMITED' ORDER BY id
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT id,
GroupName, Attribute, Value, op FROM radgroupreply WHERE GroupName = 'B
UNLIMITED' ORDER BY id
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): Released sql socket
id: 2
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from
sql-b (rlm_sql) for request 0
Mon Oct 12 13:39:45 2009 : Debug: ++[sql-b] returns ok
Mon Oct 12 13:39:45 2009 : Debug: rad_check_password: Found Auth-Type
Accept
Mon Oct 12 13:39:45 2009 : Debug: rad_check_password: Auth-Type =
Accept, accepting the user
Mon Oct 12 13:39:45 2009 : Debug: +- entering group session
Mon Oct 12 13:39:45 2009 : Debug: modsingle[session]: calling sql-b
(rlm_sql) for request 0
Mon Oct 12 13:39:45 2009 : Debug: expand: %{User-Name} -> test
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): sql_set_user escaped
user --> 'test'
Mon Oct 12 13:39:45 2009 : Debug: expand: SELECT COUNT(*) FROM
radacct WHERE UserName='%{SQL-User-Name}' AND AcctStopTime = 0 -> SELECT
COUNT(*) FROM radacct WHERE UserName='test' AND AcctStopTime = 0
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): Reserving sql socket
id: 1
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT COUNT(*)
FROM radacct WHERE UserName='test' AND AcctStopTime = 0
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): Released sql socket
id: 1
Mon Oct 12 13:39:45 2009 : Debug: modsingle[session]: returned from
sql-b (rlm_sql) for request 0
Mon Oct 12 13:39:45 2009 : Debug: ++[sql-b] returns ok
Mon Oct 12 13:39:45 2009 : Auth: Login OK: [test/12345] (from client
Mike Test port 1 via TLS tunnel)
Mon Oct 12 13:39:45 2009 : Debug: +- entering group post-auth
Mon Oct 12 13:39:45 2009 : Debug: modsingle[post-auth]: calling sql-b
(rlm_sql) for request 0
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): Processing sql_postauth
Mon Oct 12 13:39:45 2009 : Debug: expand: %{User-Name} -> test
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-b): sql_set_user escaped
user --> 'test'
Mon Oct 12 13:39:45 2009 : Debug: modsingle[post-auth]: returned from
sql-b (rlm_sql) for request 0
Mon Oct 12 13:39:45 2009 : Debug: ++[sql-b] returns noop
Mon Oct 12 13:39:45 2009 : Debug: } # server b
Mon Oct 12 13:39:45 2009 : Debug: Going to the next request
Mon Oct 12 13:39:45 2009 : Debug: <<< Received proxied response from
internal virtual server.
Mon Oct 12 13:39:45 2009 : Debug: +- entering group authorize
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling
preprocess (rlm_preprocess) for request 0
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from
preprocess (rlm_preprocess) for request 0
Mon Oct 12 13:39:45 2009 : Debug: ++[preprocess] returns ok
Mon Oct 12 13:39:45 2009 : Debug: radius_xlat: Running registered xlat
function of module sql-a for string 'SELECT huntgroup FROM nas WHERE
nasname="%{NAS-IP-Address}"'
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): - sql_xlat
Mon Oct 12 13:39:45 2009 : Debug: expand: %{User-Name} -> test at b.com
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): sql_set_user escaped
user --> 'test at b.com'
Mon Oct 12 13:39:45 2009 : Debug: expand: SELECT huntgroup FROM nas
WHERE nasname="%{NAS-IP-Address}" -> SELECT huntgroup FROM nas WHERE
nasname="127.0.0.1"
Mon Oct 12 13:39:45 2009 : Debug: expand: /tmp/sqltrace.sql ->
/tmp/sqltrace.sql
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): Reserving sql socket
id: 2
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT
huntgroup FROM nas WHERE nasname="127.0.0.1"
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): - sql_xlat finished
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): Released sql socket
id: 2
Mon Oct 12 13:39:45 2009 : Debug: expand: %{sql-a:SELECT huntgroup
FROM nas WHERE nasname="%{NAS-IP-Address}"} -> dialup
Mon Oct 12 13:39:45 2009 : Debug: ::: FROM 1 TO 11 MAX 12
Mon Oct 12 13:39:45 2009 : Debug: ::: Examining Huntgroup-Name
Mon Oct 12 13:39:45 2009 : Debug: ::: OVERWRITING Huntgroup-Name FROM 0
TO 6
Mon Oct 12 13:39:45 2009 : Debug: ::: TO in 11 out 11
Mon Oct 12 13:39:45 2009 : Debug: ::: to[0] = User-Name
Mon Oct 12 13:39:45 2009 : Debug: ::: to[1] = User-Password
Mon Oct 12 13:39:45 2009 : Debug: ::: to[2] = NAS-IP-Address
Mon Oct 12 13:39:45 2009 : Debug: ::: to[3] = NAS-Port
Mon Oct 12 13:39:45 2009 : Debug: ::: to[4] = Framed-Protocol
Mon Oct 12 13:39:45 2009 : Debug: ::: to[5] = Service-Type
Mon Oct 12 13:39:45 2009 : Debug: ::: to[6] = Huntgroup-Name
Mon Oct 12 13:39:45 2009 : Debug: ::: to[7] = Stripped-User-Name
Mon Oct 12 13:39:45 2009 : Debug: ::: to[8] = Realm
Mon Oct 12 13:39:45 2009 : Debug: ::: to[9] = Realm
Mon Oct 12 13:39:45 2009 : Debug: ::: to[10] = SQL-User-Name
Mon Oct 12 13:39:45 2009 : Debug: ++[request] returns ok
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling chap
(rlm_chap) for request 0
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from
chap (rlm_chap) for request 0
Mon Oct 12 13:39:45 2009 : Debug: ++[chap] returns noop
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling IPASS
(rlm_realm) for request 0
Mon Oct 12 13:39:45 2009 : Debug: rlm_realm: Proxy reply, or no
User-Name. Ignoring.
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from
IPASS (rlm_realm) for request 0
Mon Oct 12 13:39:45 2009 : Debug: ++[IPASS] returns noop
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling suffix
(rlm_realm) for request 0
Mon Oct 12 13:39:45 2009 : Debug: rlm_realm: Proxy reply, or no
User-Name. Ignoring.
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from
suffix (rlm_realm) for request 0
Mon Oct 12 13:39:45 2009 : Debug: ++[suffix] returns noop
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling files
(rlm_files) for request 0
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from
files (rlm_files) for request 0
Mon Oct 12 13:39:45 2009 : Debug: ++[files] returns noop
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: calling sql-a
(rlm_sql) for request 0
Mon Oct 12 13:39:45 2009 : Debug: expand: %{User-Name} -> test at b.com
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): sql_set_user escaped
user --> 'test at b.com'
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): Reserving sql socket
id: 1
Mon Oct 12 13:39:45 2009 : Debug: expand: SELECT id, UserName,
Attribute, Value, op FROM radcheck WHERE Username = '%{SQL-User-Name}'
ORDER BY id -> SELECT id, UserName, Attribute, Value, op FROM radcheck
WHERE Username = 'test at b.com' ORDER BY id
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT id,
UserName, Attribute, Value, op FROM radcheck WHERE Username =
'test at b.com' ORDER BY id
Mon Oct 12 13:39:45 2009 : Debug: expand: SELECT GroupName FROM
usergroup WHERE UserName = '%{SQL-User-Name}' AND HuntGroupName =
'%{Huntgroup-Name}' -> SELECT GroupName FROM usergroup WHERE UserName =
'test at b.com' AND HuntGroupName = 'dialup'
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT
GroupName FROM usergroup WHERE UserName = 'test at b.com' AND HuntGroupName
= 'dialup'
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): Checking profile DEFAULT
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): sql_set_user escaped
user --> 'DEFAULT'
Mon Oct 12 13:39:45 2009 : Debug: expand: SELECT GroupName FROM
usergroup WHERE UserName = '%{SQL-User-Name}' AND HuntGroupName =
'%{Huntgroup-Name}' -> SELECT GroupName FROM usergroup WHERE UserName =
'DEFAULT' AND HuntGroupName = 'dialup'
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT
GroupName FROM usergroup WHERE UserName = 'DEFAULT' AND HuntGroupName =
'dialup'
Mon Oct 12 13:39:45 2009 : Debug: expand: 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
AND radgroupcheck.HuntgroupName = '%{Huntgroup-Name}' ORDER BY
radgroupcheck.id -> SELECT radgroupcheck.id, radgroupcheck.GroupName,
radgroupcheck.Attribute, radgroupcheck.Value, radgroupcheck.op FROM
radgroupcheck, usergroup WHERE usergroup.Username = 'DEFAULT' AND
usergroup.GroupName = radgroupcheck.GroupName AND
radgroupcheck.HuntgroupName = 'dialup' ORDER BY radgroupcheck.id
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT
radgroupcheck.id, radgroupcheck.GroupName, radgroupcheck.Attribute,
radgroupcheck.Value, radgroupcheck.op FROM radgroupcheck, usergroup
WHERE usergroup.Username = 'DEFAULT' AND usergroup.GroupName =
radgroupcheck.GroupName AND radgroupcheck.HuntgroupName = 'dialup' ORDER
BY radgroupcheck.id
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): User found in group
DISABLED
Mon Oct 12 13:39:45 2009 : Debug: expand: SELECT id, GroupName,
Attribute, Value, op FROM radgroupreply WHERE GroupName = '%{Sql-Group}'
ORDER BY id -> SELECT id, GroupName, Attribute, Value, op FROM
radgroupreply WHERE GroupName = 'DISABLED' ORDER BY id
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query: SELECT id,
GroupName, Attribute, Value, op FROM radgroupreply WHERE GroupName =
'DISABLED' ORDER BY id
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): Released sql socket
id: 1
Mon Oct 12 13:39:45 2009 : Debug: modsingle[authorize]: returned from
sql-a (rlm_sql) for request 0
Mon Oct 12 13:39:45 2009 : Debug: ++[sql-a] returns ok
Mon Oct 12 13:39:45 2009 : Debug: rad_check_password: Found Auth-Type
Reject
Mon Oct 12 13:39:45 2009 : Debug: rad_check_password: Auth-Type =
Reject, rejecting user
Mon Oct 12 13:39:45 2009 : Debug: auth: Failed to validate the user.
Mon Oct 12 13:39:45 2009 : Auth: Login incorrect: [test at b.com/12345]
(from client Mike Test port 1)
Mon Oct 12 13:39:45 2009 : Debug: Delaying reject of request 0 for 1
seconds
Mon Oct 12 13:39:45 2009 : Debug: Going to the next request
Mon Oct 12 13:39:45 2009 : Debug: Waking up in 0.9 seconds.
Mon Oct 12 13:39:46 2009 : Debug: Sending delayed reject for request 0
Sending Access-Reject of id 193 to 127.0.0.1 port 33589
Reply-Message := "This account has been disabled"
Mon Oct 12 13:39:46 2009 : Debug: Waking up in 4.9 seconds.
Mon Oct 12 13:39:51 2009 : Debug: Cleaning up request 0 ID 193 with
timestamp +8
Mon Oct 12 13:39:51 2009 : Debug: Ready to process requests.
Thanks for any help you can provide...
Michael Schlies
More information about the Freeradius-Users
mailing list