EAP/TLS Fails FR3.0.4 Centos7
Kris Armstrong
kris.armstrong at me.com
Tue Jul 7 18:59:02 CEST 2015
I've installed CentOS 7 with all patches and then installed FR3.04 along with Mysql authentications. Since installing MYSQL authentication I can't get EAP/TLS to work. I'm using the default Certs at this point created by FR3.04 durring the install.
It looks like FR3.0.4 is still attempting authentication via the SQL database even when the client is using EAP-TLS. Any ideas why? how to fix?
Below is is FR3.0.4 in Debug Mode
Ready to process requests
soh {
dhcp = yes
}
# Instantiating module "sradutmp" from file /etc/raddb/mods-enabled/sradutmp
radutmp sradutmp {
filename = "/var/log/radius/sradutmp"
username = "%{User-Name}"
case_sensitive = yes
check_with_nas = yes
permissions = 420
caller_id = no
}
# Loaded module rlm_unix
# Instantiating module "unix" from file /etc/raddb/mods-enabled/unix
unix {
radwtmp = "/var/log/radius/radwtmp"
}
# Loaded module rlm_unpack
# Instantiating module "unpack" from file /etc/raddb/mods-enabled/unpack
# Loaded module rlm_utf8
# Instantiating module "utf8" from file /etc/raddb/mods-enabled/utf8
# Loaded module rlm_sql
# Instantiating module "sql" from file /etc/raddb/mods-enabled/sql
sql {
driver = "rlm_sql_mysql"
server = "localhost"
port = "3306"
login = "radius"
password = <<< secret >>>
radius_db = "radius"
read_groups = yes
read_profiles = yes
read_clients = yes
delete_stale_sessions = yes
sql_user_name = "%{User-Name}"
default_user_profile = ""
client_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"
group_membership_query = "SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority"
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"
safe_characters = "@abcdefghijklmnopqrstuvwxyzABCDEFGHIJKLMNOPQRSTUVWXYZ0123456789.-_: /"
}
accounting {
reference = "%{tolower:type.%{Acct-Status-Type}.query}"
}
post-auth {
reference = ".query"
}
mysql {
tls {
}
}
rlm_sql (sql): Driver rlm_sql_mysql (module rlm_sql_mysql) loaded and linked
rlm_sql (sql): Attempting to connect to database "radius"
rlm_sql (sql): Initialising connection pool
pool {
start = 5
min = 4
max = 32
spare = 3
uses = 0
lifetime = 0
cleanup_interval = 30
idle_timeout = 60
retry_delay = 1
spread = no
}
rlm_sql (sql): Opening additional connection (0)
rlm_sql_mysql: Starting connect to MySQL server
rlm_sql (sql): Opening additional connection (1)
rlm_sql_mysql: Starting connect to MySQL server
rlm_sql (sql): Opening additional connection (2)
rlm_sql_mysql: Starting connect to MySQL server
rlm_sql (sql): Opening additional connection (3)
rlm_sql_mysql: Starting connect to MySQL server
rlm_sql (sql): Opening additional connection (4)
rlm_sql_mysql: Starting connect to MySQL server
rlm_sql (sql): Processing generate_sql_clients
rlm_sql (sql) in generate_sql_clients: query is SELECT id, nasname, shortname, type, secret, server FROM nas
rlm_sql (sql): Reserved connection (4)
rlm_sql (sql): Executing query: 'SELECT id, nasname, shortname, type, secret, server FROM nas'
rlm_sql (sql): Adding client 10.250.0.0/23 (network) to global clients list
Failed to add duplicate client network
Failed to add client, possible duplicate?
rlm_sql (sql): Adding client 10.250.8.0/23 (AP) to global clients list
rlm_sql (10.250.8.0): Client "AP" (sql) added
rlm_sql (sql): Released connection (4)
} # modules
radiusd: #### Loading Virtual Servers ####
server { # from file /etc/raddb/radiusd.conf
} # server
server default { # from file /etc/raddb/sites-enabled/default
# Creating Auth-Type = digest
# Loading authenticate {...}
# Loading authorize {...}
Ignoring "ldap" (see raddb/mods-available/README.rst)
# Loading preacct {...}
# Loading accounting {...}
# Loading post-proxy {...}
# Loading post-auth {...}
} # server default
server inner-tunnel { # from file /etc/raddb/sites-enabled/inner-tunnel
# Loading authenticate {...}
# Loading authorize {...}
# Loading session {...}
# Loading post-proxy {...}
# Loading post-auth {...}
} # server inner-tunnel
radiusd: #### Opening IP addresses and Ports ####
listen {
type = "auth"
ipaddr = *
port = 0
limit {
max_connections = 16
lifetime = 0
idle_timeout = 30
}
}
listen {
type = "acct"
ipaddr = *
port = 0
limit {
max_connections = 16
lifetime = 0
idle_timeout = 30
}
}
listen {
type = "auth"
ipv6addr = ::
port = 0
limit {
max_connections = 16
lifetime = 0
idle_timeout = 30
}
}
listen {
type = "acct"
ipv6addr = ::
port = 0
limit {
max_connections = 16
lifetime = 0
idle_timeout = 30
}
}
listen {
type = "auth"
ipaddr = 127.0.0.1
port = 18120
}
Listening on auth address * port 1812 as server default
Listening on acct address * port 1813 as server default
Listening on auth address :: port 1812 as server default
Listening on acct address :: port 1813 as server default
Listening on auth address 127.0.0.1 port 18120 as server inner-tunnel
Opening new proxy socket 'proxy address * port 0'
Listening on proxy address * port 59282
Ready to process requests
Received Access-Request Id 2 from 10.250.8.180:33695 to 10.250.16.126:1812 length 145
User-Name = 'user at example.com'
NAS-IP-Address = 10.250.8.180
Called-Station-Id = 'c8d71992a9d7'
Calling-Station-Id = '00c01732012e'
NAS-Identifier = 'c8d71992a9d7'
NAS-Port = 29
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
EAP-Message = 0x020000150175736572406578616d706c652e636f6d
Message-Authenticator = 0x16054b79b216d8da1c4571f81ad49f4c
(0) Received Access-Request packet from host 10.250.8.180 port 33695, id=2, length=145
(0) User-Name = 'user at example.com'
(0) NAS-IP-Address = 10.250.8.180
(0) Called-Station-Id = 'c8d71992a9d7'
(0) Calling-Station-Id = '00c01732012e'
(0) NAS-Identifier = 'c8d71992a9d7'
(0) NAS-Port = 29
(0) Framed-MTU = 1400
(0) NAS-Port-Type = Wireless-802.11
(0) EAP-Message = 0x020000150175736572406578616d706c652e636f6d
(0) Message-Authenticator = 0x16054b79b216d8da1c4571f81ad49f4c
(0) # Executing section authorize from file /etc/raddb/sites-enabled/default
(0) authorize {
(0) filter_username filter_username {
(0) if (!&User-Name)
(0) if (!&User-Name) -> FALSE
(0) if (&User-Name =~ / /)
(0) if (&User-Name =~ / /) -> FALSE
(0) if (&User-Name =~ /@.*@/ )
(0) if (&User-Name =~ /@.*@/ ) -> FALSE
(0) if (&User-Name =~ /\\.\\./ )
(0) if (&User-Name =~ /\\.\\./ ) -> FALSE
(0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))
(0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE
(0) if (&User-Name =~ /\\.$/)
(0) if (&User-Name =~ /\\.$/) -> FALSE
(0) if (&User-Name =~ /@\\./)
(0) if (&User-Name =~ /@\\./) -> FALSE
(0) } # filter_username filter_username = notfound
(0) [preprocess] = ok
(0) [chap] = noop
(0) [mschap] = noop
(0) [digest] = noop
(0) suffix : Checking for suffix after "@"
(0) suffix : Looking up realm "example.com" for User-Name = "user at example.com"
(0) suffix : Found realm "example.com"
(0) suffix : Adding Stripped-User-Name = "user"
(0) suffix : Adding Realm = "example.com"
(0) suffix : Proxying request from user user to realm example.com
(0) suffix : Preparing to proxy authentication request to realm "example.com"
(0) [suffix] = updated
(0) eap : Request is supposed to be proxied to Realm example.com. Not doing EAP.
(0) [eap] = noop
(0) [files] = noop
(0) sql : EXPAND %{User-Name}
(0) sql : --> user at example.com
(0) sql : SQL-User-Name set to 'user at example.com'
rlm_sql (sql): Reserved connection (4)
(0) sql : EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
(0) sql : --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user at example.com' ORDER BY id
rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user at example.com' ORDER BY id'
(0) sql : EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
(0) sql : --> SELECT groupname FROM radusergroup WHERE username = 'user at example.com' ORDER BY priority
rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'user at example.com' ORDER BY priority'
(0) sql : User not found in any groups
rlm_sql (sql): Released connection (4)
rlm_sql (sql): Closing connection (0), from 1 unused connections
rlm_sql_mysql: Socket destructor called, closing socket
(0) [sql] = notfound
(0) [expiration] = noop
(0) [logintime] = noop
(0) [pap] = noop
(0) } # authorize = updated
Opening new proxy socket 'proxy address * port 0'
Listening on proxy address * port 36256
(0) Proxying request to home server 127.0.0.1 port 1812 timeout 20.000000
(0) Sending Access-Request packet to host 127.0.0.1 port 1812, id=241, length=0
(0) User-Name = 'user'
(0) NAS-IP-Address = 10.250.8.180
(0) Called-Station-Id = 'c8d71992a9d7'
(0) Calling-Station-Id = '00c01732012e'
(0) NAS-Identifier = 'c8d71992a9d7'
(0) NAS-Port = 29
(0) Framed-MTU = 1400
(0) NAS-Port-Type = Wireless-802.11
(0) EAP-Message = 0x020000150175736572406578616d706c652e636f6d
(0) Message-Authenticator = 0x16054b79b216d8da1c4571f81ad49f4c
(0) Event-Timestamp = 'Jul 7 2015 10:46:25 MDT'
(0) Stripped-User-Name = 'user'
(0) Realm = 'example.com'
(0) EAP-Type = Identity
(0) Proxy-State = 0x32
Sending Access-Request Id 241 from 0.0.0.0:36256 to 127.0.0.1:1812
User-Name = 'user'
NAS-IP-Address = 10.250.8.180
Called-Station-Id = 'c8d71992a9d7'
Calling-Station-Id = '00c01732012e'
NAS-Identifier = 'c8d71992a9d7'
NAS-Port = 29
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
EAP-Message = 0x020000150175736572406578616d706c652e636f6d
Message-Authenticator = 0x16054b79b216d8da1c4571f81ad49f4c
Event-Timestamp = 'Jul 7 2015 10:46:25 MDT'
Proxy-State = 0x32
Waking up in 0.3 seconds.
Received Access-Request Id 241 from 127.0.0.1:36256 to 127.0.0.1:1812 length 142
User-Name = 'user'
NAS-IP-Address = 10.250.8.180
Called-Station-Id = 'c8d71992a9d7'
Calling-Station-Id = '00c01732012e'
NAS-Identifier = 'c8d71992a9d7'
NAS-Port = 29
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
EAP-Message = 0x020000150175736572406578616d706c652e636f6d
Message-Authenticator = 0x90c2755352698013c98625381ba727bf
Event-Timestamp = 'Jul 7 2015 10:46:25 MDT'
Proxy-State = 0x32
(1) Received Access-Request packet from host 127.0.0.1 port 36256, id=241, length=142
(1) User-Name = 'user'
(1) NAS-IP-Address = 10.250.8.180
(1) Called-Station-Id = 'c8d71992a9d7'
(1) Calling-Station-Id = '00c01732012e'
(1) NAS-Identifier = 'c8d71992a9d7'
(1) NAS-Port = 29
(1) Framed-MTU = 1400
(1) NAS-Port-Type = Wireless-802.11
(1) EAP-Message = 0x020000150175736572406578616d706c652e636f6d
(1) Message-Authenticator = 0x90c2755352698013c98625381ba727bf
(1) Event-Timestamp = 'Jul 7 2015 10:46:25 MDT'
(1) Proxy-State = 0x32
(1) # Executing section authorize from file /etc/raddb/sites-enabled/default
(1) authorize {
(1) filter_username filter_username {
(1) if (!&User-Name)
(1) if (!&User-Name) -> FALSE
(1) if (&User-Name =~ / /)
(1) if (&User-Name =~ / /) -> FALSE
(1) if (&User-Name =~ /@.*@/ )
(1) if (&User-Name =~ /@.*@/ ) -> FALSE
(1) if (&User-Name =~ /\\.\\./ )
(1) if (&User-Name =~ /\\.\\./ ) -> FALSE
(1) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))
(1) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE
(1) if (&User-Name =~ /\\.$/)
(1) if (&User-Name =~ /\\.$/) -> FALSE
(1) if (&User-Name =~ /@\\./)
(1) if (&User-Name =~ /@\\./) -> FALSE
(1) } # filter_username filter_username = notfound
(1) [preprocess] = ok
(1) [chap] = noop
(1) [mschap] = noop
(1) [digest] = noop
(1) suffix : Checking for suffix after "@"
(1) suffix : No '@' in User-Name = "user", looking up realm NULL
(1) suffix : No such realm "NULL"
(1) [suffix] = noop
(1) eap : Peer sent code Response (2) ID 0 length 21
(1) eap : EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize
(1) [eap] = ok
(1) } # authorize = ok
(1) Found Auth-Type = EAP
(1) # Executing group from file /etc/raddb/sites-enabled/default
(1) authenticate {
(1) eap : Identity does not match User-Name, setting from EAP Identity
(1) eap : Failed in handler
(1) [eap] = invalid
(1) } # authenticate = invalid
(1) Failed to authenticate the user
(1) Using Post-Auth-Type Reject
(1) # Executing group from file /etc/raddb/sites-enabled/default
(1) Post-Auth-Type REJECT {
(1) sql : EXPAND .query
(1) sql : --> .query
(1) sql : Using query template 'query'
rlm_sql (sql): Reserved connection (4)
(1) sql : EXPAND %{User-Name}
(1) sql : --> user
(1) sql : SQL-User-Name set to 'user'
(1) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
(1) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '', 'Access-Reject', '2015-07-07 10:46:25')
rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '', 'Access-Reject', '2015-07-07 10:46:25')'
rlm_sql (sql): Released connection (4)
(1) [sql] = ok
(1) attr_filter.access_reject : EXPAND %{User-Name}
(1) attr_filter.access_reject : --> user
(1) attr_filter.access_reject : Matched entry DEFAULT at line 11
(1) [attr_filter.access_reject] = updated
(1) eap : Identity does not match User-Name, setting from EAP Identity
(1) eap : Failed to get handler, probably already removed, not inserting EAP-Failure
(1) [eap] = noop
(1) remove_reply_message_if_eap remove_reply_message_if_eap {
(1) if (&reply:EAP-Message && &reply:Reply-Message)
(1) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
(1) else else {
(1) [noop] = noop
(1) } # else else = noop
(1) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
(1) } # Post-Auth-Type REJECT = updated
(1) Delaying response for 1 seconds
Waking up in 0.3 seconds.
Waking up in 0.1 seconds.
(0) Expecting proxy response no later than 19.499798 seconds from now
Waking up in 0.5 seconds.
(1) Sending delayed response
(1) Sending Access-Reject packet to host 127.0.0.1 port 36256, id=241, length=0
(1) Proxy-State = 0x32
Sending Access-Reject Id 241 from 127.0.0.1:1812 to 127.0.0.1:36256
Proxy-State = 0x32
Waking up in 3.9 seconds.
Received Access-Reject Id 241 from 127.0.0.1:1812 to 127.0.0.1:36256 length 23
Proxy-State = 0x32
(0) Received Access-Reject packet from host 127.0.0.1 port 1812, id=241, length=23
(0) Proxy-State = 0x32
(0) # Executing section post-proxy from file /etc/raddb/sites-enabled/default
(0) post-proxy {
(0) eap : No pre-existing handler found
(0) [eap] = noop
(0) } # post-proxy = noop
(0) Using Post-Auth-Type Reject
(0) # Executing group from file /etc/raddb/sites-enabled/default
(0) Post-Auth-Type REJECT {
(0) sql : EXPAND .query
(0) sql : --> .query
(0) sql : Using query template 'query'
rlm_sql (sql): Reserved connection (4)
(0) sql : EXPAND %{User-Name}
(0) sql : --> user at example.com
(0) sql : SQL-User-Name set to 'user at example.com'
(0) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
(0) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user at example.com', '', 'Access-Reject', '2015-07-07 10:46:25')
rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user at example.com', '', 'Access-Reject', '2015-07-07 10:46:25')'
rlm_sql (sql): Released connection (4)
(0) [sql] = ok
(0) attr_filter.access_reject : EXPAND %{User-Name}
(0) attr_filter.access_reject : --> user at example.com
(0) attr_filter.access_reject : Matched entry DEFAULT at line 11
(0) [attr_filter.access_reject] = updated
(0) eap : Request was previously rejected, inserting EAP-Failure
(0) [eap] = updated
(0) remove_reply_message_if_eap remove_reply_message_if_eap {
(0) if (&reply:EAP-Message && &reply:Reply-Message)
(0) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
(0) else else {
(0) [noop] = noop
(0) } # else else = noop
(0) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
(0) } # Post-Auth-Type REJECT = updated
(0) Delaying response for 1 seconds
Waking up in 0.3 seconds.
Waking up in 0.6 seconds.
(0) Sending delayed response
(0) Sending Access-Reject packet to host 10.250.8.180 port 33695, id=2, length=0
(0) EAP-Message = 0x04000004
(0) Message-Authenticator = 0x00000000000000000000000000000000
Sending Access-Reject Id 2 from 10.250.16.126:1812 to 10.250.8.180:33695
EAP-Message = 0x04000004
Message-Authenticator = 0x00000000000000000000000000000000
Waking up in 2.9 seconds.
(1) Cleaning up request packet ID 241 with timestamp +40
Waking up in 0.9 seconds.
(0) Cleaning up request packet ID 2 with timestamp +40
Ready to process requests
Received Access-Request Id 2 from 10.250.8.180:33695 to 10.250.16.126:1812 length 145
User-Name = 'user at example.com'
NAS-IP-Address = 10.250.8.180
Called-Station-Id = 'c8d71992a9d7'
Calling-Station-Id = '00c01732012e'
NAS-Identifier = 'c8d71992a9d7'
NAS-Port = 29
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
EAP-Message = 0x020000150175736572406578616d706c652e636f6d
Message-Authenticator = 0x16054b79b216d8da1c4571f81ad49f4c
(0) Received Access-Request packet from host 10.250.8.180 port 33695, id=2, length=145
(0) User-Name = 'user at example.com'
(0) NAS-IP-Address = 10.250.8.180
(0) Called-Station-Id = 'c8d71992a9d7'
(0) Calling-Station-Id = '00c01732012e'
(0) NAS-Identifier = 'c8d71992a9d7'
(0) NAS-Port = 29
(0) Framed-MTU = 1400
(0) NAS-Port-Type = Wireless-802.11
(0) EAP-Message = 0x020000150175736572406578616d706c652e636f6d
(0) Message-Authenticator = 0x16054b79b216d8da1c4571f81ad49f4c
(0) # Executing section authorize from file /etc/raddb/sites-enabled/default
(0) authorize {
(0) filter_username filter_username {
(0) if (!&User-Name)
(0) if (!&User-Name) -> FALSE
(0) if (&User-Name =~ / /)
(0) if (&User-Name =~ / /) -> FALSE
(0) if (&User-Name =~ /@.*@/ )
(0) if (&User-Name =~ /@.*@/ ) -> FALSE
(0) if (&User-Name =~ /\\.\\./ )
(0) if (&User-Name =~ /\\.\\./ ) -> FALSE
(0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))
(0) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE
(0) if (&User-Name =~ /\\.$/)
(0) if (&User-Name =~ /\\.$/) -> FALSE
(0) if (&User-Name =~ /@\\./)
(0) if (&User-Name =~ /@\\./) -> FALSE
(0) } # filter_username filter_username = notfound
(0) [preprocess] = ok
(0) [chap] = noop
(0) [mschap] = noop
(0) [digest] = noop
(0) suffix : Checking for suffix after "@"
(0) suffix : Looking up realm "example.com" for User-Name = "user at example.com"
(0) suffix : Found realm "example.com"
(0) suffix : Adding Stripped-User-Name = "user"
(0) suffix : Adding Realm = "example.com"
(0) suffix : Proxying request from user user to realm example.com
(0) suffix : Preparing to proxy authentication request to realm "example.com"
(0) [suffix] = updated
(0) eap : Request is supposed to be proxied to Realm example.com. Not doing EAP.
(0) [eap] = noop
(0) [files] = noop
(0) sql : EXPAND %{User-Name}
(0) sql : --> user at example.com
(0) sql : SQL-User-Name set to 'user at example.com'
rlm_sql (sql): Reserved connection (4)
(0) sql : EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
(0) sql : --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user at example.com' ORDER BY id
rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user at example.com' ORDER BY id'
(0) sql : EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
(0) sql : --> SELECT groupname FROM radusergroup WHERE username = 'user at example.com' ORDER BY priority
rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'user at example.com' ORDER BY priority'
(0) sql : User not found in any groups
rlm_sql (sql): Released connection (4)
rlm_sql (sql): Closing connection (0), from 1 unused connections
rlm_sql_mysql: Socket destructor called, closing socket
(0) [sql] = notfound
(0) [expiration] = noop
(0) [logintime] = noop
(0) [pap] = noop
(0) } # authorize = updated
Opening new proxy socket 'proxy address * port 0'
Listening on proxy address * port 36256
(0) Proxying request to home server 127.0.0.1 port 1812 timeout 20.000000
(0) Sending Access-Request packet to host 127.0.0.1 port 1812, id=241, length=0
(0) User-Name = 'user'
(0) NAS-IP-Address = 10.250.8.180
(0) Called-Station-Id = 'c8d71992a9d7'
(0) Calling-Station-Id = '00c01732012e'
(0) NAS-Identifier = 'c8d71992a9d7'
(0) NAReceived Access-Request Id 2 from 10.250.8.180:33695 to 10.250.16.126:1812 length 145
User-Name = 'user at example.com'
NAS-IP-Address = 10.250.8.180
Called-Station-Id = 'c8d71992a9d7'
Calling-Station-Id = '00c01732012e'
NAS-Identifier = 'c8d71992a9d7'
NAS-Port = 29
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
EAP-Message = 0x020100150175736572406578616d706c652e636f6d
Message-Authenticator = 0x81f5808340b398c3e4d670f6b300a7a7
(2) Received Access-Request packet from host 10.250.8.180 port 33695, id=2, length=145
(2) User-Name = 'user at example.com'
(2) NAS-IP-Address = 10.250.8.180
(2) Called-Station-Id = 'c8d71992a9d7'
(2) Calling-Station-Id = '00c01732012e'
(2) NAS-Identifier = 'c8d71992a9d7'
(2) NAS-Port = 29
(2) Framed-MTU = 1400
(2) NAS-Port-Type = Wireless-802.11
(2) EAP-Message = 0x020100150175736572406578616d706c652e636f6d
(2) Message-Authenticator = 0x81f5808340b398c3e4d670f6b300a7a7
(2) # Executing section authorize from file /etc/raddb/sites-enabled/default
(2) authorize {
(2) filter_username filter_username {
(2) if (!&User-Name)
(2) if (!&User-Name) -> FALSE
(2) if (&User-Name =~ / /)
(2) if (&User-Name =~ / /) -> FALSE
(2) if (&User-Name =~ /@.*@/ )
(2) if (&User-Name =~ /@.*@/ ) -> FALSE
(2) if (&User-Name =~ /\\.\\./ )
(2) if (&User-Name =~ /\\.\\./ ) -> FALSE
(2) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))
(2) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE
(2) if (&User-Name =~ /\\.$/)
(2) if (&User-Name =~ /\\.$/) -> FALSE
(2) if (&User-Name =~ /@\\./)
(2) if (&User-Name =~ /@\\./) -> FALSE
(2) } # filter_username filter_username = notfound
(2) [preprocess] = ok
(2) [chap] = noop
(2) [mschap] = noop
(2) [digest] = noop
(2) suffix : Checking for suffix after "@"
(2) suffix : Looking up realm "example.com" for User-Name = "user at example.com"
(2) suffix : Found realm "example.com"
(2) suffix : Adding Stripped-User-Name = "user"
(2) suffix : Adding Realm = "example.com"
(2) suffix : Proxying request from user user to realm example.com
(2) suffix : Preparing to proxy authentication request to realm "example.com"
(2) [suffix] = updated
(2) eap : Request is supposed to be proxied to Realm example.com. Not doing EAP.
(2) [eap] = noop
(2) [files] = noop
(2) sql : EXPAND %{User-Name}
(2) sql : --> user at example.com
(2) sql : SQL-User-Name set to 'user at example.com'
rlm_sql (sql): Reserved connection (4)
(2) sql : EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
(2) sql : --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user at example.com' ORDER BY id
rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user at example.com' ORDER BY id'
(2) sql : EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
(2) sql : --> SELECT groupname FROM radusergroup WHERE username = 'user at example.com' ORDER BY priority
rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'user at example.com' ORDER BY priority'
(2) sql : User not found in any groups
rlm_sql (sql): Released connection (4)
rlm_sql (sql): Closing connection (3): Hit idle_timeout, was idle for 134 seconds
rlm_sql (sql): You probably need to lower "min"
rlm_sql_mysql: Socket destructor called, closing socket
rlm_sql (sql): Closing connection (2): Hit idle_timeout, was idle for 134 seconds
rlm_sql (sql): You probably need to lower "min"
rlm_sql_mysql: Socket destructor called, closing socket
rlm_sql (sql): Closing connection (1): Hit idle_timeout, was idle for 134 seconds
rlm_sql (sql): You probably need to lower "min"
rlm_sql_mysql: Socket destructor called, closing socket
(2) [sql] = notfound
(2) [expiration] = noop
(2) [logintime] = noop
(2) [pap] = noop
(2) } # authorize = updated
(2) Proxying request to home server 127.0.0.1 port 1812 timeout 20.000000
(2) Sending Access-Request packet to host 127.0.0.1 port 1812, id=195, length=0
(2) User-Name = 'user'
(2) NAS-IP-Address = 10.250.8.180
(2) Called-Station-Id = 'c8d71992a9d7'
(2) Calling-Station-Id = '00c01732012e'
(2) NAS-Identifier = 'c8d71992a9d7'
(2) NAS-Port = 29
(2) Framed-MTU = 1400
(2) NAS-Port-Type = Wireless-802.11
(2) EAP-Message = 0x020100150175736572406578616d706c652e636f6d
(2) Message-Authenticator = 0x81f5808340b398c3e4d670f6b300a7a7
(2) Event-Timestamp = 'Jul 7 2015 10:47:59 MDT'
(2) Stripped-User-Name = 'user'
(2) Realm = 'example.com'
(2) EAP-Type = Identity
(2) Proxy-State = 0x32
Sending Access-Request Id 195 from 0.0.0.0:36256 to 127.0.0.1:1812
User-Name = 'user'
NAS-IP-Address = 10.250.8.180
Called-Station-Id = 'c8d71992a9d7'
Calling-Station-Id = '00c01732012e'
NAS-Identifier = 'c8d71992a9d7'
NAS-Port = 29
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
EAP-Message = 0x020100150175736572406578616d706c652e636f6d
Message-Authenticator = 0x81f5808340b398c3e4d670f6b300a7a7
Event-Timestamp = 'Jul 7 2015 10:47:59 MDT'
Proxy-State = 0x32
Waking up in 0.3 seconds.
Received Access-Request Id 195 from 127.0.0.1:36256 to 127.0.0.1:1812 length 142
User-Name = 'user'
NAS-IP-Address = 10.250.8.180
Called-Station-Id = 'c8d71992a9d7'
Calling-Station-Id = '00c01732012e'
NAS-Identifier = 'c8d71992a9d7'
NAS-Port = 29
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
EAP-Message = 0x020100150175736572406578616d706c652e636f6d
Message-Authenticator = 0xb0b349a74d58945205b266f508870912
Event-Timestamp = 'Jul 7 2015 10:47:59 MDT'
Proxy-State = 0x32
(3) Received Access-Request packet from host 127.0.0.1 port 36256, id=195, length=142
(3) User-Name = 'user'
(3) NAS-IP-Address = 10.250.8.180
(3) Called-Station-Id = 'c8d71992a9d7'
(3) Calling-Station-Id = '00c01732012e'
(3) NAS-Identifier = 'c8d71992a9d7'
(3) NAS-Port = 29
(3) Framed-MTU = 1400
(3) NAS-Port-Type = Wireless-802.11
(3) EAP-Message = 0x020100150175736572406578616d706c652e636f6d
(3) Message-Authenticator = 0xb0b349a74d58945205b266f508870912
(3) Event-Timestamp = 'Jul 7 2015 10:47:59 MDT'
(3) Proxy-State = 0x32
(3) # Executing section authorize from file /etc/raddb/sites-enabled/default
(3) authorize {
(3) filter_username filter_username {
(3) if (!&User-Name)
(3) if (!&User-Name) -> FALSE
(3) if (&User-Name =~ / /)
(3) if (&User-Name =~ / /) -> FALSE
(3) if (&User-Name =~ /@.*@/ )
(3) if (&User-Name =~ /@.*@/ ) -> FALSE
(3) if (&User-Name =~ /\\.\\./ )
(3) if (&User-Name =~ /\\.\\./ ) -> FALSE
(3) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))
(3) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE
(3) if (&User-Name =~ /\\.$/)
(3) if (&User-Name =~ /\\.$/) -> FALSE
(3) if (&User-Name =~ /@\\./)
(3) if (&User-Name =~ /@\\./) -> FALSE
(3) } # filter_username filter_username = notfound
(3) [preprocess] = ok
(3) [chap] = noop
(3) [mschap] = noop
(3) [digest] = noop
(3) suffix : Checking for suffix after "@"
(3) suffix : No '@' in User-Name = "user", looking up realm NULL
(3) suffix : No such realm "NULL"
(3) [suffix] = noop
(3) eap : Peer sent code Response (2) ID 1 length 21
(3) eap : EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize
(3) [eap] = ok
(3) } # authorize = ok
(3) Found Auth-Type = EAP
(3) # Executing group from file /etc/raddb/sites-enabled/default
(3) authenticate {
(3) eap : Identity does not match User-Name, setting from EAP Identity
(3) eap : Failed in handler
(3) [eap] = invalid
(3) } # authenticate = invalid
(3) Failed to authenticate the user
(3) Using Post-Auth-Type Reject
(3) # Executing group from file /etc/raddb/sites-enabled/default
(3) Post-Auth-Type REJECT {
(3) sql : EXPAND .query
(3) sql : --> .query
(3) sql : Using query template 'query'
rlm_sql (sql): Reserved connection (4)
(3) sql : EXPAND %{User-Name}
(3) sql : --> user
(3) sql : SQL-User-Name set to 'user'
(3) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
(3) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '', 'Access-Reject', '2015-07-07 10:47:59')
rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '', 'Access-Reject', '2015-07-07 10:47:59')'
rlm_sql (sql): Released connection (4)
(3) [sql] = ok
(3) attr_filter.access_reject : EXPAND %{User-Name}
(3) attr_filter.access_reject : --> user
(3) attr_filter.access_reject : Matched entry DEFAULT at line 11
(3) [attr_filter.access_reject] = updated
(3) eap : Identity does not match User-Name, setting from EAP Identity
(3) eap : Failed to get handler, probably already removed, not inserting EAP-Failure
(3) [eap] = noop
(3) remove_reply_message_if_eap remove_reply_message_if_eap {
(3) if (&reply:EAP-Message && &reply:Reply-Message)
(3) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
(3) else else {
(3) [noop] = noop
(3) } # else else = noop
(3) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
(3) } # Post-Auth-Type REJECT = updated
(3) Delaying response for 1 seconds
Waking up in 0.3 seconds.
Waking up in 0.1 seconds.
(2) Expecting proxy response no later than 19.499792 seconds from now
Waking up in 0.5 seconds.
(3) Sending delayed response
(3) Sending Access-Reject packet to host 127.0.0.1 port 36256, id=195, length=0
(3) Proxy-State = 0x32
Sending Access-Reject Id 195 from 127.0.0.1:1812 to 127.0.0.1:36256
Proxy-State = 0x32
Waking up in 3.9 seconds.
Received Access-Reject Id 195 from 127.0.0.1:1812 to 127.0.0.1:36256 length 23
Proxy-State = 0x32
(2) Received Access-Reject packet from host 127.0.0.1 port 1812, id=195, length=23
(2) Proxy-State = 0x32
(2) # Executing section post-proxy from file /etc/raddb/sites-enabled/default
(2) post-proxy {
(2) eap : No pre-existing handler found
(2) [eap] = noop
(2) } # post-proxy = noop
(2) Using Post-Auth-Type Reject
(2) # Executing group from file /etc/raddb/sites-enabled/default
(2) Post-Auth-Type REJECT {
(2) sql : EXPAND .query
(2) sql : --> .query
(2) sql : Using query template 'query'
rlm_sql (sql): Reserved connection (4)
(2) sql : EXPAND %{User-Name}
(2) sql : --> user at example.com
(2) sql : SQL-User-Name set to 'user at example.com'
(2) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
(2) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user at example.com', '', 'Access-Reject', '2015-07-07 10:47:59')
rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user at example.com', '', 'Access-Reject', '2015-07-07 10:47:59')'
rlm_sql (sql): Released connection (4)
rlm_sql (sql): 0 of 1 connections in use. Need more spares
rlm_sql (sql): Opening additional connection (5)
rlm_sql_mysql: Starting connect to MySQL server
(2) [sql] = ok
(2) attr_filter.access_reject : EXPAND %{User-Name}
(2) attr_filter.access_reject : --> user at example.com
(2) attr_filter.access_reject : Matched entry DEFAULT at line 11
(2) [attr_filter.access_reject] = updated
(2) eap : Request was previously rejected, inserting EAP-Failure
(2) [eap] = updated
(2) remove_reply_message_if_eap remove_reply_message_if_eap {
(2) if (&reply:EAP-Message && &reply:Reply-Message)
(2) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
(2) else else {
(2) [noop] = noop
(2) } # else else = noop
(2) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
(2) } # Post-Auth-Type REJECT = updated
(2) Delaying response for 1 seconds
Waking up in 0.3 seconds.
Waking up in 0.6 seconds.
(2) Sending delayed response
(2) Sending Access-Reject packet to host 10.250.8.180 port 33695, id=2, length=0
(2) EAP-Message = 0x04010004
(2) Message-Authenticator = 0x00000000000000000000000000000000
Sending Access-Reject Id 2 from 10.250.16.126:1812 to 10.250.8.180:33695
EAP-Message = 0x04010004
Message-Authenticator = 0x00000000000000000000000000000000
Waking up in 2.9 seconds.
(3) Cleaning up request packet ID 195 with timestamp +134
Waking up in 0.9 seconds.
(2) Cleaning up request packet ID 2 with timestamp +134
Ready to process requests
Received Access-Request Id 2 from 10.250.8.180:33695 to 10.250.16.126:1812 length 145
User-Name = 'user at example.com'
NAS-IP-Address = 10.250.8.180
Called-Station-Id = 'c8d71992a9d7'
Calling-Station-Id = '00c01732012e'
NAS-Identifier = 'c8d71992a9d7'
NAS-Port = 29
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
EAP-Message = 0x020000150175736572406578616d706c652e636f6d
Message-Authenticator = 0x9ba5df6ed673c67d22bc25360801cb47
(4) Received Access-Request packet from host 10.250.8.180 port 33695, id=2, length=145
(4) User-Name = 'user at example.com'
(4) NAS-IP-Address = 10.250.8.180
(4) Called-Station-Id = 'c8d71992a9d7'
(4) Calling-Station-Id = '00c01732012e'
(4) NAS-Identifier = 'c8d71992a9d7'
(4) NAS-Port = 29
(4) Framed-MTU = 1400
(4) NAS-Port-Type = Wireless-802.11
(4) EAP-Message = 0x020000150175736572406578616d706c652e636f6d
(4) Message-Authenticator = 0x9ba5df6ed673c67d22bc25360801cb47
(4) # Executing section authorize from file /etc/raddb/sites-enabled/default
(4) authorize {
(4) filter_username filter_username {
(4) if (!&User-Name)
(4) if (!&User-Name) -> FALSE
(4) if (&User-Name =~ / /)
(4) if (&User-Name =~ / /) -> FALSE
(4) if (&User-Name =~ /@.*@/ )
(4) if (&User-Name =~ /@.*@/ ) -> FALSE
(4) if (&User-Name =~ /\\.\\./ )
(4) if (&User-Name =~ /\\.\\./ ) -> FALSE
(4) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))
(4) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE
(4) if (&User-Name =~ /\\.$/)
(4) if (&User-Name =~ /\\.$/) -> FALSE
(4) if (&User-Name =~ /@\\./)
(4) if (&User-Name =~ /@\\./) -> FALSE
(4) } # filter_username filter_username = notfound
(4) [preprocess] = ok
(4) [chap] = noop
(4) [mschap] = noop
(4) [digest] = noop
(4) suffix : Checking for suffix after "@"
(4) suffix : Looking up realm "example.com" for User-Name = "user at example.com"
(4) suffix : Found realm "example.com"
(4) suffix : Adding Stripped-User-Name = "user"
(4) suffix : Adding Realm = "example.com"
(4) suffix : Proxying request from user user to realm example.com
(4) suffix : Preparing to proxy authentication request to realm "example.com"
(4) [suffix] = updated
(4) eap : Request is supposed to be proxied to Realm example.com. Not doing EAP.
(4) [eap] = noop
(4) [files] = noop
(4) sql : EXPAND %{User-Name}
(4) sql : --> user at example.com
(4) sql : SQL-User-Name set to 'user at example.com'
rlm_sql (sql): Reserved connection (5)
(4) sql : EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
(4) sql : --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user at example.com' ORDER BY id
rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user at example.com' ORDER BY id'
(4) sql : EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
(4) sql : --> SELECT groupname FROM radusergroup WHERE username = 'user at example.com' ORDER BY priority
rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'user at example.com' ORDER BY priority'
(4) sql : User not found in any groups
rlm_sql (sql): Released connection (5)
rlm_sql (sql): 0 of 2 connections in use. Need more spares
rlm_sql (sql): Opening additional connection (6)
rlm_sql_mysql: Starting connect to MySQL server
(4) [sql] = notfound
(4) [expiration] = noop
(4) [logintime] = noop
(4) [pap] = noop
(4) } # authorize = updated
(4) Proxying request to home server 127.0.0.1 port 1812 timeout 20.000000
(4) Sending Access-Request packet to host 127.0.0.1 port 1812, id=230, length=0
(4) User-Name = 'user'
(4) NAS-IP-Address = 10.250.8.180
(4) Called-Station-Id = 'c8d71992a9d7'
(4) Calling-Station-Id = '00c01732012e'
(4) NAS-Identifier = 'c8d71992a9d7'
(4) NAS-Port = 29
(4) Framed-MTU = 1400
(4) NAS-Port-Type = Wireless-802.11
(4) EAP-Message = 0x020000150175736572406578616d706c652e636f6d
(4) Message-Authenticator = 0x9ba5df6ed673c67d22bc25360801cb47
(4) Event-Timestamp = 'Jul 7 2015 10:48:07 MDT'
(4) Stripped-User-Name = 'user'
(4) Realm = 'example.com'
(4) EAP-Type = Identity
(4) Proxy-State = 0x32
Sending Access-Request Id 230 from 0.0.0.0:36256 to 127.0.0.1:1812
User-Name = 'user'
NAS-IP-Address = 10.250.8.180
Called-Station-Id = 'c8d71992a9d7'
Calling-Station-Id = '00c01732012e'
NAS-Identifier = 'c8d71992a9d7'
NAS-Port = 29
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
EAP-Message = 0x020000150175736572406578616d706c652e636f6d
Message-Authenticator = 0x9ba5df6ed673c67d22bc25360801cb47
Event-Timestamp = 'Jul 7 2015 10:48:07 MDT'
Proxy-State = 0x32
Waking up in 0.3 seconds.
Received Access-Request Id 230 from 127.0.0.1:36256 to 127.0.0.1:1812 length 142
User-Name = 'user'
NAS-IP-Address = 10.250.8.180
Called-Station-Id = 'c8d71992a9d7'
Calling-Station-Id = '00c01732012e'
NAS-Identifier = 'c8d71992a9d7'
NAS-Port = 29
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
EAP-Message = 0x020000150175736572406578616d706c652e636f6d
Message-Authenticator = 0x4c386d1361dbbd34947533bd5874d113
Event-Timestamp = 'Jul 7 2015 10:48:07 MDT'
Proxy-State = 0x32
(5) Received Access-Request packet from host 127.0.0.1 port 36256, id=230, length=142
(5) User-Name = 'user'
(5) NAS-IP-Address = 10.250.8.180
(5) Called-Station-Id = 'c8d71992a9d7'
(5) Calling-Station-Id = '00c01732012e'
(5) NAS-Identifier = 'c8d71992a9d7'
(5) NAS-Port = 29
(5) Framed-MTU = 1400
(5) NAS-Port-Type = Wireless-802.11
(5) EAP-Message = 0x020000150175736572406578616d706c652e636f6d
(5) Message-Authenticator = 0x4c386d1361dbbd34947533bd5874d113
(5) Event-Timestamp = 'Jul 7 2015 10:48:07 MDT'
(5) Proxy-State = 0x32
(5) # Executing section authorize from file /etc/raddb/sites-enabled/default
(5) authorize {
(5) filter_username filter_username {
(5) if (!&User-Name)
(5) if (!&User-Name) -> FALSE
(5) if (&User-Name =~ / /)
(5) if (&User-Name =~ / /) -> FALSE
(5) if (&User-Name =~ /@.*@/ )
(5) if (&User-Name =~ /@.*@/ ) -> FALSE
(5) if (&User-Name =~ /\\.\\./ )
(5) if (&User-Name =~ /\\.\\./ ) -> FALSE
(5) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))
(5) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE
(5) if (&User-Name =~ /\\.$/)
(5) if (&User-Name =~ /\\.$/) -> FALSE
(5) if (&User-Name =~ /@\\./)
(5) if (&User-Name =~ /@\\./) -> FALSE
(5) } # filter_username filter_username = notfound
(5) [preprocess] = ok
(5) [chap] = noop
(5) [mschap] = noop
(5) [digest] = noop
(5) suffix : Checking for suffix after "@"
(5) suffix : No '@' in User-Name = "user", looking up realm NULL
(5) suffix : No such realm "NULL"
(5) [suffix] = noop
(5) eap : Peer sent code Response (2) ID 0 length 21
(5) eap : EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize
(5) [eap] = ok
(5) } # authorize = ok
(5) Found Auth-Type = EAP
(5) # Executing group from file /etc/raddb/sites-enabled/default
(5) authenticate {
(5) eap : Identity does not match User-Name, setting from EAP Identity
(5) eap : Failed in handler
(5) [eap] = invalid
(5) } # authenticate = invalid
(5) Failed to authenticate the user
(5) Using Post-Auth-Type Reject
(5) # Executing group from file /etc/raddb/sites-enabled/default
(5) Post-Auth-Type REJECT {
(5) sql : EXPAND .query
(5) sql : --> .query
(5) sql : Using query template 'query'
rlm_sql (sql): Reserved connection (6)
(5) sql : EXPAND %{User-Name}
(5) sql : --> user
(5) sql : SQL-User-Name set to 'user'
(5) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
(5) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '', 'Access-Reject', '2015-07-07 10:48:07')
rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '', 'Access-Reject', '2015-07-07 10:48:07')'
rlm_sql (sql): Released connection (6)
(5) [sql] = ok
(5) attr_filter.access_reject : EXPAND %{User-Name}
(5) attr_filter.access_reject : --> user
(5) attr_filter.access_reject : Matched entry DEFAULT at line 11
(5) [attr_filter.access_reject] = updated
(5) eap : Identity does not match User-Name, setting from EAP Identity
(5) eap : Failed to get handler, probably already removed, not inserting EAP-Failure
(5) [eap] = noop
(5) remove_reply_message_if_eap remove_reply_message_if_eap {
(5) if (&reply:EAP-Message && &reply:Reply-Message)
(5) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
(5) else else {
(5) [noop] = noop
(5) } # else else = noop
(5) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
(5) } # Post-Auth-Type REJECT = updated
(5) Delaying response for 1 seconds
Waking up in 0.3 seconds.
Waking up in 0.1 seconds.
(4) Expecting proxy response no later than 19.499792 seconds from now
Waking up in 0.5 seconds.
(5) Sending delayed response
(5) Sending Access-Reject packet to host 127.0.0.1 port 36256, id=230, length=0
(5) Proxy-State = 0x32
Sending Access-Reject Id 230 from 127.0.0.1:1812 to 127.0.0.1:36256
Proxy-State = 0x32
Waking up in 3.9 seconds.
Received Access-Reject Id 230 from 127.0.0.1:1812 to 127.0.0.1:36256 length 23
Proxy-State = 0x32
(4) Received Access-Reject packet from host 127.0.0.1 port 1812, id=230, length=23
(4) Proxy-State = 0x32
(4) # Executing section post-proxy from file /etc/raddb/sites-enabled/default
(4) post-proxy {
(4) eap : No pre-existing handler found
(4) [eap] = noop
(4) } # post-proxy = noop
(4) Using Post-Auth-Type Reject
(4) # Executing group from file /etc/raddb/sites-enabled/default
(4) Post-Auth-Type REJECT {
(4) sql : EXPAND .query
(4) sql : --> .query
(4) sql : Using query template 'query'
rlm_sql (sql): Reserved connection (6)
(4) sql : EXPAND %{User-Name}
(4) sql : --> user at example.com
(4) sql : SQL-User-Name set to 'user at example.com'
(4) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
(4) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user at example.com', '', 'Access-Reject', '2015-07-07 10:48:07')
rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user at example.com', '', 'Access-Reject', '2015-07-07 10:48:07')'
rlm_sql (sql): Released connection (6)
rlm_sql (sql): 0 of 3 connections in use. Need more spares
rlm_sql (sql): Opening additional connection (7)
rlm_sql_mysql: Starting connect to MySQL server
(4) [sql] = ok
(4) attr_filter.access_reject : EXPAND %{User-Name}
(4) attr_filter.access_reject : --> user at example.com
(4) attr_filter.access_reject : Matched entry DEFAULT at line 11
(4) [attr_filter.access_reject] = updated
(4) eap : Request was previously rejected, inserting EAP-Failure
(4) [eap] = updated
(4) remove_reply_message_if_eap remove_reply_message_if_eap {
(4) if (&reply:EAP-Message && &reply:Reply-Message)
(4) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
(4) else else {
(4) [noop] = noop
(4) } # else else = noop
(4) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
(4) } # Post-Auth-Type REJECT = updated
(4) Delaying response for 1 seconds
Waking up in 0.3 seconds.
Waking up in 0.6 seconds.
(4) Sending delayed response
(4) Sending Access-Reject packet to host 10.250.8.180 port 33695, id=2, length=0
(4) EAP-Message = 0x04000004
(4) Message-Authenticator = 0x00000000000000000000000000000000
Sending Access-Reject Id 2 from 10.250.16.126:1812 to 10.250.8.180:33695
EAP-Message = 0x04000004
Message-Authenticator = 0x00000000000000000000000000000000
Waking up in 2.9 seconds.
(5) Cleaning up request packet ID 230 with timestamp +142
Waking up in 0.9 seconds.
(4) Cleaning up request packet ID 2 with timestamp +142
Ready to process requests
Received Access-Request Id 2 from 10.250.8.180:33695 to 10.250.16.126:1812 length 145
User-Name = 'user at example.com'
NAS-IP-Address = 10.250.8.180
Called-Station-Id = 'c8d71992a9d7'
Calling-Station-Id = '00c01732012e'
NAS-Identifier = 'c8d71992a9d7'
NAS-Port = 29
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
EAP-Message = 0x020100150175736572406578616d706c652e636f6d
Message-Authenticator = 0x4b34d8d4d2a2b9fb214740384d697831
(6) Received Access-Request packet from host 10.250.8.180 port 33695, id=2, length=145
(6) User-Name = 'user at example.com'
(6) NAS-IP-Address = 10.250.8.180
(6) Called-Station-Id = 'c8d71992a9d7'
(6) Calling-Station-Id = '00c01732012e'
(6) NAS-Identifier = 'c8d71992a9d7'
(6) NAS-Port = 29
(6) Framed-MTU = 1400
(6) NAS-Port-Type = Wireless-802.11
(6) EAP-Message = 0x020100150175736572406578616d706c652e636f6d
(6) Message-Authenticator = 0x4b34d8d4d2a2b9fb214740384d697831
(6) # Executing section authorize from file /etc/raddb/sites-enabled/default
(6) authorize {
(6) filter_username filter_username {
(6) if (!&User-Name)
(6) if (!&User-Name) -> FALSE
(6) if (&User-Name =~ / /)
(6) if (&User-Name =~ / /) -> FALSE
(6) if (&User-Name =~ /@.*@/ )
(6) if (&User-Name =~ /@.*@/ ) -> FALSE
(6) if (&User-Name =~ /\\.\\./ )
(6) if (&User-Name =~ /\\.\\./ ) -> FALSE
(6) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))
(6) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE
(6) if (&User-Name =~ /\\.$/)
(6) if (&User-Name =~ /\\.$/) -> FALSE
(6) if (&User-Name =~ /@\\./)
(6) if (&User-Name =~ /@\\./) -> FALSE
(6) } # filter_username filter_username = notfound
(6) [preprocess] = ok
(6) [chap] = noop
(6) [mschap] = noop
(6) [digest] = noop
(6) suffix : Checking for suffix after "@"
(6) suffix : Looking up realm "example.com" for User-Name = "user at example.com"
(6) suffix : Found realm "example.com"
(6) suffix : Adding Stripped-User-Name = "user"
(6) suffix : Adding Realm = "example.com"
(6) suffix : Proxying request from user user to realm example.com
(6) suffix : Preparing to proxy authentication request to realm "example.com"
(6) [suffix] = updated
(6) eap : Request is supposed to be proxied to Realm example.com. Not doing EAP.
(6) [eap] = noop
(6) [files] = noop
(6) sql : EXPAND %{User-Name}
(6) sql : --> user at example.com
(6) sql : SQL-User-Name set to 'user at example.com'
rlm_sql (sql): Reserved connection (7)
(6) sql : EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
(6) sql : --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user at example.com' ORDER BY id
rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user at example.com' ORDER BY id'
(6) sql : EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
(6) sql : --> SELECT groupname FROM radusergroup WHERE username = 'user at example.com' ORDER BY priority
rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'user at example.com' ORDER BY priority'
(6) sql : User not found in any groups
rlm_sql (sql): Released connection (7)
rlm_sql (sql): Closing connection (6): Hit idle_timeout, was idle for 63 seconds
rlm_sql (sql): You probably need to lower "min"
rlm_sql_mysql: Socket destructor called, closing socket
rlm_sql (sql): Closing connection (5): Hit idle_timeout, was idle for 64 seconds
rlm_sql (sql): You probably need to lower "min"
rlm_sql_mysql: Socket destructor called, closing socket
rlm_sql (sql): Closing connection (4): Hit idle_timeout, was idle for 71 seconds
rlm_sql (sql): You probably need to lower "min"
rlm_sql_mysql: Socket destructor called, closing socket
(6) [sql] = notfound
(6) [expiration] = noop
(6) [logintime] = noop
(6) [pap] = noop
(6) } # authorize = updated
(6) Proxying request to home server 127.0.0.1 port 1812 timeout 20.000000
(6) Sending Access-Request packet to host 127.0.0.1 port 1812, id=123, length=0
(6) User-Name = 'user'
(6) NAS-IP-Address = 10.250.8.180
(6) Called-Station-Id = 'c8d71992a9d7'
(6) Calling-Station-Id = '00c01732012e'
(6) NAS-Identifier = 'c8d71992a9d7'
(6) NAS-Port = 29
(6) Framed-MTU = 1400
(6) NAS-Port-Type = Wireless-802.11
(6) EAP-Message = 0x020100150175736572406578616d706c652e636f6d
(6) Message-Authenticator = 0x4b34d8d4d2a2b9fb214740384d697831
(6) Event-Timestamp = 'Jul 7 2015 10:49:11 MDT'
(6) Stripped-User-Name = 'user'
(6) Realm = 'example.com'
(6) EAP-Type = Identity
(6) Proxy-State = 0x32
Sending Access-Request Id 123 from 0.0.0.0:36256 to 127.0.0.1:1812
User-Name = 'user'
NAS-IP-Address = 10.250.8.180
Called-Station-Id = 'c8d71992a9d7'
Calling-Station-Id = '00c01732012e'
NAS-Identifier = 'c8d71992a9d7'
NAS-Port = 29
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
EAP-Message = 0x020100150175736572406578616d706c652e636f6d
Message-Authenticator = 0x4b34d8d4d2a2b9fb214740384d697831
Event-Timestamp = 'Jul 7 2015 10:49:11 MDT'
Proxy-State = 0x32
Waking up in 0.3 seconds.
Received Access-Request Id 123 from 127.0.0.1:36256 to 127.0.0.1:1812 length 142
User-Name = 'user'
NAS-IP-Address = 10.250.8.180
Called-Station-Id = 'c8d71992a9d7'
Calling-Station-Id = '00c01732012e'
NAS-Identifier = 'c8d71992a9d7'
NAS-Port = 29
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
EAP-Message = 0x020100150175736572406578616d706c652e636f6d
Message-Authenticator = 0x633c8474dcfb64843fbce8453a51c816
Event-Timestamp = 'Jul 7 2015 10:49:11 MDT'
Proxy-State = 0x32
(7) Received Access-Request packet from host 127.0.0.1 port 36256, id=123, length=142
(7) User-Name = 'user'
(7) NAS-IP-Address = 10.250.8.180
(7) Called-Station-Id = 'c8d71992a9d7'
(7) Calling-Station-Id = '00c01732012e'
(7) NAS-Identifier = 'c8d71992a9d7'
(7) NAS-Port = 29
(7) Framed-MTU = 1400
(7) NAS-Port-Type = Wireless-802.11
(7) EAP-Message = 0x020100150175736572406578616d706c652e636f6d
(7) Message-Authenticator = 0x633c8474dcfb64843fbce8453a51c816
(7) Event-Timestamp = 'Jul 7 2015 10:49:11 MDT'
(7) Proxy-State = 0x32
(7) # Executing section authorize from file /etc/raddb/sites-enabled/default
(7) authorize {
(7) filter_username filter_username {
(7) if (!&User-Name)
(7) if (!&User-Name) -> FALSE
(7) if (&User-Name =~ / /)
(7) if (&User-Name =~ / /) -> FALSE
(7) if (&User-Name =~ /@.*@/ )
(7) if (&User-Name =~ /@.*@/ ) -> FALSE
(7) if (&User-Name =~ /\\.\\./ )
(7) if (&User-Name =~ /\\.\\./ ) -> FALSE
(7) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))
(7) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE
(7) if (&User-Name =~ /\\.$/)
(7) if (&User-Name =~ /\\.$/) -> FALSE
(7) if (&User-Name =~ /@\\./)
(7) if (&User-Name =~ /@\\./) -> FALSE
(7) } # filter_username filter_username = notfound
(7) [preprocess] = ok
(7) [chap] = noop
(7) [mschap] = noop
(7) [digest] = noop
(7) suffix : Checking for suffix after "@"
(7) suffix : No '@' in User-Name = "user", looking up realm NULL
(7) suffix : No such realm "NULL"
(7) [suffix] = noop
(7) eap : Peer sent code Response (2) ID 1 length 21
(7) eap : EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize
(7) [eap] = ok
(7) } # authorize = ok
(7) Found Auth-Type = EAP
(7) # Executing group from file /etc/raddb/sites-enabled/default
(7) authenticate {
(7) eap : Identity does not match User-Name, setting from EAP Identity
(7) eap : Failed in handler
(7) [eap] = invalid
(7) } # authenticate = invalid
(7) Failed to authenticate the user
(7) Using Post-Auth-Type Reject
(7) # Executing group from file /etc/raddb/sites-enabled/default
(7) Post-Auth-Type REJECT {
(7) sql : EXPAND .query
(7) sql : --> .query
(7) sql : Using query template 'query'
rlm_sql (sql): Reserved connection (7)
(7) sql : EXPAND %{User-Name}
(7) sql : --> user
(7) sql : SQL-User-Name set to 'user'
(7) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
(7) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '', 'Access-Reject', '2015-07-07 10:49:11')
rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '', 'Access-Reject', '2015-07-07 10:49:11')'
rlm_sql (sql): Released connection (7)
(7) [sql] = ok
(7) attr_filter.access_reject : EXPAND %{User-Name}
(7) attr_filter.access_reject : --> user
(7) attr_filter.access_reject : Matched entry DEFAULT at line 11
(7) [attr_filter.access_reject] = updated
(7) eap : Identity does not match User-Name, setting from EAP Identity
(7) eap : Failed to get handler, probably already removed, not inserting EAP-Failure
(7) [eap] = noop
(7) remove_reply_message_if_eap remove_reply_message_if_eap {
(7) if (&reply:EAP-Message && &reply:Reply-Message)
(7) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
(7) else else {
(7) [noop] = noop
(7) } # else else = noop
(7) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
(7) } # Post-Auth-Type REJECT = updated
(7) Delaying response for 1 seconds
Waking up in 0.3 seconds.
Waking up in 0.1 seconds.
(6) Expecting proxy response no later than 19.499801 seconds from now
Waking up in 0.5 seconds.
(7) Sending delayed response
(7) Sending Access-Reject packet to host 127.0.0.1 port 36256, id=123, length=0
(7) Proxy-State = 0x32
Sending Access-Reject Id 123 from 127.0.0.1:1812 to 127.0.0.1:36256
Proxy-State = 0x32
Waking up in 3.9 seconds.
Received Access-Reject Id 123 from 127.0.0.1:1812 to 127.0.0.1:36256 length 23
Proxy-State = 0x32
(6) Received Access-Reject packet from host 127.0.0.1 port 1812, id=123, length=23
(6) Proxy-State = 0x32
(6) # Executing section post-proxy from file /etc/raddb/sites-enabled/default
(6) post-proxy {
(6) eap : No pre-existing handler found
(6) [eap] = noop
(6) } # post-proxy = noop
(6) Using Post-Auth-Type Reject
(6) # Executing group from file /etc/raddb/sites-enabled/default
(6) Post-Auth-Type REJECT {
(6) sql : EXPAND .query
(6) sql : --> .query
(6) sql : Using query template 'query'
rlm_sql (sql): Reserved connection (7)
(6) sql : EXPAND %{User-Name}
(6) sql : --> user at example.com
(6) sql : SQL-User-Name set to 'user at example.com'
(6) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
(6) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user at example.com', '', 'Access-Reject', '2015-07-07 10:49:11')
rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user at example.com', '', 'Access-Reject', '2015-07-07 10:49:11')'
rlm_sql (sql): Released connection (7)
rlm_sql (sql): 0 of 1 connections in use. Need more spares
rlm_sql (sql): Opening additional connection (8)
rlm_sql_mysql: Starting connect to MySQL server
(6) [sql] = ok
(6) attr_filter.access_reject : EXPAND %{User-Name}
(6) attr_filter.access_reject : --> user at example.com
(6) attr_filter.access_reject : Matched entry DEFAULT at line 11
(6) [attr_filter.access_reject] = updated
(6) eap : Request was previously rejected, inserting EAP-Failure
(6) [eap] = updated
(6) remove_reply_message_if_eap remove_reply_message_if_eap {
(6) if (&reply:EAP-Message && &reply:Reply-Message)
(6) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
(6) else else {
(6) [noop] = noop
(6) } # else else = noop
(6) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
(6) } # Post-Auth-Type REJECT = updated
(6) Delaying response for 1 seconds
Waking up in 0.3 seconds.
Waking up in 0.6 seconds.
(6) Sending delayed response
(6) Sending Access-Reject packet to host 10.250.8.180 port 33695, id=2, length=0
(6) EAP-Message = 0x04010004
(6) Message-Authenticator = 0x00000000000000000000000000000000
Sending Access-Reject Id 2 from 10.250.16.126:1812 to 10.250.8.180:33695
EAP-Message = 0x04010004
Message-Authenticator = 0x00000000000000000000000000000000
Waking up in 2.9 seconds.
(7) Cleaning up request packet ID 123 with timestamp +206
Waking up in 0.9 seconds.
(6) Cleaning up request packet ID 2 with timestamp +206
Ready to process requests
Received Access-Request Id 2 from 10.250.8.180:33695 to 10.250.16.126:1812 length 145
User-Name = 'user at example.com'
NAS-IP-Address = 10.250.8.180
Called-Station-Id = 'c8d71992a9d7'
Calling-Station-Id = '00c01732012e'
NAS-Identifier = 'c8d71992a9d7'
NAS-Port = 29
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
EAP-Message = 0x020000150175736572406578616d706c652e636f6d
Message-Authenticator = 0x9b7a8a3a6a4b84660b1963a763f23653
(8) Received Access-Request packet from host 10.250.8.180 port 33695, id=2, length=145
(8) User-Name = 'user at example.com'
(8) NAS-IP-Address = 10.250.8.180
(8) Called-Station-Id = 'c8d71992a9d7'
(8) Calling-Station-Id = '00c01732012e'
(8) NAS-Identifier = 'c8d71992a9d7'
(8) NAS-Port = 29
(8) Framed-MTU = 1400
(8) NAS-Port-Type = Wireless-802.11
(8) EAP-Message = 0x020000150175736572406578616d706c652e636f6d
(8) Message-Authenticator = 0x9b7a8a3a6a4b84660b1963a763f23653
(8) # Executing section authorize from file /etc/raddb/sites-enabled/default
(8) authorize {
(8) filter_username filter_username {
(8) if (!&User-Name)
(8) if (!&User-Name) -> FALSE
(8) if (&User-Name =~ / /)
(8) if (&User-Name =~ / /) -> FALSE
(8) if (&User-Name =~ /@.*@/ )
(8) if (&User-Name =~ /@.*@/ ) -> FALSE
(8) if (&User-Name =~ /\\.\\./ )
(8) if (&User-Name =~ /\\.\\./ ) -> FALSE
(8) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))
(8) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE
(8) if (&User-Name =~ /\\.$/)
(8) if (&User-Name =~ /\\.$/) -> FALSE
(8) if (&User-Name =~ /@\\./)
(8) if (&User-Name =~ /@\\./) -> FALSE
(8) } # filter_username filter_username = notfound
(8) [preprocess] = ok
(8) [chap] = noop
(8) [mschap] = noop
(8) [digest] = noop
(8) suffix : Checking for suffix after "@"
(8) suffix : Looking up realm "example.com" for User-Name = "user at example.com"
(8) suffix : Found realm "example.com"
(8) suffix : Adding Stripped-User-Name = "user"
(8) suffix : Adding Realm = "example.com"
(8) suffix : Proxying request from user user to realm example.com
(8) suffix : Preparing to proxy authentication request to realm "example.com"
(8) [suffix] = updated
(8) eap : Request is supposed to be proxied to Realm example.com. Not doing EAP.
(8) [eap] = noop
(8) [files] = noop
(8) sql : EXPAND %{User-Name}
(8) sql : --> user at example.com
(8) sql : SQL-User-Name set to 'user at example.com'
rlm_sql (sql): Reserved connection (8)
(8) sql : EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
(8) sql : --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user at example.com' ORDER BY id
rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user at example.com' ORDER BY id'
(8) sql : EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
(8) sql : --> SELECT groupname FROM radusergroup WHERE username = 'user at example.com' ORDER BY priority
rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'user at example.com' ORDER BY priority'
(8) sql : User not found in any groups
rlm_sql (sql): Released connection (8)
rlm_sql (sql): 0 of 2 connections in use. Need more spares
rlm_sql (sql): Opening additional connection (9)
rlm_sql_mysql: Starting connect to MySQL server
(8) [sql] = notfound
(8) [expiration] = noop
(8) [logintime] = noop
(8) [pap] = noop
(8) } # authorize = updated
(8) Proxying request to home server 127.0.0.1 port 1812 timeout 20.000000
(8) Sending Access-Request packet to host 127.0.0.1 port 1812, id=41, length=0
(8) User-Name = 'user'
(8) NAS-IP-Address = 10.250.8.180
(8) Called-Station-Id = 'c8d71992a9d7'
(8) Calling-Station-Id = '00c01732012e'
(8) NAS-Identifier = 'c8d71992a9d7'
(8) NAS-Port = 29
(8) Framed-MTU = 1400
(8) NAS-Port-Type = Wireless-802.11
(8) EAP-Message = 0x020000150175736572406578616d706c652e636f6d
(8) Message-Authenticator = 0x9b7a8a3a6a4b84660b1963a763f23653
(8) Event-Timestamp = 'Jul 7 2015 10:49:19 MDT'
(8) Stripped-User-Name = 'user'
(8) Realm = 'example.com'
(8) EAP-Type = Identity
(8) Proxy-State = 0x32
Sending Access-Request Id 41 from 0.0.0.0:36256 to 127.0.0.1:1812
User-Name = 'user'
NAS-IP-Address = 10.250.8.180
Called-Station-Id = 'c8d71992a9d7'
Calling-Station-Id = '00c01732012e'
NAS-Identifier = 'c8d71992a9d7'
NAS-Port = 29
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
EAP-Message = 0x020000150175736572406578616d706c652e636f6d
Message-Authenticator = 0x9b7a8a3a6a4b84660b1963a763f23653
Event-Timestamp = 'Jul 7 2015 10:49:19 MDT'
Proxy-State = 0x32
Waking up in 0.3 seconds.
Received Access-Request Id 41 from 127.0.0.1:36256 to 127.0.0.1:1812 length 142
User-Name = 'user'
NAS-IP-Address = 10.250.8.180
Called-Station-Id = 'c8d71992a9d7'
Calling-Station-Id = '00c01732012e'
NAS-Identifier = 'c8d71992a9d7'
NAS-Port = 29
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
EAP-Message = 0x020000150175736572406578616d706c652e636f6d
Message-Authenticator = 0x518309c772102e181c99a2850fa821ba
Event-Timestamp = 'Jul 7 2015 10:49:19 MDT'
Proxy-State = 0x32
(9) Received Access-Request packet from host 127.0.0.1 port 36256, id=41, length=142
(9) User-Name = 'user'
(9) NAS-IP-Address = 10.250.8.180
(9) Called-Station-Id = 'c8d71992a9d7'
(9) Calling-Station-Id = '00c01732012e'
(9) NAS-Identifier = 'c8d71992a9d7'
(9) NAS-Port = 29
(9) Framed-MTU = 1400
(9) NAS-Port-Type = Wireless-802.11
(9) EAP-Message = 0x020000150175736572406578616d706c652e636f6d
(9) Message-Authenticator = 0x518309c772102e181c99a2850fa821ba
(9) Event-Timestamp = 'Jul 7 2015 10:49:19 MDT'
(9) Proxy-State = 0x32
(9) # Executing section authorize from file /etc/raddb/sites-enabled/default
(9) authorize {
(9) filter_username filter_username {
(9) if (!&User-Name)
(9) if (!&User-Name) -> FALSE
(9) if (&User-Name =~ / /)
(9) if (&User-Name =~ / /) -> FALSE
(9) if (&User-Name =~ /@.*@/ )
(9) if (&User-Name =~ /@.*@/ ) -> FALSE
(9) if (&User-Name =~ /\\.\\./ )
(9) if (&User-Name =~ /\\.\\./ ) -> FALSE
(9) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))
(9) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE
(9) if (&User-Name =~ /\\.$/)
(9) if (&User-Name =~ /\\.$/) -> FALSE
(9) if (&User-Name =~ /@\\./)
(9) if (&User-Name =~ /@\\./) -> FALSE
(9) } # filter_username filter_username = notfound
(9) [preprocess] = ok
(9) [chap] = noop
(9) [mschap] = noop
(9) [digest] = noop
(9) suffix : Checking for suffix after "@"
(9) suffix : No '@' in User-Name = "user", looking up realm NULL
(9) suffix : No such realm "NULL"
(9) [suffix] = noop
(9) eap : Peer sent code Response (2) ID 0 length 21
(9) eap : EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize
(9) [eap] = ok
(9) } # authorize = ok
(9) Found Auth-Type = EAP
(9) # Executing group from file /etc/raddb/sites-enabled/default
(9) authenticate {
(9) eap : Identity does not match User-Name, setting from EAP Identity
(9) eap : Failed in handler
(9) [eap] = invalid
(9) } # authenticate = invalid
(9) Failed to authenticate the user
(9) Using Post-Auth-Type Reject
(9) # Executing group from file /etc/raddb/sites-enabled/default
(9) Post-Auth-Type REJECT {
(9) sql : EXPAND .query
(9) sql : --> .query
(9) sql : Using query template 'query'
rlm_sql (sql): Reserved connection (9)
(9) sql : EXPAND %{User-Name}
(9) sql : --> user
(9) sql : SQL-User-Name set to 'user'
(9) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
(9) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '', 'Access-Reject', '2015-07-07 10:49:19')
rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '', 'Access-Reject', '2015-07-07 10:49:19')'
rlm_sql (sql): Released connection (9)
(9) [sql] = ok
(9) attr_filter.access_reject : EXPAND %{User-Name}
(9) attr_filter.access_reject : --> user
(9) attr_filter.access_reject : Matched entry DEFAULT at line 11
(9) [attr_filter.access_reject] = updated
(9) eap : Identity does not match User-Name, setting from EAP Identity
(9) eap : Failed to get handler, probably already removed, not inserting EAP-Failure
(9) [eap] = noop
(9) remove_reply_message_if_eap remove_reply_message_if_eap {
(9) if (&reply:EAP-Message && &reply:Reply-Message)
(9) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
(9) else else {
(9) [noop] = noop
(9) } # else else = noop
(9) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
(9) } # Post-Auth-Type REJECT = updated
(9) Delaying response for 1 seconds
Waking up in 0.3 seconds.
Waking up in 0.1 seconds.
(8) Expecting proxy response no later than 19.499781 seconds from now
Waking up in 0.5 seconds.
(9) Sending delayed response
(9) Sending Access-Reject packet to host 127.0.0.1 port 36256, id=41, length=0
(9) Proxy-State = 0x32
Sending Access-Reject Id 41 from 127.0.0.1:1812 to 127.0.0.1:36256
Proxy-State = 0x32
Waking up in 3.9 seconds.
Received Access-Reject Id 41 from 127.0.0.1:1812 to 127.0.0.1:36256 length 23
Proxy-State = 0x32
(8) Received Access-Reject packet from host 127.0.0.1 port 1812, id=41, length=23
(8) Proxy-State = 0x32
(8) # Executing section post-proxy from file /etc/raddb/sites-enabled/default
(8) post-proxy {
(8) eap : No pre-existing handler found
(8) [eap] = noop
(8) } # post-proxy = noop
(8) Using Post-Auth-Type Reject
(8) # Executing group from file /etc/raddb/sites-enabled/default
(8) Post-Auth-Type REJECT {
(8) sql : EXPAND .query
(8) sql : --> .query
(8) sql : Using query template 'query'
rlm_sql (sql): Reserved connection (9)
(8) sql : EXPAND %{User-Name}
(8) sql : --> user at example.com
(8) sql : SQL-User-Name set to 'user at example.com'
(8) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
(8) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user at example.com', '', 'Access-Reject', '2015-07-07 10:49:19')
rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user at example.com', '', 'Access-Reject', '2015-07-07 10:49:19')'
rlm_sql (sql): Released connection (9)
rlm_sql (sql): 0 of 3 connections in use. Need more spares
rlm_sql (sql): Opening additional connection (10)
rlm_sql_mysql: Starting connect to MySQL server
(8) [sql] = ok
(8) attr_filter.access_reject : EXPAND %{User-Name}
(8) attr_filter.access_reject : --> user at example.com
(8) attr_filter.access_reject : Matched entry DEFAULT at line 11
(8) [attr_filter.access_reject] = updated
(8) eap : Request was previously rejected, inserting EAP-Failure
(8) [eap] = updated
(8) remove_reply_message_if_eap remove_reply_message_if_eap {
(8) if (&reply:EAP-Message && &reply:Reply-Message)
(8) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
(8) else else {
(8) [noop] = noop
(8) } # else else = noop
(8) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
(8) } # Post-Auth-Type REJECT = updated
(8) Delaying response for 1 seconds
Waking up in 0.3 seconds.
Waking up in 0.6 seconds.
(8) Sending delayed response
(8) Sending Access-Reject packet to host 10.250.8.180 port 33695, id=2, length=0
(8) EAP-Message = 0x04000004
(8) Message-Authenticator = 0x00000000000000000000000000000000
Sending Access-Reject Id 2 from 10.250.16.126:1812 to 10.250.8.180:33695
EAP-Message = 0x04000004
Message-Authenticator = 0x00000000000000000000000000000000
Waking up in 2.9 seconds.
(9) Cleaning up request packet ID 41 with timestamp +214
Waking up in 0.9 seconds.
(8) Cleaning up request packet ID 2 with timestamp +214
Ready to process requests
Received Access-Request Id 2 from 10.250.8.180:33695 to 10.250.16.126:1812 length 145
User-Name = 'user at example.com'
NAS-IP-Address = 10.250.8.180
Called-Station-Id = 'c8d71992a9d7'
Calling-Station-Id = '00c01732012e'
NAS-Identifier = 'c8d71992a9d7'
NAS-Port = 29
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
EAP-Message = 0x020100150175736572406578616d706c652e636f6d
Message-Authenticator = 0x8638dc158cbc4d42ff9e8f180ff022d0
(10) Received Access-Request packet from host 10.250.8.180 port 33695, id=2, length=145
(10) User-Name = 'user at example.com'
(10) NAS-IP-Address = 10.250.8.180
(10) Called-Station-Id = 'c8d71992a9d7'
(10) Calling-Station-Id = '00c01732012e'
(10) NAS-Identifier = 'c8d71992a9d7'
(10) NAS-Port = 29
(10) Framed-MTU = 1400
(10) NAS-Port-Type = Wireless-802.11
(10) EAP-Message = 0x020100150175736572406578616d706c652e636f6d
(10) Message-Authenticator = 0x8638dc158cbc4d42ff9e8f180ff022d0
(10) # Executing section authorize from file /etc/raddb/sites-enabled/default
(10) authorize {
(10) filter_username filter_username {
(10) if (!&User-Name)
(10) if (!&User-Name) -> FALSE
(10) if (&User-Name =~ / /)
(10) if (&User-Name =~ / /) -> FALSE
(10) if (&User-Name =~ /@.*@/ )
(10) if (&User-Name =~ /@.*@/ ) -> FALSE
(10) if (&User-Name =~ /\\.\\./ )
(10) if (&User-Name =~ /\\.\\./ ) -> FALSE
(10) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))
(10) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE
(10) if (&User-Name =~ /\\.$/)
(10) if (&User-Name =~ /\\.$/) -> FALSE
(10) if (&User-Name =~ /@\\./)
(10) if (&User-Name =~ /@\\./) -> FALSE
(10) } # filter_username filter_username = notfound
(10) [preprocess] = ok
(10) [chap] = noop
(10) [mschap] = noop
(10) [digest] = noop
(10) suffix : Checking for suffix after "@"
(10) suffix : Looking up realm "example.com" for User-Name = "user at example.com"
(10) suffix : Found realm "example.com"
(10) suffix : Adding Stripped-User-Name = "user"
(10) suffix : Adding Realm = "example.com"
(10) suffix : Proxying request from user user to realm example.com
(10) suffix : Preparing to proxy authentication request to realm "example.com"
(10) [suffix] = updated
(10) eap : Request is supposed to be proxied to Realm example.com. Not doing EAP.
(10) [eap] = noop
(10) [files] = noop
(10) sql : EXPAND %{User-Name}
(10) sql : --> user at example.com
(10) sql : SQL-User-Name set to 'user at example.com'
rlm_sql (sql): Reserved connection (10)
(10) sql : EXPAND SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id
(10) sql : --> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user at example.com' ORDER BY id
rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user at example.com' ORDER BY id'
(10) sql : EXPAND SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority
(10) sql : --> SELECT groupname FROM radusergroup WHERE username = 'user at example.com' ORDER BY priority
rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'user at example.com' ORDER BY priority'
(10) sql : User not found in any groups
rlm_sql (sql): Released connection (10)
rlm_sql (sql): Closing connection (9): Hit idle_timeout, was idle for 62 seconds
rlm_sql (sql): You probably need to lower "min"
rlm_sql_mysql: Socket destructor called, closing socket
rlm_sql (sql): Closing connection (8): Hit idle_timeout, was idle for 63 seconds
rlm_sql (sql): You probably need to lower "min"
rlm_sql_mysql: Socket destructor called, closing socket
rlm_sql (sql): Closing connection (7): Hit idle_timeout, was idle for 70 seconds
rlm_sql (sql): You probably need to lower "min"
rlm_sql_mysql: Socket destructor called, closing socket
(10) [sql] = notfound
(10) [expiration] = noop
(10) [logintime] = noop
(10) [pap] = noop
(10) } # authorize = updated
(10) Proxying request to home server 127.0.0.1 port 1812 timeout 20.000000
(10) Sending Access-Request packet to host 127.0.0.1 port 1812, id=200, length=0
(10) User-Name = 'user'
(10) NAS-IP-Address = 10.250.8.180
(10) Called-Station-Id = 'c8d71992a9d7'
(10) Calling-Station-Id = '00c01732012e'
(10) NAS-Identifier = 'c8d71992a9d7'
(10) NAS-Port = 29
(10) Framed-MTU = 1400
(10) NAS-Port-Type = Wireless-802.11
(10) EAP-Message = 0x020100150175736572406578616d706c652e636f6d
(10) Message-Authenticator = 0x8638dc158cbc4d42ff9e8f180ff022d0
(10) Event-Timestamp = 'Jul 7 2015 10:50:22 MDT'
(10) Stripped-User-Name = 'user'
(10) Realm = 'example.com'
(10) EAP-Type = Identity
(10) Proxy-State = 0x32
Sending Access-Request Id 200 from 0.0.0.0:36256 to 127.0.0.1:1812
User-Name = 'user'
NAS-IP-Address = 10.250.8.180
Called-Station-Id = 'c8d71992a9d7'
Calling-Station-Id = '00c01732012e'
NAS-Identifier = 'c8d71992a9d7'
NAS-Port = 29
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
EAP-Message = 0x020100150175736572406578616d706c652e636f6d
Message-Authenticator = 0x8638dc158cbc4d42ff9e8f180ff022d0
Event-Timestamp = 'Jul 7 2015 10:50:22 MDT'
Proxy-State = 0x32
Waking up in 0.3 seconds.
Received Access-Request Id 200 from 127.0.0.1:36256 to 127.0.0.1:1812 length 142
User-Name = 'user'
NAS-IP-Address = 10.250.8.180
Called-Station-Id = 'c8d71992a9d7'
Calling-Station-Id = '00c01732012e'
NAS-Identifier = 'c8d71992a9d7'
NAS-Port = 29
Framed-MTU = 1400
NAS-Port-Type = Wireless-802.11
EAP-Message = 0x020100150175736572406578616d706c652e636f6d
Message-Authenticator = 0x1cc629a26c42673ec8925d9b46a9cdad
Event-Timestamp = 'Jul 7 2015 10:50:22 MDT'
Proxy-State = 0x32
(11) Received Access-Request packet from host 127.0.0.1 port 36256, id=200, length=142
(11) User-Name = 'user'
(11) NAS-IP-Address = 10.250.8.180
(11) Called-Station-Id = 'c8d71992a9d7'
(11) Calling-Station-Id = '00c01732012e'
(11) NAS-Identifier = 'c8d71992a9d7'
(11) NAS-Port = 29
(11) Framed-MTU = 1400
(11) NAS-Port-Type = Wireless-802.11
(11) EAP-Message = 0x020100150175736572406578616d706c652e636f6d
(11) Message-Authenticator = 0x1cc629a26c42673ec8925d9b46a9cdad
(11) Event-Timestamp = 'Jul 7 2015 10:50:22 MDT'
(11) Proxy-State = 0x32
(11) # Executing section authorize from file /etc/raddb/sites-enabled/default
(11) authorize {
(11) filter_username filter_username {
(11) if (!&User-Name)
(11) if (!&User-Name) -> FALSE
(11) if (&User-Name =~ / /)
(11) if (&User-Name =~ / /) -> FALSE
(11) if (&User-Name =~ /@.*@/ )
(11) if (&User-Name =~ /@.*@/ ) -> FALSE
(11) if (&User-Name =~ /\\.\\./ )
(11) if (&User-Name =~ /\\.\\./ ) -> FALSE
(11) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/))
(11) if ((&User-Name =~ /@/) && (&User-Name !~ /@(.+)\\.(.+)$/)) -> FALSE
(11) if (&User-Name =~ /\\.$/)
(11) if (&User-Name =~ /\\.$/) -> FALSE
(11) if (&User-Name =~ /@\\./)
(11) if (&User-Name =~ /@\\./) -> FALSE
(11) } # filter_username filter_username = notfound
(11) [preprocess] = ok
(11) [chap] = noop
(11) [mschap] = noop
(11) [digest] = noop
(11) suffix : Checking for suffix after "@"
(11) suffix : No '@' in User-Name = "user", looking up realm NULL
(11) suffix : No such realm "NULL"
(11) [suffix] = noop
(11) eap : Peer sent code Response (2) ID 1 length 21
(11) eap : EAP-Identity reply, returning 'ok' so we can short-circuit the rest of authorize
(11) [eap] = ok
(11) } # authorize = ok
(11) Found Auth-Type = EAP
(11) # Executing group from file /etc/raddb/sites-enabled/default
(11) authenticate {
(11) eap : Identity does not match User-Name, setting from EAP Identity
(11) eap : Failed in handler
(11) [eap] = invalid
(11) } # authenticate = invalid
(11) Failed to authenticate the user
(11) Using Post-Auth-Type Reject
(11) # Executing group from file /etc/raddb/sites-enabled/default
(11) Post-Auth-Type REJECT {
(11) sql : EXPAND .query
(11) sql : --> .query
(11) sql : Using query template 'query'
rlm_sql (sql): Reserved connection (10)
(11) sql : EXPAND %{User-Name}
(11) sql : --> user
(11) sql : SQL-User-Name set to 'user'
(11) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
(11) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '', 'Access-Reject', '2015-07-07 10:50:22')
rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user', '', 'Access-Reject', '2015-07-07 10:50:22')'
rlm_sql (sql): Released connection (10)
(11) [sql] = ok
(11) attr_filter.access_reject : EXPAND %{User-Name}
(11) attr_filter.access_reject : --> user
(11) attr_filter.access_reject : Matched entry DEFAULT at line 11
(11) [attr_filter.access_reject] = updated
(11) eap : Identity does not match User-Name, setting from EAP Identity
(11) eap : Failed to get handler, probably already removed, not inserting EAP-Failure
(11) [eap] = noop
(11) remove_reply_message_if_eap remove_reply_message_if_eap {
(11) if (&reply:EAP-Message && &reply:Reply-Message)
(11) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
(11) else else {
(11) [noop] = noop
(11) } # else else = noop
(11) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
(11) } # Post-Auth-Type REJECT = updated
(11) Delaying response for 1 seconds
Waking up in 0.3 seconds.
Waking up in 0.1 seconds.
(10) Expecting proxy response no later than 19.499789 seconds from now
Waking up in 0.5 seconds.
(11) Sending delayed response
(11) Sending Access-Reject packet to host 127.0.0.1 port 36256, id=200, length=0
(11) Proxy-State = 0x32
Sending Access-Reject Id 200 from 127.0.0.1:1812 to 127.0.0.1:36256
Proxy-State = 0x32
Waking up in 3.9 seconds.
Received Access-Reject Id 200 from 127.0.0.1:1812 to 127.0.0.1:36256 length 23
Proxy-State = 0x32
(10) Received Access-Reject packet from host 127.0.0.1 port 1812, id=200, length=23
(10) Proxy-State = 0x32
(10) # Executing section post-proxy from file /etc/raddb/sites-enabled/default
(10) post-proxy {
(10) eap : No pre-existing handler found
(10) [eap] = noop
(10) } # post-proxy = noop
(10) Using Post-Auth-Type Reject
(10) # Executing group from file /etc/raddb/sites-enabled/default
(10) Post-Auth-Type REJECT {
(10) sql : EXPAND .query
(10) sql : --> .query
(10) sql : Using query template 'query'
rlm_sql (sql): Reserved connection (10)
(10) sql : EXPAND %{User-Name}
(10) sql : --> user at example.com
(10) sql : SQL-User-Name set to 'user at example.com'
(10) sql : EXPAND INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{SQL-User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S')
(10) sql : --> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user at example.com', '', 'Access-Reject', '2015-07-07 10:50:22')
rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user at example.com', '', 'Access-Reject', '2015-07-07 10:50:22')'
rlm_sql (sql): Released connection (10)
rlm_sql (sql): 0 of 1 connections in use. Need more spares
rlm_sql (sql): Opening additional connection (11)
rlm_sql_mysql: Starting connect to MySQL server
(10) [sql] = ok
(10) attr_filter.access_reject : EXPAND %{User-Name}
(10) attr_filter.access_reject : --> user at example.com
(10) attr_filter.access_reject : Matched entry DEFAULT at line 11
(10) [attr_filter.access_reject] = updated
(10) eap : Request was previously rejected, inserting EAP-Failure
(10) [eap] = updated
(10) remove_reply_message_if_eap remove_reply_message_if_eap {
(10) if (&reply:EAP-Message && &reply:Reply-Message)
(10) if (&reply:EAP-Message && &reply:Reply-Message) -> FALSE
(10) else else {
(10) [noop] = noop
(10) } # else else = noop
(10) } # remove_reply_message_if_eap remove_reply_message_if_eap = noop
(10) } # Post-Auth-Type REJECT = updated
(10) Delaying response for 1 seconds
Waking up in 0.3 seconds.
Waking up in 0.6 seconds.
(10) Sending delayed response
(10) Sending Access-Reject packet to host 10.250.8.180 port 33695, id=2, length=0
(10) EAP-Message = 0x04010004
(10) Message-Authenticator = 0x00000000000000000000000000000000
Sending Access-Reject Id 2 from 10.250.16.126:1812 to 10.250.8.180:33695
EAP-Message = 0x04010004
Message-Authenticator = 0x00000000000000000000000000000000
Waking up in 2.9 seconds.
(11) Cleaning up request packet ID 200 with timestamp +277
Waking up in 0.9 seconds.
(10) Cleaning up request packet ID 2 with timestamp +277
Ready to process requests
More information about the Freeradius-Users
mailing list