Copied in here: Lin: acceess5f7710d57421263eee182648807ba62a350203010001a38201323082012e301d0603551d0e04160414a03774d8725132d320078de9b79f287a932dbb313081c60603551d230481be3081bb8014a03774d8725132d320078de9b79f287a932dbb31a18197a48194308191310b3009060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e311e301c06092a864886f70d0109 EAP-Message = 0x01160f6c696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f72697479820900953acc864d06fcaf300c0603551d13040530030101ff30360603551d1f042f302d302ba029a0278625687474703a2f2f7777772e6578616d706c652e636f6d2f6578616d706c655f63612e63726c300d06092a864886f70d01010b05000381810096d9c719eca5c64ddfb7b3bac54ebd6356850c3aa3e0b7151857dcdf5cc6d2b1ffd1f0c9d6dfa4b54f9fee7f58e8ac99b16ad14217064be2a4fb2db683f640fd5d331cf1e714bb19be54d3581949100b7ad051714be5c6a332d004b9c96d2f EAP-Message = 0xbe89c214a17767ea2ad030de4f430984f9e53daa448b464748a99ab846e132c6b916030100cb0c0000c70300174104aa58bd6268496ed70e16953f6a601778c86f0a98212e99ab2ad97845634caaa8424d10fffcc32bc84c1b2c3f769ccb6f5d987d4766b5d834c0561f136e735e2f008027413db279d297803f3560639d009fdc84d884e4d8fd17cfd6474f8c76d0b4595dc97879e57543ffcdc6c63e75dfe96b97c3bb33d601aa375919dddae503423911d012b6d0c1f0fd8fd139ee45abef8fee7dd867deff19bb6f11317a3c48ba95a5d3cfaa0f8633bbe36e01880a6f40fe1f975a6948bcf950e55aa6b769d95f4316030100a40d00009c030102 EAP-Message = 0x4000960094308191310b3009 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x0452373b064d3acf9b22daa195414c61 Mon Sep 28 18:15:08 2015 : Info: Finished request 2. Mon Sep 28 18:15:08 2015 : Debug: Going to the next request Mon Sep 28 18:15:08 2015 : Debug: Waking up in 4.9 seconds. rad_recv: Access-Request packet from host 192.168.1.50 port 1111, id=31, length=205 Message-Authenticator = 0x2b7e24d764a9126ba0564b4cb081ec03 Service-Type = Framed-User User-Name = "lin" Framed-MTU = 1488 State = 0x0452373b064d3acf9b22daa195414c61 Called-Station-Id = "B8-A3-86-92-86-B7:testconn" Calling-Station-Id = "EC-55-F9-2A-CC-86" NAS-Identifier = "D-Link Access Point" NAS-Port-Type = Wireless-802.11 Connect-Info = "CONNECT 54Mbps 802.11g" EAP-Message = 0x021f00060d00 NAS-IP-Address = 192.168.1.50 NAS-Port = 5 NAS-Port-Id = "STA port # 5" Mon Sep 28 18:15:08 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:15:08 2015 : Info: +group authorize { Mon Sep 28 18:15:08 2015 : Info: ++[preprocess] = ok Mon Sep 28 18:15:08 2015 : Info: ++[chap] = noop Mon Sep 28 18:15:08 2015 : Info: ++[mschap] = noop Mon Sep 28 18:15:08 2015 : Info: ++[digest] = noop Mon Sep 28 18:15:08 2015 : Info: [suffix] No '@' in User-Name = "lin", looking up realm NULL Mon Sep 28 18:15:08 2015 : Info: [suffix] No such realm "NULL" Mon Sep 28 18:15:08 2015 : Info: ++[suffix] = noop Mon Sep 28 18:15:08 2015 : Info: [eap] EAP packet type response id 31 length 6 Mon Sep 28 18:15:08 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Mon Sep 28 18:15:08 2015 : Info: ++[eap] = updated Mon Sep 28 18:15:08 2015 : Info: [files] users: Matched entry lin at line 123 Mon Sep 28 18:15:08 2015 : Info: ++[files] = ok Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{Stripped-User-Name} -> Mon Sep 28 18:15:08 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{User-Name} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] sql_set_user escaped user --> 'lin' Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 27 Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'lin' ORDER BY id Mon Sep 28 18:15:08 2015 : Info: [sql] User found in radcheck table Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'lin' ORDER BY id Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'lin' ORDER BY priority Mon Sep 28 18:15:08 2015 : Info: [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 = 'dynamic' ORDER BY id Mon Sep 28 18:15:08 2015 : Info: [sql] User found in group dynamic Mon Sep 28 18:15:08 2015 : Info: [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 = 'dynamic' ORDER BY id Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Released sql socket id: 27 Mon Sep 28 18:15:08 2015 : Info: ++[sql] = ok Mon Sep 28 18:15:08 2015 : Info: ++[expiration] = noop Mon Sep 28 18:15:08 2015 : Info: ++[logintime] = noop Mon Sep 28 18:15:08 2015 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP Mon Sep 28 18:15:08 2015 : Info: ++[pap] = noop Mon Sep 28 18:15:08 2015 : Info: +} # group authorize = updated Mon Sep 28 18:15:08 2015 : Info: Found Auth-Type = EAP Mon Sep 28 18:15:08 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:15:08 2015 : Info: +group authenticate { Mon Sep 28 18:15:08 2015 : Info: [eap] Request found, released from the list Mon Sep 28 18:15:08 2015 : Info: [eap] EAP/tls Mon Sep 28 18:15:08 2015 : Info: [eap] processing type tls Mon Sep 28 18:15:08 2015 : Info: [tls] Authenticate Mon Sep 28 18:15:08 2015 : Info: [tls] processing EAP-TLS Mon Sep 28 18:15:08 2015 : Info: [tls] Received TLS ACK Mon Sep 28 18:15:08 2015 : Info: [tls] ACK handshake fragment handler Mon Sep 28 18:15:08 2015 : Info: [tls] eaptls_verify returned 1 Mon Sep 28 18:15:08 2015 : Info: [tls] eaptls_process returned 13 Mon Sep 28 18:15:08 2015 : Info: ++[eap] = handled Mon Sep 28 18:15:08 2015 : Info: +} # group authenticate = handled Sending Access-Challenge of id 31 to 192.168.1.50 port 1111 Framed-IP-Address := 192.168.1.111 Service-Type := Framed-User Acct-Interim-Interval := 300 EAP-Message = 0x0120009b0d800000087d060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e311e301c06092a864886f70d010901160f6c696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f726974790e000000 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x0452373b07723acf9b22daa195414c61 Mon Sep 28 18:15:08 2015 : Info: Finished request 3. Mon Sep 28 18:15:08 2015 : Debug: Going to the next request Mon Sep 28 18:15:08 2015 : Debug: Waking up in 4.9 seconds. rad_recv: Access-Request packet from host 192.168.1.50 port 1111, id=32, length=1519 Message-Authenticator = 0xf72b1041d2b3d855f3fb77c1404866b5 Service-Type = Framed-User User-Name = "lin" Framed-MTU = 1488 State = 0x0452373b07723acf9b22daa195414c61 Called-Station-Id = "B8-A3-86-92-86-B7:testconn" Calling-Station-Id = "EC-55-F9-2A-CC-86" NAS-Identifier = "D-Link Access Point" NAS-Port-Type = Wireless-802.11 Connect-Info = "CONNECT 54Mbps 802.11g" EAP-Message = 0x0220051e0dc0000007c716030106b10b0006ad0006aa0002ca308202c63082022fa003020102020104300d06092a864886f70d01010b0500308191310b3009060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e311e301c06092a864886f70d010901160f6c696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f72697479301e170d3135303932313134343631385a170d3136303932303134343631385a306f310b3009060355040613024652310f EAP-Message = 0x300d0603550408130652616469757331153013060355040a130c4578616d706c6520496e632e311830160603550403140f6c696e406578616d706c652e636f6d311e301c06092a864886f70d010901160f6c696e406578616d706c652e636f6d30819f300d06092a864886f70d010101050003818d0030818902818100e69d6bb25f13d2b6947eb4ac90f5826d9b69a2dbdba314f66d5b195b6a2ff30dcdefe39a7592ca935d3762b0e19e78c70c5f34994c8b53d1eb771672061adbf69bd6628b7692316ea423cc45a8814abfc88b94349bbec2296a87684dda1f82d442507d850c1c46eb929d0cc9b6f78b0eb9d87e1030fbd98a5c05b004666b6d8b EAP-Message = 0x0203010001a34f304d30130603551d25040c300a06082b0601050507030230360603551d1f042f302d302ba029a0278625687474703a2f2f7777772e6578616d706c652e636f6d2f6578616d706c655f63612e63726c300d06092a864886f70d01010b050003818100066a5a7745b713bb8560c5544a2475c8c1c7dfc12562462e40a63c4b31429b32f01e43121ef0832e3ceab27b80bfacc69327f1a4ef64291977f1bb756c32a40dbe41f4a7c211c2895487cebd0501feb42cf60bd4dd5181f43117196675fa8897193e494f9ed8313b7ce84ab2649bbbbcc845b4f72752d90220ddd29b4202eec10003da308203d63082033fa00302010202090095 EAP-Message = 0x3acc864d06fcaf300d06092a864886f70d01010b0500308191310b3009060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e311e301c06092a864886f70d010901160f6c696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f72697479301e170d3135303932313134343530385a170d3136303932303134343530385a308191310b3009060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865 EAP-Message = 0x726531153013060355040a130c4578616d706c6520496e632e311e301c06092a864886f70d010901160f6c696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f7269747930819f300d06092a864886f70d010101050003818d0030818902818100f309afd4d9180f80257d3479b73786a195fd036f97d8be49339135c7b01aeb36a2e8d1ef13fbcf7d06a64395a884d9afa73aa3150c396688aea76d851f4b797b10f3cf5111fa817406fb0b569dcef28b2bdc26fe315311cfc8882e291b66bbc4cedba308b619f3cc59737470d848445f7710d57421263eee182648807ba62a EAP-Message = 0x350203010001a38201323082012e301d0603551d0e04160414a03774d8725132d320078de9b79f287a932dbb31 NAS-IP-Address = 192.168.1.50 NAS-Port = 5 NAS-Port-Id = "STA port # 5" Mon Sep 28 18:15:08 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:15:08 2015 : Info: +group authorize { Mon Sep 28 18:15:08 2015 : Info: ++[preprocess] = ok Mon Sep 28 18:15:08 2015 : Info: ++[chap] = noop Mon Sep 28 18:15:08 2015 : Info: ++[mschap] = noop Mon Sep 28 18:15:08 2015 : Info: ++[digest] = noop Mon Sep 28 18:15:08 2015 : Info: [suffix] No '@' in User-Name = "lin", looking up realm NULL Mon Sep 28 18:15:08 2015 : Info: [suffix] No such realm "NULL" Mon Sep 28 18:15:08 2015 : Info: ++[suffix] = noop Mon Sep 28 18:15:08 2015 : Info: [eap] EAP packet type response id 32 length 253 Mon Sep 28 18:15:08 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Mon Sep 28 18:15:08 2015 : Info: ++[eap] = updated Mon Sep 28 18:15:08 2015 : Info: [files] users: Matched entry lin at line 123 Mon Sep 28 18:15:08 2015 : Info: ++[files] = ok Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{Stripped-User-Name} -> Mon Sep 28 18:15:08 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{User-Name} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] sql_set_user escaped user --> 'lin' Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 26 Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'lin' ORDER BY id Mon Sep 28 18:15:08 2015 : Info: [sql] User found in radcheck table Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'lin' ORDER BY id Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'lin' ORDER BY priority Mon Sep 28 18:15:08 2015 : Info: [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 = 'dynamic' ORDER BY id Mon Sep 28 18:15:08 2015 : Info: [sql] User found in group dynamic Mon Sep 28 18:15:08 2015 : Info: [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 = 'dynamic' ORDER BY id Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Released sql socket id: 26 Mon Sep 28 18:15:08 2015 : Info: ++[sql] = ok Mon Sep 28 18:15:08 2015 : Info: ++[expiration] = noop Mon Sep 28 18:15:08 2015 : Info: ++[logintime] = noop Mon Sep 28 18:15:08 2015 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP Mon Sep 28 18:15:08 2015 : Info: ++[pap] = noop Mon Sep 28 18:15:08 2015 : Info: +} # group authorize = updated Mon Sep 28 18:15:08 2015 : Info: Found Auth-Type = EAP Mon Sep 28 18:15:08 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:15:08 2015 : Info: +group authenticate { Mon Sep 28 18:15:08 2015 : Info: [eap] Request found, released from the list Mon Sep 28 18:15:08 2015 : Info: [eap] EAP/tls Mon Sep 28 18:15:08 2015 : Info: [eap] processing type tls Mon Sep 28 18:15:08 2015 : Info: [tls] Authenticate Mon Sep 28 18:15:08 2015 : Info: [tls] processing EAP-TLS Mon Sep 28 18:15:08 2015 : Debug: TLS Length 1991 Mon Sep 28 18:15:08 2015 : Info: [tls] Received EAP-TLS First Fragment of the message Mon Sep 28 18:15:08 2015 : Info: [tls] eaptls_verify returned 9 Mon Sep 28 18:15:08 2015 : Info: [tls] eaptls_process returned 13 Mon Sep 28 18:15:08 2015 : Info: ++[eap] = handled Mon Sep 28 18:15:08 2015 : Info: +} # group authenticate = handled Sending Access-Challenge of id 32 to 192.168.1.50 port 1111 Framed-IP-Address := 192.168.1.111 Service-Type := Framed-User Acct-Interim-Interval := 300 EAP-Message = 0x012100060d00 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x0452373b00733acf9b22daa195414c61 Mon Sep 28 18:15:08 2015 : Info: Finished request 4. Mon Sep 28 18:15:08 2015 : Debug: Going to the next request Mon Sep 28 18:15:08 2015 : Debug: Waking up in 4.9 seconds. rad_recv: Access-Request packet from host 192.168.1.50 port 1111, id=33, length=900 Message-Authenticator = 0xaf7d00e343341dd0272004d8497a4774 Service-Type = Framed-User User-Name = "lin" Framed-MTU = 1488 State = 0x0452373b00733acf9b22daa195414c61 Called-Station-Id = "B8-A3-86-92-86-B7:testconn" Calling-Station-Id = "EC-55-F9-2A-CC-86" NAS-Identifier = "D-Link Access Point" NAS-Port-Type = Wireless-802.11 Connect-Info = "CONNECT 54Mbps 802.11g" EAP-Message = 0x022102b90d003081c60603551d230481be3081bb8014a03774d8725132d320078de9b79f287a932dbb31a18197a48194308191310b3009060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e311e301c06092a864886f70d010901160f6c696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f72697479820900953acc864d06fcaf300c0603551d13040530030101ff30360603551d1f042f302d302ba029a0278625687474703a2f2f7777772e6578 EAP-Message = 0x616d706c652e636f6d2f6578616d706c655f63612e63726c300d06092a864886f70d01010b05000381810096d9c719eca5c64ddfb7b3bac54ebd6356850c3aa3e0b7151857dcdf5cc6d2b1ffd1f0c9d6dfa4b54f9fee7f58e8ac99b16ad14217064be2a4fb2db683f640fd5d331cf1e714bb19be54d3581949100b7ad051714be5c6a332d004b9c96d2fbe89c214a17767ea2ad030de4f430984f9e53daa448b464748a99ab846e132c6b916030100461000004241048bd7c69292592488d8102295acb943d161ffb84be68ffc183c2d3a316ab63de0701053bf7c13f25129d365cdb99dfc74ca37b75a7afbb33074a180aaab40d10916030100860f00 EAP-Message = 0x0082008084f396947106198627824d622b5db60eac3ad4195c132781f79e6b403ec760d8bb74b0e7f32ecf78584d6021296ebed3746734e79aeddea8d8ab7902e0a636706ed6306e0b75fe9691908f4d327166fd74f99851cb03c2185a5999bd51ab4d1a03aa8addd90b07a62aa9548167300117c6db54a161b914d6dc33dea1d9dd64561403010001011603010030043441932a96e3f2d769f4928d4423eb5bc393e425a82ce0a2d811250ff08967ef0de002934be36c7fb3c055323161a9 NAS-IP-Address = 192.168.1.50 NAS-Port = 5 NAS-Port-Id = "STA port # 5" Mon Sep 28 18:15:08 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:15:08 2015 : Info: +group authorize { Mon Sep 28 18:15:08 2015 : Info: ++[preprocess] = ok Mon Sep 28 18:15:08 2015 : Info: ++[chap] = noop Mon Sep 28 18:15:08 2015 : Info: ++[mschap] = noop Mon Sep 28 18:15:08 2015 : Info: ++[digest] = noop Mon Sep 28 18:15:08 2015 : Info: [suffix] No '@' in User-Name = "lin", looking up realm NULL Mon Sep 28 18:15:08 2015 : Info: [suffix] No such realm "NULL" Mon Sep 28 18:15:08 2015 : Info: ++[suffix] = noop Mon Sep 28 18:15:08 2015 : Info: [eap] EAP packet type response id 33 length 253 Mon Sep 28 18:15:08 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Mon Sep 28 18:15:08 2015 : Info: ++[eap] = updated Mon Sep 28 18:15:08 2015 : Info: [files] users: Matched entry lin at line 123 Mon Sep 28 18:15:08 2015 : Info: ++[files] = ok Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{Stripped-User-Name} -> Mon Sep 28 18:15:08 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{User-Name} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] sql_set_user escaped user --> 'lin' Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 25 Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'lin' ORDER BY id Mon Sep 28 18:15:08 2015 : Info: [sql] User found in radcheck table Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'lin' ORDER BY id Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'lin' ORDER BY priority Mon Sep 28 18:15:08 2015 : Info: [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 = 'dynamic' ORDER BY id Mon Sep 28 18:15:08 2015 : Info: [sql] User found in group dynamic Mon Sep 28 18:15:08 2015 : Info: [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 = 'dynamic' ORDER BY id Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Released sql socket id: 25 Mon Sep 28 18:15:08 2015 : Info: ++[sql] = ok Mon Sep 28 18:15:08 2015 : Info: ++[expiration] = noop Mon Sep 28 18:15:08 2015 : Info: ++[logintime] = noop Mon Sep 28 18:15:08 2015 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP Mon Sep 28 18:15:08 2015 : Info: ++[pap] = noop Mon Sep 28 18:15:08 2015 : Info: +} # group authorize = updated Mon Sep 28 18:15:08 2015 : Info: Found Auth-Type = EAP Mon Sep 28 18:15:08 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:15:08 2015 : Info: +group authenticate { Mon Sep 28 18:15:08 2015 : Info: [eap] Request found, released from the list Mon Sep 28 18:15:08 2015 : Info: [eap] EAP/tls Mon Sep 28 18:15:08 2015 : Info: [eap] processing type tls Mon Sep 28 18:15:08 2015 : Info: [tls] Authenticate Mon Sep 28 18:15:08 2015 : Info: [tls] processing EAP-TLS Mon Sep 28 18:15:08 2015 : Info: [tls] eaptls_verify returned 7 Mon Sep 28 18:15:08 2015 : Info: [tls] Done initial handshake Mon Sep 28 18:15:08 2015 : Info: [tls] <<< TLS 1.0 Handshake [length 06b1], Certificate Mon Sep 28 18:15:08 2015 : Info: [tls] chain-depth=1, Mon Sep 28 18:15:08 2015 : Info: [tls] error=0 Mon Sep 28 18:15:08 2015 : Info: [tls] --> User-Name = lin Mon Sep 28 18:15:08 2015 : Info: [tls] --> BUF-Name = Example Certificate Authority Mon Sep 28 18:15:08 2015 : Info: [tls] --> subject = /C=FR/ST=Radius/L=Somewhere/O=Example Inc./emailAddress= lin@example.com/CN=Example Certificate Authority Mon Sep 28 18:15:08 2015 : Info: [tls] --> issuer = /C=FR/ST=Radius/L=Somewhere/O=Example Inc./emailAddress= lin@example.com/CN=Example Certificate Authority Mon Sep 28 18:15:08 2015 : Info: [tls] --> verify return:1 TLS-Client-Cert-X509v3-Extended-Key-Usage += "TLS Web Client Authentication" Mon Sep 28 18:15:08 2015 : Info: [tls] chain-depth=0, Mon Sep 28 18:15:08 2015 : Info: [tls] error=0 Mon Sep 28 18:15:08 2015 : Info: [tls] --> User-Name = lin Mon Sep 28 18:15:08 2015 : Info: [tls] --> BUF-Name = lin@example.com Mon Sep 28 18:15:08 2015 : Info: [tls] --> subject = /C=FR/ST=Radius/O=Example Inc./CN= lin@example.com/emailAddress=lin@example.com Mon Sep 28 18:15:08 2015 : Info: [tls] --> issuer = /C=FR/ST=Radius/L=Somewhere/O=Example Inc./emailAddress= lin@example.com/CN=Example Certificate Authority Mon Sep 28 18:15:08 2015 : Info: [tls] --> verify return:1 Mon Sep 28 18:15:08 2015 : Info: [tls] TLS_accept: SSLv3 read client certificate A Mon Sep 28 18:15:08 2015 : Info: [tls] <<< TLS 1.0 Handshake [length 0046], ClientKeyExchange Mon Sep 28 18:15:08 2015 : Info: [tls] TLS_accept: SSLv3 read client key exchange A Mon Sep 28 18:15:08 2015 : Info: [tls] <<< TLS 1.0 Handshake [length 0086], CertificateVerify Mon Sep 28 18:15:08 2015 : Info: [tls] TLS_accept: SSLv3 read certificate verify A Mon Sep 28 18:15:08 2015 : Info: [tls] <<< TLS 1.0 ChangeCipherSpec [length 0001] Mon Sep 28 18:15:08 2015 : Info: [tls] <<< TLS 1.0 Handshake [length 0010], Finished Mon Sep 28 18:15:08 2015 : Info: [tls] TLS_accept: SSLv3 read finished A Mon Sep 28 18:15:08 2015 : Info: [tls] >>> TLS 1.0 ChangeCipherSpec [length 0001] Mon Sep 28 18:15:08 2015 : Info: [tls] TLS_accept: SSLv3 write change cipher spec A Mon Sep 28 18:15:08 2015 : Info: [tls] >>> TLS 1.0 Handshake [length 0010], Finished Mon Sep 28 18:15:08 2015 : Info: [tls] TLS_accept: SSLv3 write finished A Mon Sep 28 18:15:08 2015 : Info: [tls] TLS_accept: SSLv3 flush data Mon Sep 28 18:15:08 2015 : Info: [tls] (other): SSL negotiation finished successfully Mon Sep 28 18:15:08 2015 : Debug: SSL Connection Established Mon Sep 28 18:15:08 2015 : Info: [tls] eaptls_process returned 13 Mon Sep 28 18:15:08 2015 : Info: ++[eap] = handled Mon Sep 28 18:15:08 2015 : Info: +} # group authenticate = handled Sending Access-Challenge of id 33 to 192.168.1.50 port 1111 Framed-IP-Address := 192.168.1.111 Service-Type := Framed-User Acct-Interim-Interval := 300 EAP-Message = 0x012200450d800000003b1403010001011603010030a7ab9f1bcecbf88696a57789c86619fb0ed0466ac2a9c5431bbc6f6864d50a9555256c85fa50c3f0c1e47b84d0a9db1f Message-Authenticator = 0x00000000000000000000000000000000 State = 0x0452373b01703acf9b22daa195414c61 Mon Sep 28 18:15:08 2015 : Info: Finished request 5. Mon Sep 28 18:15:08 2015 : Debug: Going to the next request Mon Sep 28 18:15:08 2015 : Debug: Waking up in 4.9 seconds. rad_recv: Access-Request packet from host 192.168.1.50 port 1111, id=34, length=205 Message-Authenticator = 0xcbd99f506ca47b9960390bb23f413c91 Service-Type = Framed-User User-Name = "lin" Framed-MTU = 1488 State = 0x0452373b01703acf9b22daa195414c61 Called-Station-Id = "B8-A3-86-92-86-B7:testconn" Calling-Station-Id = "EC-55-F9-2A-CC-86" NAS-Identifier = "D-Link Access Point" NAS-Port-Type = Wireless-802.11 Connect-Info = "CONNECT 54Mbps 802.11g" EAP-Message = 0x022200060d00 NAS-IP-Address = 192.168.1.50 NAS-Port = 5 NAS-Port-Id = "STA port # 5" Mon Sep 28 18:15:08 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:15:08 2015 : Info: +group authorize { Mon Sep 28 18:15:08 2015 : Info: ++[preprocess] = ok Mon Sep 28 18:15:08 2015 : Info: ++[chap] = noop Mon Sep 28 18:15:08 2015 : Info: ++[mschap] = noop Mon Sep 28 18:15:08 2015 : Info: ++[digest] = noop Mon Sep 28 18:15:08 2015 : Info: [suffix] No '@' in User-Name = "lin", looking up realm NULL Mon Sep 28 18:15:08 2015 : Info: [suffix] No such realm "NULL" Mon Sep 28 18:15:08 2015 : Info: ++[suffix] = noop Mon Sep 28 18:15:08 2015 : Info: [eap] EAP packet type response id 34 length 6 Mon Sep 28 18:15:08 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Mon Sep 28 18:15:08 2015 : Info: ++[eap] = updated Mon Sep 28 18:15:08 2015 : Info: [files] users: Matched entry lin at line 123 Mon Sep 28 18:15:08 2015 : Info: ++[files] = ok Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{Stripped-User-Name} -> Mon Sep 28 18:15:08 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{User-Name} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] sql_set_user escaped user --> 'lin' Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 24 Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'lin' ORDER BY id Mon Sep 28 18:15:08 2015 : Info: [sql] User found in radcheck table Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'lin' ORDER BY id Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'lin' ORDER BY priority Mon Sep 28 18:15:08 2015 : Info: [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 = 'dynamic' ORDER BY id Mon Sep 28 18:15:08 2015 : Info: [sql] User found in group dynamic Mon Sep 28 18:15:08 2015 : Info: [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 = 'dynamic' ORDER BY id Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Released sql socket id: 24 Mon Sep 28 18:15:08 2015 : Info: ++[sql] = ok Mon Sep 28 18:15:08 2015 : Info: ++[expiration] = noop Mon Sep 28 18:15:08 2015 : Info: ++[logintime] = noop Mon Sep 28 18:15:08 2015 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP Mon Sep 28 18:15:08 2015 : Info: ++[pap] = noop Mon Sep 28 18:15:08 2015 : Info: +} # group authorize = updated Mon Sep 28 18:15:08 2015 : Info: Found Auth-Type = EAP Mon Sep 28 18:15:08 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:15:08 2015 : Info: +group authenticate { Mon Sep 28 18:15:08 2015 : Info: [eap] Request found, released from the list Mon Sep 28 18:15:08 2015 : Info: [eap] EAP/tls Mon Sep 28 18:15:08 2015 : Info: [eap] processing type tls Mon Sep 28 18:15:08 2015 : Info: [tls] Authenticate Mon Sep 28 18:15:08 2015 : Info: [tls] processing EAP-TLS Mon Sep 28 18:15:08 2015 : Info: [tls] Received TLS ACK Mon Sep 28 18:15:08 2015 : Info: [tls] ACK handshake is finished Mon Sep 28 18:15:08 2015 : Info: [tls] eaptls_verify returned 3 Mon Sep 28 18:15:08 2015 : Info: [tls] eaptls_process returned 3 Mon Sep 28 18:15:08 2015 : Info: [tls] Adding user data to cached session Mon Sep 28 18:15:08 2015 : Info: [eap] Freeing handler Mon Sep 28 18:15:08 2015 : Info: ++[eap] = ok Mon Sep 28 18:15:08 2015 : Info: +} # group authenticate = ok Mon Sep 28 18:15:08 2015 : Info: # Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:15:08 2015 : Info: +group post-auth { Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{Stripped-User-Name} -> Mon Sep 28 18:15:08 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{User-Name} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] sql_set_user escaped user --> 'lin' Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{User-Password} -> Mon Sep 28 18:15:08 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{Chap-Password} -> Mon Sep 28 18:15:08 2015 : Info: [sql] expand: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'lin', '', 'Access-Accept', '2015-09-28 18:15:08') Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'lin', '', 'Access-Accept', '2015-09-28 18:15:08') Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 23 Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Released sql socket id: 23 Mon Sep 28 18:15:08 2015 : Info: ++[sql] = ok Mon Sep 28 18:15:08 2015 : Info: ++[exec] = noop Mon Sep 28 18:15:08 2015 : Info: +} # group post-auth = ok Sending Access-Accept of id 34 to 192.168.1.50 port 1111 Framed-IP-Address := 192.168.1.111 Service-Type := Framed-User Acct-Interim-Interval := 300 MS-MPPE-Recv-Key = 0x5169f84f16f190a14650f49720fd76765fcac67faec4553a6adfa63295d04926 MS-MPPE-Send-Key = 0xf998605b6a1c35fcf47e304754e84708f01b0b42941170086b1f108270084ab0 EAP-Message = 0x03220004 Message-Authenticator = 0x00000000000000000000000000000000 User-Name = "lin" Mon Sep 28 18:15:08 2015 : Info: Finished request 6. Mon Sep 28 18:15:08 2015 : Debug: Going to the next request Mon Sep 28 18:15:08 2015 : Debug: Waking up in 4.8 seconds. rad_recv: Accounting-Request packet from host 192.168.1.50 port 1473, id=104, length=96 Acct-Status-Type = Start Acct-Delay-Time = 0 Acct-Session-Id = "0000000018:0000000049" Acct-Authentic = RADIUS Acct-Multi-Session-Id = "lin" User-Name = "lin" Calling-Station-Id = "ec-55-f9-2a-cc-86" NAS-IP-Address = 192.168.1.50 Mon Sep 28 18:15:09 2015 : Info: # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:15:09 2015 : Info: +group preacct { Mon Sep 28 18:15:09 2015 : Info: ++[preprocess] = ok Mon Sep 28 18:15:09 2015 : Info: [acct_unique] WARNING: Attribute NAS-Port was not found in request, unique ID MAY be inconsistent Mon Sep 28 18:15:09 2015 : Info: [acct_unique] WARNING: Attribute NAS-Identifier was not found in request, unique ID MAY be inconsistent Mon Sep 28 18:15:09 2015 : Info: [acct_unique] Hashing ',,NAS-IP-Address = 192.168.1.50,Acct-Session-Id = "0000000018:0000000049",User-Name = "lin"' Mon Sep 28 18:15:09 2015 : Info: [acct_unique] Acct-Unique-Session-ID = "0bdf67000ebbc82f". Mon Sep 28 18:15:09 2015 : Info: ++[acct_unique] = ok Mon Sep 28 18:15:09 2015 : Info: [suffix] No '@' in User-Name = "lin", looking up realm NULL Mon Sep 28 18:15:09 2015 : Info: [suffix] No such realm "NULL" Mon Sep 28 18:15:09 2015 : Info: ++[suffix] = noop Mon Sep 28 18:15:09 2015 : Info: ++[files] = noop Mon Sep 28 18:15:09 2015 : Info: +} # group preacct = ok Mon Sep 28 18:15:09 2015 : Info: # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:15:09 2015 : Info: +group accounting { Mon Sep 28 18:15:09 2015 : Info: [detail] expand: %{Packet-Src-IP-Address} -> 192.168.1.50 Mon Sep 28 18:15:09 2015 : Info: [detail] expand: /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d -> /usr/local/var/log/radius/radacct/192.168.1.50/detail-20150928 Mon Sep 28 18:15:09 2015 : Info: [detail] /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/192.168.1.50/detail-20150928 Mon Sep 28 18:15:09 2015 : Info: [detail] expand: %t -> Mon Sep 28 18:15:09 2015 Mon Sep 28 18:15:09 2015 : Info: ++[detail] = ok Mon Sep 28 18:15:09 2015 : Info: [sql] expand: %{Stripped-User-Name} -> Mon Sep 28 18:15:09 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:15:09 2015 : Info: [sql] expand: %{User-Name} -> lin Mon Sep 28 18:15:09 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> lin Mon Sep 28 18:15:09 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> lin Mon Sep 28 18:15:09 2015 : Info: [sql] sql_set_user escaped user --> 'lin' Mon Sep 28 18:15:09 2015 : Info: [sql] expand: %{Acct-Delay-Time} -> 0 Mon Sep 28 18:15:09 2015 : Info: [sql] expand: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress, acctinputpackets, acctoutputpackets, acctstartdelay, acctstopdelay, xascendsessionsvrkey) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', '%S', NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Prot Mon Sep 28 18:15:09 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 22 Mon Sep 28 18:15:09 2015 : Debug: rlm_sql (sql): Released sql socket id: 22 Mon Sep 28 18:15:09 2015 : Info: ++[sql] = ok Mon Sep 28 18:15:09 2015 : Info: ++[exec] = noop Mon Sep 28 18:15:09 2015 : Info: [attr_filter.accounting_response] expand: %{User-Name} -> lin Mon Sep 28 18:15:09 2015 : Debug: attr_filter: Matched entry DEFAULT at line 12 Mon Sep 28 18:15:09 2015 : Info: ++[attr_filter.accounting_response] = updated Mon Sep 28 18:15:09 2015 : Info: +} # group accounting = updated Sending Accounting-Response of id 104 to 192.168.1.50 port 1473 Mon Sep 28 18:15:09 2015 : Info: Finished request 7. Mon Sep 28 18:15:09 2015 : Info: Cleaning up request 7 ID 104 with timestamp +7 Mon Sep 28 18:15:09 2015 : Debug: Going to the next request Mon Sep 28 18:15:09 2015 : Debug: Waking up in 3.3 seconds. Anisa: Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{Stripped-User-Name} -> Mon Sep 28 18:11:55 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{User-Name} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] sql_set_user escaped user --> 'anisa' Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 28 Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'anisa' ORDER BY id Mon Sep 28 18:11:55 2015 : Info: [sql] User found in radcheck table Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'anisa' ORDER BY id Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'anisa' ORDER BY priority Mon Sep 28 18:11:55 2015 : Info: [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 = 'dynamic' ORDER BY id Mon Sep 28 18:11:55 2015 : Info: [sql] User found in group dynamic Mon Sep 28 18:11:55 2015 : Info: [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 = 'dynamic' ORDER BY id Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Released sql socket id: 28 Mon Sep 28 18:11:55 2015 : Info: ++[sql] = ok Mon Sep 28 18:11:55 2015 : Info: ++[expiration] = noop Mon Sep 28 18:11:55 2015 : Info: ++[logintime] = noop Mon Sep 28 18:11:55 2015 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP Mon Sep 28 18:11:55 2015 : Info: ++[pap] = noop Mon Sep 28 18:11:55 2015 : Info: +} # group authorize = updated Mon Sep 28 18:11:55 2015 : Info: Found Auth-Type = EAP Mon Sep 28 18:11:55 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Mon Sep 28 18:11:55 2015 : Info: +group authenticate { Mon Sep 28 18:11:55 2015 : Info: [eap] EAP Identity Mon Sep 28 18:11:55 2015 : Info: [eap] processing type mschapv2 Mon Sep 28 18:11:55 2015 : Debug: rlm_eap_mschapv2: Issuing Challenge Mon Sep 28 18:11:55 2015 : Info: ++[eap] = handled Mon Sep 28 18:11:55 2015 : Info: +} # group authenticate = handled } # server inner-tunnel Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled reply code 11 Service-Type := Framed-User Acct-Interim-Interval := 300 EAP-Message = 0x0107001f1a0107001a108698ce981e43c912de335f90fcd25fa2616e697361 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x3b6746a13b605c83f83cbfdedcbd78b1 Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled reply RADIUS code Access-Challenge Service-Type := Framed-User Acct-Interim-Interval := 300 EAP-Message = 0x0107001f1a0107001a108698ce981e43c912de335f90fcd25fa2616e697361 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x3b6746a13b605c83f83cbfdedcbd78b1 Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled Access-Challenge Mon Sep 28 18:11:55 2015 : Info: ++[eap] = handled Mon Sep 28 18:11:55 2015 : Info: +} # group authenticate = handled Sending Access-Challenge of id 6 to 192.168.1.50 port 1470 EAP-Message = 0x0107003b19001703010030ced49eb6fbfef0894cf62b79588b07ea20ff88af2bc299988ea03f222237fa7abb0cd1d3bd0429045d242aa522f6f590 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xc3eeda0cc5e9c372bc5743d8d31a4433 Mon Sep 28 18:11:55 2015 : Info: Finished request 6. Mon Sep 28 18:11:55 2015 : Debug: Going to the next request Mon Sep 28 18:11:55 2015 : Debug: Waking up in 3.1 seconds. rad_recv: Access-Request packet from host 192.168.1.50 port 1470, id=7, length=308 Message-Authenticator = 0xc46f910074dc1a8ba0a44a0d069e1885 Service-Type = Framed-User User-Name = "anisa" Framed-MTU = 1488 State = 0xc3eeda0cc5e9c372bc5743d8d31a4433 Called-Station-Id = "B8-A3-86-92-86-B7:testconn" Calling-Station-Id = "50-1A-C5-07-FB-74" NAS-Identifier = "D-Link Access Point" NAS-Port-Type = Wireless-802.11 Connect-Info = "CONNECT 54Mbps 802.11g" EAP-Message = 0x0207006b19001703010060a40fef4ff7f461f4febe0274b3cc03cced1a212194d965990e69cfcd57eeca19aba259b5aae8609763632446c35de175665ec1633e2edab48769497b7bc4e65eb3d9c8d891a44efc1220eb6970f5453e708ce1356c3a3a4306b4c9b7ace86bfb NAS-IP-Address = 192.168.1.50 NAS-Port = 1 NAS-Port-Id = "STA port # 1" Mon Sep 28 18:11:55 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:11:55 2015 : Info: +group authorize { Mon Sep 28 18:11:55 2015 : Info: ++[preprocess] = ok Mon Sep 28 18:11:55 2015 : Info: ++[chap] = noop Mon Sep 28 18:11:55 2015 : Info: ++[mschap] = noop Mon Sep 28 18:11:55 2015 : Info: ++[digest] = noop Mon Sep 28 18:11:55 2015 : Info: [suffix] No '@' in User-Name = "anisa", looking up realm NULL Mon Sep 28 18:11:55 2015 : Info: [suffix] No such realm "NULL" Mon Sep 28 18:11:55 2015 : Info: ++[suffix] = noop Mon Sep 28 18:11:55 2015 : Info: [eap] EAP packet type response id 7 length 107 Mon Sep 28 18:11:55 2015 : Info: [eap] Continuing tunnel setup. Mon Sep 28 18:11:55 2015 : Info: ++[eap] = ok Mon Sep 28 18:11:55 2015 : Info: +} # group authorize = ok Mon Sep 28 18:11:55 2015 : Info: Found Auth-Type = EAP Mon Sep 28 18:11:55 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:11:55 2015 : Info: +group authenticate { Mon Sep 28 18:11:55 2015 : Info: [eap] Request found, released from the list Mon Sep 28 18:11:55 2015 : Info: [eap] EAP/peap Mon Sep 28 18:11:55 2015 : Info: [eap] processing type peap Mon Sep 28 18:11:55 2015 : Info: [peap] processing EAP-TLS Mon Sep 28 18:11:55 2015 : Info: [peap] eaptls_verify returned 7 Mon Sep 28 18:11:55 2015 : Info: [peap] Done initial handshake Mon Sep 28 18:11:55 2015 : Info: [peap] eaptls_process returned 7 Mon Sep 28 18:11:55 2015 : Info: [peap] EAPTLS_OK Mon Sep 28 18:11:55 2015 : Info: [peap] Session established. Decoding tunneled attributes. Mon Sep 28 18:11:55 2015 : Info: [peap] Peap state phase2 Mon Sep 28 18:11:55 2015 : Info: [peap] EAP type mschapv2 Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled request EAP-Message = 0x020700401a0207003b317793af47d95c6742aaed702ad9c1c9a90000000000000000666e0718883cd5b235cba76f0817430ebb65c50b583fbb2000616e697361 server { Mon Sep 28 18:11:55 2015 : Info: [peap] Setting User-Name to anisa Sending tunneled request EAP-Message = 0x020700401a0207003b317793af47d95c6742aaed702ad9c1c9a90000000000000000666e0718883cd5b235cba76f0817430ebb65c50b583fbb2000616e697361 FreeRADIUS-Proxied-To = 127.0.0.1 User-Name = "anisa" State = 0x3b6746a13b605c83f83cbfdedcbd78b1 server inner-tunnel { Mon Sep 28 18:11:55 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Mon Sep 28 18:11:55 2015 : Info: +group authorize { Mon Sep 28 18:11:55 2015 : Info: ++[chap] = noop Mon Sep 28 18:11:55 2015 : Info: ++[mschap] = noop Mon Sep 28 18:11:55 2015 : Info: [suffix] No '@' in User-Name = "anisa", looking up realm NULL Mon Sep 28 18:11:55 2015 : Info: [suffix] No such realm "NULL" Mon Sep 28 18:11:55 2015 : Info: ++[suffix] = noop Mon Sep 28 18:11:55 2015 : Info: ++update control { Mon Sep 28 18:11:55 2015 : Info: ++} # update control = noop Mon Sep 28 18:11:55 2015 : Info: [eap] EAP packet type response id 7 length 64 Mon Sep 28 18:11:55 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Mon Sep 28 18:11:55 2015 : Info: ++[eap] = updated Mon Sep 28 18:11:55 2015 : Info: [files] users: Matched entry anisa at line 97 Mon Sep 28 18:11:55 2015 : Info: ++[files] = ok Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{Stripped-User-Name} -> Mon Sep 28 18:11:55 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{User-Name} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] sql_set_user escaped user --> 'anisa' Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 27 Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'anisa' ORDER BY id Mon Sep 28 18:11:55 2015 : Info: [sql] User found in radcheck table Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'anisa' ORDER BY id Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'anisa' ORDER BY priority Mon Sep 28 18:11:55 2015 : Info: [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 = 'dynamic' ORDER BY id Mon Sep 28 18:11:55 2015 : Info: [sql] User found in group dynamic Mon Sep 28 18:11:55 2015 : Info: [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 = 'dynamic' ORDER BY id Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Released sql socket id: 27 Mon Sep 28 18:11:55 2015 : Info: ++[sql] = ok Mon Sep 28 18:11:55 2015 : Info: ++[expiration] = noop Mon Sep 28 18:11:55 2015 : Info: ++[logintime] = noop Mon Sep 28 18:11:55 2015 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP Mon Sep 28 18:11:55 2015 : Info: ++[pap] = noop Mon Sep 28 18:11:55 2015 : Info: +} # group authorize = updated Mon Sep 28 18:11:55 2015 : Info: Found Auth-Type = EAP Mon Sep 28 18:11:55 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Mon Sep 28 18:11:55 2015 : Info: +group authenticate { Mon Sep 28 18:11:55 2015 : Info: [eap] Request found, released from the list Mon Sep 28 18:11:55 2015 : Info: [eap] EAP/mschapv2 Mon Sep 28 18:11:55 2015 : Info: [eap] processing type mschapv2 Mon Sep 28 18:11:55 2015 : Info: [mschapv2] # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Mon Sep 28 18:11:55 2015 : Info: [mschapv2] +group MS-CHAP { Mon Sep 28 18:11:55 2015 : Info: [mschap] Creating challenge hash with username: anisa Mon Sep 28 18:11:55 2015 : Info: [mschap] Client is using MS-CHAPv2 for anisa, we need NT-Password Mon Sep 28 18:11:55 2015 : Info: [mschap] adding MS-CHAPv2 MPPE keys Mon Sep 28 18:11:55 2015 : Info: ++[mschap] = ok Mon Sep 28 18:11:55 2015 : Info: +} # group MS-CHAP = ok Mon Sep 28 18:11:55 2015 : Debug: MSCHAP Success Mon Sep 28 18:11:55 2015 : Info: ++[eap] = handled Mon Sep 28 18:11:55 2015 : Info: +} # group authenticate = handled } # server inner-tunnel Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled reply code 11 Service-Type := Framed-User Acct-Interim-Interval := 300 EAP-Message = 0x010800331a0307002e533d38324237303643433631313141423744464137393244314234334446313244363730314332413232 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x3b6746a13a6f5c83f83cbfdedcbd78b1 Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled reply RADIUS code Access-Challenge Service-Type := Framed-User Acct-Interim-Interval := 300 EAP-Message = 0x010800331a0307002e533d38324237303643433631313141423744464137393244314234334446313244363730314332413232 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x3b6746a13a6f5c83f83cbfdedcbd78b1 Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled Access-Challenge Mon Sep 28 18:11:55 2015 : Info: ++[eap] = handled Mon Sep 28 18:11:55 2015 : Info: +} # group authenticate = handled Sending Access-Challenge of id 7 to 192.168.1.50 port 1470 EAP-Message = 0x0108005b19001703010050534c5beda3fe7057018278a62d4eb5c26cfbce6eb7fb0a19f4e80f87980c9320463c1f574939f1deba0554db1cec1c39c6e6a7c5480a6ca3367feafd86364e75689762b3099d4cdcb713e642b34f32ba Message-Authenticator = 0x00000000000000000000000000000000 State = 0xc3eeda0cc4e6c372bc5743d8d31a4433 Mon Sep 28 18:11:55 2015 : Info: Finished request 7. Mon Sep 28 18:11:55 2015 : Debug: Going to the next request Mon Sep 28 18:11:55 2015 : Debug: Waking up in 3.0 seconds. rad_recv: Access-Request packet from host 192.168.1.50 port 1470, id=8, length=244 Message-Authenticator = 0x2b92c7f8d9fed66f3d395036ee6aa574 Service-Type = Framed-User User-Name = "anisa" Framed-MTU = 1488 State = 0xc3eeda0cc4e6c372bc5743d8d31a4433 Called-Station-Id = "B8-A3-86-92-86-B7:testconn" Calling-Station-Id = "50-1A-C5-07-FB-74" NAS-Identifier = "D-Link Access Point" NAS-Port-Type = Wireless-802.11 Connect-Info = "CONNECT 54Mbps 802.11g" EAP-Message = 0x0208002b190017030100201cc04c5980d678a0e2a80296c2270f13be39b8aff030aec8ad55be6304eb0657 NAS-IP-Address = 192.168.1.50 NAS-Port = 1 NAS-Port-Id = "STA port # 1" Mon Sep 28 18:11:55 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:11:55 2015 : Info: +group authorize { Mon Sep 28 18:11:55 2015 : Info: ++[preprocess] = ok Mon Sep 28 18:11:55 2015 : Info: ++[chap] = noop Mon Sep 28 18:11:55 2015 : Info: ++[mschap] = noop Mon Sep 28 18:11:55 2015 : Info: ++[digest] = noop Mon Sep 28 18:11:55 2015 : Info: [suffix] No '@' in User-Name = "anisa", looking up realm NULL Mon Sep 28 18:11:55 2015 : Info: [suffix] No such realm "NULL" Mon Sep 28 18:11:55 2015 : Info: ++[suffix] = noop Mon Sep 28 18:11:55 2015 : Info: [eap] EAP packet type response id 8 length 43 Mon Sep 28 18:11:55 2015 : Info: [eap] Continuing tunnel setup. Mon Sep 28 18:11:55 2015 : Info: ++[eap] = ok Mon Sep 28 18:11:55 2015 : Info: +} # group authorize = ok Mon Sep 28 18:11:55 2015 : Info: Found Auth-Type = EAP Mon Sep 28 18:11:55 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:11:55 2015 : Info: +group authenticate { Mon Sep 28 18:11:55 2015 : Info: [eap] Request found, released from the list Mon Sep 28 18:11:55 2015 : Info: [eap] EAP/peap Mon Sep 28 18:11:55 2015 : Info: [eap] processing type peap Mon Sep 28 18:11:55 2015 : Info: [peap] processing EAP-TLS Mon Sep 28 18:11:55 2015 : Info: [peap] eaptls_verify returned 7 Mon Sep 28 18:11:55 2015 : Info: [peap] Done initial handshake Mon Sep 28 18:11:55 2015 : Info: [peap] eaptls_process returned 7 Mon Sep 28 18:11:55 2015 : Info: [peap] EAPTLS_OK Mon Sep 28 18:11:55 2015 : Info: [peap] Session established. Decoding tunneled attributes. Mon Sep 28 18:11:55 2015 : Info: [peap] Peap state phase2 Mon Sep 28 18:11:55 2015 : Info: [peap] EAP type mschapv2 Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled request EAP-Message = 0x020800061a03 server { Mon Sep 28 18:11:55 2015 : Info: [peap] Setting User-Name to anisa Sending tunneled request EAP-Message = 0x020800061a03 FreeRADIUS-Proxied-To = 127.0.0.1 User-Name = "anisa" State = 0x3b6746a13a6f5c83f83cbfdedcbd78b1 server inner-tunnel { Mon Sep 28 18:11:55 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Mon Sep 28 18:11:55 2015 : Info: +group authorize { Mon Sep 28 18:11:55 2015 : Info: ++[chap] = noop Mon Sep 28 18:11:55 2015 : Info: ++[mschap] = noop Mon Sep 28 18:11:55 2015 : Info: [suffix] No '@' in User-Name = "anisa", looking up realm NULL Mon Sep 28 18:11:55 2015 : Info: [suffix] No such realm "NULL" Mon Sep 28 18:11:55 2015 : Info: ++[suffix] = noop Mon Sep 28 18:11:55 2015 : Info: ++update control { Mon Sep 28 18:11:55 2015 : Info: ++} # update control = noop Mon Sep 28 18:11:55 2015 : Info: [eap] EAP packet type response id 8 length 6 Mon Sep 28 18:11:55 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Mon Sep 28 18:11:55 2015 : Info: ++[eap] = updated Mon Sep 28 18:11:55 2015 : Info: [files] users: Matched entry anisa at line 97 Mon Sep 28 18:11:55 2015 : Info: ++[files] = ok Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{Stripped-User-Name} -> Mon Sep 28 18:11:55 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{User-Name} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] sql_set_user escaped user --> 'anisa' Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 26 Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'anisa' ORDER BY id Mon Sep 28 18:11:55 2015 : Info: [sql] User found in radcheck table Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'anisa' ORDER BY id Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'anisa' ORDER BY priority Mon Sep 28 18:11:55 2015 : Info: [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 = 'dynamic' ORDER BY id Mon Sep 28 18:11:55 2015 : Info: [sql] User found in group dynamic Mon Sep 28 18:11:55 2015 : Info: [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 = 'dynamic' ORDER BY id Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Released sql socket id: 26 Mon Sep 28 18:11:55 2015 : Info: ++[sql] = ok Mon Sep 28 18:11:55 2015 : Info: ++[expiration] = noop Mon Sep 28 18:11:55 2015 : Info: ++[logintime] = noop Mon Sep 28 18:11:55 2015 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP Mon Sep 28 18:11:55 2015 : Info: ++[pap] = noop Mon Sep 28 18:11:55 2015 : Info: +} # group authorize = updated Mon Sep 28 18:11:55 2015 : Info: Found Auth-Type = EAP Mon Sep 28 18:11:55 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Mon Sep 28 18:11:55 2015 : Info: +group authenticate { Mon Sep 28 18:11:55 2015 : Info: [eap] Request found, released from the list Mon Sep 28 18:11:55 2015 : Info: [eap] EAP/mschapv2 Mon Sep 28 18:11:55 2015 : Info: [eap] processing type mschapv2 Mon Sep 28 18:11:55 2015 : Info: [eap] Freeing handler Mon Sep 28 18:11:55 2015 : Info: ++[eap] = ok Mon Sep 28 18:11:55 2015 : Info: +} # group authenticate = ok Mon Sep 28 18:11:55 2015 : Info: # Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Mon Sep 28 18:11:55 2015 : Info: +group post-auth { Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{Stripped-User-Name} -> Mon Sep 28 18:11:55 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{User-Name} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] sql_set_user escaped user --> 'anisa' Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{User-Password} -> Mon Sep 28 18:11:55 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{Chap-Password} -> Mon Sep 28 18:11:55 2015 : Info: [sql] expand: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'anisa', '', 'Access-Accept', '2015-09-28 18:11:55') Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'anisa', '', 'Access-Accept', '2015-09-28 18:11:55') Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 25 Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Released sql socket id: 25 Mon Sep 28 18:11:55 2015 : Info: ++[sql] = ok Mon Sep 28 18:11:55 2015 : Info: +} # group post-auth = ok } # server inner-tunnel Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled reply code 2 Service-Type := Framed-User Acct-Interim-Interval := 300 MS-MPPE-Encryption-Policy = 0x00000001 MS-MPPE-Encryption-Types = 0x00000006 MS-MPPE-Send-Key = 0xbfa620e08b1e488d52de139d6ff937e5 MS-MPPE-Recv-Key = 0x64dee5827ef29d967c023a071cdde43e EAP-Message = 0x03080004 Message-Authenticator = 0x00000000000000000000000000000000 User-Name = "anisa" Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled reply RADIUS code Access-Accept Service-Type := Framed-User Acct-Interim-Interval := 300 MS-MPPE-Encryption-Policy = 0x00000001 MS-MPPE-Encryption-Types = 0x00000006 MS-MPPE-Send-Key = 0xbfa620e08b1e488d52de139d6ff937e5 MS-MPPE-Recv-Key = 0x64dee5827ef29d967c023a071cdde43e EAP-Message = 0x03080004 Message-Authenticator = 0x00000000000000000000000000000000 User-Name = "anisa" Mon Sep 28 18:11:55 2015 : Info: [peap] Tunneled authentication was successful. Mon Sep 28 18:11:55 2015 : Info: [peap] SUCCESS Mon Sep 28 18:11:55 2015 : Info: ++[eap] = handled Mon Sep 28 18:11:55 2015 : Info: +} # group authenticate = handled Sending Access-Challenge of id 8 to 192.168.1.50 port 1470 EAP-Message = 0x0109002b19001703010020106737f22f11fcfbd10498cc96e4e8aac4a5f4afcbfe9671590dca0fb2c080a9 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xc3eeda0ccbe7c372bc5743d8d31a4433 Mon Sep 28 18:11:55 2015 : Info: Finished request 8. Mon Sep 28 18:11:55 2015 : Debug: Going to the next request Mon Sep 28 18:11:55 2015 : Debug: Waking up in 3.0 seconds. rad_recv: Access-Request packet from host 192.168.1.50 port 1470, id=9, length=244 Message-Authenticator = 0x0ba8761e38d7451894d5974c2bda5be1 Service-Type = Framed-User User-Name = "anisa" Framed-MTU = 1488 State = 0xc3eeda0ccbe7c372bc5743d8d31a4433 Called-Station-Id = "B8-A3-86-92-86-B7:testconn" Calling-Station-Id = "50-1A-C5-07-FB-74" NAS-Identifier = "D-Link Access Point" NAS-Port-Type = Wireless-802.11 Connect-Info = "CONNECT 54Mbps 802.11g" EAP-Message = 0x0209002b19001703010020759b0d2b7486951db12fa7f4eff5b2e88aedbfa86e323ceeac2c40fd656b2d50 NAS-IP-Address = 192.168.1.50 NAS-Port = 1 NAS-Port-Id = "STA port # 1" Mon Sep 28 18:11:55 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:11:55 2015 : Info: +group authorize { Mon Sep 28 18:11:55 2015 : Info: ++[preprocess] = ok Mon Sep 28 18:11:55 2015 : Info: ++[chap] = noop Mon Sep 28 18:11:55 2015 : Info: ++[mschap] = noop Mon Sep 28 18:11:55 2015 : Info: ++[digest] = noop Mon Sep 28 18:11:55 2015 : Info: [suffix] No '@' in User-Name = "anisa", looking up realm NULL Mon Sep 28 18:11:55 2015 : Info: [suffix] No such realm "NULL" Mon Sep 28 18:11:55 2015 : Info: ++[suffix] = noop Mon Sep 28 18:11:55 2015 : Info: [eap] EAP packet type response id 9 length 43 Mon Sep 28 18:11:55 2015 : Info: [eap] Continuing tunnel setup. Mon Sep 28 18:11:55 2015 : Info: ++[eap] = ok Mon Sep 28 18:11:55 2015 : Info: +} # group authorize = ok Mon Sep 28 18:11:55 2015 : Info: Found Auth-Type = EAP Mon Sep 28 18:11:55 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:11:55 2015 : Info: +group authenticate { Mon Sep 28 18:11:55 2015 : Info: [eap] Request found, released from the list Mon Sep 28 18:11:55 2015 : Info: [eap] EAP/peap Mon Sep 28 18:11:55 2015 : Info: [eap] processing type peap Mon Sep 28 18:11:55 2015 : Info: [peap] processing EAP-TLS Mon Sep 28 18:11:55 2015 : Info: [peap] eaptls_verify returned 7 Mon Sep 28 18:11:55 2015 : Info: [peap] Done initial handshake Mon Sep 28 18:11:55 2015 : Info: [peap] eaptls_process returned 7 Mon Sep 28 18:11:55 2015 : Info: [peap] EAPTLS_OK Mon Sep 28 18:11:55 2015 : Info: [peap] Session established. Decoding tunneled attributes. Mon Sep 28 18:11:55 2015 : Info: [peap] Peap state send tlv success Mon Sep 28 18:11:55 2015 : Info: [peap] Received EAP-TLV response. Mon Sep 28 18:11:55 2015 : Info: [peap] Success Mon Sep 28 18:11:55 2015 : Info: [eap] Freeing handler Mon Sep 28 18:11:55 2015 : Info: ++[eap] = ok Mon Sep 28 18:11:55 2015 : Info: +} # group authenticate = ok Mon Sep 28 18:11:55 2015 : Info: # Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:11:55 2015 : Info: +group post-auth { Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{Stripped-User-Name} -> Mon Sep 28 18:11:55 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{User-Name} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] sql_set_user escaped user --> 'anisa' Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{User-Password} -> Mon Sep 28 18:11:55 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{Chap-Password} -> Mon Sep 28 18:11:55 2015 : Info: [sql] expand: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'anisa', '', 'Access-Accept', '2015-09-28 18:11:55') Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'anisa', '', 'Access-Accept', '2015-09-28 18:11:55') Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 24 Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Released sql socket id: 24 Mon Sep 28 18:11:55 2015 : Info: ++[sql] = ok Mon Sep 28 18:11:55 2015 : Info: ++[exec] = noop Mon Sep 28 18:11:55 2015 : Info: +} # group post-auth = ok Sending Access-Accept of id 9 to 192.168.1.50 port 1470 MS-MPPE-Recv-Key = 0x42efb6e0ef913216d3db461ba6cfda613405babfd84fdf31401796ad8e0e630b MS-MPPE-Send-Key = 0xacf63f04031d9623cb14e101cf636cedd674bb9635bbdec29945d12bc0c3a7cb EAP-Message = 0x03090004 Message-Authenticator = 0x00000000000000000000000000000000 User-Name = "anisa" Mon Sep 28 18:11:55 2015 : Info: Finished request 9. Mon Sep 28 18:11:55 2015 : Debug: Going to the next request Mon Sep 28 18:11:55 2015 : Debug: Waking up in 2.9 seconds. rad_recv: Accounting-Request packet from host 192.168.1.50 port 1471, id=2, length=100 Acct-Status-Type = Start Acct-Delay-Time = 0 Acct-Session-Id = "0000000018:0000000048" Acct-Authentic = RADIUS Acct-Multi-Session-Id = "anisa" User-Name = "anisa" Calling-Station-Id = "50-1a-c5-07-fb-74" NAS-IP-Address = 192.168.1.50 Mon Sep 28 18:11:57 2015 : Info: # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:11:57 2015 : Info: +group preacct { Mon Sep 28 18:11:57 2015 : Info: ++[preprocess] = ok Mon Sep 28 18:11:57 2015 : Info: [acct_unique] WARNING: Attribute NAS-Port was not found in request, unique ID MAY be inconsistent Mon Sep 28 18:11:57 2015 : Info: [acct_unique] WARNING: Attribute NAS-Identifier was not found in request, unique ID MAY be inconsistent Mon Sep 28 18:11:57 2015 : Info: [acct_unique] Hashing ',,NAS-IP-Address = 192.168.1.50,Acct-Session-Id = "0000000018:0000000048",User-Name = "anisa"' Mon Sep 28 18:11:57 2015 : Info: [acct_unique] Acct-Unique-Session-ID = "b404cb6fbd3afd18". Mon Sep 28 18:11:57 2015 : Info: ++[acct_unique] = ok Mon Sep 28 18:11:57 2015 : Info: [suffix] No '@' in User-Name = "anisa", looking up realm NULL Mon Sep 28 18:11:57 2015 : Info: [suffix] No such realm "NULL" Mon Sep 28 18:11:57 2015 : Info: ++[suffix] = noop Mon Sep 28 18:11:57 2015 : Info: ++[files] = noop Mon Sep 28 18:11:57 2015 : Info: +} # group preacct = ok Mon Sep 28 18:11:57 2015 : Info: # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:11:57 2015 : Info: +group accounting { Mon Sep 28 18:11:57 2015 : Info: [detail] expand: %{Packet-Src-IP-Address} -> 192.168.1.50 Mon Sep 28 18:11:57 2015 : Info: [detail] expand: /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d -> /usr/local/var/log/radius/radacct/192.168.1.50/detail-20150928 Mon Sep 28 18:11:57 2015 : Info: [detail] /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/192.168.1.50/detail-20150928 Mon Sep 28 18:11:57 2015 : Info: [detail] expand: %t -> Mon Sep 28 18:11:57 2015 Mon Sep 28 18:11:57 2015 : Info: ++[detail] = ok Mon Sep 28 18:11:57 2015 : Info: [sql] expand: %{Stripped-User-Name} -> Mon Sep 28 18:11:57 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:11:57 2015 : Info: [sql] expand: %{User-Name} -> anisa Mon Sep 28 18:11:57 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> anisa Mon Sep 28 18:11:57 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> anisa Mon Sep 28 18:11:57 2015 : Info: [sql] sql_set_user escaped user --> 'anisa' Mon Sep 28 18:11:57 2015 : Info: [sql] expand: %{Acct-Delay-Time} -> 0 Mon Sep 28 18:11:57 2015 : Info: [sql] expand: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress, acctinputpackets, acctoutputpackets, acctstartdelay, acctstopdelay, xascendsessionsvrkey) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', '%S', NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Prot Mon Sep 28 18:11:57 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 23 Mon Sep 28 18:11:57 2015 : Debug: rlm_sql (sql): Released sql socket id: 23 Mon Sep 28 18:11:57 2015 : Info: ++[sql] = ok Mon Sep 28 18:11:57 2015 : Info: ++[exec] = noop Mon Sep 28 18:11:57 2015 : Info: [attr_filter.accounting_response] expand: %{User-Name} -> anisa Mon Sep 28 18:11:57 2015 : Debug: attr_filter: Matched entry DEFAULT at line 12 Mon Sep 28 18:11:57 2015 : Info: ++[attr_filter.accounting_response] = updated Mon Sep 28 18:11:57 2015 : Info: +} # group accounting = updated Sending Accounting-Response of id 2 to 192.168.1.50 port 1471 Mon Sep 28 18:11:57 2015 : Info: Finished request 10. Mon Sep 28 18:11:57 2015 : Info: Cleaning up request 10 ID 2 with timestamp +98 Mon Sep 28 18:11:57 2015 : Debug: Going to the next request Mon Sep 28 18:11:57 2015 : Debug: Waking up in 1.0 seconds. Mon Sep 28 18:11:58 2015 : Info: Cleaning up request 0 ID 0 with timestamp +94 Mon Sep 28 18:11:58 2015 : Info: Cleaning up request 1 ID 1 with timestamp +94 Mon Sep 28 18:11:58 2015 : Info: Cleaning up request 2 ID 2 with timestamp +94 Mon Sep 28 18:11:58 2015 : Info: Cleaning up request 3 ID 3 with timestamp +94 Mon Sep 28 18:11:58 2015 : Info: Cleaning up request 4 ID 4 with timestamp +94 Mon Sep 28 18:11:58 2015 : Debug: Waking up in 1.8 seconds. Mon Sep 28 18:12:00 2015 : Info: Cleaning up request 5 ID 5 with timestamp +96 Mon Sep 28 18:12:00 2015 : Info: Cleaning up request 6 ID 6 with timestamp +96 Mon Sep 28 18:12:00 2015 : Info: Cleaning up request 7 ID 7 with timestamp +96 Mon Sep 28 18:12:00 2015 : Info: Cleaning up request 8 ID 8 with timestamp +96 Mon Sep 28 18:12:00 2015 : Info: Cleaning up request 9 ID 9 with timestamp +96 Mon Sep 28 18:12:00 2015 : Info: Ready to process requests. On Mon, Sep 28, 2015 at 6:53 PM, Anisa Allahdadi <anisa.alla@gmail.com> wrote:
Hi all,
There is just one NAS, and 4-5 mobile stations.
I realized that there are 2 passes for the devices to get authenticated (I guess the second one is due to checking the certificates). And I see that in the first pass, Access-Accept *contains* the Acct-Interim-Update, but the second Access-Accecpt *does not*. I'm not saying the problem is with FreeRadius, I guess it might be related to the authentication, or my certificates, or my proxy setting.
I ran radiusd -XXX and attached the output for what I got from two different users: *anisa* is the not working user and *lin* is the working user. Sorry for the long text, I did some highlights.
Thanks for the help
On Mon, Sep 28, 2015 at 5:38 PM, <A.L.M.Buxey@lboro.ac.uk> wrote:
Hi,
I don't understand you guys! All I'm saying is that one of my stations sends Interim-Updates and the others do not, so the problem shouldn't be with NAS. If you don't want to help, feel free and don't. I don't expect
why do you think the RADIUS server is the place to look? one of them sends the data, the others dont. so, are they the same make, do they have the same firmware? do they have the same configuration? a NAS does what a NAS does. look at the NAS.
alan - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html