Failure to Process radgroupreply
Andrew Long
fursink at gmail.com
Thu Apr 5 17:19:09 CEST 2012
OK, the test from an actual client behind the Nomadix fails even after
un-commenting read_groups = yes and restarting, still no group
attributes passed in reply.
This debug is rather lengthy as I thought you might want to see some
of the earlier loading (though I snipped some).
What should I try next?
<snip>
radiusd: #### Instantiating modules ####
instantiate {
Module: Linked to module rlm_exec
Module: Instantiating exec
exec {
wait = no
input_pairs = "request"
shell_escape = yes
}
Module: Linked to module rlm_expr
Module: Instantiating expr
Module: Linked to module rlm_expiration
Module: Instantiating expiration
expiration {
reply-message = "Password Has Expired "
}
Module: Linked to module rlm_logintime
Module: Instantiating logintime
logintime {
reply-message = "You are calling outside your allowed timespan "
minimum-timeout = 60
}
}
radiusd: #### Loading Virtual Servers ####
server {
modules {
Module: Checking authenticate {...} for more modules to load
Module: Linked to module rlm_pap
Module: Instantiating pap
pap {
encryption_scheme = "auto"
auto_header = no
}
Module: Linked to module rlm_chap
Module: Instantiating chap
Module: Linked to module rlm_mschap
Module: Instantiating mschap
mschap {
use_mppe = yes
require_encryption = no
require_strong = no
with_ntdomain_hack = no
}
Module: Checking authorize {...} for more modules to load
Module: Linked to module rlm_preprocess
Module: Instantiating 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_realm
Module: Instantiating suffix
realm suffix {
format = "suffix"
delimiter = "@"
ignore_default = no
ignore_null = no
}
Module: Linked to module rlm_sql
Module: Instantiating sql
sql {
driver = "rlm_sql_mysql"
server = "localhost"
port = ""
login = "radiusd"
password = "radiusd"
radius_db = "radius2"
read_groups = yes
sqltrace = no
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 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 at localhost:/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 noresetcounter
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: 1333638543 [2012-04-05 11:09:03], Next
reset 0 [2012-04-05 11:00:00]
rlm_sqlcounter: Current Time: 1333638543 [2012-04-05 11:09:03], Prev
reset 0 [2012-04-05 11:00:00]
Module: Instantiating dailycounter
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: 1333638543 [2012-04-05 11:09:03], Next
reset 1333684800 [2012-04-06 00:00:00]
rlm_sqlcounter: Current Time: 1333638543 [2012-04-05 11:09:03], Prev
reset 1333598400 [2012-04-05 00:00:00]
Module: Instantiating monthlycounter
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: 1333638543 [2012-04-05 11:09:03], Next
reset 1335844800 [2012-05-01 00:00:00]
rlm_sqlcounter: Current Time: 1333638543 [2012-04-05 11:09:03], Prev
reset 1333252800 [2012-04-01 00:00:00]
Module: Instantiating daypasscounter
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: 1333638543 [2012-04-05 11:09:03], Next
reset 0 [2012-04-05 11:00:00]
rlm_sqlcounter: Current Time: 1333638543 [2012-04-05 11:09:03], Prev
reset 0 [2012-04-05 11:00:00]
Module: Checking preacct {...} for more modules to load
Module: Linked to module rlm_acct_unique
Module: Instantiating 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 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 detail
detail {
detailfile =
"/var/log/radius/radacct/%{Client-IP-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 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 attr_filter.accounting_response
attr_filter attr_filter.accounting_response {
attrsfile = "/etc/raddb/attrs.accounting_response"
key = "%{User-Name}"
}
Module: Checking session {...} for more modules to load
Module: Checking post-auth {...} for more modules to load
Module: Instantiating attr_filter.access_reject
attr_filter attr_filter.access_reject {
attrsfile = "/etc/raddb/attrs.access_reject"
key = "%{User-Name}"
}
} # 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"
}
}
Listening on authentication address * port 1812
Listening on accounting address * port 1813
Listening on command file /var/run/radiusd/radiusd.sock
Ready to process requests.
<snip>
rad_recv: Access-Request packet from host xx.xx.xx.xx port 1031,
id=26, length=260
User-Name = "memwg140412"
NAS-IP-Address = xx.xx.xx.xx
NAS-Port = 0
Service-Type = Login-User
Acct-Session-Id = "0F00008E"
Called-Station-Id = "00-50-E8-03-13-0D"
Calling-Station-Id = "00-1F-3C-83-3C-E4"
Nomadix-Logoff-URL = "http://1.1.1.1"
WISPr-Location-ID = "isocc=840,cc=011,ac=901,network=Holiday Inn"
Framed-IP-Address = 192.168.1.52
MS-CHAP-Challenge = 0xb03f0000a3090000056d00007d520000
MS-CHAP2-Response =
0xbc000c3c0000700100001c640000f967000000000000000000007e96645fb3fad2e732972a2672cf55e17f24a48e753ea09f
+- entering group authorize {...}
++[preprocess] returns ok
++[chap] returns noop
[mschap] Found MS-CHAP attributes. Setting 'Auth-Type = mschap'
++[mschap] returns ok
[suffix] No '@' in User-Name = "memwg140412", looking up realm NULL
[suffix] No such realm "NULL"
++[suffix] returns noop
[sql] expand: %{User-Name} -> memwg140412
[sql] sql_set_user escaped user --> 'memwg140412'
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 = 'memwg140412' 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 = 'memwg140412' ORDER
BY id
[sql] expand: SELECT groupname FROM radusergroup
WHERE username = '%{SQL-User-Name}' ORDER BY priority ->
SELECT groupname FROM radusergroup WHERE username
= 'memwg140412' 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 (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] Found existing Auth-Type, not changing it.
++[pap] returns noop
Found Auth-Type = MSCHAP
+- entering group MS-CHAP {...}
[mschap] Told to do MS-CHAPv2 for memwg140412 with NT-Password
[mschap] adding MS-CHAPv2 MPPE keys
++[mschap] returns ok
Login OK: [memwg140412] (from client xxx-gateway port 0 cli 00-1F-3C-83-3C-E4)
+- entering group post-auth {...}
[sql] expand: %{User-Name} -> memwg140412
[sql] sql_set_user escaped user --> 'memwg140412'
[sql] expand: %{User-Password} ->
[sql] ... expanding second conditional
[sql] expand: %{Chap-Password} ->
[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 ( 'memwg140412',
'', 'Access-Accept', '2012-04-05
11:09:17')
rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth
(username, pass, reply, authdate)
VALUES ( 'memwg140412',
'', 'Access-Accept',
'2012-04-05 11:09:17')
rlm_sql (sql): Reserving sql socket id: 1
rlm_sql (sql): Released sql socket id: 1
++[sql] returns ok
++[exec] returns noop
Sending Access-Accept of id 26 to xx.xx.xx.xx port 1031
MS-CHAP2-Success =
0xbc533d43323337463532313532393933423839464445453446374145384342433643383235343231313037
MS-MPPE-Recv-Key = 0xa9df6d6d7c6e4c8c4956f26197314f4d
MS-MPPE-Send-Key = 0x7bc8f7efdf37c3d17a107b73dc7fedcb
MS-MPPE-Encryption-Policy = 0x00000001
MS-MPPE-Encryption-Types = 0x00000006
Finished request 1.
More information about the Freeradius-Users
mailing list