Alive sessions in radacct table
Anisa Allahdadi
anisa.alla at gmail.com
Mon Sep 28 20:25:48 CEST 2015
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 at 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 at 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 at example.com
Mon Sep 28 18:15:08 2015 : Info: [tls] --> subject =
/C=FR/ST=Radius/O=Example Inc./CN=
lin at example.com/emailAddress=lin at example.com
Mon Sep 28 18:15:08 2015 : Info: [tls] --> issuer =
/C=FR/ST=Radius/L=Somewhere/O=Example Inc./emailAddress=
lin at 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 at 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 at 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
>>
>
>
More information about the Freeradius-Users
mailing list