Alive sessions in radacct table
Anisa Allahdadi
anisa.alla at gmail.com
Wed Sep 30 12:19:10 CEST 2015
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 at 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 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