Group Processing with MySQL

14 Apr 2012

      This continues questions related to group processing not always
working as expected,
in particluar why group replies are not sent when the users are
members of groups
for which there are replies in radgroupreply.

I should mention that Alan's response to my previous post a couple weeks ago
was simply to run the server in debug and look at the queries...this is what
I've done here (I hope).

The queries printed out when starting the server in debug show the correct
authorize_group_reply_query, but it never gets run during an auth request.

I began with 2.1.8 on CentOS 5.8 - and have now moved to a clean
2.1.12 (stock) on
CentOS 6.0. All are using a MySQL backend built from the schema by
Mike Machado. The only
change to the tables is the addition of two fields to some tables,
'notes' and 'expires';
none of the FreeRADIUS queries have been altered.

Any help with how to get this working?
Thank you
- Andrew Long

Here are the queries for the user's auth request:

[sql] sql_set_user escaped user --> 'memwg150412'
rlm_sql (sql): Reserving sql socket id: 1
[sql]   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
= 'memwg150412' ORDER BY id
rlm_sql_mysql: query:
SELECT id, username, attribute, value, op FROM radcheck WHERE username
= 'memwg150412' ORDER BY id
[sql] User found in radcheck table
[sql]   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
= 'memwg150412' ORDER BY id
rlm_sql_mysql: query:
SELECT id, username, attribute, value, op FROM radreply WHERE username
= 'memwg150412' ORDER BY id
[sql]   expand:
SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}'
ORDER BY priority ->
SELECT groupname FROM radusergroup WHERE username = 'memwg150412'
ORDER BY priority
rlm_sql_mysql: query:
SELECT groupname FROM radusergroup WHERE username = 'memwg150412'
ORDER BY priority
[sql]   expand:
SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE
groupname = '%{Sql-Group}' ORDER BY id ->
SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE
groupname = 'wolfchase-guest-group' ORDER BY id
rlm_sql_mysql: query:
SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE
groupname = 'wolfchase-guest-group' ORDER BY id
rlm_sql (sql): Released sql socket id: 1

and here is the reply sent:

Sending Access-Accept of id 215 to 192.168.245.1 port 58639
        Nomadix-Bw-Down := 768
        Nomadix-Bw-Up := 256
Finished request 0.

The problem is that these attributes are from radreply based on the
username, and processing
is not continuing to radgroupreply.

When I manually run:
'SELECT groupname FROM radusergroup WHERE username = 'memwg150412'
ORDER BY priority;'
MySQL returns:
"wolfchase-guest-group" and processing should continue to
radgroupreply (where there are
reply attributes), but never does.

In sql.conf, we have 	"read_groups = yes"

So the question: why are goups not being processed and how can I fix this?

###
Below is a complete debug from this session:
###

FreeRADIUS Version 2.1.12, for host i686-redhat-linux-gnu, built on
Feb 22 2012 at 15:07:38
Copyright (C) 1999-2009 The FreeRADIUS server project and contributors.
There is NO warranty; not even for MERCHANTABILITY or FITNESS FOR A
PARTICULAR PURPOSE.
You may redistribute copies of FreeRADIUS under the terms of the
GNU General Public License v2.
Starting - reading configuration files ...
including configuration file /etc/raddb/radiusd.conf
including configuration file /etc/raddb/clients.conf
including files in directory /etc/raddb/modules/
including configuration file /etc/raddb/modules/smbpasswd
including configuration file /etc/raddb/modules/smsotp
including configuration file /etc/raddb/modules/ntlm_auth
including configuration file /etc/raddb/modules/acct_unique
including configuration file /etc/raddb/modules/sqlcounter_expire_on_login
including configuration file /etc/raddb/modules/cui
including configuration file /etc/raddb/modules/soh
including configuration file /etc/raddb/modules/exec
including configuration file /etc/raddb/modules/sradutmp
including configuration file /etc/raddb/modules/attr_filter
including configuration file /etc/raddb/modules/pam
including configuration file /etc/raddb/modules/preprocess
including configuration file /etc/raddb/modules/mschap
including configuration file /etc/raddb/modules/mac2ip
including configuration file /etc/raddb/modules/realm
including configuration file /etc/raddb/modules/logintime
including configuration file /etc/raddb/modules/always
including configuration file /etc/raddb/modules/rediswho
including configuration file /etc/raddb/modules/inner-eap
including configuration file /etc/raddb/modules/policy
including configuration file /etc/raddb/modules/attr_rewrite
including configuration file /etc/raddb/modules/passwd
including configuration file /etc/raddb/modules/mac2vlan
including configuration file /etc/raddb/modules/detail
including configuration file /etc/raddb/modules/dynamic_clients
including configuration file /etc/raddb/modules/redis
including configuration file /etc/raddb/modules/files
including configuration file /etc/raddb/modules/digest
including configuration file /etc/raddb/modules/detail.example.com
including configuration file /etc/raddb/modules/detail.log
including configuration file /etc/raddb/modules/wimax
including configuration file /etc/raddb/modules/otp
including configuration file /etc/raddb/modules/etc_group
including configuration file /etc/raddb/modules/replicate
including configuration file /etc/raddb/modules/echo
including configuration file /etc/raddb/modules/ippool
including configuration file /etc/raddb/modules/perl
including configuration file /etc/raddb/modules/radutmp
including configuration file /etc/raddb/modules/expr
including configuration file /etc/raddb/modules/opendirectory
including configuration file /etc/raddb/modules/unix
including configuration file /etc/raddb/modules/chap
including configuration file /etc/raddb/modules/checkval
including configuration file /etc/raddb/modules/expiration
including configuration file /etc/raddb/modules/counter
including configuration file /etc/raddb/modules/sql_log
including configuration file /etc/raddb/modules/linelog
including configuration file /etc/raddb/modules/pap
including configuration file /etc/raddb/eap.conf
including configuration file /etc/raddb/sql.conf
including configuration file /etc/raddb/sql/mysql/dialup.conf
including configuration file /etc/raddb/sqlcounter.conf
including configuration file /etc/raddb/policy.conf
including files in directory /etc/raddb/sites-enabled/
including configuration file /etc/raddb/sites-enabled/default
including configuration file /etc/raddb/sites-enabled/control-socket
including configuration file /etc/raddb/sites-enabled/inner-tunnel
main {
	user = "radiusd"
	group = "radiusd"
	allow_core_dumps = no
}
including dictionary file /etc/raddb/dictionary
main {
	name = "radiusd"
	prefix = "/usr"
	localstatedir = "/var"
	sbindir = "/usr/sbin"
	logdir = "/var/log/radius"
	run_dir = "/var/run/radiusd"
	libdir = "/usr/lib/freeradius"
	radacctdir = "/var/log/radius/radacct"
	hostname_lookups = no
	max_request_time = 30
	cleanup_delay = 5
	max_requests = 1024
	pidfile = "/var/run/radiusd/radiusd.pid"
	checkrad = "/usr/sbin/checkrad"
	debug_level = 0
	proxy_requests = no
 log {
	stripped_names = no
	auth = yes
	auth_badpass = yes
	auth_goodpass = no
 }
 security {
	max_attributes = 200
	reject_delay = 1
	status_server = yes
 }
}
radiusd: #### Loading Realms and Home Servers ####
radiusd: #### Loading Clients ####

...snip...

 client 192.168.245.0/24 {
	require_message_authenticator = no
	secret = "xxx"
	shortname = "vmHost"
	nastype = "other"
 }

...snip...

radiusd: #### Instantiating modules ####
 instantiate {
 Module: Linked to module rlm_exec
 Module: Instantiating module "exec" from file /etc/raddb/modules/exec
  exec {
	wait = no
	input_pairs = "request"
	shell_escape = yes
  }
 Module: Linked to module rlm_expr
 Module: Instantiating module "expr" from file /etc/raddb/modules/expr
 Module: Linked to module rlm_expiration
 Module: Instantiating module "expiration" from file
/etc/raddb/modules/expiration
  expiration {
	reply-message = "Password Has Expired  "
  }
 Module: Linked to module rlm_logintime
 Module: Instantiating module "logintime" from file /etc/raddb/modules/logintime
  logintime {
	reply-message = "You are calling outside your allowed timespan  "
	minimum-timeout = 60
  }
 }
radiusd: #### Loading Virtual Servers ####
server { # from file /etc/raddb/radiusd.conf
 modules {
  Module: Creating Post-Auth-Type = REJECT
 Module: Checking authenticate {...} for more modules to load
 Module: Linked to module rlm_pap
 Module: Instantiating module "pap" from file /etc/raddb/modules/pap
  pap {
	encryption_scheme = "auto"
	auto_header = no
  }
 Module: Linked to module rlm_chap
 Module: Instantiating module "chap" from file /etc/raddb/modules/chap
 Module: Linked to module rlm_mschap
 Module: Instantiating module "mschap" from file /etc/raddb/modules/mschap
  mschap {
	use_mppe = yes
	require_encryption = no
	require_strong = no
	with_ntdomain_hack = no
	allow_retry = yes
  }
 Module: Checking authorize {...} for more modules to load
 Module: Linked to module rlm_preprocess
 Module: Instantiating module "preprocess" from file
/etc/raddb/modules/preprocess
  preprocess {
	huntgroups = "/etc/raddb/huntgroups"
	hints = "/etc/raddb/hints"
	with_ascend_hack = no
	ascend_channels_per_line = 23
	with_ntdomain_hack = no
	with_specialix_jetstream_hack = no
	with_cisco_vsa_hack = no
	with_alvarion_vsa_hack = no
  }
 Module: Linked to module rlm_digest
 Module: Instantiating module "digest" from file /etc/raddb/modules/digest
 Module: Linked to module rlm_realm
 Module: Instantiating module "suffix" from file /etc/raddb/modules/realm
  realm suffix {
	format = "suffix"
	delimiter = "@"
	ignore_default = no
	ignore_null = no
  }
 Module: Linked to module rlm_sql
 Module: Instantiating module "sql" from file /etc/raddb/sql.conf
  sql {
	driver = "rlm_sql_mysql"
	server = "localhost"
	port = "3306"
	login = "radxxxxxx"
	password = "radxxxxxx"
	radius_db = "radius"
	read_groups = yes
	sqltrace = yes
	sqltracefile = "/var/log/radius/sqltrace.sql"
	readclients = no
	deletestalesessions = yes
	num_sql_socks = 5
	lifetime = 0
	max_queries = 0
	sql_user_name = "%{User-Name}"
	default_user_profile = ""
	nas_query = "SELECT id, nasname, shortname, type, secret, server FROM nas"
	authorize_check_query = "SELECT id, username, attribute, value, op
       FROM radcheck           WHERE username = '%{SQL-User-Name}'
      ORDER BY id"
	authorize_reply_query = "SELECT id, username, attribute, value, op
       FROM radreply           WHERE username = '%{SQL-User-Name}'
      ORDER BY id"
	authorize_group_check_query = "SELECT id, groupname, attribute,
    Value, op           FROM radgroupcheck           WHERE groupname =
'%{Sql-Group}'           ORDER BY id"
	authorize_group_reply_query = "SELECT id, groupname, attribute,
    value, op           FROM radgroupreply           WHERE groupname =
'%{Sql-Group}'           ORDER BY id"
	accounting_onoff_query = "          UPDATE radacct           SET
        acctstoptime       =  '%S',              acctsessiontime    =
unix_timestamp('%S') -
unix_timestamp(acctstarttime),              acctterminatecause =
'%{Acct-Terminate-Cause}',              acctstopdelay      =
%{%{Acct-Delay-Time}:-0}           WHERE acctstoptime IS NULL
 AND nasipaddress      =  '%{NAS-IP-Address}'           AND
acctstarttime     <= '%S'"
	accounting_update_query = "           UPDATE radacct           SET
          framedipaddress = '%{Framed-IP-Address}',
acctsessiontime     = '%{Acct-Session-Time}',
acctinputoctets     = '%{%{Acct-Input-Gigawords}:-0}'  << 32 |
                           '%{%{Acct-Input-Octets}:-0}',
acctoutputoctets    = '%{%{Acct-Output-Gigawords}:-0}' << 32 |
                           '%{%{Acct-Output-Octets}:-0}'
WHERE acctsessionid = '%{Acct-Session-Id}'           AND username
  = '%{SQL-User-Name}'           AND nasipaddress    =
'%{NAS-IP-Address}'"
	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,   xascendsessionsvrkey)           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-Gigawords}:-0}' << 32 |
'%{%{Acct-Input-Octets}:-0}',
'%{%{Acct-Output-Gigawords}:-0}' << 32 |
'%{%{Acct-Output-Octets}:-0}',              '%{Called-Station-Id}',
'%{Calling-Station-Id}',              '%{Service-Type}',
'%{Framed-Protocol}',              '%{Framed-IP-Address}',
 '0', '%{X-Ascend-Session-Svr-Key}')"
	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,    xascendsessionsvrkey)           VALUES
('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}',
'%{SQL-User-Name}',              '%{Realm}', '%{NAS-IP-Address}',
'%{NAS-Port}',              '%{NAS-Port-Type}', '%S', NULL,
  '0', '%{Acct-Authentic}', '%{Connect-Info}',              '', '0',
'0',              '%{Called-Station-Id}', '%{Calling-Station-Id}', '',
             '%{Service-Type}', '%{Framed-Protocol}',
'%{Framed-IP-Address}',              '%{%{Acct-Delay-Time}:-0}', '0',
'%{X-Ascend-Session-Svr-Key}')"
	accounting_start_query_alt = "           UPDATE radacct SET
   acctstarttime     = '%S',              acctstartdelay    =
'%{%{Acct-Delay-Time}:-0}',              connectinfo_start =
'%{Connect-Info}'           WHERE acctsessionid  =
'%{Acct-Session-Id}'           AND username         =
'%{SQL-User-Name}'           AND nasipaddress     =
'%{NAS-IP-Address}'"
	accounting_stop_query = "           UPDATE radacct SET
acctstoptime       = '%S',              acctsessiontime    =
'%{Acct-Session-Time}',              acctinputoctets    =
'%{%{Acct-Input-Gigawords}:-0}' << 32 |
   '%{%{Acct-Input-Octets}:-0}',              acctoutputoctets   =
'%{%{Acct-Output-Gigawords}:-0}' << 32 |
    '%{%{Acct-Output-Octets}:-0}',              acctterminatecause =
'%{Acct-Terminate-Cause}',              acctstopdelay      =
'%{%{Acct-Delay-Time}:-0}',              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 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-Gigawords}:-0}' << 32
|              '%{%{Acct-Input-Octets}:-0}',
'%{%{Acct-Output-Gigawords}:-0}' << 32 |
'%{%{Acct-Output-Octets}:-0}',              '%{Called-Station-Id}',
'%{Calling-Station-Id}',              '%{Acct-Terminate-Cause}',
       '%{Service-Type}', '%{Framed-Protocol}',
'%{Framed-IP-Address}',              '0', '%{%{Acct-Delay-Time}:-0}')"
	group_membership_query = "SELECT groupname           FROM
radusergroup           WHERE username = '%{SQL-User-Name}'
ORDER BY priority"
	connect_failure_retry_delay = 60
	simul_count_query = ""
	simul_verify_query = "SELECT radacctid, acctsessionid, username,
                          nasipaddress, nasportid, framedipaddress,
                            callingstationid, framedprotocol
                     FROM radacct                                WHERE
username = '%{SQL-User-Name}'                                AND
acctstoptime IS NULL"
	postauth_query = "INSERT INTO radpostauth
(username, pass, reply, authdate)                           VALUES (
                        '%{User-Name}',
'%{%{User-Password}:-%{Chap-Password}}',
'%{reply:Packet-Type}', '%S')"
	safe-characters =
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_:
/"
  }
rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked
rlm_sql (sql): Attempting to connect to radiusd@localhost:3306/radius2
rlm_sql (sql): starting 0
rlm_sql (sql): Attempting to connect rlm_sql_mysql #0
rlm_sql_mysql: Starting connect to MySQL server for #0
rlm_sql (sql): Connected new DB handle, #0
rlm_sql (sql): starting 1
rlm_sql (sql): Attempting to connect rlm_sql_mysql #1
rlm_sql_mysql: Starting connect to MySQL server for #1
rlm_sql (sql): Connected new DB handle, #1
rlm_sql (sql): starting 2
rlm_sql (sql): Attempting to connect rlm_sql_mysql #2
rlm_sql_mysql: Starting connect to MySQL server for #2
rlm_sql (sql): Connected new DB handle, #2
rlm_sql (sql): starting 3
rlm_sql (sql): Attempting to connect rlm_sql_mysql #3
rlm_sql_mysql: Starting connect to MySQL server for #3
rlm_sql (sql): Connected new DB handle, #3
rlm_sql (sql): starting 4
rlm_sql (sql): Attempting to connect rlm_sql_mysql #4
rlm_sql_mysql: Starting connect to MySQL server for #4
rlm_sql (sql): Connected new DB handle, #4
 Module: Linked to module rlm_sqlcounter
 Module: Instantiating module "noresetcounter" from file
/etc/raddb/sqlcounter.conf
  sqlcounter noresetcounter {
	counter-name = "Max-All-Session-Time"
	check-name = "Max-All-Session"
	key = "User-Name"
	sqlmod-inst = "sql"
	query = "SELECT SUM(AcctSessionTime) FROM radacct WHERE UserName='%{%k}'"
	reset = "never"
	safe-characters =
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_:
/"
  }
rlm_sqlcounter: Reply attribute set to Session-Timeout.
rlm_sqlcounter: Counter attribute Max-All-Session-Time is number 11273
rlm_sqlcounter: Check attribute Max-All-Session is number 11274
rlm_sqlcounter: Current Time: 1334416365 [2012-04-14 11:12:45], Next
reset 0 [2012-04-14 11:00:00]
rlm_sqlcounter: Current Time: 1334416365 [2012-04-14 11:12:45], Prev
reset 0 [2012-04-14 11:00:00]
 Module: Instantiating module "dailycounter" from file
/etc/raddb/sqlcounter.conf
  sqlcounter dailycounter {
	counter-name = "Daily-Session-Time"
	check-name = "Max-Daily-Session"
	key = "User-Name"
	sqlmod-inst = "sql"
	query = "SELECT SUM(AcctSessionTime - GREATEST((%b -
UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE
UserName='%{%k}' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime >
'%b'"
	reset = "daily"
	safe-characters =
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_:
/"
  }
rlm_sqlcounter: Reply attribute set to Session-Timeout.
rlm_sqlcounter: Counter attribute Daily-Session-Time is number 11275
rlm_sqlcounter: Check attribute Max-Daily-Session is number 11276
rlm_sqlcounter: Current Time: 1334416365 [2012-04-14 11:12:45], Next
reset 1334462400 [2012-04-15 00:00:00]
rlm_sqlcounter: Current Time: 1334416365 [2012-04-14 11:12:45], Prev
reset 1334376000 [2012-04-14 00:00:00]
 Module: Instantiating module "monthlycounter" from file
/etc/raddb/sqlcounter.conf
  sqlcounter monthlycounter {
	counter-name = "Monthly-Session-Time"
	check-name = "Max-Monthly-Session"
	key = "User-Name"
	sqlmod-inst = "sqlcca3"
	query = "SELECT SUM(AcctSessionTime - GREATEST((%b -
UNIX_TIMESTAMP(AcctStartTime)), 0)) FROM radacct WHERE
UserName='%{%k}' AND UNIX_TIMESTAMP(AcctStartTime) + AcctSessionTime >
'%b'"
	reset = "monthly"
	safe-characters =
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_:
/"
  }
rlm_sqlcounter: Reply attribute set to Session-Timeout.
rlm_sqlcounter: Counter attribute Monthly-Session-Time is number 11277
rlm_sqlcounter: Check attribute Max-Monthly-Session is number 11278
rlm_sqlcounter: Current Time: 1334416365 [2012-04-14 11:12:45], Next
reset 1335844800 [2012-05-01 00:00:00]
rlm_sqlcounter: Current Time: 1334416365 [2012-04-14 11:12:45], Prev
reset 1333252800 [2012-04-01 00:00:00]
 Module: Instantiating module "daypasscounter" from file
/etc/raddb/sqlcounter.conf
  sqlcounter daypasscounter {
	counter-name = "Day-Term-Code"
	check-name = "Check-Login-Day"
	key = "User-Name"
	sqlmod-inst = "sql"
	query = "SELECT UNIX_TIMESTAMP(now())  -
UNIX_TIMESTAMP(min(AcctStartTime)) FROM radacct WHERE UserName='%{%k}'
LIMIT 1"
	reset = "never"
	safe-characters =
"@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_:
/"
  }
rlm_sqlcounter: Reply attribute set to Session-Timeout.
rlm_sqlcounter: Counter attribute Day-Term-Code is number 11279
rlm_sqlcounter: Check attribute Check-Login-Day is number 11280
rlm_sqlcounter: Current Time: 1334416365 [2012-04-14 11:12:45], Next
reset 0 [2012-04-14 11:00:00]
rlm_sqlcounter: Current Time: 1334416365 [2012-04-14 11:12:45], Prev
reset 0 [2012-04-14 11:00:00]
 Module: Checking preacct {...} for more modules to load
 Module: Linked to module rlm_acct_unique
 Module: Instantiating module "acct_unique" from file
/etc/raddb/modules/acct_unique
  acct_unique {
	key = "User-Name, Acct-Session-Id, NAS-IP-Address, Client-IP-Address, NAS-Port"
  }
 Module: Linked to module rlm_files
 Module: Instantiating module "files" from file /etc/raddb/modules/files
  files {
	usersfile = "/etc/raddb/users"
	acctusersfile = "/etc/raddb/acct_users"
	preproxy_usersfile = "/etc/raddb/preproxy_users"
	compat = "no"
  }
 Module: Checking accounting {...} for more modules to load
 Module: Linked to module rlm_detail
 Module: Instantiating module "detail" from file /etc/raddb/modules/detail
  detail {
	detailfile = "/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d"
	header = "%t"
	detailperm = 384
	dirperm = 493
	locking = no
	log_packet_header = no
  }
 Module: Linked to module rlm_radutmp
 Module: Instantiating module "radutmp" from file /etc/raddb/modules/radutmp
  radutmp {
	filename = "/var/log/radius/radutmp"
	username = "%{User-Name}"
	case_sensitive = yes
	check_with_nas = yes
	perm = 384
	callerid = yes
  }
 Module: Linked to module rlm_attr_filter
 Module: Instantiating module "attr_filter.accounting_response" from
file /etc/raddb/modules/attr_filter
  attr_filter attr_filter.accounting_response {
	attrsfile = "/etc/raddb/attrs.accounting_response"
	key = "%{User-Name}"
	relaxed = no
  }
 Module: Checking session {...} for more modules to load
 Module: Checking post-auth {...} for more modules to load
 Module: Instantiating module "attr_filter.access_reject" from file
/etc/raddb/modules/attr_filter
  attr_filter attr_filter.access_reject {
	attrsfile = "/etc/raddb/attrs.access_reject"
	key = "%{User-Name}"
	relaxed = no
  }
 } # modules
} # server
server inner-tunnel { # from file /etc/raddb/sites-enabled/inner-tunnel
 modules {
 Module: Checking authenticate {...} for more modules to load
 Module: Linked to module rlm_unix
 Module: Instantiating module "unix" from file /etc/raddb/modules/unix
  unix {
	radwtmp = "/var/log/radius/radwtmp"
  }
 Module: Linked to module rlm_eap
 Module: Instantiating module "eap" from file /etc/raddb/eap.conf
  eap {
	default_eap_type = "md5"
	timer_expire = 60
	ignore_unknown_eap_types = no
	cisco_accounting_username_bug = no
	max_sessions = 4096
  }
 Module: Linked to sub-module rlm_eap_md5
 Module: Instantiating eap-md5
 Module: Linked to sub-module rlm_eap_leap
 Module: Instantiating eap-leap
 Module: Linked to sub-module rlm_eap_gtc
 Module: Instantiating eap-gtc
   gtc {
	challenge = "Password: "
	auth_type = "PAP"
   }
 Module: Linked to sub-module rlm_eap_tls
 Module: Instantiating eap-tls
   tls {
	rsa_key_exchange = no
	dh_key_exchange = yes
	rsa_key_length = 512
	dh_key_length = 512
	verify_depth = 0
	CA_path = "/etc/raddb/certs"
	pem_file_type = yes
	private_key_file = "/etc/raddb/certs/server.pem"
	certificate_file = "/etc/raddb/certs/server.pem"
	CA_file = "/etc/raddb/certs/ca.pem"
	private_key_password = "whatever"
	dh_file = "/etc/raddb/certs/dh"
	random_file = "/etc/raddb/certs/random"
	fragment_size = 1024
	include_length = yes
	check_crl = no
	cipher_list = "DEFAULT"
    cache {
	enable = no
	lifetime = 24
	max_entries = 255
    }
    verify {
    }
    ocsp {
	enable = no
	override_cert_url = yes
	url = "http://127.0.0.1/ocsp/"
    }
   }
 Module: Linked to sub-module rlm_eap_ttls
 Module: Instantiating eap-ttls
   ttls {
	default_eap_type = "md5"
	copy_request_to_tunnel = no
	use_tunneled_reply = no
	virtual_server = "inner-tunnel"
	include_length = yes
   }
 Module: Linked to sub-module rlm_eap_peap
 Module: Instantiating eap-peap
   peap {
	default_eap_type = "mschapv2"
	copy_request_to_tunnel = no
	use_tunneled_reply = no
	proxy_tunneled_request_as_eap = yes
	virtual_server = "inner-tunnel"
	soh = no
   }
 Module: Linked to sub-module rlm_eap_mschapv2
 Module: Instantiating eap-mschapv2
   mschapv2 {
	with_ntdomain_hack = no
	send_error = no
   }
 Module: Checking authorize {...} for more modules to load
 Module: Checking session {...} for more modules to load
 Module: Checking post-proxy {...} for more modules to load
 Module: Checking post-auth {...} for more modules to load
 } # modules
} # server
radiusd: #### Opening IP addresses and Ports ####
listen {
	type = "auth"
	ipaddr = *
	port = 1812
}
listen {
	type = "acct"
	ipaddr = *
	port = 1813
}
listen {
	type = "control"
 listen {
	socket = "/var/run/radiusd/radiusd.sock"
 }
}
listen {
	type = "auth"
	ipaddr = 127.0.0.1
	port = 18120
}
Listening on authentication address * port 1812
Listening on accounting address * port 1813
Listening on command file /var/run/radiusd/radiusd.sock
Listening on authentication address 127.0.0.1 port 18120 as server inner-tunnel
Ready to process requests.
rad_recv: Access-Request packet from host 192.168.245.1 port 58639,
id=215, length=51
	User-Password = "wolfchase-guest"
	User-Name = "memwg150412"
# Executing section authorize from file /etc/raddb/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[suffix] No '@' in User-Name = "memwg150412", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[sql] 	expand: %{User-Name} -> memwg150412
[sql] sql_set_user escaped user --> 'memwg150412'
rlm_sql (sql): Reserving sql socket id: 4
[sql] 	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 = 'memwg150412'           ORDER
BY id
rlm_sql_mysql: query:  SELECT id, username, attribute, value, op
    FROM radcheck           WHERE username = 'memwg150412'
ORDER BY id
[sql] User found in radcheck table
[sql] 	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 = 'memwg150412'           ORDER
BY id
rlm_sql_mysql: query:  SELECT id, username, attribute, value, op
    FROM radreply           WHERE username = 'memwg150412'
ORDER BY id
[sql] 	expand: SELECT groupname           FROM radusergroup
WHERE username = '%{SQL-User-Name}'           ORDER BY priority ->
SELECT groupname           FROM radusergroup           WHERE username
= 'memwg150412'           ORDER BY priority
rlm_sql_mysql: query:  SELECT groupname           FROM radusergroup
       WHERE username = 'memwg150412'           ORDER BY priority
[sql] 	expand: SELECT id, groupname, attribute,           Value, op
       FROM radgroupcheck           WHERE groupname = '%{Sql-Group}'
        ORDER BY id -> SELECT id, groupname, attribute,
Value, op           FROM radgroupcheck           WHERE groupname =
'wolfchase-guest-group'           ORDER BY id
rlm_sql_mysql: query:  SELECT id, groupname, attribute,
Value, op           FROM radgroupcheck           WHERE groupname =
'wolfchase-guest-group'           ORDER BY id
rlm_sql (sql): Released sql socket id: 4
++[sql] returns ok
++[expiration] returns noop
++[logintime] returns noop
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
++[noresetcounter] returns noop
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
++[dailycounter] returns noop
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
++[monthlycounter] returns noop
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
++[daypasscounter] returns noop
++[pap] returns updated
Found Auth-Type = PAP
# Executing group from file /etc/raddb/sites-enabled/default
+- entering group PAP {...}
[pap] login attempt with password "wolfchase-guest"
[pap] Using clear text password "wolfchase-guest"
[pap] User authenticated successfully
++[pap] returns ok
Login OK: [memwg150412] (from client vmHost port 0)
# Executing section post-auth from file /etc/raddb/sites-enabled/default
+- entering group post-auth {...}
[sql] 	expand: %{User-Name} -> memwg150412
[sql] sql_set_user escaped user --> 'memwg150412'
[sql] 	expand: %{User-Password} -> wolfchase-guest
[sql] 	expand: INSERT INTO radpostauth
(username, pass, reply, authdate)                           VALUES (
                        '%{User-Name}',
'%{%{User-Password}:-%{Chap-Password}}',
'%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth
            (username, pass, reply, authdate)
 VALUES (                           'memwg150412',
      'wolfchase-guest',                           'Access-Accept',
'2012-04-14 11:12:53')
[sql] 	expand: /var/log/radius/sqltrace.sql -> /var/log/radius/sqltrace.sql
rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth
                   (username, pass, reply, authdate)
        VALUES (                           'memwg150412',
             'wolfchase-guest',
'Access-Accept', '2012-04-14 11:12:53')
rlm_sql (sql): Reserving sql socket id: 3
rlm_sql_mysql: query:  INSERT INTO radpostauth
  (username, pass, reply, authdate)                           VALUES (
                          'memwg150412',
'wolfchase-guest',                           'Access-Accept',
'2012-04-14 11:12:53')
rlm_sql (sql): Released sql socket id: 3
++[sql] returns ok
++[exec] returns noop
Sending Access-Accept of id 215 to 192.168.245.1 port 58639
	Nomadix-Bw-Down := 768
	Nomadix-Bw-Up := 256
Finished request 0.
Going to the next request
Waking up in 4.9 seconds.
Cleaning up request 0 ID 215 with timestamp +8
Ready to process requests.
rad_recv: Access-Request packet from host 192.168.245.1 port 65287,
id=120, length=49
	User-Name = "ithce0412"
	User-Password = "hiit_pass"
# Executing section authorize from file /etc/raddb/sites-enabled/default
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
++[mschap] returns noop
++[digest] returns noop
[suffix] No '@' in User-Name = "ithce0412", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[sql] 	expand: %{User-Name} -> ithce0412
[sql] sql_set_user escaped user --> 'ithce0412'
rlm_sql (sql): Reserving sql socket id: 2
[sql] 	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 = 'ithce0412'           ORDER
BY id
rlm_sql_mysql: query:  SELECT id, username, attribute, value, op
    FROM radcheck           WHERE username = 'ithce0412'
ORDER BY id
[sql] User found in radcheck table
[sql] 	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 = 'ithce0412'           ORDER
BY id
rlm_sql_mysql: query:  SELECT id, username, attribute, value, op
    FROM radreply           WHERE username = 'ithce0412'
ORDER BY id
[sql] 	expand: SELECT groupname           FROM radusergroup
WHERE username = '%{SQL-User-Name}'           ORDER BY priority ->
SELECT groupname           FROM radusergroup           WHERE username
= 'ithce0412'           ORDER BY priority
rlm_sql_mysql: query:  SELECT groupname           FROM radusergroup
       WHERE username = 'ithce0412'           ORDER BY priority
[sql] 	expand: SELECT id, groupname, attribute,           Value, op
       FROM radgroupcheck           WHERE groupname = '%{Sql-Group}'
        ORDER BY id -> SELECT id, groupname, attribute,
Value, op           FROM radgroupcheck           WHERE groupname =
'ithce-guest-group'           ORDER BY id
rlm_sql_mysql: query:  SELECT id, groupname, attribute,
Value, op           FROM radgroupcheck           WHERE groupname =
'ithce-guest-group'           ORDER BY id
rlm_sql (sql): Released sql socket id: 2
++[sql] returns ok
++[expiration] returns noop
++[logintime] returns noop
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
++[noresetcounter] returns noop
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
++[dailycounter] returns noop
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
++[monthlycounter] returns noop
rlm_sqlcounter: Entering module authorize code
rlm_sqlcounter: Could not find Check item value pair
++[daypasscounter] returns noop
++[pap] returns updated
Found Auth-Type = PAP
# Executing group from file /etc/raddb/sites-enabled/default
+- entering group PAP {...}
[pap] login attempt with password "hiit_pass"
[pap] Using clear text password "hiit_pass"
[pap] User authenticated successfully
++[pap] returns ok
Login OK: [ithce0412] (from client vmHost port 0)
# Executing section post-auth from file /etc/raddb/sites-enabled/default
+- entering group post-auth {...}
[sql] 	expand: %{User-Name} -> ithce0412
[sql] sql_set_user escaped user --> 'ithce0412'
[sql] 	expand: %{User-Password} -> hiit_pass
[sql] 	expand: INSERT INTO radpostauth
(username, pass, reply, authdate)                           VALUES (
                        '%{User-Name}',
'%{%{User-Password}:-%{Chap-Password}}',
'%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth
            (username, pass, reply, authdate)
 VALUES (                           'ithce0412',
    'hiit_pass',                           'Access-Accept',
'2012-04-14 11:14:42')
[sql] 	expand: /var/log/radius/sqltrace.sql -> /var/log/radius/sqltrace.sql
rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth
                   (username, pass, reply, authdate)
        VALUES (                           'ithce0412',
           'hiit_pass',                           'Access-Accept',
'2012-04-14 11:14:42')
rlm_sql (sql): Reserving sql socket id: 1
rlm_sql_mysql: query:  INSERT INTO radpostauth
  (username, pass, reply, authdate)                           VALUES (
                          'ithce0412',
'hiit_pass',                           'Access-Accept', '2012-04-14
11:14:42')
rlm_sql (sql): Released sql socket id: 1
++[sql] returns ok
++[exec] returns noop
Sending Access-Accept of id 120 to 192.168.245.1 port 65287
Finished request 1.
Going to the next request
Waking up in 4.9 seconds.
Cleaning up request 1 ID 120 with timestamp +117
Ready to process requests.