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@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@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@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@example.com (0) sql : SQL-User-Name set to 'user@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@example.com' ORDER BY id rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user@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@example.com' ORDER BY priority rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'user@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@example.com (0) sql : SQL-User-Name set to 'user@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@example.com', '', 'Access-Reject', '2015-07-07 10:46:25') rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user@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@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@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@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@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@example.com (0) sql : SQL-User-Name set to 'user@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@example.com' ORDER BY id rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user@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@example.com' ORDER BY priority rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'user@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@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@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@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@example.com (2) sql : SQL-User-Name set to 'user@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@example.com' ORDER BY id rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user@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@example.com' ORDER BY priority rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'user@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@example.com (2) sql : SQL-User-Name set to 'user@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@example.com', '', 'Access-Reject', '2015-07-07 10:47:59') rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user@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@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@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@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@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@example.com (4) sql : SQL-User-Name set to 'user@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@example.com' ORDER BY id rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user@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@example.com' ORDER BY priority rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'user@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@example.com (4) sql : SQL-User-Name set to 'user@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@example.com', '', 'Access-Reject', '2015-07-07 10:48:07') rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user@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@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@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@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@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@example.com (6) sql : SQL-User-Name set to 'user@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@example.com' ORDER BY id rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user@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@example.com' ORDER BY priority rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'user@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@example.com (6) sql : SQL-User-Name set to 'user@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@example.com', '', 'Access-Reject', '2015-07-07 10:49:11') rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user@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@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@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@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@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@example.com (8) sql : SQL-User-Name set to 'user@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@example.com' ORDER BY id rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user@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@example.com' ORDER BY priority rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'user@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@example.com (8) sql : SQL-User-Name set to 'user@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@example.com', '', 'Access-Reject', '2015-07-07 10:49:19') rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user@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@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@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@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@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@example.com (10) sql : SQL-User-Name set to 'user@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@example.com' ORDER BY id rlm_sql (sql): Executing query: 'SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'user@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@example.com' ORDER BY priority rlm_sql (sql): Executing query: 'SELECT groupname FROM radusergroup WHERE username = 'user@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@example.com (10) sql : SQL-User-Name set to 'user@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@example.com', '', 'Access-Reject', '2015-07-07 10:50:22') rlm_sql (sql): Executing query: 'INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'user@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@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