rad_recv: Access-Request packet from host 10.77.95.10 port 35964, id=28, length=252 Service-Type = Framed-User Framed-MTU = 1400 User-Name = "robert@za.testrealm.net" NAS-Port-Id = "wlan1" NAS-Port-Type = Wireless-802.11 Acct-Session-Id = "82400097" Acct-Multi-Session-Id = "D4-CA-6D-E1-1A-49-38-AA-3C-5E-7E-40-82-40-00-00-00-00-00-96" Calling-Station-Id = "38-AA-3C-5E-7E-40" Called-Station-Id = "D4-CA-6D-E1-1A-49:RadiusTest" EAP-Message = 0x0200001b01726f62657274407a612e7577696e6977696e2e6e6574 Message-Authenticator = 0x44c926aeef619bcbf4405eb865f2db61 NAS-Identifier = "MikroTik" NAS-IP-Address = 10.53.0.7 # Executing section authorize from file /etc/raddb/sites-enabled/default +- entering group authorize {...} ++[preprocess] returns ok [auth_log] expand: /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> /var/log/radius/radacct/10.77.95.10/auth-detail-20140212 [auth_log] /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/10.77.95.10/auth-detail-20140212 [auth_log] expand: %t -> Wed Feb 12 16:12:59 2014 ++[auth_log] returns ok ++[mschap] returns noop [suffix] Looking up realm "za.testrealm.net" for User-Name = " robert@za.testrealm.net" [suffix] Found realm "za.testrealm.net" [suffix] Adding Realm = "za.testrealm.net" [suffix] Proxying request from user robert to realm za.testrealm.net [suffix] Preparing to proxy authentication request to realm " za.testrealm.net" ++[suffix] returns updated ++? if ("%{Realm}" == "za.testrealm.net") expand: %{Realm} -> za.testrealm.net ? Evaluating ("%{Realm}" == "za.testrealm.net") -> TRUE ++? if ("%{Realm}" == "za.testrealm.net") -> TRUE ++- entering if ("%{Realm}" == "za.testrealm.net") {...} +++[control] returns updated ++- if ("%{Realm}" == "za.testrealm.net") returns updated [eap] Request is supposed to be proxied to Realm za..net. Not doing EAP. ++[eap] returns noop [sql] expand: %{User-Name} -> robert@za.testrealm.net [sql] sql_set_user escaped user --> 'robert@za.testrealm.net' rlm_sql (sql): Reserving sql socket id: 3 [sql] expand: SELECT radcheck.id, radcheck.UserName, radcheck.Attribute, radcheck.Value, radcheck.Op FROM radcheck inner join users on radcheck.username = users.strusername WHERE Username = '%{SQL-User-Name}' AND (users.imballowed + users.imbadded) > users.imbused AND users.dtExpire > now() ORDER BY radcheck.id -> SELECT radcheck.id, radcheck.UserName, radcheck.Attribute, radcheck.Value, radcheck.Op FROM radcheck inner join users on radcheck.username = users.strusername WHERE Username = 'robert@za.testrealm.net' AND (users.imballowed + users.imbadded) > users.imbused AND users.dtExpire > now() ORDER BY radcheck.id rlm_sql_postgresql: query: SELECT radcheck.id, radcheck.UserName, radcheck.Attribute, radcheck.Value, radcheck.Op FROM radcheck inner join users on radcheck.username = users.strusername WHERE Username = ' robert@za.testrealm.net' AND (users.imballowed + users.imbadded) > users.imbused AND users.dtExpire > now() ORDER BY radcheck.id rlm_sql_postgresql: Status: PGRES_TUPLES_OK rlm_sql_postgresql: query affected rows = 0 , fields = 5 [sql] expand: SELECT GroupName FROM radhuntgroup WHERE nasipaddress='%{NAS-IP-Address}' -> SELECT GroupName FROM radhuntgroup WHERE nasipaddress='10.53.0.7' rlm_sql_postgresql: query: SELECT GroupName FROM radhuntgroup WHERE nasipaddress='10.53.0.7' rlm_sql_postgresql: Status: PGRES_TUPLES_OK rlm_sql_postgresql: query affected rows = 1 , fields = 1 [sql] expand: SELECT id, GroupName, Attribute, Value, op FROM radgroupcheck WHERE GroupName = '%{Sql-Group}' ORDER BY id -> SELECT id, GroupName, Attribute, Value, op FROM radgroupcheck WHERE GroupName = 'South Africa' ORDER BY id rlm_sql_postgresql: query: SELECT id, GroupName, Attribute, Value, op FROM radgroupcheck WHERE GroupName = 'South Africa' ORDER BY id rlm_sql_postgresql: Status: PGRES_TUPLES_OK rlm_sql_postgresql: query affected rows = 1 , fields = 5 [sql] User found in group South Africa [sql] expand: SELECT id, GroupName, Attribute, Value, op FROM radgroupreply WHERE GroupName = '%{Sql-Group}' ORDER BY id -> SELECT id, GroupName, Attribute, Value, op FROM radgroupreply WHERE GroupName = 'South Africa' ORDER BY id rlm_sql_postgresql: query: SELECT id, GroupName, Attribute, Value, op FROM radgroupreply WHERE GroupName = 'South Africa' ORDER BY id rlm_sql_postgresql: Status: PGRES_TUPLES_OK rlm_sql_postgresql: query affected rows = 0 , fields = 5 rlm_sql (sql): Released sql socket id: 3 ++[sql] returns ok ++[expiration] returns noop ++[logintime] returns noop # Executing section pre-proxy from file /etc/raddb/sites-enabled/default +- entering group pre-proxy {...} [attr_filter.pre-proxy] expand: %{Realm} -> za.testrealm.net attr_filter: Matched entry DEFAULT at line 49 ++[attr_filter.pre-proxy] returns updated Sending Access-Request of id 32 to 10.77.82.21 port 1812 User-Name = "robert@za.testrealm.net" EAP-Message = 0x0200001b01726f62657274407a612e7577696e6977696e2e6e6574 Message-Authenticator = 0x00000000000000000000000000000000 NAS-Identifier = "MikroTik" NAS-IP-Address = 10.53.0.7 Proxy-State = 0x3238 Proxying request 0 to home server 10.77.82.21 port 1812 Sending Access-Request of id 32 to 10.77.82.21 port 1812 User-Name = "robert@za.testrealm.net" EAP-Message = 0x0200001b01726f62657274407a612e7577696e6977696e2e6e6574 Message-Authenticator = 0x00000000000000000000000000000000 NAS-Identifier = "MikroTik" NAS-IP-Address = 10.53.0.7 Proxy-State = 0x3238 Going to the next request Waking up in 0.9 seconds. rad_recv: Access-Reject packet from host 10.77.82.21 port 1812, id=32, length=48 Proxy-State = 0x3238 EAP-Message = 0x04000004 Message-Authenticator = 0x1998a50868057d003c4b22bd6fc4dfa6 # Executing section post-proxy from file /etc/raddb/sites-enabled/default +- entering group post-proxy {...} [eap] No pre-existing handler found ++[eap] returns noop Login incorrect (Home Server says so): [robert@za.testrealm.net/<no User-Password attribute>] (from client howifi port 0 cli 38-AA-3C-5E-7E-40) Using Post-Auth-Type Reject # Executing group from file /etc/raddb/sites-enabled/default +- entering group REJECT {...} [attr_filter.access_reject] expand: %{User-Name} -> robert@za.testrealm.net attr_filter: Matched entry DEFAULT at line 11 ++[attr_filter.access_reject] returns updated Delaying reject of request 0 for 1 seconds Going to the next request Waking up in 0.9 seconds. rad_recv: Access-Request packet from host 10.77.95.10 port 35964, id=28, length=252 Waiting to send Access-Reject to client howifi port 35964 - ID: 28 Waking up in 0.7 seconds. rad_recv: Access-Request packet from host 10.77.95.10 port 35964, id=28, length=252 Waiting to send Access-Reject to client howifi port 35964 - ID: 28 Waking up in 0.4 seconds. rad_recv: Access-Request packet from host 10.77.95.10 port 35638, id=29, length=252 Service-Type = Framed-User Framed-MTU = 1400 User-Name = "robert@za.testrealm.net" NAS-Port-Id = "wlan1" NAS-Port-Type = Wireless-802.11 Acct-Session-Id = "82400097" Acct-Multi-Session-Id = "D4-CA-6D-E1-1A-49-38-AA-3C-5E-7E-40-82-40-00-00-00-00-00-96" Calling-Station-Id = "38-AA-3C-5E-7E-40" Called-Station-Id = "D4-CA-6D-E1-1A-49:RadiusTest" EAP-Message = 0x0201001b01726f62657274407a612e7577696e6977696e2e6e6574 Message-Authenticator = 0xd56ecf33a92105224bd3fdd34260820b NAS-Identifier = "MikroTik" NAS-IP-Address = 10.53.0.7 # Executing section authorize from file /etc/raddb/sites-enabled/default +- entering group authorize {...} ++[preprocess] returns ok [auth_log] expand: /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d -> /var/log/radius/radacct/10.77.95.10/auth-detail-20140212 [auth_log] /var/log/radius/radacct/%{Client-IP-Address}/auth-detail-%Y%m%d expands to /var/log/radius/radacct/10.77.95.10/auth-detail-20140212 [auth_log] expand: %t -> Wed Feb 12 16:13:00 2014 ++[auth_log] returns ok ++[mschap] returns noop [suffix] Looking up realm "za.testrealm.net" for User-Name = " robert@za.testrealm.net" [suffix] Found realm "za.testrealm.net" [suffix] Adding Realm = "za.testrealm.net" [suffix] Proxying request from user robert to realm za.testrealm.net [suffix] Preparing to proxy authentication request to realm " za.testrealm.net" ++[suffix] returns updated ++? if ("%{Realm}" == "za.testrealm.net") expand: %{Realm} -> za.testrealm.net ? Evaluating ("%{Realm}" == "za.testrealm.net") -> TRUE ++? if ("%{Realm}" == "za.testrealm.net") -> TRUE ++- entering if ("%{Realm}" == "za.testrealm.net") {...} +++[control] returns updated ++- if ("%{Realm}" == "za.testrealm.net") returns updated [eap] Request is supposed to be proxied to Realm za.testrealm.net. Not doing EAP. ++[eap] returns noop [sql] expand: %{User-Name} -> robert@za.testrealm.net [sql] sql_set_user escaped user --> 'robert@za.testrealm.net' rlm_sql (sql): Reserving sql socket id: 2 [sql] expand: SELECT radcheck.id, radcheck.UserName, radcheck.Attribute, radcheck.Value, radcheck.Op FROM radcheck inner join users on radcheck.username = users.strusername WHERE Username = '%{SQL-User-Name}' AND (users.imballowed + users.imbadded) > users.imbused AND users.dtExpire > now() ORDER BY radcheck.id -> SELECT radcheck.id, radcheck.UserName, radcheck.Attribute, radcheck.Value, radcheck.Op FROM radcheck inner join users on radcheck.username = users.strusername WHERE Username = 'robert@za.testrealm.net' AND (users.imballowed + users.imbadded) > users.imbused AND users.dtExpire > now() ORDER BY radcheck.id rlm_sql_postgresql: query: SELECT radcheck.id, radcheck.UserName, radcheck.Attribute, radcheck.Value, radcheck.Op FROM radcheck inner join users on radcheck.username = users.strusername WHERE Username = ' robert@za.testrealm.net' AND (users.imballowed + users.imbadded) > users.imbused AND users.dtExpire > now() ORDER BY radcheck.id rlm_sql_postgresql: Status: PGRES_TUPLES_OK rlm_sql_postgresql: query affected rows = 0 , fields = 5 [sql] expand: SELECT GroupName FROM radhuntgroup WHERE nasipaddress='%{NAS-IP-Address}' -> SELECT GroupName FROM radhuntgroup WHERE nasipaddress='10.53.0.7' rlm_sql_postgresql: query: SELECT GroupName FROM radhuntgroup WHERE nasipaddress='10.53.0.7' rlm_sql_postgresql: Status: PGRES_TUPLES_OK rlm_sql_postgresql: query affected rows = 1 , fields = 1 [sql] expand: SELECT id, GroupName, Attribute, Value, op FROM radgroupcheck WHERE GroupName = '%{Sql-Group}' ORDER BY id -> SELECT id, GroupName, Attribute, Value, op FROM radgroupcheck WHERE GroupName = 'South Africa' ORDER BY id rlm_sql_postgresql: query: SELECT id, GroupName, Attribute, Value, op FROM radgroupcheck WHERE GroupName = 'South Africa' ORDER BY id rlm_sql_postgresql: Status: PGRES_TUPLES_OK rlm_sql_postgresql: query affected rows = 1 , fields = 5 [sql] User found in group South Africa [sql] expand: SELECT id, GroupName, Attribute, Value, op FROM radgroupreply WHERE GroupName = '%{Sql-Group}' ORDER BY id -> SELECT id, GroupName, Attribute, Value, op FROM radgroupreply WHERE GroupName = 'South Africa' ORDER BY id rlm_sql_postgresql: query: SELECT id, GroupName, Attribute, Value, op FROM radgroupreply WHERE GroupName = 'South Africa' ORDER BY id rlm_sql_postgresql: Status: PGRES_TUPLES_OK rlm_sql_postgresql: query affected rows = 0 , fields = 5 rlm_sql (sql): Released sql socket id: 2 ++[sql] returns ok ++[expiration] returns noop ++[logintime] returns noop # Executing section pre-proxy from file /etc/raddb/sites-enabled/default +- entering group pre-proxy {...} [attr_filter.pre-proxy] expand: %{Realm} -> za.testrealm.net attr_filter: Matched entry DEFAULT at line 49 ++[attr_filter.pre-proxy] returns updated Sending Access-Request of id 102 to 10.77.82.21 port 1812 User-Name = "robert@za.testrealm.net" EAP-Message = 0x0201001b01726f62657274407a612e7577696e6977696e2e6e6574 Message-Authenticator = 0x00000000000000000000000000000000 NAS-Identifier = "MikroTik" NAS-IP-Address = 10.53.0.7 Proxy-State = 0x3239 Proxying request 1 to home server 10.77.82.21 port 1812 Sending Access-Request of id 102 to 10.77.82.21 port 1812 User-Name = "robert@za.testrealm.net" EAP-Message = 0x0201001b01726f62657274407a612e7577696e6977696e2e6e6574 Message-Authenticator = 0x00000000000000000000000000000000 NAS-Identifier = "MikroTik" NAS-IP-Address = 10.53.0.7 Proxy-State = 0x3239 Going to the next request rad_recv: Access-Reject packet from host 10.77.82.21 port 1812, id=102, length=48 Proxy-State = 0x3239 EAP-Message = 0x04010004 Message-Authenticator = 0x7efe32cfecd297b0390c734552907db7 # Executing section post-proxy from file /etc/raddb/sites-enabled/default +- entering group post-proxy {...} [eap] No pre-existing handler found ++[eap] returns noop Login incorrect (Home Server says so): [robert@za.testrealm.net/<no User-Password attribute>] (from client howifi port 0 cli 38-AA-3C-5E-7E-40) Using Post-Auth-Type Reject # Executing group from file /etc/raddb/sites-enabled/default +- entering group REJECT {...} [attr_filter.access_reject] expand: %{User-Name} -> robert@za.testrealm.net attr_filter: Matched entry DEFAULT at line 11 ++[attr_filter.access_reject] returns updated Delaying reject of request 1 for 1 seconds