Alive sessions in radacct table
Hi all, My FreeRADIUS is up and running. However, in 'radacct' table, there are only 'acctstarttime' and 'acctstoptime' being recorded, how about 'alive'? In the real world situation we can record Alive sessions every 10-15 min. Could anybody tell me if it is possible in FreeRADIUS as well? Many thanks Anisa
On Sep 25, 2015, at 5:47 AM, Anisa Allahdadi <anisa.alla@gmail.com> wrote:
My FreeRADIUS is up and running. However, in 'radacct' table, there are only 'acctstarttime' and 'acctstoptime' being recorded, how about 'alive'? In the real world situation we can record Alive sessions every 10-15 min. Could anybody tell me if it is possible in FreeRADIUS as well?
Yes. If the NAS sends Alive packets, the server will record them. So... check that the NAS is sending Alive packets. Alan DeKok.
Thanks Alan for your response. How should I check that? Is that somewhere in AP settings or FreeRADIUS configurations itself? Thanks Anisa On Fri, Sep 25, 2015 at 12:09 PM, Alan DeKok <aland@deployingradius.com> wrote:
On Sep 25, 2015, at 5:47 AM, Anisa Allahdadi <anisa.alla@gmail.com> wrote:
My FreeRADIUS is up and running. However, in 'radacct' table, there are only 'acctstarttime' and 'acctstoptime' being recorded, how about 'alive'? In the real world situation we can record Alive sessions every 10-15 min. Could anybody tell me if it is possible in FreeRADIUS as well?
Yes. If the NAS sends Alive packets, the server will record them.
So... check that the NAS is sending Alive packets.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Hi Alan, Did you mean interim-updates? Regards, Randeep On Fri, Sep 25, 2015 at 7:13 PM, Alan DeKok <aland@deployingradius.com> wrote:
On Sep 25, 2015, at 9:41 AM, Anisa Allahdadi <anisa.alla@gmail.com> wrote:
Thanks Alan for your response.
How should I check that? Is that somewhere in AP settings or FreeRADIUS configurations itself?
It's in the AP. That's what my message said.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- Randeep Mob: +919447831699[kerala] Mob: +919880050349[B'lore] http://twitter.com/Randeeppr http://in.linkedin.com/in/randeeppr [image: --] Randeep Raman [image: http://]about.me/Randeeppr <http://about.me/Randeeppr>
Hi Randeep, I think that's it and I found more explanation in here: https://www.ietf.org/proceedings/42/I-D/draft-ietf-radius-acct-interim-01.tx... But still don't know where to set this value. Thanks for the hint On Fri, Sep 25, 2015 at 2:47 PM, Randeep <randeep123@gmail.com> wrote:
Hi Alan,
Did you mean interim-updates?
Regards, Randeep
On Fri, Sep 25, 2015 at 7:13 PM, Alan DeKok <aland@deployingradius.com> wrote:
On Sep 25, 2015, at 9:41 AM, Anisa Allahdadi <anisa.alla@gmail.com> wrote:
Thanks Alan for your response.
How should I check that? Is that somewhere in AP settings or FreeRADIUS configurations itself?
It's in the AP. That's what my message said.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- Randeep Mob: +919447831699[kerala] Mob: +919880050349[B'lore] http://twitter.com/Randeeppr http://in.linkedin.com/in/randeeppr
[image: --] Randeep Raman [image: http://]about.me/Randeeppr <http://about.me/Randeeppr> - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Anisa, If you want Interim-Update accounting, your NAS (AP) has to support it. What AP is it? Regards, Nick
Hi Nick, It is D-link DWL-2100AP. I doubt it supports that. Is there any way we can set this attribute in Radius configuration? Thanks On Fri, Sep 25, 2015 at 3:18 PM, Nick Lowe <nick.lowe@gmail.com> wrote:
Anisa,
If you want Interim-Update accounting, your NAS (AP) has to support it. What AP is it?
Regards,
Nick - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Hi Anisa, Interim update is what NAS is sending to FreeRadius. It will be processed in accounting section and it will be written to radacct table. But you need to configure it in that to send this to radius. Check whether your nas supports this or not. And in your radreply or radgroupreply table you can specify the interval for the interim updates. Usually it will be in seconds. 50s or 300s. Regards Randeep On Fri, Sep 25, 2015 at 7:51 PM, Anisa Allahdadi <anisa.alla@gmail.com> wrote:
Hi Nick,
It is D-link DWL-2100AP. I doubt it supports that. Is there any way we can set this attribute in Radius configuration?
Thanks
On Fri, Sep 25, 2015 at 3:18 PM, Nick Lowe <nick.lowe@gmail.com> wrote:
Anisa,
If you want Interim-Update accounting, your NAS (AP) has to support it. What AP is it?
Regards,
Nick - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- Randeep Mob: +919447831699[kerala] Mob: +919880050349[B'lore] http://twitter.com/Randeeppr http://in.linkedin.com/in/randeeppr [image: --] Randeep Raman [image: http://]about.me/Randeeppr <http://about.me/Randeeppr>
Hi all, Thanks for all your helps. Eventually, I kinda solved the problem and faced new ones. First of all, I didn't change any setting in the Access Point configuration (it seems it was somehow there), but I added one line to the 'attrs' file, in the DEFAULT section: Acct-Interim-Interval <= 300 And since then, one station is sending Interim-Update requests, but not the other stations! Why is that so? This station that sends Interim-Update has the wireless connection on the Radius Server itself. Does anybody have any idea why is that so? Many thanks Anisa On Fri, Sep 25, 2015 at 3:26 PM, Randeep <randeep123@gmail.com> wrote:
Hi Anisa,
Interim update is what NAS is sending to FreeRadius. It will be processed in accounting section and it will be written to radacct table. But you need to configure it in that to send this to radius.
Check whether your nas supports this or not. And in your radreply or radgroupreply table you can specify the interval for the interim updates. Usually it will be in seconds. 50s or 300s.
Regards Randeep
On Fri, Sep 25, 2015 at 7:51 PM, Anisa Allahdadi <anisa.alla@gmail.com> wrote:
Hi Nick,
It is D-link DWL-2100AP. I doubt it supports that. Is there any way we can set this attribute in Radius configuration?
Thanks
On Fri, Sep 25, 2015 at 3:18 PM, Nick Lowe <nick.lowe@gmail.com> wrote:
Anisa,
If you want Interim-Update accounting, your NAS (AP) has to support it. What AP is it?
Regards,
Nick - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- Randeep Mob: +919447831699[kerala] Mob: +919880050349[B'lore] http://twitter.com/Randeeppr http://in.linkedin.com/in/randeeppr
[image: --] Randeep Raman [image: http://]about.me/Randeeppr <http://about.me/Randeeppr> - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Sep 28, 2015, at 5:52 AM, Anisa Allahdadi <anisa.alla@gmail.com> wrote:
First of all, I didn't change any setting in the Access Point configuration (it seems it was somehow there), but I added one line to the 'attrs' file, in the DEFAULT section: Acct-Interim-Interval <= 300
And since then, one station is sending Interim-Update requests, but not the other stations! Why is that so? This station that sends Interim-Update has the wireless connection on the Radius Server itself. Does anybody have any idea why is that so?
Because it's the fault of the NAS. Ask the NAS vendors why they don't implement Acct-Interim-Interval. As a general rule, when a NAS ignores an attribute... YOU MUST FIX THE NAS. No amount of poking the RADIUS server will cause the NAS to behave differently. Alan DeKok.
But isn't it the same NAS sending Interim-Update? My question is why only one station sends and the others not? I use just one NAS! By the way, I figured that this type of AP (DWL-2100AP) supports Acct-Interim-Interval (the newer firmwares), but I can't find any clue how to set that! On Mon, Sep 28, 2015 at 12:38 PM, Alan DeKok <aland@deployingradius.com> wrote:
On Sep 28, 2015, at 5:52 AM, Anisa Allahdadi <anisa.alla@gmail.com> wrote:
First of all, I didn't change any setting in the Access Point configuration (it seems it was somehow there), but I added one line to the 'attrs' file, in the DEFAULT section: Acct-Interim-Interval <= 300
And since then, one station is sending Interim-Update requests, but not the other stations! Why is that so? This station that sends Interim-Update has the wireless connection on the Radius Server itself. Does anybody have any idea why is that so?
Because it's the fault of the NAS. Ask the NAS vendors why they don't implement Acct-Interim-Interval.
As a general rule, when a NAS ignores an attribute... YOU MUST FIX THE NAS. No amount of poking the RADIUS server will cause the NAS to behave differently.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Sep 28, 2015, at 8:45 AM, Anisa Allahdadi <anisa.alla@gmail.com> wrote:
But isn't it the same NAS sending Interim-Update?
I have no idea. It's your network.
My question is why only one station sends and the others not? I use just one NAS!
Ask the NAS vendor. It's not a FreeRADIUS problem.
By the way, I figured that this type of AP (DWL-2100AP) supports Acct-Interim-Interval (the newer firmwares), but I can't find any clue how to set that!
Ask the NAS vendor how their product works. I can't be any more clear than that. We CANNOT HELP YOU. You MUST ASK THE VENDOR how their product works. We didn't sell you the NAS, so we can't answer questions about it. Alan DeKok.
It is my network and it has only one NAS! Thanks for being so kind and patient! Don't bother, I won't ask any further question for sure! On Mon, Sep 28, 2015 at 2:20 PM, Alan DeKok <aland@deployingradius.com> wrote:
On Sep 28, 2015, at 8:45 AM, Anisa Allahdadi <anisa.alla@gmail.com> wrote:
But isn't it the same NAS sending Interim-Update?
I have no idea. It's your network.
My question is why only one station sends and the others not? I use just one NAS!
Ask the NAS vendor. It's not a FreeRADIUS problem.
By the way, I figured that this type of AP (DWL-2100AP) supports Acct-Interim-Interval (the newer firmwares), but I can't find any clue how to set that!
Ask the NAS vendor how their product works.
I can't be any more clear than that. We CANNOT HELP YOU. You MUST ASK THE VENDOR how their product works.
We didn't sell you the NAS, so we can't answer questions about it.
Alan DeKok.
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Come off it, you're not making any effort to understand this conceptually and expecting others to do all the work for you. That's not remotely reasonable. Nick
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 anyone to help, just to be clear on this. Thank you very much! On Mon, Sep 28, 2015 at 3:04 PM, Nick Lowe <nick.lowe@gmail.com> wrote:
Come off it, you're not making any effort to understand this conceptually and expecting others to do all the work for you. That's not remotely reasonable.
Nick - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Your NAS sends the Interim-Updates, not the stations. If you are returning the same pertinent RADIUS attributes in the Access-Accept and the NAS is accounting for one but not the others, logically, it can only be the NAS. This has nothing to do with FreeRADIUS at that point. It is the NAS that performs the accounting based on its configuration or instruction it receives in the Access-Accept. Nick On Mon, Sep 28, 2015 at 3:39 PM, Anisa Allahdadi <anisa.alla@gmail.com> wrote:
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 anyone to help, just to be clear on this. Thank you very much!
On Mon, Sep 28, 2015 at 3:04 PM, Nick Lowe <nick.lowe@gmail.com> wrote:
Come off it, you're not making any effort to understand this conceptually and expecting others to do all the work for you. That's not remotely reasonable.
Nick - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Anisa, Its not the stations. Its NAS sending the interim updates. How do the other stations connect to the NAS? Hotspot?PPPoE? Regards, Randeep On Mon, Sep 28, 2015 at 8:13 PM, Nick Lowe <nick.lowe@gmail.com> wrote:
Your NAS sends the Interim-Updates, not the stations. If you are returning the same pertinent RADIUS attributes in the Access-Accept and the NAS is accounting for one but not the others, logically, it can only be the NAS. This has nothing to do with FreeRADIUS at that point. It is the NAS that performs the accounting based on its configuration or instruction it receives in the Access-Accept.
Nick
On Mon, Sep 28, 2015 at 3:39 PM, Anisa Allahdadi <anisa.alla@gmail.com> wrote:
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 anyone to help, just to be clear on this. Thank you very much!
On Mon, Sep 28, 2015 at 3:04 PM, Nick Lowe <nick.lowe@gmail.com> wrote:
Come off it, you're not making any effort to understand this conceptually and expecting others to do all the work for you. That's not remotely reasonable.
Nick - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- Randeep Mob: +919447831699[kerala] Mob: +919880050349[B'lore] http://twitter.com/Randeeppr http://in.linkedin.com/in/randeeppr [image: --] Randeep Raman [image: http://]about.me/Randeeppr <http://about.me/Randeeppr>
Randeep, The station that is working (contains Acct-Interim-Update in its Access-Accept) is the wireless connection on the RadiusServer itself (the Linux machine which is connected via ethernet to the router). The other connections are normal wireless connections (WPA/WPA2). This is the only difference. Thanks On Mon, Sep 28, 2015 at 3:45 PM, Randeep <randeep123@gmail.com> wrote:
Anisa,
Its not the stations. Its NAS sending the interim updates. How do the other stations connect to the NAS? Hotspot?PPPoE?
Regards, Randeep
On Mon, Sep 28, 2015 at 8:13 PM, Nick Lowe <nick.lowe@gmail.com> wrote:
Your NAS sends the Interim-Updates, not the stations. If you are returning the same pertinent RADIUS attributes in the Access-Accept and the NAS is accounting for one but not the others, logically, it can only be the NAS. This has nothing to do with FreeRADIUS at that point. It is the NAS that performs the accounting based on its configuration or instruction it receives in the Access-Accept.
Nick
On Mon, Sep 28, 2015 at 3:39 PM, Anisa Allahdadi <anisa.alla@gmail.com> wrote:
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 anyone to help, just to be clear on this. Thank you very much!
On Mon, Sep 28, 2015 at 3:04 PM, Nick Lowe <nick.lowe@gmail.com> wrote:
Come off it, you're not making any effort to understand this conceptually and expecting others to do all the work for you. That's not remotely reasonable.
Nick - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
-- Randeep Mob: +919447831699[kerala] Mob: +919880050349[B'lore] http://twitter.com/Randeeppr http://in.linkedin.com/in/randeeppr
[image: --] Randeep Raman [image: http://]about.me/Randeeppr <http://about.me/Randeeppr> - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Have you actually looked in Wireshark at what you see on port 1812 (auth) and 1813 (accounting) coming in to and out of the RADIUS server? Nick
You could also likely use tcpdump with verbosity enabled to debug this. I've done this in the past when writing PHP radius client hooks to see what accounting data I actually sent. example - tcpdump -i eth0 -vvvn port 1812 Brock -----Original Message----- From: Freeradius-Users [mailto:freeradius-users-bounces+brock=corp.digitalpath.net@lists.freeradius.org] On Behalf Of Nick Lowe Sent: Monday, September 28, 2015 8:03 AM To: FreeRadius users mailing list Subject: Re: Alive sessions in radacct table Have you actually looked in Wireshark at what you see on port 1812 (auth) and 1813 (accounting) coming in to and out of the RADIUS server? Nick - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Well I believe accounting data comes on port 1813 . Secondly i guess enabling detail file which can have accounting details would be more easier to read than using tcpdump. Regards Vijay A. On Sep 28, 2015 10:01 PM, "Brock Eastman" <brock@corp.digitalpath.net> wrote:
You could also likely use tcpdump with verbosity enabled to debug this. I've done this in the past when writing PHP radius client hooks to see what accounting data I actually sent.
example -
tcpdump -i eth0 -vvvn port 1812
Brock
-----Original Message----- From: Freeradius-Users [mailto:freeradius-users-bounces+brock= corp.digitalpath.net@lists.freeradius.org] On Behalf Of Nick Lowe Sent: Monday, September 28, 2015 8:03 AM To: FreeRadius users mailing list Subject: Re: Alive sessions in radacct table
Have you actually looked in Wireshark at what you see on port 1812 (auth) and 1813 (accounting) coming in to and out of the RADIUS server?
Nick - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
- List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
On Sep 28, 2015, at 10:39 AM, Anisa Allahdadi <anisa.alla@gmail.com> wrote:
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.
You're wrong. If you're going to ask questions and then argue with the answers, you should not be asking questions on this list.
If you don't want to help, feel free and don't. I don't expect anyone to help, just to be clear on this.
You will stop complaining, or you will be unsubscribed from the list, and permanently banned. This is your only warning. Alan DeKok.
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
Hi all, There is just one NAS, and 4-5 mobile stations. I realized that there are 2 passes for the devices to get authenticated (I guess the second one is due to checking the certificates). And I see that in the first pass, Access-Accept *contains* the Acct-Interim-Update, but the second Access-Accecpt *does not*. I'm not saying the problem is with FreeRadius, I guess it might be related to the authentication, or my certificates, or my proxy setting. I ran radiusd -XXX and attached the output for what I got from two different users: *anisa* is the not working user and *lin* is the working user. Sorry for the long text, I did some highlights. Thanks for the help On Mon, Sep 28, 2015 at 5:38 PM, <A.L.M.Buxey@lboro.ac.uk> wrote:
Hi,
I don't understand you guys! All I'm saying is that one of my stations sends Interim-Updates and the others do not, so the problem shouldn't be with NAS. If you don't want to help, feel free and don't. I don't expect
why do you think the RADIUS server is the place to look? one of them sends the data, the others dont. so, are they the same make, do they have the same firmware? do they have the same configuration? a NAS does what a NAS does. look at the NAS.
alan - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
Copied in here: Lin: acceess5f7710d57421263eee182648807ba62a350203010001a38201323082012e301d0603551d0e04160414a03774d8725132d320078de9b79f287a932dbb313081c60603551d230481be3081bb8014a03774d8725132d320078de9b79f287a932dbb31a18197a48194308191310b3009060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e311e301c06092a864886f70d0109 EAP-Message = 0x01160f6c696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f72697479820900953acc864d06fcaf300c0603551d13040530030101ff30360603551d1f042f302d302ba029a0278625687474703a2f2f7777772e6578616d706c652e636f6d2f6578616d706c655f63612e63726c300d06092a864886f70d01010b05000381810096d9c719eca5c64ddfb7b3bac54ebd6356850c3aa3e0b7151857dcdf5cc6d2b1ffd1f0c9d6dfa4b54f9fee7f58e8ac99b16ad14217064be2a4fb2db683f640fd5d331cf1e714bb19be54d3581949100b7ad051714be5c6a332d004b9c96d2f EAP-Message = 0xbe89c214a17767ea2ad030de4f430984f9e53daa448b464748a99ab846e132c6b916030100cb0c0000c70300174104aa58bd6268496ed70e16953f6a601778c86f0a98212e99ab2ad97845634caaa8424d10fffcc32bc84c1b2c3f769ccb6f5d987d4766b5d834c0561f136e735e2f008027413db279d297803f3560639d009fdc84d884e4d8fd17cfd6474f8c76d0b4595dc97879e57543ffcdc6c63e75dfe96b97c3bb33d601aa375919dddae503423911d012b6d0c1f0fd8fd139ee45abef8fee7dd867deff19bb6f11317a3c48ba95a5d3cfaa0f8633bbe36e01880a6f40fe1f975a6948bcf950e55aa6b769d95f4316030100a40d00009c030102 EAP-Message = 0x4000960094308191310b3009 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x0452373b064d3acf9b22daa195414c61 Mon Sep 28 18:15:08 2015 : Info: Finished request 2. Mon Sep 28 18:15:08 2015 : Debug: Going to the next request Mon Sep 28 18:15:08 2015 : Debug: Waking up in 4.9 seconds. rad_recv: Access-Request packet from host 192.168.1.50 port 1111, id=31, length=205 Message-Authenticator = 0x2b7e24d764a9126ba0564b4cb081ec03 Service-Type = Framed-User User-Name = "lin" Framed-MTU = 1488 State = 0x0452373b064d3acf9b22daa195414c61 Called-Station-Id = "B8-A3-86-92-86-B7:testconn" Calling-Station-Id = "EC-55-F9-2A-CC-86" NAS-Identifier = "D-Link Access Point" NAS-Port-Type = Wireless-802.11 Connect-Info = "CONNECT 54Mbps 802.11g" EAP-Message = 0x021f00060d00 NAS-IP-Address = 192.168.1.50 NAS-Port = 5 NAS-Port-Id = "STA port # 5" Mon Sep 28 18:15:08 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:15:08 2015 : Info: +group authorize { Mon Sep 28 18:15:08 2015 : Info: ++[preprocess] = ok Mon Sep 28 18:15:08 2015 : Info: ++[chap] = noop Mon Sep 28 18:15:08 2015 : Info: ++[mschap] = noop Mon Sep 28 18:15:08 2015 : Info: ++[digest] = noop Mon Sep 28 18:15:08 2015 : Info: [suffix] No '@' in User-Name = "lin", looking up realm NULL Mon Sep 28 18:15:08 2015 : Info: [suffix] No such realm "NULL" Mon Sep 28 18:15:08 2015 : Info: ++[suffix] = noop Mon Sep 28 18:15:08 2015 : Info: [eap] EAP packet type response id 31 length 6 Mon Sep 28 18:15:08 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Mon Sep 28 18:15:08 2015 : Info: ++[eap] = updated Mon Sep 28 18:15:08 2015 : Info: [files] users: Matched entry lin at line 123 Mon Sep 28 18:15:08 2015 : Info: ++[files] = ok Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{Stripped-User-Name} -> Mon Sep 28 18:15:08 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{User-Name} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] sql_set_user escaped user --> 'lin' Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 27 Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'lin' ORDER BY id Mon Sep 28 18:15:08 2015 : Info: [sql] User found in radcheck table Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'lin' ORDER BY id Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'lin' ORDER BY priority Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'dynamic' ORDER BY id Mon Sep 28 18:15:08 2015 : Info: [sql] User found in group dynamic Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'dynamic' ORDER BY id Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Released sql socket id: 27 Mon Sep 28 18:15:08 2015 : Info: ++[sql] = ok Mon Sep 28 18:15:08 2015 : Info: ++[expiration] = noop Mon Sep 28 18:15:08 2015 : Info: ++[logintime] = noop Mon Sep 28 18:15:08 2015 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP Mon Sep 28 18:15:08 2015 : Info: ++[pap] = noop Mon Sep 28 18:15:08 2015 : Info: +} # group authorize = updated Mon Sep 28 18:15:08 2015 : Info: Found Auth-Type = EAP Mon Sep 28 18:15:08 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:15:08 2015 : Info: +group authenticate { Mon Sep 28 18:15:08 2015 : Info: [eap] Request found, released from the list Mon Sep 28 18:15:08 2015 : Info: [eap] EAP/tls Mon Sep 28 18:15:08 2015 : Info: [eap] processing type tls Mon Sep 28 18:15:08 2015 : Info: [tls] Authenticate Mon Sep 28 18:15:08 2015 : Info: [tls] processing EAP-TLS Mon Sep 28 18:15:08 2015 : Info: [tls] Received TLS ACK Mon Sep 28 18:15:08 2015 : Info: [tls] ACK handshake fragment handler Mon Sep 28 18:15:08 2015 : Info: [tls] eaptls_verify returned 1 Mon Sep 28 18:15:08 2015 : Info: [tls] eaptls_process returned 13 Mon Sep 28 18:15:08 2015 : Info: ++[eap] = handled Mon Sep 28 18:15:08 2015 : Info: +} # group authenticate = handled Sending Access-Challenge of id 31 to 192.168.1.50 port 1111 Framed-IP-Address := 192.168.1.111 Service-Type := Framed-User Acct-Interim-Interval := 300 EAP-Message = 0x0120009b0d800000087d060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e311e301c06092a864886f70d010901160f6c696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f726974790e000000 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x0452373b07723acf9b22daa195414c61 Mon Sep 28 18:15:08 2015 : Info: Finished request 3. Mon Sep 28 18:15:08 2015 : Debug: Going to the next request Mon Sep 28 18:15:08 2015 : Debug: Waking up in 4.9 seconds. rad_recv: Access-Request packet from host 192.168.1.50 port 1111, id=32, length=1519 Message-Authenticator = 0xf72b1041d2b3d855f3fb77c1404866b5 Service-Type = Framed-User User-Name = "lin" Framed-MTU = 1488 State = 0x0452373b07723acf9b22daa195414c61 Called-Station-Id = "B8-A3-86-92-86-B7:testconn" Calling-Station-Id = "EC-55-F9-2A-CC-86" NAS-Identifier = "D-Link Access Point" NAS-Port-Type = Wireless-802.11 Connect-Info = "CONNECT 54Mbps 802.11g" EAP-Message = 0x0220051e0dc0000007c716030106b10b0006ad0006aa0002ca308202c63082022fa003020102020104300d06092a864886f70d01010b0500308191310b3009060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e311e301c06092a864886f70d010901160f6c696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f72697479301e170d3135303932313134343631385a170d3136303932303134343631385a306f310b3009060355040613024652310f EAP-Message = 0x300d0603550408130652616469757331153013060355040a130c4578616d706c6520496e632e311830160603550403140f6c696e406578616d706c652e636f6d311e301c06092a864886f70d010901160f6c696e406578616d706c652e636f6d30819f300d06092a864886f70d010101050003818d0030818902818100e69d6bb25f13d2b6947eb4ac90f5826d9b69a2dbdba314f66d5b195b6a2ff30dcdefe39a7592ca935d3762b0e19e78c70c5f34994c8b53d1eb771672061adbf69bd6628b7692316ea423cc45a8814abfc88b94349bbec2296a87684dda1f82d442507d850c1c46eb929d0cc9b6f78b0eb9d87e1030fbd98a5c05b004666b6d8b EAP-Message = 0x0203010001a34f304d30130603551d25040c300a06082b0601050507030230360603551d1f042f302d302ba029a0278625687474703a2f2f7777772e6578616d706c652e636f6d2f6578616d706c655f63612e63726c300d06092a864886f70d01010b050003818100066a5a7745b713bb8560c5544a2475c8c1c7dfc12562462e40a63c4b31429b32f01e43121ef0832e3ceab27b80bfacc69327f1a4ef64291977f1bb756c32a40dbe41f4a7c211c2895487cebd0501feb42cf60bd4dd5181f43117196675fa8897193e494f9ed8313b7ce84ab2649bbbbcc845b4f72752d90220ddd29b4202eec10003da308203d63082033fa00302010202090095 EAP-Message = 0x3acc864d06fcaf300d06092a864886f70d01010b0500308191310b3009060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e311e301c06092a864886f70d010901160f6c696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f72697479301e170d3135303932313134343530385a170d3136303932303134343530385a308191310b3009060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865 EAP-Message = 0x726531153013060355040a130c4578616d706c6520496e632e311e301c06092a864886f70d010901160f6c696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f7269747930819f300d06092a864886f70d010101050003818d0030818902818100f309afd4d9180f80257d3479b73786a195fd036f97d8be49339135c7b01aeb36a2e8d1ef13fbcf7d06a64395a884d9afa73aa3150c396688aea76d851f4b797b10f3cf5111fa817406fb0b569dcef28b2bdc26fe315311cfc8882e291b66bbc4cedba308b619f3cc59737470d848445f7710d57421263eee182648807ba62a EAP-Message = 0x350203010001a38201323082012e301d0603551d0e04160414a03774d8725132d320078de9b79f287a932dbb31 NAS-IP-Address = 192.168.1.50 NAS-Port = 5 NAS-Port-Id = "STA port # 5" Mon Sep 28 18:15:08 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:15:08 2015 : Info: +group authorize { Mon Sep 28 18:15:08 2015 : Info: ++[preprocess] = ok Mon Sep 28 18:15:08 2015 : Info: ++[chap] = noop Mon Sep 28 18:15:08 2015 : Info: ++[mschap] = noop Mon Sep 28 18:15:08 2015 : Info: ++[digest] = noop Mon Sep 28 18:15:08 2015 : Info: [suffix] No '@' in User-Name = "lin", looking up realm NULL Mon Sep 28 18:15:08 2015 : Info: [suffix] No such realm "NULL" Mon Sep 28 18:15:08 2015 : Info: ++[suffix] = noop Mon Sep 28 18:15:08 2015 : Info: [eap] EAP packet type response id 32 length 253 Mon Sep 28 18:15:08 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Mon Sep 28 18:15:08 2015 : Info: ++[eap] = updated Mon Sep 28 18:15:08 2015 : Info: [files] users: Matched entry lin at line 123 Mon Sep 28 18:15:08 2015 : Info: ++[files] = ok Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{Stripped-User-Name} -> Mon Sep 28 18:15:08 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{User-Name} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] sql_set_user escaped user --> 'lin' Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 26 Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'lin' ORDER BY id Mon Sep 28 18:15:08 2015 : Info: [sql] User found in radcheck table Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'lin' ORDER BY id Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'lin' ORDER BY priority Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'dynamic' ORDER BY id Mon Sep 28 18:15:08 2015 : Info: [sql] User found in group dynamic Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'dynamic' ORDER BY id Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Released sql socket id: 26 Mon Sep 28 18:15:08 2015 : Info: ++[sql] = ok Mon Sep 28 18:15:08 2015 : Info: ++[expiration] = noop Mon Sep 28 18:15:08 2015 : Info: ++[logintime] = noop Mon Sep 28 18:15:08 2015 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP Mon Sep 28 18:15:08 2015 : Info: ++[pap] = noop Mon Sep 28 18:15:08 2015 : Info: +} # group authorize = updated Mon Sep 28 18:15:08 2015 : Info: Found Auth-Type = EAP Mon Sep 28 18:15:08 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:15:08 2015 : Info: +group authenticate { Mon Sep 28 18:15:08 2015 : Info: [eap] Request found, released from the list Mon Sep 28 18:15:08 2015 : Info: [eap] EAP/tls Mon Sep 28 18:15:08 2015 : Info: [eap] processing type tls Mon Sep 28 18:15:08 2015 : Info: [tls] Authenticate Mon Sep 28 18:15:08 2015 : Info: [tls] processing EAP-TLS Mon Sep 28 18:15:08 2015 : Debug: TLS Length 1991 Mon Sep 28 18:15:08 2015 : Info: [tls] Received EAP-TLS First Fragment of the message Mon Sep 28 18:15:08 2015 : Info: [tls] eaptls_verify returned 9 Mon Sep 28 18:15:08 2015 : Info: [tls] eaptls_process returned 13 Mon Sep 28 18:15:08 2015 : Info: ++[eap] = handled Mon Sep 28 18:15:08 2015 : Info: +} # group authenticate = handled Sending Access-Challenge of id 32 to 192.168.1.50 port 1111 Framed-IP-Address := 192.168.1.111 Service-Type := Framed-User Acct-Interim-Interval := 300 EAP-Message = 0x012100060d00 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x0452373b00733acf9b22daa195414c61 Mon Sep 28 18:15:08 2015 : Info: Finished request 4. Mon Sep 28 18:15:08 2015 : Debug: Going to the next request Mon Sep 28 18:15:08 2015 : Debug: Waking up in 4.9 seconds. rad_recv: Access-Request packet from host 192.168.1.50 port 1111, id=33, length=900 Message-Authenticator = 0xaf7d00e343341dd0272004d8497a4774 Service-Type = Framed-User User-Name = "lin" Framed-MTU = 1488 State = 0x0452373b00733acf9b22daa195414c61 Called-Station-Id = "B8-A3-86-92-86-B7:testconn" Calling-Station-Id = "EC-55-F9-2A-CC-86" NAS-Identifier = "D-Link Access Point" NAS-Port-Type = Wireless-802.11 Connect-Info = "CONNECT 54Mbps 802.11g" EAP-Message = 0x022102b90d003081c60603551d230481be3081bb8014a03774d8725132d320078de9b79f287a932dbb31a18197a48194308191310b3009060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e311e301c06092a864886f70d010901160f6c696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f72697479820900953acc864d06fcaf300c0603551d13040530030101ff30360603551d1f042f302d302ba029a0278625687474703a2f2f7777772e6578 EAP-Message = 0x616d706c652e636f6d2f6578616d706c655f63612e63726c300d06092a864886f70d01010b05000381810096d9c719eca5c64ddfb7b3bac54ebd6356850c3aa3e0b7151857dcdf5cc6d2b1ffd1f0c9d6dfa4b54f9fee7f58e8ac99b16ad14217064be2a4fb2db683f640fd5d331cf1e714bb19be54d3581949100b7ad051714be5c6a332d004b9c96d2fbe89c214a17767ea2ad030de4f430984f9e53daa448b464748a99ab846e132c6b916030100461000004241048bd7c69292592488d8102295acb943d161ffb84be68ffc183c2d3a316ab63de0701053bf7c13f25129d365cdb99dfc74ca37b75a7afbb33074a180aaab40d10916030100860f00 EAP-Message = 0x0082008084f396947106198627824d622b5db60eac3ad4195c132781f79e6b403ec760d8bb74b0e7f32ecf78584d6021296ebed3746734e79aeddea8d8ab7902e0a636706ed6306e0b75fe9691908f4d327166fd74f99851cb03c2185a5999bd51ab4d1a03aa8addd90b07a62aa9548167300117c6db54a161b914d6dc33dea1d9dd64561403010001011603010030043441932a96e3f2d769f4928d4423eb5bc393e425a82ce0a2d811250ff08967ef0de002934be36c7fb3c055323161a9 NAS-IP-Address = 192.168.1.50 NAS-Port = 5 NAS-Port-Id = "STA port # 5" Mon Sep 28 18:15:08 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:15:08 2015 : Info: +group authorize { Mon Sep 28 18:15:08 2015 : Info: ++[preprocess] = ok Mon Sep 28 18:15:08 2015 : Info: ++[chap] = noop Mon Sep 28 18:15:08 2015 : Info: ++[mschap] = noop Mon Sep 28 18:15:08 2015 : Info: ++[digest] = noop Mon Sep 28 18:15:08 2015 : Info: [suffix] No '@' in User-Name = "lin", looking up realm NULL Mon Sep 28 18:15:08 2015 : Info: [suffix] No such realm "NULL" Mon Sep 28 18:15:08 2015 : Info: ++[suffix] = noop Mon Sep 28 18:15:08 2015 : Info: [eap] EAP packet type response id 33 length 253 Mon Sep 28 18:15:08 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Mon Sep 28 18:15:08 2015 : Info: ++[eap] = updated Mon Sep 28 18:15:08 2015 : Info: [files] users: Matched entry lin at line 123 Mon Sep 28 18:15:08 2015 : Info: ++[files] = ok Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{Stripped-User-Name} -> Mon Sep 28 18:15:08 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{User-Name} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] sql_set_user escaped user --> 'lin' Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 25 Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'lin' ORDER BY id Mon Sep 28 18:15:08 2015 : Info: [sql] User found in radcheck table Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'lin' ORDER BY id Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'lin' ORDER BY priority Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'dynamic' ORDER BY id Mon Sep 28 18:15:08 2015 : Info: [sql] User found in group dynamic Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'dynamic' ORDER BY id Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Released sql socket id: 25 Mon Sep 28 18:15:08 2015 : Info: ++[sql] = ok Mon Sep 28 18:15:08 2015 : Info: ++[expiration] = noop Mon Sep 28 18:15:08 2015 : Info: ++[logintime] = noop Mon Sep 28 18:15:08 2015 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP Mon Sep 28 18:15:08 2015 : Info: ++[pap] = noop Mon Sep 28 18:15:08 2015 : Info: +} # group authorize = updated Mon Sep 28 18:15:08 2015 : Info: Found Auth-Type = EAP Mon Sep 28 18:15:08 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:15:08 2015 : Info: +group authenticate { Mon Sep 28 18:15:08 2015 : Info: [eap] Request found, released from the list Mon Sep 28 18:15:08 2015 : Info: [eap] EAP/tls Mon Sep 28 18:15:08 2015 : Info: [eap] processing type tls Mon Sep 28 18:15:08 2015 : Info: [tls] Authenticate Mon Sep 28 18:15:08 2015 : Info: [tls] processing EAP-TLS Mon Sep 28 18:15:08 2015 : Info: [tls] eaptls_verify returned 7 Mon Sep 28 18:15:08 2015 : Info: [tls] Done initial handshake Mon Sep 28 18:15:08 2015 : Info: [tls] <<< TLS 1.0 Handshake [length 06b1], Certificate Mon Sep 28 18:15:08 2015 : Info: [tls] chain-depth=1, Mon Sep 28 18:15:08 2015 : Info: [tls] error=0 Mon Sep 28 18:15:08 2015 : Info: [tls] --> User-Name = lin Mon Sep 28 18:15:08 2015 : Info: [tls] --> BUF-Name = Example Certificate Authority Mon Sep 28 18:15:08 2015 : Info: [tls] --> subject = /C=FR/ST=Radius/L=Somewhere/O=Example Inc./emailAddress= lin@example.com/CN=Example Certificate Authority Mon Sep 28 18:15:08 2015 : Info: [tls] --> issuer = /C=FR/ST=Radius/L=Somewhere/O=Example Inc./emailAddress= lin@example.com/CN=Example Certificate Authority Mon Sep 28 18:15:08 2015 : Info: [tls] --> verify return:1 TLS-Client-Cert-X509v3-Extended-Key-Usage += "TLS Web Client Authentication" Mon Sep 28 18:15:08 2015 : Info: [tls] chain-depth=0, Mon Sep 28 18:15:08 2015 : Info: [tls] error=0 Mon Sep 28 18:15:08 2015 : Info: [tls] --> User-Name = lin Mon Sep 28 18:15:08 2015 : Info: [tls] --> BUF-Name = lin@example.com Mon Sep 28 18:15:08 2015 : Info: [tls] --> subject = /C=FR/ST=Radius/O=Example Inc./CN= lin@example.com/emailAddress=lin@example.com Mon Sep 28 18:15:08 2015 : Info: [tls] --> issuer = /C=FR/ST=Radius/L=Somewhere/O=Example Inc./emailAddress= lin@example.com/CN=Example Certificate Authority Mon Sep 28 18:15:08 2015 : Info: [tls] --> verify return:1 Mon Sep 28 18:15:08 2015 : Info: [tls] TLS_accept: SSLv3 read client certificate A Mon Sep 28 18:15:08 2015 : Info: [tls] <<< TLS 1.0 Handshake [length 0046], ClientKeyExchange Mon Sep 28 18:15:08 2015 : Info: [tls] TLS_accept: SSLv3 read client key exchange A Mon Sep 28 18:15:08 2015 : Info: [tls] <<< TLS 1.0 Handshake [length 0086], CertificateVerify Mon Sep 28 18:15:08 2015 : Info: [tls] TLS_accept: SSLv3 read certificate verify A Mon Sep 28 18:15:08 2015 : Info: [tls] <<< TLS 1.0 ChangeCipherSpec [length 0001] Mon Sep 28 18:15:08 2015 : Info: [tls] <<< TLS 1.0 Handshake [length 0010], Finished Mon Sep 28 18:15:08 2015 : Info: [tls] TLS_accept: SSLv3 read finished A Mon Sep 28 18:15:08 2015 : Info: [tls] >>> TLS 1.0 ChangeCipherSpec [length 0001] Mon Sep 28 18:15:08 2015 : Info: [tls] TLS_accept: SSLv3 write change cipher spec A Mon Sep 28 18:15:08 2015 : Info: [tls] >>> TLS 1.0 Handshake [length 0010], Finished Mon Sep 28 18:15:08 2015 : Info: [tls] TLS_accept: SSLv3 write finished A Mon Sep 28 18:15:08 2015 : Info: [tls] TLS_accept: SSLv3 flush data Mon Sep 28 18:15:08 2015 : Info: [tls] (other): SSL negotiation finished successfully Mon Sep 28 18:15:08 2015 : Debug: SSL Connection Established Mon Sep 28 18:15:08 2015 : Info: [tls] eaptls_process returned 13 Mon Sep 28 18:15:08 2015 : Info: ++[eap] = handled Mon Sep 28 18:15:08 2015 : Info: +} # group authenticate = handled Sending Access-Challenge of id 33 to 192.168.1.50 port 1111 Framed-IP-Address := 192.168.1.111 Service-Type := Framed-User Acct-Interim-Interval := 300 EAP-Message = 0x012200450d800000003b1403010001011603010030a7ab9f1bcecbf88696a57789c86619fb0ed0466ac2a9c5431bbc6f6864d50a9555256c85fa50c3f0c1e47b84d0a9db1f Message-Authenticator = 0x00000000000000000000000000000000 State = 0x0452373b01703acf9b22daa195414c61 Mon Sep 28 18:15:08 2015 : Info: Finished request 5. Mon Sep 28 18:15:08 2015 : Debug: Going to the next request Mon Sep 28 18:15:08 2015 : Debug: Waking up in 4.9 seconds. rad_recv: Access-Request packet from host 192.168.1.50 port 1111, id=34, length=205 Message-Authenticator = 0xcbd99f506ca47b9960390bb23f413c91 Service-Type = Framed-User User-Name = "lin" Framed-MTU = 1488 State = 0x0452373b01703acf9b22daa195414c61 Called-Station-Id = "B8-A3-86-92-86-B7:testconn" Calling-Station-Id = "EC-55-F9-2A-CC-86" NAS-Identifier = "D-Link Access Point" NAS-Port-Type = Wireless-802.11 Connect-Info = "CONNECT 54Mbps 802.11g" EAP-Message = 0x022200060d00 NAS-IP-Address = 192.168.1.50 NAS-Port = 5 NAS-Port-Id = "STA port # 5" Mon Sep 28 18:15:08 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:15:08 2015 : Info: +group authorize { Mon Sep 28 18:15:08 2015 : Info: ++[preprocess] = ok Mon Sep 28 18:15:08 2015 : Info: ++[chap] = noop Mon Sep 28 18:15:08 2015 : Info: ++[mschap] = noop Mon Sep 28 18:15:08 2015 : Info: ++[digest] = noop Mon Sep 28 18:15:08 2015 : Info: [suffix] No '@' in User-Name = "lin", looking up realm NULL Mon Sep 28 18:15:08 2015 : Info: [suffix] No such realm "NULL" Mon Sep 28 18:15:08 2015 : Info: ++[suffix] = noop Mon Sep 28 18:15:08 2015 : Info: [eap] EAP packet type response id 34 length 6 Mon Sep 28 18:15:08 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Mon Sep 28 18:15:08 2015 : Info: ++[eap] = updated Mon Sep 28 18:15:08 2015 : Info: [files] users: Matched entry lin at line 123 Mon Sep 28 18:15:08 2015 : Info: ++[files] = ok Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{Stripped-User-Name} -> Mon Sep 28 18:15:08 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{User-Name} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] sql_set_user escaped user --> 'lin' Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 24 Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'lin' ORDER BY id Mon Sep 28 18:15:08 2015 : Info: [sql] User found in radcheck table Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'lin' ORDER BY id Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'lin' ORDER BY priority Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'dynamic' ORDER BY id Mon Sep 28 18:15:08 2015 : Info: [sql] User found in group dynamic Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'dynamic' ORDER BY id Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Released sql socket id: 24 Mon Sep 28 18:15:08 2015 : Info: ++[sql] = ok Mon Sep 28 18:15:08 2015 : Info: ++[expiration] = noop Mon Sep 28 18:15:08 2015 : Info: ++[logintime] = noop Mon Sep 28 18:15:08 2015 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP Mon Sep 28 18:15:08 2015 : Info: ++[pap] = noop Mon Sep 28 18:15:08 2015 : Info: +} # group authorize = updated Mon Sep 28 18:15:08 2015 : Info: Found Auth-Type = EAP Mon Sep 28 18:15:08 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:15:08 2015 : Info: +group authenticate { Mon Sep 28 18:15:08 2015 : Info: [eap] Request found, released from the list Mon Sep 28 18:15:08 2015 : Info: [eap] EAP/tls Mon Sep 28 18:15:08 2015 : Info: [eap] processing type tls Mon Sep 28 18:15:08 2015 : Info: [tls] Authenticate Mon Sep 28 18:15:08 2015 : Info: [tls] processing EAP-TLS Mon Sep 28 18:15:08 2015 : Info: [tls] Received TLS ACK Mon Sep 28 18:15:08 2015 : Info: [tls] ACK handshake is finished Mon Sep 28 18:15:08 2015 : Info: [tls] eaptls_verify returned 3 Mon Sep 28 18:15:08 2015 : Info: [tls] eaptls_process returned 3 Mon Sep 28 18:15:08 2015 : Info: [tls] Adding user data to cached session Mon Sep 28 18:15:08 2015 : Info: [eap] Freeing handler Mon Sep 28 18:15:08 2015 : Info: ++[eap] = ok Mon Sep 28 18:15:08 2015 : Info: +} # group authenticate = ok Mon Sep 28 18:15:08 2015 : Info: # Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:15:08 2015 : Info: +group post-auth { Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{Stripped-User-Name} -> Mon Sep 28 18:15:08 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{User-Name} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> lin Mon Sep 28 18:15:08 2015 : Info: [sql] sql_set_user escaped user --> 'lin' Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{User-Password} -> Mon Sep 28 18:15:08 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{Chap-Password} -> Mon Sep 28 18:15:08 2015 : Info: [sql] expand: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'lin', '', 'Access-Accept', '2015-09-28 18:15:08') Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'lin', '', 'Access-Accept', '2015-09-28 18:15:08') Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 23 Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Released sql socket id: 23 Mon Sep 28 18:15:08 2015 : Info: ++[sql] = ok Mon Sep 28 18:15:08 2015 : Info: ++[exec] = noop Mon Sep 28 18:15:08 2015 : Info: +} # group post-auth = ok Sending Access-Accept of id 34 to 192.168.1.50 port 1111 Framed-IP-Address := 192.168.1.111 Service-Type := Framed-User Acct-Interim-Interval := 300 MS-MPPE-Recv-Key = 0x5169f84f16f190a14650f49720fd76765fcac67faec4553a6adfa63295d04926 MS-MPPE-Send-Key = 0xf998605b6a1c35fcf47e304754e84708f01b0b42941170086b1f108270084ab0 EAP-Message = 0x03220004 Message-Authenticator = 0x00000000000000000000000000000000 User-Name = "lin" Mon Sep 28 18:15:08 2015 : Info: Finished request 6. Mon Sep 28 18:15:08 2015 : Debug: Going to the next request Mon Sep 28 18:15:08 2015 : Debug: Waking up in 4.8 seconds. rad_recv: Accounting-Request packet from host 192.168.1.50 port 1473, id=104, length=96 Acct-Status-Type = Start Acct-Delay-Time = 0 Acct-Session-Id = "0000000018:0000000049" Acct-Authentic = RADIUS Acct-Multi-Session-Id = "lin" User-Name = "lin" Calling-Station-Id = "ec-55-f9-2a-cc-86" NAS-IP-Address = 192.168.1.50 Mon Sep 28 18:15:09 2015 : Info: # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:15:09 2015 : Info: +group preacct { Mon Sep 28 18:15:09 2015 : Info: ++[preprocess] = ok Mon Sep 28 18:15:09 2015 : Info: [acct_unique] WARNING: Attribute NAS-Port was not found in request, unique ID MAY be inconsistent Mon Sep 28 18:15:09 2015 : Info: [acct_unique] WARNING: Attribute NAS-Identifier was not found in request, unique ID MAY be inconsistent Mon Sep 28 18:15:09 2015 : Info: [acct_unique] Hashing ',,NAS-IP-Address = 192.168.1.50,Acct-Session-Id = "0000000018:0000000049",User-Name = "lin"' Mon Sep 28 18:15:09 2015 : Info: [acct_unique] Acct-Unique-Session-ID = "0bdf67000ebbc82f". Mon Sep 28 18:15:09 2015 : Info: ++[acct_unique] = ok Mon Sep 28 18:15:09 2015 : Info: [suffix] No '@' in User-Name = "lin", looking up realm NULL Mon Sep 28 18:15:09 2015 : Info: [suffix] No such realm "NULL" Mon Sep 28 18:15:09 2015 : Info: ++[suffix] = noop Mon Sep 28 18:15:09 2015 : Info: ++[files] = noop Mon Sep 28 18:15:09 2015 : Info: +} # group preacct = ok Mon Sep 28 18:15:09 2015 : Info: # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:15:09 2015 : Info: +group accounting { Mon Sep 28 18:15:09 2015 : Info: [detail] expand: %{Packet-Src-IP-Address} -> 192.168.1.50 Mon Sep 28 18:15:09 2015 : Info: [detail] expand: /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d -> /usr/local/var/log/radius/radacct/192.168.1.50/detail-20150928 Mon Sep 28 18:15:09 2015 : Info: [detail] /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/192.168.1.50/detail-20150928 Mon Sep 28 18:15:09 2015 : Info: [detail] expand: %t -> Mon Sep 28 18:15:09 2015 Mon Sep 28 18:15:09 2015 : Info: ++[detail] = ok Mon Sep 28 18:15:09 2015 : Info: [sql] expand: %{Stripped-User-Name} -> Mon Sep 28 18:15:09 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:15:09 2015 : Info: [sql] expand: %{User-Name} -> lin Mon Sep 28 18:15:09 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> lin Mon Sep 28 18:15:09 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> lin Mon Sep 28 18:15:09 2015 : Info: [sql] sql_set_user escaped user --> 'lin' Mon Sep 28 18:15:09 2015 : Info: [sql] expand: %{Acct-Delay-Time} -> 0 Mon Sep 28 18:15:09 2015 : Info: [sql] expand: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress, acctinputpackets, acctoutputpackets, acctstartdelay, acctstopdelay, xascendsessionsvrkey) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', '%S', NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Prot Mon Sep 28 18:15:09 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 22 Mon Sep 28 18:15:09 2015 : Debug: rlm_sql (sql): Released sql socket id: 22 Mon Sep 28 18:15:09 2015 : Info: ++[sql] = ok Mon Sep 28 18:15:09 2015 : Info: ++[exec] = noop Mon Sep 28 18:15:09 2015 : Info: [attr_filter.accounting_response] expand: %{User-Name} -> lin Mon Sep 28 18:15:09 2015 : Debug: attr_filter: Matched entry DEFAULT at line 12 Mon Sep 28 18:15:09 2015 : Info: ++[attr_filter.accounting_response] = updated Mon Sep 28 18:15:09 2015 : Info: +} # group accounting = updated Sending Accounting-Response of id 104 to 192.168.1.50 port 1473 Mon Sep 28 18:15:09 2015 : Info: Finished request 7. Mon Sep 28 18:15:09 2015 : Info: Cleaning up request 7 ID 104 with timestamp +7 Mon Sep 28 18:15:09 2015 : Debug: Going to the next request Mon Sep 28 18:15:09 2015 : Debug: Waking up in 3.3 seconds. Anisa: Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{Stripped-User-Name} -> Mon Sep 28 18:11:55 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{User-Name} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] sql_set_user escaped user --> 'anisa' Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 28 Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'anisa' ORDER BY id Mon Sep 28 18:11:55 2015 : Info: [sql] User found in radcheck table Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'anisa' ORDER BY id Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'anisa' ORDER BY priority Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'dynamic' ORDER BY id Mon Sep 28 18:11:55 2015 : Info: [sql] User found in group dynamic Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'dynamic' ORDER BY id Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Released sql socket id: 28 Mon Sep 28 18:11:55 2015 : Info: ++[sql] = ok Mon Sep 28 18:11:55 2015 : Info: ++[expiration] = noop Mon Sep 28 18:11:55 2015 : Info: ++[logintime] = noop Mon Sep 28 18:11:55 2015 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP Mon Sep 28 18:11:55 2015 : Info: ++[pap] = noop Mon Sep 28 18:11:55 2015 : Info: +} # group authorize = updated Mon Sep 28 18:11:55 2015 : Info: Found Auth-Type = EAP Mon Sep 28 18:11:55 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Mon Sep 28 18:11:55 2015 : Info: +group authenticate { Mon Sep 28 18:11:55 2015 : Info: [eap] EAP Identity Mon Sep 28 18:11:55 2015 : Info: [eap] processing type mschapv2 Mon Sep 28 18:11:55 2015 : Debug: rlm_eap_mschapv2: Issuing Challenge Mon Sep 28 18:11:55 2015 : Info: ++[eap] = handled Mon Sep 28 18:11:55 2015 : Info: +} # group authenticate = handled } # server inner-tunnel Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled reply code 11 Service-Type := Framed-User Acct-Interim-Interval := 300 EAP-Message = 0x0107001f1a0107001a108698ce981e43c912de335f90fcd25fa2616e697361 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x3b6746a13b605c83f83cbfdedcbd78b1 Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled reply RADIUS code Access-Challenge Service-Type := Framed-User Acct-Interim-Interval := 300 EAP-Message = 0x0107001f1a0107001a108698ce981e43c912de335f90fcd25fa2616e697361 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x3b6746a13b605c83f83cbfdedcbd78b1 Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled Access-Challenge Mon Sep 28 18:11:55 2015 : Info: ++[eap] = handled Mon Sep 28 18:11:55 2015 : Info: +} # group authenticate = handled Sending Access-Challenge of id 6 to 192.168.1.50 port 1470 EAP-Message = 0x0107003b19001703010030ced49eb6fbfef0894cf62b79588b07ea20ff88af2bc299988ea03f222237fa7abb0cd1d3bd0429045d242aa522f6f590 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xc3eeda0cc5e9c372bc5743d8d31a4433 Mon Sep 28 18:11:55 2015 : Info: Finished request 6. Mon Sep 28 18:11:55 2015 : Debug: Going to the next request Mon Sep 28 18:11:55 2015 : Debug: Waking up in 3.1 seconds. rad_recv: Access-Request packet from host 192.168.1.50 port 1470, id=7, length=308 Message-Authenticator = 0xc46f910074dc1a8ba0a44a0d069e1885 Service-Type = Framed-User User-Name = "anisa" Framed-MTU = 1488 State = 0xc3eeda0cc5e9c372bc5743d8d31a4433 Called-Station-Id = "B8-A3-86-92-86-B7:testconn" Calling-Station-Id = "50-1A-C5-07-FB-74" NAS-Identifier = "D-Link Access Point" NAS-Port-Type = Wireless-802.11 Connect-Info = "CONNECT 54Mbps 802.11g" EAP-Message = 0x0207006b19001703010060a40fef4ff7f461f4febe0274b3cc03cced1a212194d965990e69cfcd57eeca19aba259b5aae8609763632446c35de175665ec1633e2edab48769497b7bc4e65eb3d9c8d891a44efc1220eb6970f5453e708ce1356c3a3a4306b4c9b7ace86bfb NAS-IP-Address = 192.168.1.50 NAS-Port = 1 NAS-Port-Id = "STA port # 1" Mon Sep 28 18:11:55 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:11:55 2015 : Info: +group authorize { Mon Sep 28 18:11:55 2015 : Info: ++[preprocess] = ok Mon Sep 28 18:11:55 2015 : Info: ++[chap] = noop Mon Sep 28 18:11:55 2015 : Info: ++[mschap] = noop Mon Sep 28 18:11:55 2015 : Info: ++[digest] = noop Mon Sep 28 18:11:55 2015 : Info: [suffix] No '@' in User-Name = "anisa", looking up realm NULL Mon Sep 28 18:11:55 2015 : Info: [suffix] No such realm "NULL" Mon Sep 28 18:11:55 2015 : Info: ++[suffix] = noop Mon Sep 28 18:11:55 2015 : Info: [eap] EAP packet type response id 7 length 107 Mon Sep 28 18:11:55 2015 : Info: [eap] Continuing tunnel setup. Mon Sep 28 18:11:55 2015 : Info: ++[eap] = ok Mon Sep 28 18:11:55 2015 : Info: +} # group authorize = ok Mon Sep 28 18:11:55 2015 : Info: Found Auth-Type = EAP Mon Sep 28 18:11:55 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:11:55 2015 : Info: +group authenticate { Mon Sep 28 18:11:55 2015 : Info: [eap] Request found, released from the list Mon Sep 28 18:11:55 2015 : Info: [eap] EAP/peap Mon Sep 28 18:11:55 2015 : Info: [eap] processing type peap Mon Sep 28 18:11:55 2015 : Info: [peap] processing EAP-TLS Mon Sep 28 18:11:55 2015 : Info: [peap] eaptls_verify returned 7 Mon Sep 28 18:11:55 2015 : Info: [peap] Done initial handshake Mon Sep 28 18:11:55 2015 : Info: [peap] eaptls_process returned 7 Mon Sep 28 18:11:55 2015 : Info: [peap] EAPTLS_OK Mon Sep 28 18:11:55 2015 : Info: [peap] Session established. Decoding tunneled attributes. Mon Sep 28 18:11:55 2015 : Info: [peap] Peap state phase2 Mon Sep 28 18:11:55 2015 : Info: [peap] EAP type mschapv2 Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled request EAP-Message = 0x020700401a0207003b317793af47d95c6742aaed702ad9c1c9a90000000000000000666e0718883cd5b235cba76f0817430ebb65c50b583fbb2000616e697361 server { Mon Sep 28 18:11:55 2015 : Info: [peap] Setting User-Name to anisa Sending tunneled request EAP-Message = 0x020700401a0207003b317793af47d95c6742aaed702ad9c1c9a90000000000000000666e0718883cd5b235cba76f0817430ebb65c50b583fbb2000616e697361 FreeRADIUS-Proxied-To = 127.0.0.1 User-Name = "anisa" State = 0x3b6746a13b605c83f83cbfdedcbd78b1 server inner-tunnel { Mon Sep 28 18:11:55 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Mon Sep 28 18:11:55 2015 : Info: +group authorize { Mon Sep 28 18:11:55 2015 : Info: ++[chap] = noop Mon Sep 28 18:11:55 2015 : Info: ++[mschap] = noop Mon Sep 28 18:11:55 2015 : Info: [suffix] No '@' in User-Name = "anisa", looking up realm NULL Mon Sep 28 18:11:55 2015 : Info: [suffix] No such realm "NULL" Mon Sep 28 18:11:55 2015 : Info: ++[suffix] = noop Mon Sep 28 18:11:55 2015 : Info: ++update control { Mon Sep 28 18:11:55 2015 : Info: ++} # update control = noop Mon Sep 28 18:11:55 2015 : Info: [eap] EAP packet type response id 7 length 64 Mon Sep 28 18:11:55 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Mon Sep 28 18:11:55 2015 : Info: ++[eap] = updated Mon Sep 28 18:11:55 2015 : Info: [files] users: Matched entry anisa at line 97 Mon Sep 28 18:11:55 2015 : Info: ++[files] = ok Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{Stripped-User-Name} -> Mon Sep 28 18:11:55 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{User-Name} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] sql_set_user escaped user --> 'anisa' Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 27 Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'anisa' ORDER BY id Mon Sep 28 18:11:55 2015 : Info: [sql] User found in radcheck table Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'anisa' ORDER BY id Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'anisa' ORDER BY priority Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'dynamic' ORDER BY id Mon Sep 28 18:11:55 2015 : Info: [sql] User found in group dynamic Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'dynamic' ORDER BY id Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Released sql socket id: 27 Mon Sep 28 18:11:55 2015 : Info: ++[sql] = ok Mon Sep 28 18:11:55 2015 : Info: ++[expiration] = noop Mon Sep 28 18:11:55 2015 : Info: ++[logintime] = noop Mon Sep 28 18:11:55 2015 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP Mon Sep 28 18:11:55 2015 : Info: ++[pap] = noop Mon Sep 28 18:11:55 2015 : Info: +} # group authorize = updated Mon Sep 28 18:11:55 2015 : Info: Found Auth-Type = EAP Mon Sep 28 18:11:55 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Mon Sep 28 18:11:55 2015 : Info: +group authenticate { Mon Sep 28 18:11:55 2015 : Info: [eap] Request found, released from the list Mon Sep 28 18:11:55 2015 : Info: [eap] EAP/mschapv2 Mon Sep 28 18:11:55 2015 : Info: [eap] processing type mschapv2 Mon Sep 28 18:11:55 2015 : Info: [mschapv2] # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Mon Sep 28 18:11:55 2015 : Info: [mschapv2] +group MS-CHAP { Mon Sep 28 18:11:55 2015 : Info: [mschap] Creating challenge hash with username: anisa Mon Sep 28 18:11:55 2015 : Info: [mschap] Client is using MS-CHAPv2 for anisa, we need NT-Password Mon Sep 28 18:11:55 2015 : Info: [mschap] adding MS-CHAPv2 MPPE keys Mon Sep 28 18:11:55 2015 : Info: ++[mschap] = ok Mon Sep 28 18:11:55 2015 : Info: +} # group MS-CHAP = ok Mon Sep 28 18:11:55 2015 : Debug: MSCHAP Success Mon Sep 28 18:11:55 2015 : Info: ++[eap] = handled Mon Sep 28 18:11:55 2015 : Info: +} # group authenticate = handled } # server inner-tunnel Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled reply code 11 Service-Type := Framed-User Acct-Interim-Interval := 300 EAP-Message = 0x010800331a0307002e533d38324237303643433631313141423744464137393244314234334446313244363730314332413232 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x3b6746a13a6f5c83f83cbfdedcbd78b1 Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled reply RADIUS code Access-Challenge Service-Type := Framed-User Acct-Interim-Interval := 300 EAP-Message = 0x010800331a0307002e533d38324237303643433631313141423744464137393244314234334446313244363730314332413232 Message-Authenticator = 0x00000000000000000000000000000000 State = 0x3b6746a13a6f5c83f83cbfdedcbd78b1 Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled Access-Challenge Mon Sep 28 18:11:55 2015 : Info: ++[eap] = handled Mon Sep 28 18:11:55 2015 : Info: +} # group authenticate = handled Sending Access-Challenge of id 7 to 192.168.1.50 port 1470 EAP-Message = 0x0108005b19001703010050534c5beda3fe7057018278a62d4eb5c26cfbce6eb7fb0a19f4e80f87980c9320463c1f574939f1deba0554db1cec1c39c6e6a7c5480a6ca3367feafd86364e75689762b3099d4cdcb713e642b34f32ba Message-Authenticator = 0x00000000000000000000000000000000 State = 0xc3eeda0cc4e6c372bc5743d8d31a4433 Mon Sep 28 18:11:55 2015 : Info: Finished request 7. Mon Sep 28 18:11:55 2015 : Debug: Going to the next request Mon Sep 28 18:11:55 2015 : Debug: Waking up in 3.0 seconds. rad_recv: Access-Request packet from host 192.168.1.50 port 1470, id=8, length=244 Message-Authenticator = 0x2b92c7f8d9fed66f3d395036ee6aa574 Service-Type = Framed-User User-Name = "anisa" Framed-MTU = 1488 State = 0xc3eeda0cc4e6c372bc5743d8d31a4433 Called-Station-Id = "B8-A3-86-92-86-B7:testconn" Calling-Station-Id = "50-1A-C5-07-FB-74" NAS-Identifier = "D-Link Access Point" NAS-Port-Type = Wireless-802.11 Connect-Info = "CONNECT 54Mbps 802.11g" EAP-Message = 0x0208002b190017030100201cc04c5980d678a0e2a80296c2270f13be39b8aff030aec8ad55be6304eb0657 NAS-IP-Address = 192.168.1.50 NAS-Port = 1 NAS-Port-Id = "STA port # 1" Mon Sep 28 18:11:55 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:11:55 2015 : Info: +group authorize { Mon Sep 28 18:11:55 2015 : Info: ++[preprocess] = ok Mon Sep 28 18:11:55 2015 : Info: ++[chap] = noop Mon Sep 28 18:11:55 2015 : Info: ++[mschap] = noop Mon Sep 28 18:11:55 2015 : Info: ++[digest] = noop Mon Sep 28 18:11:55 2015 : Info: [suffix] No '@' in User-Name = "anisa", looking up realm NULL Mon Sep 28 18:11:55 2015 : Info: [suffix] No such realm "NULL" Mon Sep 28 18:11:55 2015 : Info: ++[suffix] = noop Mon Sep 28 18:11:55 2015 : Info: [eap] EAP packet type response id 8 length 43 Mon Sep 28 18:11:55 2015 : Info: [eap] Continuing tunnel setup. Mon Sep 28 18:11:55 2015 : Info: ++[eap] = ok Mon Sep 28 18:11:55 2015 : Info: +} # group authorize = ok Mon Sep 28 18:11:55 2015 : Info: Found Auth-Type = EAP Mon Sep 28 18:11:55 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:11:55 2015 : Info: +group authenticate { Mon Sep 28 18:11:55 2015 : Info: [eap] Request found, released from the list Mon Sep 28 18:11:55 2015 : Info: [eap] EAP/peap Mon Sep 28 18:11:55 2015 : Info: [eap] processing type peap Mon Sep 28 18:11:55 2015 : Info: [peap] processing EAP-TLS Mon Sep 28 18:11:55 2015 : Info: [peap] eaptls_verify returned 7 Mon Sep 28 18:11:55 2015 : Info: [peap] Done initial handshake Mon Sep 28 18:11:55 2015 : Info: [peap] eaptls_process returned 7 Mon Sep 28 18:11:55 2015 : Info: [peap] EAPTLS_OK Mon Sep 28 18:11:55 2015 : Info: [peap] Session established. Decoding tunneled attributes. Mon Sep 28 18:11:55 2015 : Info: [peap] Peap state phase2 Mon Sep 28 18:11:55 2015 : Info: [peap] EAP type mschapv2 Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled request EAP-Message = 0x020800061a03 server { Mon Sep 28 18:11:55 2015 : Info: [peap] Setting User-Name to anisa Sending tunneled request EAP-Message = 0x020800061a03 FreeRADIUS-Proxied-To = 127.0.0.1 User-Name = "anisa" State = 0x3b6746a13a6f5c83f83cbfdedcbd78b1 server inner-tunnel { Mon Sep 28 18:11:55 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Mon Sep 28 18:11:55 2015 : Info: +group authorize { Mon Sep 28 18:11:55 2015 : Info: ++[chap] = noop Mon Sep 28 18:11:55 2015 : Info: ++[mschap] = noop Mon Sep 28 18:11:55 2015 : Info: [suffix] No '@' in User-Name = "anisa", looking up realm NULL Mon Sep 28 18:11:55 2015 : Info: [suffix] No such realm "NULL" Mon Sep 28 18:11:55 2015 : Info: ++[suffix] = noop Mon Sep 28 18:11:55 2015 : Info: ++update control { Mon Sep 28 18:11:55 2015 : Info: ++} # update control = noop Mon Sep 28 18:11:55 2015 : Info: [eap] EAP packet type response id 8 length 6 Mon Sep 28 18:11:55 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation Mon Sep 28 18:11:55 2015 : Info: ++[eap] = updated Mon Sep 28 18:11:55 2015 : Info: [files] users: Matched entry anisa at line 97 Mon Sep 28 18:11:55 2015 : Info: ++[files] = ok Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{Stripped-User-Name} -> Mon Sep 28 18:11:55 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{User-Name} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] sql_set_user escaped user --> 'anisa' Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 26 Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'anisa' ORDER BY id Mon Sep 28 18:11:55 2015 : Info: [sql] User found in radcheck table Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'anisa' ORDER BY id Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'anisa' ORDER BY priority Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'dynamic' ORDER BY id Mon Sep 28 18:11:55 2015 : Info: [sql] User found in group dynamic Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'dynamic' ORDER BY id Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Released sql socket id: 26 Mon Sep 28 18:11:55 2015 : Info: ++[sql] = ok Mon Sep 28 18:11:55 2015 : Info: ++[expiration] = noop Mon Sep 28 18:11:55 2015 : Info: ++[logintime] = noop Mon Sep 28 18:11:55 2015 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP Mon Sep 28 18:11:55 2015 : Info: ++[pap] = noop Mon Sep 28 18:11:55 2015 : Info: +} # group authorize = updated Mon Sep 28 18:11:55 2015 : Info: Found Auth-Type = EAP Mon Sep 28 18:11:55 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Mon Sep 28 18:11:55 2015 : Info: +group authenticate { Mon Sep 28 18:11:55 2015 : Info: [eap] Request found, released from the list Mon Sep 28 18:11:55 2015 : Info: [eap] EAP/mschapv2 Mon Sep 28 18:11:55 2015 : Info: [eap] processing type mschapv2 Mon Sep 28 18:11:55 2015 : Info: [eap] Freeing handler Mon Sep 28 18:11:55 2015 : Info: ++[eap] = ok Mon Sep 28 18:11:55 2015 : Info: +} # group authenticate = ok Mon Sep 28 18:11:55 2015 : Info: # Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/inner-tunnel Mon Sep 28 18:11:55 2015 : Info: +group post-auth { Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{Stripped-User-Name} -> Mon Sep 28 18:11:55 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{User-Name} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] sql_set_user escaped user --> 'anisa' Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{User-Password} -> Mon Sep 28 18:11:55 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{Chap-Password} -> Mon Sep 28 18:11:55 2015 : Info: [sql] expand: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'anisa', '', 'Access-Accept', '2015-09-28 18:11:55') Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'anisa', '', 'Access-Accept', '2015-09-28 18:11:55') Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 25 Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Released sql socket id: 25 Mon Sep 28 18:11:55 2015 : Info: ++[sql] = ok Mon Sep 28 18:11:55 2015 : Info: +} # group post-auth = ok } # server inner-tunnel Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled reply code 2 Service-Type := Framed-User Acct-Interim-Interval := 300 MS-MPPE-Encryption-Policy = 0x00000001 MS-MPPE-Encryption-Types = 0x00000006 MS-MPPE-Send-Key = 0xbfa620e08b1e488d52de139d6ff937e5 MS-MPPE-Recv-Key = 0x64dee5827ef29d967c023a071cdde43e EAP-Message = 0x03080004 Message-Authenticator = 0x00000000000000000000000000000000 User-Name = "anisa" Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled reply RADIUS code Access-Accept Service-Type := Framed-User Acct-Interim-Interval := 300 MS-MPPE-Encryption-Policy = 0x00000001 MS-MPPE-Encryption-Types = 0x00000006 MS-MPPE-Send-Key = 0xbfa620e08b1e488d52de139d6ff937e5 MS-MPPE-Recv-Key = 0x64dee5827ef29d967c023a071cdde43e EAP-Message = 0x03080004 Message-Authenticator = 0x00000000000000000000000000000000 User-Name = "anisa" Mon Sep 28 18:11:55 2015 : Info: [peap] Tunneled authentication was successful. Mon Sep 28 18:11:55 2015 : Info: [peap] SUCCESS Mon Sep 28 18:11:55 2015 : Info: ++[eap] = handled Mon Sep 28 18:11:55 2015 : Info: +} # group authenticate = handled Sending Access-Challenge of id 8 to 192.168.1.50 port 1470 EAP-Message = 0x0109002b19001703010020106737f22f11fcfbd10498cc96e4e8aac4a5f4afcbfe9671590dca0fb2c080a9 Message-Authenticator = 0x00000000000000000000000000000000 State = 0xc3eeda0ccbe7c372bc5743d8d31a4433 Mon Sep 28 18:11:55 2015 : Info: Finished request 8. Mon Sep 28 18:11:55 2015 : Debug: Going to the next request Mon Sep 28 18:11:55 2015 : Debug: Waking up in 3.0 seconds. rad_recv: Access-Request packet from host 192.168.1.50 port 1470, id=9, length=244 Message-Authenticator = 0x0ba8761e38d7451894d5974c2bda5be1 Service-Type = Framed-User User-Name = "anisa" Framed-MTU = 1488 State = 0xc3eeda0ccbe7c372bc5743d8d31a4433 Called-Station-Id = "B8-A3-86-92-86-B7:testconn" Calling-Station-Id = "50-1A-C5-07-FB-74" NAS-Identifier = "D-Link Access Point" NAS-Port-Type = Wireless-802.11 Connect-Info = "CONNECT 54Mbps 802.11g" EAP-Message = 0x0209002b19001703010020759b0d2b7486951db12fa7f4eff5b2e88aedbfa86e323ceeac2c40fd656b2d50 NAS-IP-Address = 192.168.1.50 NAS-Port = 1 NAS-Port-Id = "STA port # 1" Mon Sep 28 18:11:55 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:11:55 2015 : Info: +group authorize { Mon Sep 28 18:11:55 2015 : Info: ++[preprocess] = ok Mon Sep 28 18:11:55 2015 : Info: ++[chap] = noop Mon Sep 28 18:11:55 2015 : Info: ++[mschap] = noop Mon Sep 28 18:11:55 2015 : Info: ++[digest] = noop Mon Sep 28 18:11:55 2015 : Info: [suffix] No '@' in User-Name = "anisa", looking up realm NULL Mon Sep 28 18:11:55 2015 : Info: [suffix] No such realm "NULL" Mon Sep 28 18:11:55 2015 : Info: ++[suffix] = noop Mon Sep 28 18:11:55 2015 : Info: [eap] EAP packet type response id 9 length 43 Mon Sep 28 18:11:55 2015 : Info: [eap] Continuing tunnel setup. Mon Sep 28 18:11:55 2015 : Info: ++[eap] = ok Mon Sep 28 18:11:55 2015 : Info: +} # group authorize = ok Mon Sep 28 18:11:55 2015 : Info: Found Auth-Type = EAP Mon Sep 28 18:11:55 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:11:55 2015 : Info: +group authenticate { Mon Sep 28 18:11:55 2015 : Info: [eap] Request found, released from the list Mon Sep 28 18:11:55 2015 : Info: [eap] EAP/peap Mon Sep 28 18:11:55 2015 : Info: [eap] processing type peap Mon Sep 28 18:11:55 2015 : Info: [peap] processing EAP-TLS Mon Sep 28 18:11:55 2015 : Info: [peap] eaptls_verify returned 7 Mon Sep 28 18:11:55 2015 : Info: [peap] Done initial handshake Mon Sep 28 18:11:55 2015 : Info: [peap] eaptls_process returned 7 Mon Sep 28 18:11:55 2015 : Info: [peap] EAPTLS_OK Mon Sep 28 18:11:55 2015 : Info: [peap] Session established. Decoding tunneled attributes. Mon Sep 28 18:11:55 2015 : Info: [peap] Peap state send tlv success Mon Sep 28 18:11:55 2015 : Info: [peap] Received EAP-TLV response. Mon Sep 28 18:11:55 2015 : Info: [peap] Success Mon Sep 28 18:11:55 2015 : Info: [eap] Freeing handler Mon Sep 28 18:11:55 2015 : Info: ++[eap] = ok Mon Sep 28 18:11:55 2015 : Info: +} # group authenticate = ok Mon Sep 28 18:11:55 2015 : Info: # Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:11:55 2015 : Info: +group post-auth { Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{Stripped-User-Name} -> Mon Sep 28 18:11:55 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{User-Name} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> anisa Mon Sep 28 18:11:55 2015 : Info: [sql] sql_set_user escaped user --> 'anisa' Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{User-Password} -> Mon Sep 28 18:11:55 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{Chap-Password} -> Mon Sep 28 18:11:55 2015 : Info: [sql] expand: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'anisa', '', 'Access-Accept', '2015-09-28 18:11:55') Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'anisa', '', 'Access-Accept', '2015-09-28 18:11:55') Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 24 Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Released sql socket id: 24 Mon Sep 28 18:11:55 2015 : Info: ++[sql] = ok Mon Sep 28 18:11:55 2015 : Info: ++[exec] = noop Mon Sep 28 18:11:55 2015 : Info: +} # group post-auth = ok Sending Access-Accept of id 9 to 192.168.1.50 port 1470 MS-MPPE-Recv-Key = 0x42efb6e0ef913216d3db461ba6cfda613405babfd84fdf31401796ad8e0e630b MS-MPPE-Send-Key = 0xacf63f04031d9623cb14e101cf636cedd674bb9635bbdec29945d12bc0c3a7cb EAP-Message = 0x03090004 Message-Authenticator = 0x00000000000000000000000000000000 User-Name = "anisa" Mon Sep 28 18:11:55 2015 : Info: Finished request 9. Mon Sep 28 18:11:55 2015 : Debug: Going to the next request Mon Sep 28 18:11:55 2015 : Debug: Waking up in 2.9 seconds. rad_recv: Accounting-Request packet from host 192.168.1.50 port 1471, id=2, length=100 Acct-Status-Type = Start Acct-Delay-Time = 0 Acct-Session-Id = "0000000018:0000000048" Acct-Authentic = RADIUS Acct-Multi-Session-Id = "anisa" User-Name = "anisa" Calling-Station-Id = "50-1a-c5-07-fb-74" NAS-IP-Address = 192.168.1.50 Mon Sep 28 18:11:57 2015 : Info: # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:11:57 2015 : Info: +group preacct { Mon Sep 28 18:11:57 2015 : Info: ++[preprocess] = ok Mon Sep 28 18:11:57 2015 : Info: [acct_unique] WARNING: Attribute NAS-Port was not found in request, unique ID MAY be inconsistent Mon Sep 28 18:11:57 2015 : Info: [acct_unique] WARNING: Attribute NAS-Identifier was not found in request, unique ID MAY be inconsistent Mon Sep 28 18:11:57 2015 : Info: [acct_unique] Hashing ',,NAS-IP-Address = 192.168.1.50,Acct-Session-Id = "0000000018:0000000048",User-Name = "anisa"' Mon Sep 28 18:11:57 2015 : Info: [acct_unique] Acct-Unique-Session-ID = "b404cb6fbd3afd18". Mon Sep 28 18:11:57 2015 : Info: ++[acct_unique] = ok Mon Sep 28 18:11:57 2015 : Info: [suffix] No '@' in User-Name = "anisa", looking up realm NULL Mon Sep 28 18:11:57 2015 : Info: [suffix] No such realm "NULL" Mon Sep 28 18:11:57 2015 : Info: ++[suffix] = noop Mon Sep 28 18:11:57 2015 : Info: ++[files] = noop Mon Sep 28 18:11:57 2015 : Info: +} # group preacct = ok Mon Sep 28 18:11:57 2015 : Info: # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default Mon Sep 28 18:11:57 2015 : Info: +group accounting { Mon Sep 28 18:11:57 2015 : Info: [detail] expand: %{Packet-Src-IP-Address} -> 192.168.1.50 Mon Sep 28 18:11:57 2015 : Info: [detail] expand: /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d -> /usr/local/var/log/radius/radacct/192.168.1.50/detail-20150928 Mon Sep 28 18:11:57 2015 : Info: [detail] /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/192.168.1.50/detail-20150928 Mon Sep 28 18:11:57 2015 : Info: [detail] expand: %t -> Mon Sep 28 18:11:57 2015 Mon Sep 28 18:11:57 2015 : Info: ++[detail] = ok Mon Sep 28 18:11:57 2015 : Info: [sql] expand: %{Stripped-User-Name} -> Mon Sep 28 18:11:57 2015 : Info: [sql] ... expanding second conditional Mon Sep 28 18:11:57 2015 : Info: [sql] expand: %{User-Name} -> anisa Mon Sep 28 18:11:57 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> anisa Mon Sep 28 18:11:57 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> anisa Mon Sep 28 18:11:57 2015 : Info: [sql] sql_set_user escaped user --> 'anisa' Mon Sep 28 18:11:57 2015 : Info: [sql] expand: %{Acct-Delay-Time} -> 0 Mon Sep 28 18:11:57 2015 : Info: [sql] expand: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress, acctinputpackets, acctoutputpackets, acctstartdelay, acctstopdelay, xascendsessionsvrkey) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', '%S', NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Prot Mon Sep 28 18:11:57 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 23 Mon Sep 28 18:11:57 2015 : Debug: rlm_sql (sql): Released sql socket id: 23 Mon Sep 28 18:11:57 2015 : Info: ++[sql] = ok Mon Sep 28 18:11:57 2015 : Info: ++[exec] = noop Mon Sep 28 18:11:57 2015 : Info: [attr_filter.accounting_response] expand: %{User-Name} -> anisa Mon Sep 28 18:11:57 2015 : Debug: attr_filter: Matched entry DEFAULT at line 12 Mon Sep 28 18:11:57 2015 : Info: ++[attr_filter.accounting_response] = updated Mon Sep 28 18:11:57 2015 : Info: +} # group accounting = updated Sending Accounting-Response of id 2 to 192.168.1.50 port 1471 Mon Sep 28 18:11:57 2015 : Info: Finished request 10. Mon Sep 28 18:11:57 2015 : Info: Cleaning up request 10 ID 2 with timestamp +98 Mon Sep 28 18:11:57 2015 : Debug: Going to the next request Mon Sep 28 18:11:57 2015 : Debug: Waking up in 1.0 seconds. Mon Sep 28 18:11:58 2015 : Info: Cleaning up request 0 ID 0 with timestamp +94 Mon Sep 28 18:11:58 2015 : Info: Cleaning up request 1 ID 1 with timestamp +94 Mon Sep 28 18:11:58 2015 : Info: Cleaning up request 2 ID 2 with timestamp +94 Mon Sep 28 18:11:58 2015 : Info: Cleaning up request 3 ID 3 with timestamp +94 Mon Sep 28 18:11:58 2015 : Info: Cleaning up request 4 ID 4 with timestamp +94 Mon Sep 28 18:11:58 2015 : Debug: Waking up in 1.8 seconds. Mon Sep 28 18:12:00 2015 : Info: Cleaning up request 5 ID 5 with timestamp +96 Mon Sep 28 18:12:00 2015 : Info: Cleaning up request 6 ID 6 with timestamp +96 Mon Sep 28 18:12:00 2015 : Info: Cleaning up request 7 ID 7 with timestamp +96 Mon Sep 28 18:12:00 2015 : Info: Cleaning up request 8 ID 8 with timestamp +96 Mon Sep 28 18:12:00 2015 : Info: Cleaning up request 9 ID 9 with timestamp +96 Mon Sep 28 18:12:00 2015 : Info: Ready to process requests. On Mon, Sep 28, 2015 at 6:53 PM, Anisa Allahdadi <anisa.alla@gmail.com> wrote:
Hi all,
There is just one NAS, and 4-5 mobile stations.
I realized that there are 2 passes for the devices to get authenticated (I guess the second one is due to checking the certificates). And I see that in the first pass, Access-Accept *contains* the Acct-Interim-Update, but the second Access-Accecpt *does not*. I'm not saying the problem is with FreeRadius, I guess it might be related to the authentication, or my certificates, or my proxy setting.
I ran radiusd -XXX and attached the output for what I got from two different users: *anisa* is the not working user and *lin* is the working user. Sorry for the long text, I did some highlights.
Thanks for the help
On Mon, Sep 28, 2015 at 5:38 PM, <A.L.M.Buxey@lboro.ac.uk> wrote:
Hi,
I don't understand you guys! All I'm saying is that one of my stations sends Interim-Updates and the others do not, so the problem shouldn't be with NAS. If you don't want to help, feel free and don't. I don't expect
why do you think the RADIUS server is the place to look? one of them sends the data, the others dont. so, are they the same make, do they have the same firmware? do they have the same configuration? a NAS does what a NAS does. look at the NAS.
alan - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
To whom it may concern: Keep alive sessions do not work with TLS, the second run of Access-Accept does not contain Acct-Interim-Update. However TTLS works and I didn't check but PEAP will probably work as well. On Mon, Sep 28, 2015 at 7:25 PM, Anisa Allahdadi <anisa.alla@gmail.com> wrote:
Copied in here:
Lin:
acceess5f7710d57421263eee182648807ba62a350203010001a38201323082012e301d0603551d0e04160414a03774d8725132d320078de9b79f287a932dbb313081c60603551d230481be3081bb8014a03774d8725132d320078de9b79f287a932dbb31a18197a48194308191310b3009060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e311e301c06092a864886f70d0109
EAP-Message = 0x01160f6c696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f72697479820900953acc864d06fcaf300c0603551d13040530030101ff30360603551d1f042f302d302ba029a0278625687474703a2f2f7777772e6578616d706c652e636f6d2f6578616d706c655f63612e63726c300d06092a864886f70d01010b05000381810096d9c719eca5c64ddfb7b3bac54ebd6356850c3aa3e0b7151857dcdf5cc6d2b1ffd1f0c9d6dfa4b54f9fee7f58e8ac99b16ad14217064be2a4fb2db683f640fd5d331cf1e714bb19be54d3581949100b7ad051714be5c6a332d004b9c96d2f
EAP-Message = 0xbe89c214a17767ea2ad030de4f430984f9e53daa448b464748a99ab846e132c6b916030100cb0c0000c70300174104aa58bd6268496ed70e16953f6a601778c86f0a98212e99ab2ad97845634caaa8424d10fffcc32bc84c1b2c3f769ccb6f5d987d4766b5d834c0561f136e735e2f008027413db279d297803f3560639d009fdc84d884e4d8fd17cfd6474f8c76d0b4595dc97879e57543ffcdc6c63e75dfe96b97c3bb33d601aa375919dddae503423911d012b6d0c1f0fd8fd139ee45abef8fee7dd867deff19bb6f11317a3c48ba95a5d3cfaa0f8633bbe36e01880a6f40fe1f975a6948bcf950e55aa6b769d95f4316030100a40d00009c030102
EAP-Message = 0x4000960094308191310b3009
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x0452373b064d3acf9b22daa195414c61
Mon Sep 28 18:15:08 2015 : Info: Finished request 2.
Mon Sep 28 18:15:08 2015 : Debug: Going to the next request
Mon Sep 28 18:15:08 2015 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.1.50 port 1111, id=31, length=205
Message-Authenticator = 0x2b7e24d764a9126ba0564b4cb081ec03
Service-Type = Framed-User
User-Name = "lin"
Framed-MTU = 1488
State = 0x0452373b064d3acf9b22daa195414c61
Called-Station-Id = "B8-A3-86-92-86-B7:testconn"
Calling-Station-Id = "EC-55-F9-2A-CC-86"
NAS-Identifier = "D-Link Access Point"
NAS-Port-Type = Wireless-802.11
Connect-Info = "CONNECT 54Mbps 802.11g"
EAP-Message = 0x021f00060d00
NAS-IP-Address = 192.168.1.50
NAS-Port = 5
NAS-Port-Id = "STA port # 5"
Mon Sep 28 18:15:08 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Mon Sep 28 18:15:08 2015 : Info: +group authorize {
Mon Sep 28 18:15:08 2015 : Info: ++[preprocess] = ok
Mon Sep 28 18:15:08 2015 : Info: ++[chap] = noop
Mon Sep 28 18:15:08 2015 : Info: ++[mschap] = noop
Mon Sep 28 18:15:08 2015 : Info: ++[digest] = noop
Mon Sep 28 18:15:08 2015 : Info: [suffix] No '@' in User-Name = "lin", looking up realm NULL
Mon Sep 28 18:15:08 2015 : Info: [suffix] No such realm "NULL"
Mon Sep 28 18:15:08 2015 : Info: ++[suffix] = noop
Mon Sep 28 18:15:08 2015 : Info: [eap] EAP packet type response id 31 length 6
Mon Sep 28 18:15:08 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation
Mon Sep 28 18:15:08 2015 : Info: ++[eap] = updated
Mon Sep 28 18:15:08 2015 : Info: [files] users: Matched entry lin at line 123
Mon Sep 28 18:15:08 2015 : Info: ++[files] = ok
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{Stripped-User-Name} ->
Mon Sep 28 18:15:08 2015 : Info: [sql] ... expanding second conditional
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{User-Name} -> lin
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> lin
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> lin
Mon Sep 28 18:15:08 2015 : Info: [sql] sql_set_user escaped user --> 'lin'
Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 27
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'lin' ORDER BY id
Mon Sep 28 18:15:08 2015 : Info: [sql] User found in radcheck table
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'lin' ORDER BY id
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'lin' ORDER BY priority
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'dynamic' ORDER BY id
Mon Sep 28 18:15:08 2015 : Info: [sql] User found in group dynamic
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'dynamic' ORDER BY id
Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Released sql socket id: 27
Mon Sep 28 18:15:08 2015 : Info: ++[sql] = ok
Mon Sep 28 18:15:08 2015 : Info: ++[expiration] = noop
Mon Sep 28 18:15:08 2015 : Info: ++[logintime] = noop
Mon Sep 28 18:15:08 2015 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP
Mon Sep 28 18:15:08 2015 : Info: ++[pap] = noop
Mon Sep 28 18:15:08 2015 : Info: +} # group authorize = updated
Mon Sep 28 18:15:08 2015 : Info: Found Auth-Type = EAP
Mon Sep 28 18:15:08 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Mon Sep 28 18:15:08 2015 : Info: +group authenticate {
Mon Sep 28 18:15:08 2015 : Info: [eap] Request found, released from the list
Mon Sep 28 18:15:08 2015 : Info: [eap] EAP/tls
Mon Sep 28 18:15:08 2015 : Info: [eap] processing type tls
Mon Sep 28 18:15:08 2015 : Info: [tls] Authenticate
Mon Sep 28 18:15:08 2015 : Info: [tls] processing EAP-TLS
Mon Sep 28 18:15:08 2015 : Info: [tls] Received TLS ACK
Mon Sep 28 18:15:08 2015 : Info: [tls] ACK handshake fragment handler
Mon Sep 28 18:15:08 2015 : Info: [tls] eaptls_verify returned 1
Mon Sep 28 18:15:08 2015 : Info: [tls] eaptls_process returned 13
Mon Sep 28 18:15:08 2015 : Info: ++[eap] = handled
Mon Sep 28 18:15:08 2015 : Info: +} # group authenticate = handled
Sending Access-Challenge of id 31 to 192.168.1.50 port 1111
Framed-IP-Address := 192.168.1.111
Service-Type := Framed-User
Acct-Interim-Interval := 300
EAP-Message = 0x0120009b0d800000087d060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e311e301c06092a864886f70d010901160f6c696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f726974790e000000
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x0452373b07723acf9b22daa195414c61
Mon Sep 28 18:15:08 2015 : Info: Finished request 3.
Mon Sep 28 18:15:08 2015 : Debug: Going to the next request
Mon Sep 28 18:15:08 2015 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.1.50 port 1111, id=32, length=1519
Message-Authenticator = 0xf72b1041d2b3d855f3fb77c1404866b5
Service-Type = Framed-User
User-Name = "lin"
Framed-MTU = 1488
State = 0x0452373b07723acf9b22daa195414c61
Called-Station-Id = "B8-A3-86-92-86-B7:testconn"
Calling-Station-Id = "EC-55-F9-2A-CC-86"
NAS-Identifier = "D-Link Access Point"
NAS-Port-Type = Wireless-802.11
Connect-Info = "CONNECT 54Mbps 802.11g"
EAP-Message = 0x0220051e0dc0000007c716030106b10b0006ad0006aa0002ca308202c63082022fa003020102020104300d06092a864886f70d01010b0500308191310b3009060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e311e301c06092a864886f70d010901160f6c696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f72697479301e170d3135303932313134343631385a170d3136303932303134343631385a306f310b3009060355040613024652310f
EAP-Message = 0x300d0603550408130652616469757331153013060355040a130c4578616d706c6520496e632e311830160603550403140f6c696e406578616d706c652e636f6d311e301c06092a864886f70d010901160f6c696e406578616d706c652e636f6d30819f300d06092a864886f70d010101050003818d0030818902818100e69d6bb25f13d2b6947eb4ac90f5826d9b69a2dbdba314f66d5b195b6a2ff30dcdefe39a7592ca935d3762b0e19e78c70c5f34994c8b53d1eb771672061adbf69bd6628b7692316ea423cc45a8814abfc88b94349bbec2296a87684dda1f82d442507d850c1c46eb929d0cc9b6f78b0eb9d87e1030fbd98a5c05b004666b6d8b
EAP-Message = 0x0203010001a34f304d30130603551d25040c300a06082b0601050507030230360603551d1f042f302d302ba029a0278625687474703a2f2f7777772e6578616d706c652e636f6d2f6578616d706c655f63612e63726c300d06092a864886f70d01010b050003818100066a5a7745b713bb8560c5544a2475c8c1c7dfc12562462e40a63c4b31429b32f01e43121ef0832e3ceab27b80bfacc69327f1a4ef64291977f1bb756c32a40dbe41f4a7c211c2895487cebd0501feb42cf60bd4dd5181f43117196675fa8897193e494f9ed8313b7ce84ab2649bbbbcc845b4f72752d90220ddd29b4202eec10003da308203d63082033fa00302010202090095
EAP-Message = 0x3acc864d06fcaf300d06092a864886f70d01010b0500308191310b3009060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e311e301c06092a864886f70d010901160f6c696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f72697479301e170d3135303932313134343530385a170d3136303932303134343530385a308191310b3009060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865
EAP-Message = 0x726531153013060355040a130c4578616d706c6520496e632e311e301c06092a864886f70d010901160f6c696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f7269747930819f300d06092a864886f70d010101050003818d0030818902818100f309afd4d9180f80257d3479b73786a195fd036f97d8be49339135c7b01aeb36a2e8d1ef13fbcf7d06a64395a884d9afa73aa3150c396688aea76d851f4b797b10f3cf5111fa817406fb0b569dcef28b2bdc26fe315311cfc8882e291b66bbc4cedba308b619f3cc59737470d848445f7710d57421263eee182648807ba62a
EAP-Message = 0x350203010001a38201323082012e301d0603551d0e04160414a03774d8725132d320078de9b79f287a932dbb31
NAS-IP-Address = 192.168.1.50
NAS-Port = 5
NAS-Port-Id = "STA port # 5"
Mon Sep 28 18:15:08 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Mon Sep 28 18:15:08 2015 : Info: +group authorize {
Mon Sep 28 18:15:08 2015 : Info: ++[preprocess] = ok
Mon Sep 28 18:15:08 2015 : Info: ++[chap] = noop
Mon Sep 28 18:15:08 2015 : Info: ++[mschap] = noop
Mon Sep 28 18:15:08 2015 : Info: ++[digest] = noop
Mon Sep 28 18:15:08 2015 : Info: [suffix] No '@' in User-Name = "lin", looking up realm NULL
Mon Sep 28 18:15:08 2015 : Info: [suffix] No such realm "NULL"
Mon Sep 28 18:15:08 2015 : Info: ++[suffix] = noop
Mon Sep 28 18:15:08 2015 : Info: [eap] EAP packet type response id 32 length 253
Mon Sep 28 18:15:08 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation
Mon Sep 28 18:15:08 2015 : Info: ++[eap] = updated
Mon Sep 28 18:15:08 2015 : Info: [files] users: Matched entry lin at line 123
Mon Sep 28 18:15:08 2015 : Info: ++[files] = ok
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{Stripped-User-Name} ->
Mon Sep 28 18:15:08 2015 : Info: [sql] ... expanding second conditional
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{User-Name} -> lin
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> lin
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> lin
Mon Sep 28 18:15:08 2015 : Info: [sql] sql_set_user escaped user --> 'lin'
Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 26
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'lin' ORDER BY id
Mon Sep 28 18:15:08 2015 : Info: [sql] User found in radcheck table
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'lin' ORDER BY id
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'lin' ORDER BY priority
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'dynamic' ORDER BY id
Mon Sep 28 18:15:08 2015 : Info: [sql] User found in group dynamic
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'dynamic' ORDER BY id
Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Released sql socket id: 26
Mon Sep 28 18:15:08 2015 : Info: ++[sql] = ok
Mon Sep 28 18:15:08 2015 : Info: ++[expiration] = noop
Mon Sep 28 18:15:08 2015 : Info: ++[logintime] = noop
Mon Sep 28 18:15:08 2015 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP
Mon Sep 28 18:15:08 2015 : Info: ++[pap] = noop
Mon Sep 28 18:15:08 2015 : Info: +} # group authorize = updated
Mon Sep 28 18:15:08 2015 : Info: Found Auth-Type = EAP
Mon Sep 28 18:15:08 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Mon Sep 28 18:15:08 2015 : Info: +group authenticate {
Mon Sep 28 18:15:08 2015 : Info: [eap] Request found, released from the list
Mon Sep 28 18:15:08 2015 : Info: [eap] EAP/tls
Mon Sep 28 18:15:08 2015 : Info: [eap] processing type tls
Mon Sep 28 18:15:08 2015 : Info: [tls] Authenticate
Mon Sep 28 18:15:08 2015 : Info: [tls] processing EAP-TLS
Mon Sep 28 18:15:08 2015 : Debug: TLS Length 1991
Mon Sep 28 18:15:08 2015 : Info: [tls] Received EAP-TLS First Fragment of the message
Mon Sep 28 18:15:08 2015 : Info: [tls] eaptls_verify returned 9
Mon Sep 28 18:15:08 2015 : Info: [tls] eaptls_process returned 13
Mon Sep 28 18:15:08 2015 : Info: ++[eap] = handled
Mon Sep 28 18:15:08 2015 : Info: +} # group authenticate = handled
Sending Access-Challenge of id 32 to 192.168.1.50 port 1111
Framed-IP-Address := 192.168.1.111
Service-Type := Framed-User
Acct-Interim-Interval := 300
EAP-Message = 0x012100060d00
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x0452373b00733acf9b22daa195414c61
Mon Sep 28 18:15:08 2015 : Info: Finished request 4.
Mon Sep 28 18:15:08 2015 : Debug: Going to the next request
Mon Sep 28 18:15:08 2015 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.1.50 port 1111, id=33, length=900
Message-Authenticator = 0xaf7d00e343341dd0272004d8497a4774
Service-Type = Framed-User
User-Name = "lin"
Framed-MTU = 1488
State = 0x0452373b00733acf9b22daa195414c61
Called-Station-Id = "B8-A3-86-92-86-B7:testconn"
Calling-Station-Id = "EC-55-F9-2A-CC-86"
NAS-Identifier = "D-Link Access Point"
NAS-Port-Type = Wireless-802.11
Connect-Info = "CONNECT 54Mbps 802.11g"
EAP-Message = 0x022102b90d003081c60603551d230481be3081bb8014a03774d8725132d320078de9b79f287a932dbb31a18197a48194308191310b3009060355040613024652310f300d060355040813065261646975733112301006035504071309536f6d65776865726531153013060355040a130c4578616d706c6520496e632e311e301c06092a864886f70d010901160f6c696e406578616d706c652e636f6d312630240603550403131d4578616d706c6520436572746966696361746520417574686f72697479820900953acc864d06fcaf300c0603551d13040530030101ff30360603551d1f042f302d302ba029a0278625687474703a2f2f7777772e6578
EAP-Message = 0x616d706c652e636f6d2f6578616d706c655f63612e63726c300d06092a864886f70d01010b05000381810096d9c719eca5c64ddfb7b3bac54ebd6356850c3aa3e0b7151857dcdf5cc6d2b1ffd1f0c9d6dfa4b54f9fee7f58e8ac99b16ad14217064be2a4fb2db683f640fd5d331cf1e714bb19be54d3581949100b7ad051714be5c6a332d004b9c96d2fbe89c214a17767ea2ad030de4f430984f9e53daa448b464748a99ab846e132c6b916030100461000004241048bd7c69292592488d8102295acb943d161ffb84be68ffc183c2d3a316ab63de0701053bf7c13f25129d365cdb99dfc74ca37b75a7afbb33074a180aaab40d10916030100860f00
EAP-Message = 0x0082008084f396947106198627824d622b5db60eac3ad4195c132781f79e6b403ec760d8bb74b0e7f32ecf78584d6021296ebed3746734e79aeddea8d8ab7902e0a636706ed6306e0b75fe9691908f4d327166fd74f99851cb03c2185a5999bd51ab4d1a03aa8addd90b07a62aa9548167300117c6db54a161b914d6dc33dea1d9dd64561403010001011603010030043441932a96e3f2d769f4928d4423eb5bc393e425a82ce0a2d811250ff08967ef0de002934be36c7fb3c055323161a9
NAS-IP-Address = 192.168.1.50
NAS-Port = 5
NAS-Port-Id = "STA port # 5"
Mon Sep 28 18:15:08 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Mon Sep 28 18:15:08 2015 : Info: +group authorize {
Mon Sep 28 18:15:08 2015 : Info: ++[preprocess] = ok
Mon Sep 28 18:15:08 2015 : Info: ++[chap] = noop
Mon Sep 28 18:15:08 2015 : Info: ++[mschap] = noop
Mon Sep 28 18:15:08 2015 : Info: ++[digest] = noop
Mon Sep 28 18:15:08 2015 : Info: [suffix] No '@' in User-Name = "lin", looking up realm NULL
Mon Sep 28 18:15:08 2015 : Info: [suffix] No such realm "NULL"
Mon Sep 28 18:15:08 2015 : Info: ++[suffix] = noop
Mon Sep 28 18:15:08 2015 : Info: [eap] EAP packet type response id 33 length 253
Mon Sep 28 18:15:08 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation
Mon Sep 28 18:15:08 2015 : Info: ++[eap] = updated
Mon Sep 28 18:15:08 2015 : Info: [files] users: Matched entry lin at line 123
Mon Sep 28 18:15:08 2015 : Info: ++[files] = ok
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{Stripped-User-Name} ->
Mon Sep 28 18:15:08 2015 : Info: [sql] ... expanding second conditional
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{User-Name} -> lin
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> lin
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> lin
Mon Sep 28 18:15:08 2015 : Info: [sql] sql_set_user escaped user --> 'lin'
Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 25
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'lin' ORDER BY id
Mon Sep 28 18:15:08 2015 : Info: [sql] User found in radcheck table
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'lin' ORDER BY id
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'lin' ORDER BY priority
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'dynamic' ORDER BY id
Mon Sep 28 18:15:08 2015 : Info: [sql] User found in group dynamic
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'dynamic' ORDER BY id
Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Released sql socket id: 25
Mon Sep 28 18:15:08 2015 : Info: ++[sql] = ok
Mon Sep 28 18:15:08 2015 : Info: ++[expiration] = noop
Mon Sep 28 18:15:08 2015 : Info: ++[logintime] = noop
Mon Sep 28 18:15:08 2015 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP
Mon Sep 28 18:15:08 2015 : Info: ++[pap] = noop
Mon Sep 28 18:15:08 2015 : Info: +} # group authorize = updated
Mon Sep 28 18:15:08 2015 : Info: Found Auth-Type = EAP
Mon Sep 28 18:15:08 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Mon Sep 28 18:15:08 2015 : Info: +group authenticate {
Mon Sep 28 18:15:08 2015 : Info: [eap] Request found, released from the list
Mon Sep 28 18:15:08 2015 : Info: [eap] EAP/tls
Mon Sep 28 18:15:08 2015 : Info: [eap] processing type tls
Mon Sep 28 18:15:08 2015 : Info: [tls] Authenticate
Mon Sep 28 18:15:08 2015 : Info: [tls] processing EAP-TLS
Mon Sep 28 18:15:08 2015 : Info: [tls] eaptls_verify returned 7
Mon Sep 28 18:15:08 2015 : Info: [tls] Done initial handshake
Mon Sep 28 18:15:08 2015 : Info: [tls] <<< TLS 1.0 Handshake [length 06b1], Certificate
Mon Sep 28 18:15:08 2015 : Info: [tls] chain-depth=1,
Mon Sep 28 18:15:08 2015 : Info: [tls] error=0
Mon Sep 28 18:15:08 2015 : Info: [tls] --> User-Name = lin
Mon Sep 28 18:15:08 2015 : Info: [tls] --> BUF-Name = Example Certificate Authority
Mon Sep 28 18:15:08 2015 : Info: [tls] --> subject = /C=FR/ST=Radius/L=Somewhere/O=Example Inc./emailAddress= lin@example.com/CN=Example Certificate Authority
Mon Sep 28 18:15:08 2015 : Info: [tls] --> issuer = /C=FR/ST=Radius/L=Somewhere/O=Example Inc./emailAddress= lin@example.com/CN=Example Certificate Authority
Mon Sep 28 18:15:08 2015 : Info: [tls] --> verify return:1
TLS-Client-Cert-X509v3-Extended-Key-Usage += "TLS Web Client Authentication"
Mon Sep 28 18:15:08 2015 : Info: [tls] chain-depth=0,
Mon Sep 28 18:15:08 2015 : Info: [tls] error=0
Mon Sep 28 18:15:08 2015 : Info: [tls] --> User-Name = lin
Mon Sep 28 18:15:08 2015 : Info: [tls] --> BUF-Name = lin@example.com
Mon Sep 28 18:15:08 2015 : Info: [tls] --> subject = /C=FR/ST=Radius/O=Example Inc./CN= lin@example.com/emailAddress=lin@example.com
Mon Sep 28 18:15:08 2015 : Info: [tls] --> issuer = /C=FR/ST=Radius/L=Somewhere/O=Example Inc./emailAddress= lin@example.com/CN=Example Certificate Authority
Mon Sep 28 18:15:08 2015 : Info: [tls] --> verify return:1
Mon Sep 28 18:15:08 2015 : Info: [tls] TLS_accept: SSLv3 read client certificate A
Mon Sep 28 18:15:08 2015 : Info: [tls] <<< TLS 1.0 Handshake [length 0046], ClientKeyExchange
Mon Sep 28 18:15:08 2015 : Info: [tls] TLS_accept: SSLv3 read client key exchange A
Mon Sep 28 18:15:08 2015 : Info: [tls] <<< TLS 1.0 Handshake [length 0086], CertificateVerify
Mon Sep 28 18:15:08 2015 : Info: [tls] TLS_accept: SSLv3 read certificate verify A
Mon Sep 28 18:15:08 2015 : Info: [tls] <<< TLS 1.0 ChangeCipherSpec [length 0001]
Mon Sep 28 18:15:08 2015 : Info: [tls] <<< TLS 1.0 Handshake [length 0010], Finished
Mon Sep 28 18:15:08 2015 : Info: [tls] TLS_accept: SSLv3 read finished A
Mon Sep 28 18:15:08 2015 : Info: [tls] >>> TLS 1.0 ChangeCipherSpec [length 0001]
Mon Sep 28 18:15:08 2015 : Info: [tls] TLS_accept: SSLv3 write change cipher spec A
Mon Sep 28 18:15:08 2015 : Info: [tls] >>> TLS 1.0 Handshake [length 0010], Finished
Mon Sep 28 18:15:08 2015 : Info: [tls] TLS_accept: SSLv3 write finished A
Mon Sep 28 18:15:08 2015 : Info: [tls] TLS_accept: SSLv3 flush data
Mon Sep 28 18:15:08 2015 : Info: [tls] (other): SSL negotiation finished successfully
Mon Sep 28 18:15:08 2015 : Debug: SSL Connection Established
Mon Sep 28 18:15:08 2015 : Info: [tls] eaptls_process returned 13
Mon Sep 28 18:15:08 2015 : Info: ++[eap] = handled
Mon Sep 28 18:15:08 2015 : Info: +} # group authenticate = handled
Sending Access-Challenge of id 33 to 192.168.1.50 port 1111
Framed-IP-Address := 192.168.1.111
Service-Type := Framed-User
Acct-Interim-Interval := 300
EAP-Message = 0x012200450d800000003b1403010001011603010030a7ab9f1bcecbf88696a57789c86619fb0ed0466ac2a9c5431bbc6f6864d50a9555256c85fa50c3f0c1e47b84d0a9db1f
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x0452373b01703acf9b22daa195414c61
Mon Sep 28 18:15:08 2015 : Info: Finished request 5.
Mon Sep 28 18:15:08 2015 : Debug: Going to the next request
Mon Sep 28 18:15:08 2015 : Debug: Waking up in 4.9 seconds.
rad_recv: Access-Request packet from host 192.168.1.50 port 1111, id=34, length=205
Message-Authenticator = 0xcbd99f506ca47b9960390bb23f413c91
Service-Type = Framed-User
User-Name = "lin"
Framed-MTU = 1488
State = 0x0452373b01703acf9b22daa195414c61
Called-Station-Id = "B8-A3-86-92-86-B7:testconn"
Calling-Station-Id = "EC-55-F9-2A-CC-86"
NAS-Identifier = "D-Link Access Point"
NAS-Port-Type = Wireless-802.11
Connect-Info = "CONNECT 54Mbps 802.11g"
EAP-Message = 0x022200060d00
NAS-IP-Address = 192.168.1.50
NAS-Port = 5
NAS-Port-Id = "STA port # 5"
Mon Sep 28 18:15:08 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Mon Sep 28 18:15:08 2015 : Info: +group authorize {
Mon Sep 28 18:15:08 2015 : Info: ++[preprocess] = ok
Mon Sep 28 18:15:08 2015 : Info: ++[chap] = noop
Mon Sep 28 18:15:08 2015 : Info: ++[mschap] = noop
Mon Sep 28 18:15:08 2015 : Info: ++[digest] = noop
Mon Sep 28 18:15:08 2015 : Info: [suffix] No '@' in User-Name = "lin", looking up realm NULL
Mon Sep 28 18:15:08 2015 : Info: [suffix] No such realm "NULL"
Mon Sep 28 18:15:08 2015 : Info: ++[suffix] = noop
Mon Sep 28 18:15:08 2015 : Info: [eap] EAP packet type response id 34 length 6
Mon Sep 28 18:15:08 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation
Mon Sep 28 18:15:08 2015 : Info: ++[eap] = updated
Mon Sep 28 18:15:08 2015 : Info: [files] users: Matched entry lin at line 123
Mon Sep 28 18:15:08 2015 : Info: ++[files] = ok
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{Stripped-User-Name} ->
Mon Sep 28 18:15:08 2015 : Info: [sql] ... expanding second conditional
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{User-Name} -> lin
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> lin
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> lin
Mon Sep 28 18:15:08 2015 : Info: [sql] sql_set_user escaped user --> 'lin'
Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 24
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'lin' ORDER BY id
Mon Sep 28 18:15:08 2015 : Info: [sql] User found in radcheck table
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'lin' ORDER BY id
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'lin' ORDER BY priority
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'dynamic' ORDER BY id
Mon Sep 28 18:15:08 2015 : Info: [sql] User found in group dynamic
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'dynamic' ORDER BY id
Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Released sql socket id: 24
Mon Sep 28 18:15:08 2015 : Info: ++[sql] = ok
Mon Sep 28 18:15:08 2015 : Info: ++[expiration] = noop
Mon Sep 28 18:15:08 2015 : Info: ++[logintime] = noop
Mon Sep 28 18:15:08 2015 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP
Mon Sep 28 18:15:08 2015 : Info: ++[pap] = noop
Mon Sep 28 18:15:08 2015 : Info: +} # group authorize = updated
Mon Sep 28 18:15:08 2015 : Info: Found Auth-Type = EAP
Mon Sep 28 18:15:08 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Mon Sep 28 18:15:08 2015 : Info: +group authenticate {
Mon Sep 28 18:15:08 2015 : Info: [eap] Request found, released from the list
Mon Sep 28 18:15:08 2015 : Info: [eap] EAP/tls
Mon Sep 28 18:15:08 2015 : Info: [eap] processing type tls
Mon Sep 28 18:15:08 2015 : Info: [tls] Authenticate
Mon Sep 28 18:15:08 2015 : Info: [tls] processing EAP-TLS
Mon Sep 28 18:15:08 2015 : Info: [tls] Received TLS ACK
Mon Sep 28 18:15:08 2015 : Info: [tls] ACK handshake is finished
Mon Sep 28 18:15:08 2015 : Info: [tls] eaptls_verify returned 3
Mon Sep 28 18:15:08 2015 : Info: [tls] eaptls_process returned 3
Mon Sep 28 18:15:08 2015 : Info: [tls] Adding user data to cached session
Mon Sep 28 18:15:08 2015 : Info: [eap] Freeing handler
Mon Sep 28 18:15:08 2015 : Info: ++[eap] = ok
Mon Sep 28 18:15:08 2015 : Info: +} # group authenticate = ok
Mon Sep 28 18:15:08 2015 : Info: # Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/default
Mon Sep 28 18:15:08 2015 : Info: +group post-auth {
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{Stripped-User-Name} ->
Mon Sep 28 18:15:08 2015 : Info: [sql] ... expanding second conditional
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{User-Name} -> lin
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> lin
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> lin
Mon Sep 28 18:15:08 2015 : Info: [sql] sql_set_user escaped user --> 'lin'
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{User-Password} ->
Mon Sep 28 18:15:08 2015 : Info: [sql] ... expanding second conditional
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: %{Chap-Password} ->
Mon Sep 28 18:15:08 2015 : Info: [sql] expand: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'lin', '', 'Access-Accept', '2015-09-28 18:15:08')
Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'lin', '', 'Access-Accept', '2015-09-28 18:15:08')
Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 23
Mon Sep 28 18:15:08 2015 : Debug: rlm_sql (sql): Released sql socket id: 23
Mon Sep 28 18:15:08 2015 : Info: ++[sql] = ok
Mon Sep 28 18:15:08 2015 : Info: ++[exec] = noop
Mon Sep 28 18:15:08 2015 : Info: +} # group post-auth = ok
Sending Access-Accept of id 34 to 192.168.1.50 port 1111
Framed-IP-Address := 192.168.1.111
Service-Type := Framed-User
Acct-Interim-Interval := 300
MS-MPPE-Recv-Key = 0x5169f84f16f190a14650f49720fd76765fcac67faec4553a6adfa63295d04926
MS-MPPE-Send-Key = 0xf998605b6a1c35fcf47e304754e84708f01b0b42941170086b1f108270084ab0
EAP-Message = 0x03220004
Message-Authenticator = 0x00000000000000000000000000000000
User-Name = "lin"
Mon Sep 28 18:15:08 2015 : Info: Finished request 6.
Mon Sep 28 18:15:08 2015 : Debug: Going to the next request
Mon Sep 28 18:15:08 2015 : Debug: Waking up in 4.8 seconds.
rad_recv: Accounting-Request packet from host 192.168.1.50 port 1473, id=104, length=96
Acct-Status-Type = Start
Acct-Delay-Time = 0
Acct-Session-Id = "0000000018:0000000049"
Acct-Authentic = RADIUS
Acct-Multi-Session-Id = "lin"
User-Name = "lin"
Calling-Station-Id = "ec-55-f9-2a-cc-86"
NAS-IP-Address = 192.168.1.50
Mon Sep 28 18:15:09 2015 : Info: # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default
Mon Sep 28 18:15:09 2015 : Info: +group preacct {
Mon Sep 28 18:15:09 2015 : Info: ++[preprocess] = ok
Mon Sep 28 18:15:09 2015 : Info: [acct_unique] WARNING: Attribute NAS-Port was not found in request, unique ID MAY be inconsistent
Mon Sep 28 18:15:09 2015 : Info: [acct_unique] WARNING: Attribute NAS-Identifier was not found in request, unique ID MAY be inconsistent
Mon Sep 28 18:15:09 2015 : Info: [acct_unique] Hashing ',,NAS-IP-Address = 192.168.1.50,Acct-Session-Id = "0000000018:0000000049",User-Name = "lin"'
Mon Sep 28 18:15:09 2015 : Info: [acct_unique] Acct-Unique-Session-ID = "0bdf67000ebbc82f".
Mon Sep 28 18:15:09 2015 : Info: ++[acct_unique] = ok
Mon Sep 28 18:15:09 2015 : Info: [suffix] No '@' in User-Name = "lin", looking up realm NULL
Mon Sep 28 18:15:09 2015 : Info: [suffix] No such realm "NULL"
Mon Sep 28 18:15:09 2015 : Info: ++[suffix] = noop
Mon Sep 28 18:15:09 2015 : Info: ++[files] = noop
Mon Sep 28 18:15:09 2015 : Info: +} # group preacct = ok
Mon Sep 28 18:15:09 2015 : Info: # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default
Mon Sep 28 18:15:09 2015 : Info: +group accounting {
Mon Sep 28 18:15:09 2015 : Info: [detail] expand: %{Packet-Src-IP-Address} -> 192.168.1.50
Mon Sep 28 18:15:09 2015 : Info: [detail] expand: /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d -> /usr/local/var/log/radius/radacct/192.168.1.50/detail-20150928
Mon Sep 28 18:15:09 2015 : Info: [detail] /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/192.168.1.50/detail-20150928
Mon Sep 28 18:15:09 2015 : Info: [detail] expand: %t -> Mon Sep 28 18:15:09 2015
Mon Sep 28 18:15:09 2015 : Info: ++[detail] = ok
Mon Sep 28 18:15:09 2015 : Info: [sql] expand: %{Stripped-User-Name} ->
Mon Sep 28 18:15:09 2015 : Info: [sql] ... expanding second conditional
Mon Sep 28 18:15:09 2015 : Info: [sql] expand: %{User-Name} -> lin
Mon Sep 28 18:15:09 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> lin
Mon Sep 28 18:15:09 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> lin
Mon Sep 28 18:15:09 2015 : Info: [sql] sql_set_user escaped user --> 'lin'
Mon Sep 28 18:15:09 2015 : Info: [sql] expand: %{Acct-Delay-Time} -> 0
Mon Sep 28 18:15:09 2015 : Info: [sql] expand: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress, acctinputpackets, acctoutputpackets, acctstartdelay, acctstopdelay, xascendsessionsvrkey) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', '%S', NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Prot
Mon Sep 28 18:15:09 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 22
Mon Sep 28 18:15:09 2015 : Debug: rlm_sql (sql): Released sql socket id: 22
Mon Sep 28 18:15:09 2015 : Info: ++[sql] = ok
Mon Sep 28 18:15:09 2015 : Info: ++[exec] = noop
Mon Sep 28 18:15:09 2015 : Info: [attr_filter.accounting_response] expand: %{User-Name} -> lin
Mon Sep 28 18:15:09 2015 : Debug: attr_filter: Matched entry DEFAULT at line 12
Mon Sep 28 18:15:09 2015 : Info: ++[attr_filter.accounting_response] = updated
Mon Sep 28 18:15:09 2015 : Info: +} # group accounting = updated
Sending Accounting-Response of id 104 to 192.168.1.50 port 1473
Mon Sep 28 18:15:09 2015 : Info: Finished request 7.
Mon Sep 28 18:15:09 2015 : Info: Cleaning up request 7 ID 104 with timestamp +7
Mon Sep 28 18:15:09 2015 : Debug: Going to the next request
Mon Sep 28 18:15:09 2015 : Debug: Waking up in 3.3 seconds.
Anisa:
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{Stripped-User-Name} ->
Mon Sep 28 18:11:55 2015 : Info: [sql] ... expanding second conditional
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{User-Name} -> anisa
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> anisa
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> anisa
Mon Sep 28 18:11:55 2015 : Info: [sql] sql_set_user escaped user --> 'anisa'
Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 28
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'anisa' ORDER BY id
Mon Sep 28 18:11:55 2015 : Info: [sql] User found in radcheck table
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'anisa' ORDER BY id
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'anisa' ORDER BY priority
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'dynamic' ORDER BY id
Mon Sep 28 18:11:55 2015 : Info: [sql] User found in group dynamic
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'dynamic' ORDER BY id
Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Released sql socket id: 28
Mon Sep 28 18:11:55 2015 : Info: ++[sql] = ok
Mon Sep 28 18:11:55 2015 : Info: ++[expiration] = noop
Mon Sep 28 18:11:55 2015 : Info: ++[logintime] = noop
Mon Sep 28 18:11:55 2015 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP
Mon Sep 28 18:11:55 2015 : Info: ++[pap] = noop
Mon Sep 28 18:11:55 2015 : Info: +} # group authorize = updated
Mon Sep 28 18:11:55 2015 : Info: Found Auth-Type = EAP
Mon Sep 28 18:11:55 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel
Mon Sep 28 18:11:55 2015 : Info: +group authenticate {
Mon Sep 28 18:11:55 2015 : Info: [eap] EAP Identity
Mon Sep 28 18:11:55 2015 : Info: [eap] processing type mschapv2
Mon Sep 28 18:11:55 2015 : Debug: rlm_eap_mschapv2: Issuing Challenge
Mon Sep 28 18:11:55 2015 : Info: ++[eap] = handled
Mon Sep 28 18:11:55 2015 : Info: +} # group authenticate = handled
} # server inner-tunnel
Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled reply code 11
Service-Type := Framed-User
Acct-Interim-Interval := 300
EAP-Message = 0x0107001f1a0107001a108698ce981e43c912de335f90fcd25fa2616e697361
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x3b6746a13b605c83f83cbfdedcbd78b1
Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled reply RADIUS code Access-Challenge
Service-Type := Framed-User
Acct-Interim-Interval := 300
EAP-Message = 0x0107001f1a0107001a108698ce981e43c912de335f90fcd25fa2616e697361
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x3b6746a13b605c83f83cbfdedcbd78b1
Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled Access-Challenge
Mon Sep 28 18:11:55 2015 : Info: ++[eap] = handled
Mon Sep 28 18:11:55 2015 : Info: +} # group authenticate = handled
Sending Access-Challenge of id 6 to 192.168.1.50 port 1470
EAP-Message = 0x0107003b19001703010030ced49eb6fbfef0894cf62b79588b07ea20ff88af2bc299988ea03f222237fa7abb0cd1d3bd0429045d242aa522f6f590
Message-Authenticator = 0x00000000000000000000000000000000
State = 0xc3eeda0cc5e9c372bc5743d8d31a4433
Mon Sep 28 18:11:55 2015 : Info: Finished request 6.
Mon Sep 28 18:11:55 2015 : Debug: Going to the next request
Mon Sep 28 18:11:55 2015 : Debug: Waking up in 3.1 seconds.
rad_recv: Access-Request packet from host 192.168.1.50 port 1470, id=7, length=308
Message-Authenticator = 0xc46f910074dc1a8ba0a44a0d069e1885
Service-Type = Framed-User
User-Name = "anisa"
Framed-MTU = 1488
State = 0xc3eeda0cc5e9c372bc5743d8d31a4433
Called-Station-Id = "B8-A3-86-92-86-B7:testconn"
Calling-Station-Id = "50-1A-C5-07-FB-74"
NAS-Identifier = "D-Link Access Point"
NAS-Port-Type = Wireless-802.11
Connect-Info = "CONNECT 54Mbps 802.11g"
EAP-Message = 0x0207006b19001703010060a40fef4ff7f461f4febe0274b3cc03cced1a212194d965990e69cfcd57eeca19aba259b5aae8609763632446c35de175665ec1633e2edab48769497b7bc4e65eb3d9c8d891a44efc1220eb6970f5453e708ce1356c3a3a4306b4c9b7ace86bfb
NAS-IP-Address = 192.168.1.50
NAS-Port = 1
NAS-Port-Id = "STA port # 1"
Mon Sep 28 18:11:55 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Mon Sep 28 18:11:55 2015 : Info: +group authorize {
Mon Sep 28 18:11:55 2015 : Info: ++[preprocess] = ok
Mon Sep 28 18:11:55 2015 : Info: ++[chap] = noop
Mon Sep 28 18:11:55 2015 : Info: ++[mschap] = noop
Mon Sep 28 18:11:55 2015 : Info: ++[digest] = noop
Mon Sep 28 18:11:55 2015 : Info: [suffix] No '@' in User-Name = "anisa", looking up realm NULL
Mon Sep 28 18:11:55 2015 : Info: [suffix] No such realm "NULL"
Mon Sep 28 18:11:55 2015 : Info: ++[suffix] = noop
Mon Sep 28 18:11:55 2015 : Info: [eap] EAP packet type response id 7 length 107
Mon Sep 28 18:11:55 2015 : Info: [eap] Continuing tunnel setup.
Mon Sep 28 18:11:55 2015 : Info: ++[eap] = ok
Mon Sep 28 18:11:55 2015 : Info: +} # group authorize = ok
Mon Sep 28 18:11:55 2015 : Info: Found Auth-Type = EAP
Mon Sep 28 18:11:55 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Mon Sep 28 18:11:55 2015 : Info: +group authenticate {
Mon Sep 28 18:11:55 2015 : Info: [eap] Request found, released from the list
Mon Sep 28 18:11:55 2015 : Info: [eap] EAP/peap
Mon Sep 28 18:11:55 2015 : Info: [eap] processing type peap
Mon Sep 28 18:11:55 2015 : Info: [peap] processing EAP-TLS
Mon Sep 28 18:11:55 2015 : Info: [peap] eaptls_verify returned 7
Mon Sep 28 18:11:55 2015 : Info: [peap] Done initial handshake
Mon Sep 28 18:11:55 2015 : Info: [peap] eaptls_process returned 7
Mon Sep 28 18:11:55 2015 : Info: [peap] EAPTLS_OK
Mon Sep 28 18:11:55 2015 : Info: [peap] Session established. Decoding tunneled attributes.
Mon Sep 28 18:11:55 2015 : Info: [peap] Peap state phase2
Mon Sep 28 18:11:55 2015 : Info: [peap] EAP type mschapv2
Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled request
EAP-Message = 0x020700401a0207003b317793af47d95c6742aaed702ad9c1c9a90000000000000000666e0718883cd5b235cba76f0817430ebb65c50b583fbb2000616e697361
server {
Mon Sep 28 18:11:55 2015 : Info: [peap] Setting User-Name to anisa
Sending tunneled request
EAP-Message = 0x020700401a0207003b317793af47d95c6742aaed702ad9c1c9a90000000000000000666e0718883cd5b235cba76f0817430ebb65c50b583fbb2000616e697361
FreeRADIUS-Proxied-To = 127.0.0.1
User-Name = "anisa"
State = 0x3b6746a13b605c83f83cbfdedcbd78b1
server inner-tunnel {
Mon Sep 28 18:11:55 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel
Mon Sep 28 18:11:55 2015 : Info: +group authorize {
Mon Sep 28 18:11:55 2015 : Info: ++[chap] = noop
Mon Sep 28 18:11:55 2015 : Info: ++[mschap] = noop
Mon Sep 28 18:11:55 2015 : Info: [suffix] No '@' in User-Name = "anisa", looking up realm NULL
Mon Sep 28 18:11:55 2015 : Info: [suffix] No such realm "NULL"
Mon Sep 28 18:11:55 2015 : Info: ++[suffix] = noop
Mon Sep 28 18:11:55 2015 : Info: ++update control {
Mon Sep 28 18:11:55 2015 : Info: ++} # update control = noop
Mon Sep 28 18:11:55 2015 : Info: [eap] EAP packet type response id 7 length 64
Mon Sep 28 18:11:55 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation
Mon Sep 28 18:11:55 2015 : Info: ++[eap] = updated
Mon Sep 28 18:11:55 2015 : Info: [files] users: Matched entry anisa at line 97
Mon Sep 28 18:11:55 2015 : Info: ++[files] = ok
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{Stripped-User-Name} ->
Mon Sep 28 18:11:55 2015 : Info: [sql] ... expanding second conditional
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{User-Name} -> anisa
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> anisa
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> anisa
Mon Sep 28 18:11:55 2015 : Info: [sql] sql_set_user escaped user --> 'anisa'
Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 27
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'anisa' ORDER BY id
Mon Sep 28 18:11:55 2015 : Info: [sql] User found in radcheck table
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'anisa' ORDER BY id
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'anisa' ORDER BY priority
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'dynamic' ORDER BY id
Mon Sep 28 18:11:55 2015 : Info: [sql] User found in group dynamic
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'dynamic' ORDER BY id
Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Released sql socket id: 27
Mon Sep 28 18:11:55 2015 : Info: ++[sql] = ok
Mon Sep 28 18:11:55 2015 : Info: ++[expiration] = noop
Mon Sep 28 18:11:55 2015 : Info: ++[logintime] = noop
Mon Sep 28 18:11:55 2015 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP
Mon Sep 28 18:11:55 2015 : Info: ++[pap] = noop
Mon Sep 28 18:11:55 2015 : Info: +} # group authorize = updated
Mon Sep 28 18:11:55 2015 : Info: Found Auth-Type = EAP
Mon Sep 28 18:11:55 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel
Mon Sep 28 18:11:55 2015 : Info: +group authenticate {
Mon Sep 28 18:11:55 2015 : Info: [eap] Request found, released from the list
Mon Sep 28 18:11:55 2015 : Info: [eap] EAP/mschapv2
Mon Sep 28 18:11:55 2015 : Info: [eap] processing type mschapv2
Mon Sep 28 18:11:55 2015 : Info: [mschapv2] # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel
Mon Sep 28 18:11:55 2015 : Info: [mschapv2] +group MS-CHAP {
Mon Sep 28 18:11:55 2015 : Info: [mschap] Creating challenge hash with username: anisa
Mon Sep 28 18:11:55 2015 : Info: [mschap] Client is using MS-CHAPv2 for anisa, we need NT-Password
Mon Sep 28 18:11:55 2015 : Info: [mschap] adding MS-CHAPv2 MPPE keys
Mon Sep 28 18:11:55 2015 : Info: ++[mschap] = ok
Mon Sep 28 18:11:55 2015 : Info: +} # group MS-CHAP = ok
Mon Sep 28 18:11:55 2015 : Debug: MSCHAP Success
Mon Sep 28 18:11:55 2015 : Info: ++[eap] = handled
Mon Sep 28 18:11:55 2015 : Info: +} # group authenticate = handled
} # server inner-tunnel
Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled reply code 11
Service-Type := Framed-User
Acct-Interim-Interval := 300
EAP-Message = 0x010800331a0307002e533d38324237303643433631313141423744464137393244314234334446313244363730314332413232
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x3b6746a13a6f5c83f83cbfdedcbd78b1
Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled reply RADIUS code Access-Challenge
Service-Type := Framed-User
Acct-Interim-Interval := 300
EAP-Message = 0x010800331a0307002e533d38324237303643433631313141423744464137393244314234334446313244363730314332413232
Message-Authenticator = 0x00000000000000000000000000000000
State = 0x3b6746a13a6f5c83f83cbfdedcbd78b1
Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled Access-Challenge
Mon Sep 28 18:11:55 2015 : Info: ++[eap] = handled
Mon Sep 28 18:11:55 2015 : Info: +} # group authenticate = handled
Sending Access-Challenge of id 7 to 192.168.1.50 port 1470
EAP-Message = 0x0108005b19001703010050534c5beda3fe7057018278a62d4eb5c26cfbce6eb7fb0a19f4e80f87980c9320463c1f574939f1deba0554db1cec1c39c6e6a7c5480a6ca3367feafd86364e75689762b3099d4cdcb713e642b34f32ba
Message-Authenticator = 0x00000000000000000000000000000000
State = 0xc3eeda0cc4e6c372bc5743d8d31a4433
Mon Sep 28 18:11:55 2015 : Info: Finished request 7.
Mon Sep 28 18:11:55 2015 : Debug: Going to the next request
Mon Sep 28 18:11:55 2015 : Debug: Waking up in 3.0 seconds.
rad_recv: Access-Request packet from host 192.168.1.50 port 1470, id=8, length=244
Message-Authenticator = 0x2b92c7f8d9fed66f3d395036ee6aa574
Service-Type = Framed-User
User-Name = "anisa"
Framed-MTU = 1488
State = 0xc3eeda0cc4e6c372bc5743d8d31a4433
Called-Station-Id = "B8-A3-86-92-86-B7:testconn"
Calling-Station-Id = "50-1A-C5-07-FB-74"
NAS-Identifier = "D-Link Access Point"
NAS-Port-Type = Wireless-802.11
Connect-Info = "CONNECT 54Mbps 802.11g"
EAP-Message = 0x0208002b190017030100201cc04c5980d678a0e2a80296c2270f13be39b8aff030aec8ad55be6304eb0657
NAS-IP-Address = 192.168.1.50
NAS-Port = 1
NAS-Port-Id = "STA port # 1"
Mon Sep 28 18:11:55 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Mon Sep 28 18:11:55 2015 : Info: +group authorize {
Mon Sep 28 18:11:55 2015 : Info: ++[preprocess] = ok
Mon Sep 28 18:11:55 2015 : Info: ++[chap] = noop
Mon Sep 28 18:11:55 2015 : Info: ++[mschap] = noop
Mon Sep 28 18:11:55 2015 : Info: ++[digest] = noop
Mon Sep 28 18:11:55 2015 : Info: [suffix] No '@' in User-Name = "anisa", looking up realm NULL
Mon Sep 28 18:11:55 2015 : Info: [suffix] No such realm "NULL"
Mon Sep 28 18:11:55 2015 : Info: ++[suffix] = noop
Mon Sep 28 18:11:55 2015 : Info: [eap] EAP packet type response id 8 length 43
Mon Sep 28 18:11:55 2015 : Info: [eap] Continuing tunnel setup.
Mon Sep 28 18:11:55 2015 : Info: ++[eap] = ok
Mon Sep 28 18:11:55 2015 : Info: +} # group authorize = ok
Mon Sep 28 18:11:55 2015 : Info: Found Auth-Type = EAP
Mon Sep 28 18:11:55 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Mon Sep 28 18:11:55 2015 : Info: +group authenticate {
Mon Sep 28 18:11:55 2015 : Info: [eap] Request found, released from the list
Mon Sep 28 18:11:55 2015 : Info: [eap] EAP/peap
Mon Sep 28 18:11:55 2015 : Info: [eap] processing type peap
Mon Sep 28 18:11:55 2015 : Info: [peap] processing EAP-TLS
Mon Sep 28 18:11:55 2015 : Info: [peap] eaptls_verify returned 7
Mon Sep 28 18:11:55 2015 : Info: [peap] Done initial handshake
Mon Sep 28 18:11:55 2015 : Info: [peap] eaptls_process returned 7
Mon Sep 28 18:11:55 2015 : Info: [peap] EAPTLS_OK
Mon Sep 28 18:11:55 2015 : Info: [peap] Session established. Decoding tunneled attributes.
Mon Sep 28 18:11:55 2015 : Info: [peap] Peap state phase2
Mon Sep 28 18:11:55 2015 : Info: [peap] EAP type mschapv2
Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled request
EAP-Message = 0x020800061a03
server {
Mon Sep 28 18:11:55 2015 : Info: [peap] Setting User-Name to anisa
Sending tunneled request
EAP-Message = 0x020800061a03
FreeRADIUS-Proxied-To = 127.0.0.1
User-Name = "anisa"
State = 0x3b6746a13a6f5c83f83cbfdedcbd78b1
server inner-tunnel {
Mon Sep 28 18:11:55 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/inner-tunnel
Mon Sep 28 18:11:55 2015 : Info: +group authorize {
Mon Sep 28 18:11:55 2015 : Info: ++[chap] = noop
Mon Sep 28 18:11:55 2015 : Info: ++[mschap] = noop
Mon Sep 28 18:11:55 2015 : Info: [suffix] No '@' in User-Name = "anisa", looking up realm NULL
Mon Sep 28 18:11:55 2015 : Info: [suffix] No such realm "NULL"
Mon Sep 28 18:11:55 2015 : Info: ++[suffix] = noop
Mon Sep 28 18:11:55 2015 : Info: ++update control {
Mon Sep 28 18:11:55 2015 : Info: ++} # update control = noop
Mon Sep 28 18:11:55 2015 : Info: [eap] EAP packet type response id 8 length 6
Mon Sep 28 18:11:55 2015 : Info: [eap] No EAP Start, assuming it's an on-going EAP conversation
Mon Sep 28 18:11:55 2015 : Info: ++[eap] = updated
Mon Sep 28 18:11:55 2015 : Info: [files] users: Matched entry anisa at line 97
Mon Sep 28 18:11:55 2015 : Info: ++[files] = ok
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{Stripped-User-Name} ->
Mon Sep 28 18:11:55 2015 : Info: [sql] ... expanding second conditional
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{User-Name} -> anisa
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> anisa
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> anisa
Mon Sep 28 18:11:55 2015 : Info: [sql] sql_set_user escaped user --> 'anisa'
Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 26
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radcheck WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radcheck WHERE username = 'anisa' ORDER BY id
Mon Sep 28 18:11:55 2015 : Info: [sql] User found in radcheck table
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, username, attribute, value, op FROM radreply WHERE username = '%{SQL-User-Name}' ORDER BY id -> SELECT id, username, attribute, value, op FROM radreply WHERE username = 'anisa' ORDER BY id
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT groupname FROM radusergroup WHERE username = '%{SQL-User-Name}' ORDER BY priority -> SELECT groupname FROM radusergroup WHERE username = 'anisa' ORDER BY priority
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, Value, op FROM radgroupcheck WHERE groupname = 'dynamic' ORDER BY id
Mon Sep 28 18:11:55 2015 : Info: [sql] User found in group dynamic
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = '%{Sql-Group}' ORDER BY id -> SELECT id, groupname, attribute, value, op FROM radgroupreply WHERE groupname = 'dynamic' ORDER BY id
Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Released sql socket id: 26
Mon Sep 28 18:11:55 2015 : Info: ++[sql] = ok
Mon Sep 28 18:11:55 2015 : Info: ++[expiration] = noop
Mon Sep 28 18:11:55 2015 : Info: ++[logintime] = noop
Mon Sep 28 18:11:55 2015 : Info: [pap] WARNING: Auth-Type already set. Not setting to PAP
Mon Sep 28 18:11:55 2015 : Info: ++[pap] = noop
Mon Sep 28 18:11:55 2015 : Info: +} # group authorize = updated
Mon Sep 28 18:11:55 2015 : Info: Found Auth-Type = EAP
Mon Sep 28 18:11:55 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/inner-tunnel
Mon Sep 28 18:11:55 2015 : Info: +group authenticate {
Mon Sep 28 18:11:55 2015 : Info: [eap] Request found, released from the list
Mon Sep 28 18:11:55 2015 : Info: [eap] EAP/mschapv2
Mon Sep 28 18:11:55 2015 : Info: [eap] processing type mschapv2
Mon Sep 28 18:11:55 2015 : Info: [eap] Freeing handler
Mon Sep 28 18:11:55 2015 : Info: ++[eap] = ok
Mon Sep 28 18:11:55 2015 : Info: +} # group authenticate = ok
Mon Sep 28 18:11:55 2015 : Info: # Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/inner-tunnel
Mon Sep 28 18:11:55 2015 : Info: +group post-auth {
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{Stripped-User-Name} ->
Mon Sep 28 18:11:55 2015 : Info: [sql] ... expanding second conditional
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{User-Name} -> anisa
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> anisa
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> anisa
Mon Sep 28 18:11:55 2015 : Info: [sql] sql_set_user escaped user --> 'anisa'
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{User-Password} ->
Mon Sep 28 18:11:55 2015 : Info: [sql] ... expanding second conditional
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{Chap-Password} ->
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'anisa', '', 'Access-Accept', '2015-09-28 18:11:55')
Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'anisa', '', 'Access-Accept', '2015-09-28 18:11:55')
Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 25
Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Released sql socket id: 25
Mon Sep 28 18:11:55 2015 : Info: ++[sql] = ok
Mon Sep 28 18:11:55 2015 : Info: +} # group post-auth = ok
} # server inner-tunnel
Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled reply code 2
Service-Type := Framed-User
Acct-Interim-Interval := 300
MS-MPPE-Encryption-Policy = 0x00000001
MS-MPPE-Encryption-Types = 0x00000006
MS-MPPE-Send-Key = 0xbfa620e08b1e488d52de139d6ff937e5
MS-MPPE-Recv-Key = 0x64dee5827ef29d967c023a071cdde43e
EAP-Message = 0x03080004
Message-Authenticator = 0x00000000000000000000000000000000
User-Name = "anisa"
Mon Sep 28 18:11:55 2015 : Info: [peap] Got tunneled reply RADIUS code Access-Accept
Service-Type := Framed-User
Acct-Interim-Interval := 300
MS-MPPE-Encryption-Policy = 0x00000001
MS-MPPE-Encryption-Types = 0x00000006
MS-MPPE-Send-Key = 0xbfa620e08b1e488d52de139d6ff937e5
MS-MPPE-Recv-Key = 0x64dee5827ef29d967c023a071cdde43e
EAP-Message = 0x03080004
Message-Authenticator = 0x00000000000000000000000000000000
User-Name = "anisa"
Mon Sep 28 18:11:55 2015 : Info: [peap] Tunneled authentication was successful.
Mon Sep 28 18:11:55 2015 : Info: [peap] SUCCESS
Mon Sep 28 18:11:55 2015 : Info: ++[eap] = handled
Mon Sep 28 18:11:55 2015 : Info: +} # group authenticate = handled
Sending Access-Challenge of id 8 to 192.168.1.50 port 1470
EAP-Message = 0x0109002b19001703010020106737f22f11fcfbd10498cc96e4e8aac4a5f4afcbfe9671590dca0fb2c080a9
Message-Authenticator = 0x00000000000000000000000000000000
State = 0xc3eeda0ccbe7c372bc5743d8d31a4433
Mon Sep 28 18:11:55 2015 : Info: Finished request 8.
Mon Sep 28 18:11:55 2015 : Debug: Going to the next request
Mon Sep 28 18:11:55 2015 : Debug: Waking up in 3.0 seconds.
rad_recv: Access-Request packet from host 192.168.1.50 port 1470, id=9, length=244
Message-Authenticator = 0x0ba8761e38d7451894d5974c2bda5be1
Service-Type = Framed-User
User-Name = "anisa"
Framed-MTU = 1488
State = 0xc3eeda0ccbe7c372bc5743d8d31a4433
Called-Station-Id = "B8-A3-86-92-86-B7:testconn"
Calling-Station-Id = "50-1A-C5-07-FB-74"
NAS-Identifier = "D-Link Access Point"
NAS-Port-Type = Wireless-802.11
Connect-Info = "CONNECT 54Mbps 802.11g"
EAP-Message = 0x0209002b19001703010020759b0d2b7486951db12fa7f4eff5b2e88aedbfa86e323ceeac2c40fd656b2d50
NAS-IP-Address = 192.168.1.50
NAS-Port = 1
NAS-Port-Id = "STA port # 1"
Mon Sep 28 18:11:55 2015 : Info: # Executing section authorize from file /usr/local/etc/raddb/sites-enabled/default
Mon Sep 28 18:11:55 2015 : Info: +group authorize {
Mon Sep 28 18:11:55 2015 : Info: ++[preprocess] = ok
Mon Sep 28 18:11:55 2015 : Info: ++[chap] = noop
Mon Sep 28 18:11:55 2015 : Info: ++[mschap] = noop
Mon Sep 28 18:11:55 2015 : Info: ++[digest] = noop
Mon Sep 28 18:11:55 2015 : Info: [suffix] No '@' in User-Name = "anisa", looking up realm NULL
Mon Sep 28 18:11:55 2015 : Info: [suffix] No such realm "NULL"
Mon Sep 28 18:11:55 2015 : Info: ++[suffix] = noop
Mon Sep 28 18:11:55 2015 : Info: [eap] EAP packet type response id 9 length 43
Mon Sep 28 18:11:55 2015 : Info: [eap] Continuing tunnel setup.
Mon Sep 28 18:11:55 2015 : Info: ++[eap] = ok
Mon Sep 28 18:11:55 2015 : Info: +} # group authorize = ok
Mon Sep 28 18:11:55 2015 : Info: Found Auth-Type = EAP
Mon Sep 28 18:11:55 2015 : Info: # Executing group from file /usr/local/etc/raddb/sites-enabled/default
Mon Sep 28 18:11:55 2015 : Info: +group authenticate {
Mon Sep 28 18:11:55 2015 : Info: [eap] Request found, released from the list
Mon Sep 28 18:11:55 2015 : Info: [eap] EAP/peap
Mon Sep 28 18:11:55 2015 : Info: [eap] processing type peap
Mon Sep 28 18:11:55 2015 : Info: [peap] processing EAP-TLS
Mon Sep 28 18:11:55 2015 : Info: [peap] eaptls_verify returned 7
Mon Sep 28 18:11:55 2015 : Info: [peap] Done initial handshake
Mon Sep 28 18:11:55 2015 : Info: [peap] eaptls_process returned 7
Mon Sep 28 18:11:55 2015 : Info: [peap] EAPTLS_OK
Mon Sep 28 18:11:55 2015 : Info: [peap] Session established. Decoding tunneled attributes.
Mon Sep 28 18:11:55 2015 : Info: [peap] Peap state send tlv success
Mon Sep 28 18:11:55 2015 : Info: [peap] Received EAP-TLV response.
Mon Sep 28 18:11:55 2015 : Info: [peap] Success
Mon Sep 28 18:11:55 2015 : Info: [eap] Freeing handler
Mon Sep 28 18:11:55 2015 : Info: ++[eap] = ok
Mon Sep 28 18:11:55 2015 : Info: +} # group authenticate = ok
Mon Sep 28 18:11:55 2015 : Info: # Executing section post-auth from file /usr/local/etc/raddb/sites-enabled/default
Mon Sep 28 18:11:55 2015 : Info: +group post-auth {
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{Stripped-User-Name} ->
Mon Sep 28 18:11:55 2015 : Info: [sql] ... expanding second conditional
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{User-Name} -> anisa
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> anisa
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> anisa
Mon Sep 28 18:11:55 2015 : Info: [sql] sql_set_user escaped user --> 'anisa'
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{User-Password} ->
Mon Sep 28 18:11:55 2015 : Info: [sql] ... expanding second conditional
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: %{Chap-Password} ->
Mon Sep 28 18:11:55 2015 : Info: [sql] expand: INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( '%{User-Name}', '%{%{User-Password}:-%{Chap-Password}}', '%{reply:Packet-Type}', '%S') -> INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'anisa', '', 'Access-Accept', '2015-09-28 18:11:55')
Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql) in sql_postauth: query is INSERT INTO radpostauth (username, pass, reply, authdate) VALUES ( 'anisa', '', 'Access-Accept', '2015-09-28 18:11:55')
Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 24
Mon Sep 28 18:11:55 2015 : Debug: rlm_sql (sql): Released sql socket id: 24
Mon Sep 28 18:11:55 2015 : Info: ++[sql] = ok
Mon Sep 28 18:11:55 2015 : Info: ++[exec] = noop
Mon Sep 28 18:11:55 2015 : Info: +} # group post-auth = ok
Sending Access-Accept of id 9 to 192.168.1.50 port 1470
MS-MPPE-Recv-Key = 0x42efb6e0ef913216d3db461ba6cfda613405babfd84fdf31401796ad8e0e630b
MS-MPPE-Send-Key = 0xacf63f04031d9623cb14e101cf636cedd674bb9635bbdec29945d12bc0c3a7cb
EAP-Message = 0x03090004
Message-Authenticator = 0x00000000000000000000000000000000
User-Name = "anisa"
Mon Sep 28 18:11:55 2015 : Info: Finished request 9.
Mon Sep 28 18:11:55 2015 : Debug: Going to the next request
Mon Sep 28 18:11:55 2015 : Debug: Waking up in 2.9 seconds.
rad_recv: Accounting-Request packet from host 192.168.1.50 port 1471, id=2, length=100
Acct-Status-Type = Start
Acct-Delay-Time = 0
Acct-Session-Id = "0000000018:0000000048"
Acct-Authentic = RADIUS
Acct-Multi-Session-Id = "anisa"
User-Name = "anisa"
Calling-Station-Id = "50-1a-c5-07-fb-74"
NAS-IP-Address = 192.168.1.50
Mon Sep 28 18:11:57 2015 : Info: # Executing section preacct from file /usr/local/etc/raddb/sites-enabled/default
Mon Sep 28 18:11:57 2015 : Info: +group preacct {
Mon Sep 28 18:11:57 2015 : Info: ++[preprocess] = ok
Mon Sep 28 18:11:57 2015 : Info: [acct_unique] WARNING: Attribute NAS-Port was not found in request, unique ID MAY be inconsistent
Mon Sep 28 18:11:57 2015 : Info: [acct_unique] WARNING: Attribute NAS-Identifier was not found in request, unique ID MAY be inconsistent
Mon Sep 28 18:11:57 2015 : Info: [acct_unique] Hashing ',,NAS-IP-Address = 192.168.1.50,Acct-Session-Id = "0000000018:0000000048",User-Name = "anisa"'
Mon Sep 28 18:11:57 2015 : Info: [acct_unique] Acct-Unique-Session-ID = "b404cb6fbd3afd18".
Mon Sep 28 18:11:57 2015 : Info: ++[acct_unique] = ok
Mon Sep 28 18:11:57 2015 : Info: [suffix] No '@' in User-Name = "anisa", looking up realm NULL
Mon Sep 28 18:11:57 2015 : Info: [suffix] No such realm "NULL"
Mon Sep 28 18:11:57 2015 : Info: ++[suffix] = noop
Mon Sep 28 18:11:57 2015 : Info: ++[files] = noop
Mon Sep 28 18:11:57 2015 : Info: +} # group preacct = ok
Mon Sep 28 18:11:57 2015 : Info: # Executing section accounting from file /usr/local/etc/raddb/sites-enabled/default
Mon Sep 28 18:11:57 2015 : Info: +group accounting {
Mon Sep 28 18:11:57 2015 : Info: [detail] expand: %{Packet-Src-IP-Address} -> 192.168.1.50
Mon Sep 28 18:11:57 2015 : Info: [detail] expand: /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d -> /usr/local/var/log/radius/radacct/192.168.1.50/detail-20150928
Mon Sep 28 18:11:57 2015 : Info: [detail] /usr/local/var/log/radius/radacct/%{%{Packet-Src-IP-Address}:-%{Packet-Src-IPv6-Address}}/detail-%Y%m%d expands to /usr/local/var/log/radius/radacct/192.168.1.50/detail-20150928
Mon Sep 28 18:11:57 2015 : Info: [detail] expand: %t -> Mon Sep 28 18:11:57 2015
Mon Sep 28 18:11:57 2015 : Info: ++[detail] = ok
Mon Sep 28 18:11:57 2015 : Info: [sql] expand: %{Stripped-User-Name} ->
Mon Sep 28 18:11:57 2015 : Info: [sql] ... expanding second conditional
Mon Sep 28 18:11:57 2015 : Info: [sql] expand: %{User-Name} -> anisa
Mon Sep 28 18:11:57 2015 : Info: [sql] expand: %{%{User-Name}:-DEFAULT} -> anisa
Mon Sep 28 18:11:57 2015 : Info: [sql] expand: %{%{Stripped-User-Name}:-%{%{User-Name}:-DEFAULT}} -> anisa
Mon Sep 28 18:11:57 2015 : Info: [sql] sql_set_user escaped user --> 'anisa'
Mon Sep 28 18:11:57 2015 : Info: [sql] expand: %{Acct-Delay-Time} -> 0
Mon Sep 28 18:11:57 2015 : Info: [sql] expand: INSERT INTO radacct (acctsessionid, acctuniqueid, username, realm, nasipaddress, nasportid, nasporttype, acctstarttime, acctstoptime, acctsessiontime, acctauthentic, connectinfo_start, connectinfo_stop, acctinputoctets, acctoutputoctets, calledstationid, callingstationid, acctterminatecause, servicetype, framedprotocol, framedipaddress, acctinputpackets, acctoutputpackets, acctstartdelay, acctstopdelay, xascendsessionsvrkey) VALUES ('%{Acct-Session-Id}', '%{Acct-Unique-Session-Id}', '%{SQL-User-Name}', '%{Realm}', '%{NAS-IP-Address}', '%{NAS-Port}', '%{NAS-Port-Type}', '%S', NULL, '0', '%{Acct-Authentic}', '%{Connect-Info}', '', '0', '0', '%{Called-Station-Id}', '%{Calling-Station-Id}', '', '%{Service-Type}', '%{Framed-Prot
Mon Sep 28 18:11:57 2015 : Debug: rlm_sql (sql): Reserving sql socket id: 23
Mon Sep 28 18:11:57 2015 : Debug: rlm_sql (sql): Released sql socket id: 23
Mon Sep 28 18:11:57 2015 : Info: ++[sql] = ok
Mon Sep 28 18:11:57 2015 : Info: ++[exec] = noop
Mon Sep 28 18:11:57 2015 : Info: [attr_filter.accounting_response] expand: %{User-Name} -> anisa
Mon Sep 28 18:11:57 2015 : Debug: attr_filter: Matched entry DEFAULT at line 12
Mon Sep 28 18:11:57 2015 : Info: ++[attr_filter.accounting_response] = updated
Mon Sep 28 18:11:57 2015 : Info: +} # group accounting = updated
Sending Accounting-Response of id 2 to 192.168.1.50 port 1471
Mon Sep 28 18:11:57 2015 : Info: Finished request 10.
Mon Sep 28 18:11:57 2015 : Info: Cleaning up request 10 ID 2 with timestamp +98
Mon Sep 28 18:11:57 2015 : Debug: Going to the next request
Mon Sep 28 18:11:57 2015 : Debug: Waking up in 1.0 seconds.
Mon Sep 28 18:11:58 2015 : Info: Cleaning up request 0 ID 0 with timestamp +94
Mon Sep 28 18:11:58 2015 : Info: Cleaning up request 1 ID 1 with timestamp +94
Mon Sep 28 18:11:58 2015 : Info: Cleaning up request 2 ID 2 with timestamp +94
Mon Sep 28 18:11:58 2015 : Info: Cleaning up request 3 ID 3 with timestamp +94
Mon Sep 28 18:11:58 2015 : Info: Cleaning up request 4 ID 4 with timestamp +94
Mon Sep 28 18:11:58 2015 : Debug: Waking up in 1.8 seconds.
Mon Sep 28 18:12:00 2015 : Info: Cleaning up request 5 ID 5 with timestamp +96
Mon Sep 28 18:12:00 2015 : Info: Cleaning up request 6 ID 6 with timestamp +96
Mon Sep 28 18:12:00 2015 : Info: Cleaning up request 7 ID 7 with timestamp +96
Mon Sep 28 18:12:00 2015 : Info: Cleaning up request 8 ID 8 with timestamp +96
Mon Sep 28 18:12:00 2015 : Info: Cleaning up request 9 ID 9 with timestamp +96
Mon Sep 28 18:12:00 2015 : Info: Ready to process requests.
On Mon, Sep 28, 2015 at 6:53 PM, Anisa Allahdadi <anisa.alla@gmail.com> wrote:
Hi all,
There is just one NAS, and 4-5 mobile stations.
I realized that there are 2 passes for the devices to get authenticated (I guess the second one is due to checking the certificates). And I see that in the first pass, Access-Accept *contains* the Acct-Interim-Update, but the second Access-Accecpt *does not*. I'm not saying the problem is with FreeRadius, I guess it might be related to the authentication, or my certificates, or my proxy setting.
I ran radiusd -XXX and attached the output for what I got from two different users: *anisa* is the not working user and *lin* is the working user. Sorry for the long text, I did some highlights.
Thanks for the help
On Mon, Sep 28, 2015 at 5:38 PM, <A.L.M.Buxey@lboro.ac.uk> wrote:
Hi,
I don't understand you guys! All I'm saying is that one of my stations sends Interim-Updates and the others do not, so the problem shouldn't be with NAS. If you don't want to help, feel free and don't. I don't expect
why do you think the RADIUS server is the place to look? one of them sends the data, the others dont. so, are they the same make, do they have the same firmware? do they have the same configuration? a NAS does what a NAS does. look at the NAS.
alan - List info/subscribe/unsubscribe? See http://www.freeradius.org/list/users.html
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.
The attributes that you send from FreeRADIUS in Access-Accepts are all up to you. It depends on how you configure the RADIUS server. There is no bug in FreeRADIUS here, if you are sending the attribute in one case but not another look at where you have misconfigured the RADIUS server.
If the software on an AP doesn't support sending Interim-Updates, you need a different AP with software that does. Nick
participants (7)
-
A.L.M.Buxey＠lboro.ac.uk -
Alan DeKok -
Anisa Allahdadi -
Brock Eastman -
Nick Lowe -
Randeep -
Vijay S