To whom it may concern: Keep alive sessions do not work with TLS, the second run of Access-Accept does not contain Acct-Interim-Update. However TTLS works and I didn't check but PEAP will probably work as well. On Mon, Sep 28, 2015 at 7:25 PM, Anisa Allahdadi <anisa.alla@gmail.com> wrote:
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