Odd proxy authentication failures

12 Oct 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@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@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@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@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@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@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@b.com
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): sql_set_user escaped 
user --> 'test@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@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@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@b.com
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): sql_set_user escaped 
user --> 'test@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@b.com
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql (sql-a): sql_set_user escaped 
user --> 'test@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@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@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@b.com' AND HuntGroupName = 'dialup'
Mon Oct 12 13:39:45 2009 : Debug: rlm_sql_mysql: query:  SELECT 
GroupName FROM usergroup WHERE UserName = 'test@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@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