Per SSID authentication on ACS 5

Answered Question
Feb 23rd, 2012

Hi Everyone

I have noticed that with a basic setup on ACS 5 I can not differentiate between PEAP clients that i want to authenticate against AD and PEAP clients that I want to authenticate against a locally created database on the ACS. All clients, regardless of what SSID they are connected to, will be tried against the AD if there is no match the the client is promted for a username and password to be authenticated against the local information store.

Can someone point me to some documentaion that describes how I can seperate the two, so that the clients on one SSID are checked against AD and clients on another are checked against the local info store.

Many thanks

Simon

I have this problem too.
0 votes
Correct Answer by airframes about 2 years 1 month ago

Simon,

One of the attributes that the WLC sends in a RADIUS authentication request is the Called-Station-ID field. That field contains both the BSSID and ESSID (WLAN name) the client is trying to access, which means that you can do a compare on this field as a condition of your access rule. The format is xx-xx-xx-xx-xx-xx:wlanName. We don't really care about the BSSID, but the WLAN at the end of this string is very useful.

Here's how you can use this attribute value to influence access policy decisions:

1. Create a custom session condition (under Policy Elements) of type RADIUS-IETF using the Called-Station-ID (not the Calling-Station-ID).

2. Customize your access policy template so that your new custom session condition is available to your access policies

3. Edit your access policy: a) check the custom session condition to enable it, b) choose the "Ends with" operator, and c) type in the name of your WLAN (case sensitive).

Justin

  • 1
  • 2
  • 3
  • 4
  • 5
Average Rating: 5 (3 ratings)
Correct Answer
airframes Thu, 02/23/2012 - 18:12

Simon,

One of the attributes that the WLC sends in a RADIUS authentication request is the Called-Station-ID field. That field contains both the BSSID and ESSID (WLAN name) the client is trying to access, which means that you can do a compare on this field as a condition of your access rule. The format is xx-xx-xx-xx-xx-xx:wlanName. We don't really care about the BSSID, but the WLAN at the end of this string is very useful.

Here's how you can use this attribute value to influence access policy decisions:

1. Create a custom session condition (under Policy Elements) of type RADIUS-IETF using the Called-Station-ID (not the Calling-Station-ID).

2. Customize your access policy template so that your new custom session condition is available to your access policies

3. Edit your access policy: a) check the custom session condition to enable it, b) choose the "Ends with" operator, and c) type in the name of your WLAN (case sensitive).

Justin

George Stefanick Thu, 02/23/2012 - 20:26

Justin +5 !

Nice response!

Can you add any additional links for more reading on this or config examples?

airframes Thu, 02/23/2012 - 23:32

George,

I sort of cobbled this together with a packet sniff to figure out which fields I had available. The project I did this on was for w2k8 and I ported the solution over to ACS. Short answer is I don't have any docs or vids to link, but I'm happy to put a how-to together. Give me a few days and I'll post something a little more detailed.

Justin

Sent from Cisco Technical Support iPhone App

Nicholas Poole Fri, 02/24/2012 - 05:29

Im trying this with a Cisco autonomous AP but it doesnt seem to work.  I assume in IOS mode the AP will still be sending the RADIUS attribute required?

Scott Fella Fri, 02/24/2012 - 05:43

The best way to see the value is being passed is authenticate and look at the ACS logs. It will show you the mac address and the SSID if the attribute is being passed to the radius server.

Thanks,

Scott Fella

Sent from my iPhone

Nicholas Poole Fri, 02/24/2012 - 05:46

was just looking at at.  its sending the called-station-id as the MAC of the BVI0 inteface.  AP debug follows:

*Mar  1 04:12:54.238: RADIUS:  User-Name           [1]   15  "TEST\testwlan"

*Mar  1 04:12:54.238: RADIUS:  Framed-MTU          [12]  6   1400

*Mar  1 04:12:54.238: RADIUS:  Called-Station-Id   [30]  16  "b414.895b.ccc0"

*Mar  1 04:12:54.238: RADIUS:  Calling-Station-Id  [31]  16  "001e.4cb2.bfe1"

*Mar  1 04:12:54.238: RADIUS:  Service-Type        [6]   6   Login                     [1]

so it doesnt seem to be sending a SSID as the ID.

Scott Fella Fri, 02/24/2012 - 06:05

If it doesn't send the SSID name after the mac address, you will not be able to filter on the SSID. On ACS, the NAR field you can set is:

CLI - The calling-station-id attribute 31

DNID - The called-station-id attribute 30

Thanks,

Scott Fella

Sent from my iPhone

Nicholas Poole Fri, 02/24/2012 - 06:09

Went with a hunch and added the following commands i have to add for dot1x to work on the LAN:

radius-server vsa send accounting

radius-server vsa send authentication

The AP debug then shows:

*Mar  1 04:33:44.586: RADIUS:  User-Name           [1]   15  "TEST\testwlan"

*Mar  1 04:33:44.586: RADIUS:  Framed-MTU          [12]  6   1400

*Mar  1 04:33:44.586: RADIUS:  Called-Station-Id   [30]  16  "b414.895b.ccc0"

*Mar  1 04:33:44.586: RADIUS:  Calling-Station-Id  [31]  16  "001e.4cb2.bfe1"

*Mar  1 04:33:44.586: RADIUS:  Vendor, Cisco       [26]  18

*Mar  1 04:33:44.586: RADIUS:   Cisco AVpair       [1]   12  "ssid=Test2"

*Mar  1 04:33:44.586: RADIUS:  Service-Type        [6]   6   Login                     [1]

So I have now created a Service Selection Rule with a Compound Condition of: RADIUS-Cisco:cisco-av-pair equals ssid=Test2

and it now matches :-)

Thanks all

airframes Fri, 02/24/2012 - 07:51

Nicholas,

Wireless LAN Controllers send SSID in Called-Station-ID.

From what I see in the the rest of the thread, it looks like this field wouldn't work for an autonomous AP deployment.

Justin

Sent from Cisco Technical Support iPhone App

Scott Fella Fri, 02/24/2012 - 05:16

Here are a couple links that explain it in general. It's the same concept from the 4.2 guide to 5.x. You can also achieve this using IAS or NPS, but you have to use a different wildcard.

http://www.cisco.com/en/US/tech/tk722/tk809/technologies_configuration_example09186a00807669af.shtml

https://supportforums.cisco.com/thread/2081646

http://www.routerdiscussions.com/viewtopic.php?f=7&t=9020

Thanks,

Scott Fella

Sent from my iPhone

Scott Fella Fri, 02/24/2012 - 05:18

Oh... If you do this for ISE, you use the same attribute but the value is .*SSIDNAME

Thanks,

Scott Fella

Sent from my iPhone

s.vosper Thu, 02/23/2012 - 23:57

Justin

Thank you for your responce, thats really helpful. I will give it a try and re-post with the results.

Thanks

Simon

Scott Fella Fri, 02/24/2012 - 07:01

Thanks for posting your solution!

Sent from Cisco Technical Support iPhone App

s.vosper Mon, 02/27/2012 - 06:30

Is there anything I need to do on the controller. I am begin challenged for a user name and password but getting authentication failures with the failure "Check Service Selection Rules".

s.vosper Mon, 02/27/2012 - 08:32

Ok. I had these setup as compound conditions within the rules too. I have taken the compound condition out and am just using the custom session condition and the authentication now works and I am getting hits on my custom rules.

Thanks all

Simon

s.vosper Wed, 02/29/2012 - 02:26

Hello again everyone. A little more advice is needed here please. The device that I have setup up is now authenticated and seems to stay connected, but i am getting a constant stream of Authentication failures from it with the reason "11019 Selected DenyAccess Service". This is punctured with the occassional authentication pass.

airframes Wed, 02/29/2012 - 12:51

Simon,

What is the OS of your endpoint? Are you using Windows? If so, it could be that your supplicant is submitting both machine auth and user auth. You can configure the supplicant to use just one or the the other (or both):

802.1x-w7.png

Lots of additional, unnecessary authentications are commonly the result of the default setting "user or computer authentication." When deploying in Windows environments, I recommend setting this value statically based on the actual configured mode of authentication at the RADIUS server.

Justin

s.vosper Thu, 03/01/2012 - 00:51

Hi Justin

Thank you for posting. The clients are a bit of a mixure. There are some Zebra printers, some Windows XP clients, some Windows 7 clients and some handheld scanners that are running a mobile Windows version. I can certainly check the windows machines. The Zebra printers and the handheld windows mobile devices seem to be the worst offenders.

Thanks

Simon

s.vosper Thu, 03/01/2012 - 02:01

The client device re-authenticates every 30 mins by design, but the successful authentication is followed by a string of failures:

airframes Thu, 03/01/2012 - 23:59

Simon,

I've set up a policy in my ACS 5.2 lab to look at the Called-Station-ID and match on SSID. I'm not seeing any repeat failures. Once my W7 test client is authenticated, the logs are quiet for a full 30 minutes, at which point the WLAN session timer expires and the client authenticates again.

Can you open the details page on one of your failed authentications and post a screen shot here? (Monitoring and Reports --> Dashboard --> Troubleshooting tab --> magnifying glass next to log entry) .

Also, what other elements of your policy can you tell me about?

  • Besides Called-Station-ID, do you have any other conditions in your Service Selection rule?
  • How is your Results Access Service defined?
    • What protocols are allowed as part of the Access Service?
    • What identity store are you using in the identity policy?
    • What is your compound condition within the identity policy?



I'm trying to get an idea if you have any erroneous parameters in the policy that may be causing these issues (from the server side), or if we need to lok instead at clients for the answers. Feel free to post with sanitized screen shots if that's easier for you.

Justin

s.vosper Fri, 03/02/2012 - 02:30

Hi Justin

Thanks again for taking the time out to help with this.

Here is the failed auth details:

So here goes. I'm a bit of an ACS novice so forgive me if my terminology is wrong here.....

I have a Service Selection Poliy configured for each of the 3 seperate SSIDs that I want to work with. Each is configured to match Radius with an SSID name like so ( i have sanitised the SSID for security):

Each ones results point to the access service "WLANauthACS"

Within this service I have configured 3 authorisation policies. Again one for each SSID thus:

What we hope to achieve is, users connecting to a specific SSID, are authenticated with a user in the internal identity store within a specific group for that SSID.

This is actually working fine connectivity wise, but i am a little concered as to why we are seeing a raft of failures straight after a user authenticates.

We also have a service selection rule that does a similar thing on a 4th SSID that authenticates users against an AD external database and this works fine.

Incidently when I change the "default" service selection rule to our WLANauthACS service, the extra authentication attempts that are being generated turn in to passes rather than failures.

THanks

Simon

airframes Mon, 03/05/2012 - 13:51

Simon,

My apologies for the delayed response.

I've looked over your screenshots and explanations, and while they look like they should work as written, I think they can be simplified and brought more in line with how ACS is designed to achieve what you're trying to do. I will say that I'm not so sure that the way the policies are written is causing the problem we're troubleshooting, but I think we should try to simplify first, just to make sure that we're not hitting any issues with the policy processing.

So a few things, both right and that could use some adjustment:

  • The first is that the condition phase of your service selection policies look good to me. You're selecting a processing method (an "Access Service") based on what SSID the user is coming in on. As we've previously established, that service selection decision is being made against the last part of the Called-Station-ID field, which, when sent by the WLC, contains the SSID the client is trying to authenticate to.

  • The results phase of your service selection policy is where I would make some changes. You are starting out with 3 different service selection policies, so what I would do is create 3 different Access Services, one each that is set up to authenticate for the 3 different SSIDs that clients associate with. So, for service selection policy 1, which compares for yourSSID1, you would make the Results select WLANauthACS-yourSSID1. I.e.,
    • SSID1 --> AccessService1
    • SSID2 --> AccessService2
    • SSID3 --> AccessService3

  • Now for each of these three separate Access Services, do the following:
    • On the main properties sheet, enable all of the check boxes: Identity, Group Mapping, Authorization (Identity and Authorization are selected already, so just put a check box next to Group Mapping)
    • In the Identity Policy, get rid of the Compound Condition that checks for the group membership and instead just customize so that rule checks for a simple condition (you need at least one). I use "Protocol" and set it to equal "Radius"
    • In the Identity Policy, get rid of the condition ("ACSauthCondition") that checks Called-Station-ID for your SSID. You already did that in the service selection policy, and because this Access Service is selected specifically based on that result, you don't need it here.
    • In the Identity Policy Results, select Internal Users as the identity source
    • Now go into Group Mapping (click it in the left nav window, under your access policy, now visible between Identiy and Authorization)
    • You should be able to see and select the specific user group you want to use for this Access Policy



Your processing now goes like this:

If SSID1 --> then AccessPolicy1 --> [ protocol=radius (always true) + user is in Internal Users:customUserGroup1 ] --> access allowed

I think that will clean things up a little so that you're not making multiple comparisons on the same fields per policy, which may be interfering with the scan gun authentications.

Can you give that a try and see if the authentication errors persist? If so, then we'll want to look at the clients to see why they're trying to reauth so frequently.

Justin


s.vosper Tue, 03/06/2012 - 03:35

Hi Justin

I have re-configured the ACS to follow what you suggested and I still am getting failed attempts generated straight after a passed attempt. It appears that the failures are happening at the point of service selection. The "default" rule is the one thats clocking up the hits when its set to deny access.

Its almost as if the client device is sending multiple authentication requests but only one matches the service selection rule for matching the SSID.

Incidently, I created n additional user so that I could test it with my Windows 7 laptop and it did the same thing, so I would be suprised if it was a client issue.

Regards

Simon

airframes Tue, 03/06/2012 - 13:56

Simon,

Can you do a client debug on the controller to see if we're actually seeing additional authentication requests being sent from there? If we're seeing logs show up in ACS, it makes me think that it's because the ACS is actually recieving these requests from the WLC. But if the WLC is not sending them, then I think you are right--the ACS sounds like the issue.

On the controller:

>debug client

>debug aaa all enable

>debug dot1x all enable

Could you include enought logging events from an offending client across a the timeframe over which the ACS shows a successful authentication followed by two or three DenyAccess messages?

Justin

airframes Tue, 03/06/2012 - 21:50

Simon,

I was just looking around in ACS and I was wondering if maybe you have an authorization profile that is triggering these errors. Can you tell me what your Access Service authorization rule(s) are, and if you have none defined, can you look at the default rule at the bottom of the window and tell me what is defined there? Here is a screenshot of this on my system (one of my Access Services is arbitrarily called PEAP):

Justin

s.vosper Wed, 03/07/2012 - 02:33

Hi Justin

None of the active access services have authorization policies configured. The default service selection rule that denys services if no rule is met seems to be where all the denials are coming from. With fifty or sixty devices hitting 8 or nine failures every thirty mins the counter is going up quickly.

Below is the debug for the device. I switched it off and on again so you could observe the authentication process:

(Cisco Controller) >*apfReceiveTask: Mar 07 10:12:09.509: 00:19:70:7a:e0:85 0.0.0.0 DHCP_REQD (7) DHCP Policy timeout. Number of DHCP request 0 from client
*apfReceiveTask: Mar 07 10:12:09.509: 00:19:70:7a:e0:85 0.0.0.0 DHCP_REQD (7) Pem timed out, Try to delete client in 10 secs.
*apfReceiveTask: Mar 07 10:12:09.509: 00:19:70:7a:e0:85 Scheduling deletion of Mobile Station:  (callerId: 12) in 10 seconds
*osapiBsnTimer: Mar 07 10:12:19.509: 00:19:70:7a:e0:85 apfMsExpireCallback (apf_ms.c:608) Expiring Mobile!
*apfReceiveTask: Mar 07 10:12:19.509: 00:19:70:7a:e0:85 apfMsExpireMobileStation (apf_ms.c:5009) Changing state for mobile 00:19:70:7a:e0:85 on AP 0c:85:25:69:fd:90 from Associated to Disassociated

*apfReceiveTask: Mar 07 10:12:19.509: 00:19:70:7a:e0:85 Scheduling deletion of Mobile Station:  (callerId: 45) in 10 seconds
*osapiBsnTimer: Mar 07 10:12:29.509: 00:19:70:7a:e0:85 apfMsExpireCallback (apf_ms.c:608) Expiring Mobile!
*apfReceiveTask: Mar 07 10:12:29.509: 00:19:70:7a:e0:85 Sent Deauthenticate to mobile on BSSID 0c:85:25:69:fd:90 slot 0(caller apf_ms.c:5094)
*apfReceiveTask: Mar 07 10:12:29.509: 00:19:70:7a:e0:85 apfMsAssoStateDec
*apfReceiveTask: Mar 07 10:12:29.509: 00:19:70:7a:e0:85 apfMsExpireMobileStation (apf_ms.c:5132) Changing state for mobile 00:19:70:7a:e0:85 on AP 0c:85:25:69:fd:90 from Disassociated to Idle

*apfReceiveTask: Mar 07 10:12:29.510: 00:19:70:7a:e0:85 0.0.0.0 DHCP_REQD (7) Deleted mobile LWAPP rule on AP [0c:85:25:69:fd:90]
*apfReceiveTask: Mar 07 10:12:29.510: 00:19:70:7a:e0:85 Username entry deleted for mobile
*apfReceiveTask: Mar 07 10:12:29.510: 00:19:70:7a:e0:85 apfMs1xStateDec
*apfReceiveTask: Mar 07 10:12:29.510: 00:19:70:7a:e0:85 Deleting mobile on AP 0c:85:25:69:fd:90(0)
*pemReceiveTask: Mar 07 10:12:29.511: 00:19:70:7a:e0:85 0.0.0.0 Removed NPU entry.
*apfMsConnTask_0: Mar 07 10:12:37.955: 00:19:70:7a:e0:85 Adding mobile on LWAPP AP 0c:85:25:69:fd:90(0)
*apfMsConnTask_0: Mar 07 10:12:37.955: 00:19:70:7a:e0:85 Association received from mobile on AP 0c:85:25:69:fd:90
*apfMsConnTask_0: Mar 07 10:12:37.955: 00:19:70:7a:e0:85 0.0.0.0 START (0) Changing ACL 'Vehicle Mounts' (ACL ID 0) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1621)
*apfMsConnTask_0: Mar 07 10:12:37.955: 00:19:70:7a:e0:85 Applying site-specific IPv6 override for station 00:19:70:7a:e0:85 - vapId 4, site 'default-group', interface 'wprint_group'
*apfMsConnTask_0: Mar 07 10:12:37.955: 00:19:70:7a:e0:85 Applying IPv6 Interface Policy for station 00:19:70:7a:e0:85 - vlan 334, interface id 14, interface 'wprint_group'
*apfMsConnTask_0: Mar 07 10:12:37.955: 00:19:70:7a:e0:85 STA - rates (8): 150 12 18 24 36 48 72 96 0 0 0 0 0 0 0 0
*apfMsConnTask_0: Mar 07 10:12:37.955: 00:19:70:7a:e0:85 STA - rates (9): 150 12 18 24 36 48 72 96 108 0 0 0 0 0 0 0
*apfMsConnTask_0: Mar 07 10:12:37.955: 00:19:70:7a:e0:85 Processing RSN IE type 48, length 20 for mobile 00:19:70:7a:e0:85
*apfMsConnTask_0: Mar 07 10:12:37.955: 00:19:70:7a:e0:85 Received RSN IE with 0 PMKIDs from mobile 00:19:70:7a:e0:85
*apfMsConnTask_0: Mar 07 10:12:37.955: 00:19:70:7a:e0:85 0.0.0.0 START (0) Initializing policy
*apfMsConnTask_0: Mar 07 10:12:37.955: 00:19:70:7a:e0:85 0.0.0.0 START (0) Change state to AUTHCHECK (2) last state AUTHCHECK (2)

*apfMsConnTask_0: Mar 07 10:12:37.955: 00:19:70:7a:e0:85 0.0.0.0 AUTHCHECK (2) Change state to 8021X_REQD (3) last state 8021X_REQD (3)

*apfMsConnTask_0: Mar 07 10:12:37.955: 00:19:70:7a:e0:85 0.0.0.0 8021X_REQD (3) DHCP Not required on AP 0c:85:25:69:fd:90 vapId 4 apVapId 4for this client
*apfMsConnTask_0: Mar 07 10:12:37.955: 00:19:70:7a:e0:85 Not Using WMM Compliance code qosCap 00
*apfMsConnTask_0: Mar 07 10:12:37.955: 00:19:70:7a:e0:85 0.0.0.0 8021X_REQD (3) Plumbed mobile LWAPP rule on AP 0c:85:25:69:fd:90 vapId 4 apVapId 4
*apfMsConnTask_0: Mar 07 10:12:37.955: 00:19:70:7a:e0:85 apfMsAssoStateInc
*apfMsConnTask_0: Mar 07 10:12:37.955: 00:19:70:7a:e0:85 apfPemAddUser2 (apf_policy.c:223) Changing state for mobile 00:19:70:7a:e0:85 on AP 0c:85:25:69:fd:90 from Idle to Associated

*apfMsConnTask_0: Mar 07 10:12:37.956: 00:19:70:7a:e0:85 Stopping deletion of Mobile Station: (callerId: 48)
*apfMsConnTask_0: Mar 07 10:12:37.956: 00:19:70:7a:e0:85 Sending Assoc Response to station on BSSID 0c:85:25:69:fd:90 (status 0) ApVapId 4 Slot 0
*apfMsConnTask_0: Mar 07 10:12:37.956: 00:19:70:7a:e0:85 apfProcessAssocReq (apf_80211.c:5241) Changing state for mobile 00:19:70:7a:e0:85 on AP 0c:85:25:69:fd:90 from Associated to Associated

*dot1xMsgTask: Mar 07 10:12:37.957: 00:19:70:7a:e0:85 Disable re-auth, use PMK lifetime.
*dot1xMsgTask: Mar 07 10:12:37.957: 00:19:70:7a:e0:85 Station 00:19:70:7a:e0:85 setting dot1x reauth timeout = 1800
*dot1xMsgTask: Mar 07 10:12:37.957: 00:19:70:7a:e0:85 dot1x - moving mobile 00:19:70:7a:e0:85 into Connecting state
*dot1xMsgTask: Mar 07 10:12:37.957: 00:19:70:7a:e0:85 Sending EAP-Request/Identity to mobile 00:19:70:7a:e0:85 (EAP Id 1)
*Dot1x_NW_MsgTask_5: Mar 07 10:12:37.974: 00:19:70:7a:e0:85 Received EAPOL EAPPKT from mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:37.974: 00:19:70:7a:e0:85 Username entry (wirelessprintertest) created for mobile
*Dot1x_NW_MsgTask_5: Mar 07 10:12:37.974: 00:19:70:7a:e0:85 Received Identity Response (count=1) from mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:37.974: 00:19:70:7a:e0:85 EAP State update from Connecting to Authenticating for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:37.974: 00:19:70:7a:e0:85 dot1x - moving mobile 00:19:70:7a:e0:85 into Authenticating state
*Dot1x_NW_MsgTask_5: Mar 07 10:12:37.974: 00:19:70:7a:e0:85 Entering Backend Auth Response state for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:37.976: 00:19:70:7a:e0:85 Processing Access-Challenge for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:37.976: 00:19:70:7a:e0:85 Entering Backend Auth Req state (id=141) for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:37.976: 00:19:70:7a:e0:85 WARNING: updated EAP-Identifier 1 ===> 141 for STA 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:37.976: 00:19:70:7a:e0:85 Sending EAP Request from AAA to mobile 00:19:70:7a:e0:85 (EAP Id 141)
*Dot1x_NW_MsgTask_5: Mar 07 10:12:37.983: 00:19:70:7a:e0:85 Received EAPOL EAPPKT from mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:37.984: 00:19:70:7a:e0:85 Received EAP Response from mobile 00:19:70:7a:e0:85 (EAP Id 141, EAP Type 25)
*Dot1x_NW_MsgTask_5: Mar 07 10:12:37.984: 00:19:70:7a:e0:85 Entering Backend Auth Response state for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:37.985: 00:19:70:7a:e0:85 Processing Access-Challenge for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:37.985: 00:19:70:7a:e0:85 Entering Backend Auth Req state (id=142) for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:37.985: 00:19:70:7a:e0:85 Sending EAP Request from AAA to mobile 00:19:70:7a:e0:85 (EAP Id 142)
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.116: 00:19:70:7a:e0:85 Received EAPOL EAPPKT from mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.116: 00:19:70:7a:e0:85 Received EAP Response from mobile 00:19:70:7a:e0:85 (EAP Id 142, EAP Type 25)
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.116: 00:19:70:7a:e0:85 Entering Backend Auth Response state for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.124: 00:19:70:7a:e0:85 Processing Access-Challenge for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.124: 00:19:70:7a:e0:85 Entering Backend Auth Req state (id=143) for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.124: 00:19:70:7a:e0:85 Sending EAP Request from AAA to mobile 00:19:70:7a:e0:85 (EAP Id 143)
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.135: 00:19:70:7a:e0:85 Received EAPOL EAPPKT from mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.135: 00:19:70:7a:e0:85 Received EAP Response from mobile 00:19:70:7a:e0:85 (EAP Id 143, EAP Type 25)
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.135: 00:19:70:7a:e0:85 Entering Backend Auth Response state for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.137: 00:19:70:7a:e0:85 Processing Access-Challenge for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.137: 00:19:70:7a:e0:85 Entering Backend Auth Req state (id=144) for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.137: 00:19:70:7a:e0:85 Sending EAP Request from AAA to mobile 00:19:70:7a:e0:85 (EAP Id 144)
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.142: 00:19:70:7a:e0:85 Received EAPOL EAPPKT from mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.142: 00:19:70:7a:e0:85 Received EAP Response from mobile 00:19:70:7a:e0:85 (EAP Id 144, EAP Type 25)
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.142: 00:19:70:7a:e0:85 Entering Backend Auth Response state for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.144: 00:19:70:7a:e0:85 Processing Access-Challenge for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.144: 00:19:70:7a:e0:85 Entering Backend Auth Req state (id=145) for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.144: 00:19:70:7a:e0:85 Sending EAP Request from AAA to mobile 00:19:70:7a:e0:85 (EAP Id 145)
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.151: 00:19:70:7a:e0:85 Received EAPOL EAPPKT from mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.151: 00:19:70:7a:e0:85 Received EAP Response from mobile 00:19:70:7a:e0:85 (EAP Id 145, EAP Type 25)
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.151: 00:19:70:7a:e0:85 Entering Backend Auth Response state for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.155: 00:19:70:7a:e0:85 Processing Access-Challenge for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.155: 00:19:70:7a:e0:85 Entering Backend Auth Req state (id=146) for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.155: 00:19:70:7a:e0:85 Sending EAP Request from AAA to mobile 00:19:70:7a:e0:85 (EAP Id 146)
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.159: 00:19:70:7a:e0:85 Received EAPOL EAPPKT from mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.159: 00:19:70:7a:e0:85 Received EAP Response from mobile 00:19:70:7a:e0:85 (EAP Id 146, EAP Type 25)
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.159: 00:19:70:7a:e0:85 Entering Backend Auth Response state for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.160: 00:19:70:7a:e0:85 Processing Access-Challenge for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.160: 00:19:70:7a:e0:85 Entering Backend Auth Req state (id=147) for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.160: 00:19:70:7a:e0:85 Sending EAP Request from AAA to mobile 00:19:70:7a:e0:85 (EAP Id 147)
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.167: 00:19:70:7a:e0:85 Received EAPOL EAPPKT from mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.167: 00:19:70:7a:e0:85 Received EAP Response from mobile 00:19:70:7a:e0:85 (EAP Id 147, EAP Type 25)
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.167: 00:19:70:7a:e0:85 Entering Backend Auth Response state for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.168: 00:19:70:7a:e0:85 Processing Access-Accept for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.168: 00:19:70:7a:e0:85 Resetting web acl from 255 to 255

*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.168: 00:19:70:7a:e0:85 Setting re-auth timeout to 1800 seconds, got from WLAN config.
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.168: 00:19:70:7a:e0:85 Station 00:19:70:7a:e0:85 setting dot1x reauth timeout = 1800
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.168: 00:19:70:7a:e0:85 Creating a PKC PMKID Cache entry for station 00:19:70:7a:e0:85 (RSN 2)
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.168: 00:19:70:7a:e0:85 Adding BSSID 0c:85:25:69:fd:93 to PMKID cache for station 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.168: New PMKID: (16)

*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.168:      [0000] 5b 10 ab 13 a2 0a 56 fa 82 31 b8 23 43 85 04 2b

*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.168: 00:19:70:7a:e0:85 Disabling re-auth since PMK lifetime can take care of same.
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.169: 00:19:70:7a:e0:85 PMK sent to mobility group
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.169: 00:19:70:7a:e0:85 Sending EAP-Success to mobile 00:19:70:7a:e0:85 (EAP Id 147)
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.169: Including PMKID in M1  (16)

*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.169:      [0000] 5b 10 ab 13 a2 0a 56 fa 82 31 b8 23 43 85 04 2b

*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.169: 00:19:70:7a:e0:85 Starting key exchange to mobile 00:19:70:7a:e0:85, data packets will be dropped
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.169: 00:19:70:7a:e0:85 Sending EAPOL-Key Message to mobile 00:19:70:7a:e0:85
   state INITPMK (message 1), replay counter 00.00.00.00.00.00.00.00
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.169: 00:19:70:7a:e0:85 Entering Backend Auth Success state (id=147) for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.169: 00:19:70:7a:e0:85 Received Auth Success while in Authenticating state for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.169: 00:19:70:7a:e0:85 dot1x - moving mobile 00:19:70:7a:e0:85 into Authenticated state
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.184: 00:19:70:7a:e0:85 Received EAPOL-Key from mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.184: 00:19:70:7a:e0:85 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.184: 00:19:70:7a:e0:85 Received EAPOL-key in PTK_START state (message 2) from mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.184: 00:19:70:7a:e0:85 PMK: Sending cache add
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.184: 00:19:70:7a:e0:85 Stopping retransmission timer for mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.184: 00:19:70:7a:e0:85 Sending EAPOL-Key Message to mobile 00:19:70:7a:e0:85
   state PTKINITNEGOTIATING (message 3), replay counter 00.00.00.00.00.00.00.01
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.191: 00:19:70:7a:e0:85 Received EAPOL-Key from mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.191: 00:19:70:7a:e0:85 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.191: 00:19:70:7a:e0:85 Received EAPOL-key in PTKINITNEGOTIATING state (message 4) from mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.191: 00:19:70:7a:e0:85 apfMs1xStateInc
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.191: 00:19:70:7a:e0:85 0.0.0.0 8021X_REQD (3) Change state to L2AUTHCOMPLETE (4) last state L2AUTHCOMPLETE (4)

*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.191: 00:19:70:7a:e0:85 0.0.0.0 L2AUTHCOMPLETE (4) DHCP Not required on AP 0c:85:25:69:fd:90 vapId 4 apVapId 4for this client
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.191: 00:19:70:7a:e0:85 Not Using WMM Compliance code qosCap 00
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.191: 00:19:70:7a:e0:85 0.0.0.0 L2AUTHCOMPLETE (4) Plumbed mobile LWAPP rule on AP 0c:85:25:69:fd:90 vapId 4 apVapId 4
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.191: 00:19:70:7a:e0:85 0.0.0.0 L2AUTHCOMPLETE (4) Change state to DHCP_REQD (7) last state DHCP_REQD (7)

*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.191: 00:19:70:7a:e0:85 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 4755, Adding TMP rule
*Dot1x_NW_MsgTask_5: Mar 07 06:30:46.191: 00:19:70:7a:e0:85 0.0.0.0 DHCP_REQD (7) Adding Fast Path rule
  type = Airespace AP - Learn IP address
  on AP 0c:85:25:69:fd:90, slot 0, interface = 13, QOS = 0
  ACL Id = 255, Jumbo F
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.191: 00:19:70:7a:e0:85 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 7006  IPv6 Vlan = 334, IPv6 intf id = 14
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.191: 00:19:70:7a:e0:85 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (ACL ID 255)
*Dot1x_NW_MsgTask_5: Mar 07 10:12:38.191: 00:19:70:7a:e0:85 Stopping retransmission timer for mobile 00:19:70:7a:e0:85
*pemReceiveTask: Mar 07 10:12:38.192: 00:19:70:7a:e0:85 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0
*pemReceiveTask: Mar 07 10:12:38.192: 00:19:70:7a:e0:85 Sent an XID frame
*DHCP Socket Task: Mar 07 10:12:38.246: 00:19:70:7a:e0:85 DHCP received op BOOTREQUEST (1) (len 556,vlan 0, port 13, encap 0xec03)
*DHCP Socket Task: Mar 07 10:12:38.246: 00:19:70:7a:e0:85 DHCP dropping packet due to ongoing mobility handshake exchange, (siaddr 0.0.0.0,  mobility state = 'apfMsMmQueryRequested'
*apfReceiveTask: Mar 07 10:12:40.109: 00:19:70:7a:e0:85 0.0.0.0 DHCP_REQD (7) State Update from Mobility-Incomplete to Mobility-Complete, mobility role=Local, client state=APF_MS_STATE_ASSOCIATED
*apfReceiveTask: Mar 07 10:12:40.109: 00:19:70:7a:e0:85 0.0.0.0 DHCP_REQD (7) pemAdvanceState2 4431, Adding TMP rule
*apfReceiveTask: Mar 07 10:12:40.043: 00:19:70:7a:e0:85 0.0.0.0 DHCP_REQD (7) Replacing Fast Path rule
  type = Airespace AP - Learn IP address
  on AP 0c:85:25:69:fd:90, slot 0, interface = 13, QOS = 0
  ACL Id = 255, Jumb
*apfReceiveTask: Mar 07 10:12:40.109: 00:19:70:7a:e0:85 0.0.0.0 DHCP_REQD (7) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 7006  IPv6 Vlan = 334, IPv6 intf id = 14
*apfReceiveTask: Mar 07 10:12:40.109: 00:19:70:7a:e0:85 0.0.0.0 DHCP_REQD (7) Successfully plumbed mobile rule (ACL ID 255)
*pemReceiveTask: Mar 07 10:12:40.110: 00:19:70:7a:e0:85 0.0.0.0 Added NPU entry of type 9, dtlFlags 0x0
*pemReceiveTask: Mar 07 10:12:40.110: 00:19:70:7a:e0:85 Sent an XID frame
*DHCP Socket Task: Mar 07 10:12:40.271: 00:19:70:7a:e0:85 DHCP received op BOOTREQUEST (1) (len 556,vlan 0, port 13, encap 0xec03)
*DHCP Socket Task: Mar 07 10:12:40.271: 00:19:70:7a:e0:85 DHCP selecting relay 1 - control block settings:
   dhcpServer: 0.0.0.0, dhcpNetmask: 0.0.0.0,
   dhcpGateway: 0.0.0.0, dhcpRelay: 0.0.0.0  VLAN: 0
*DHCP Socket Task: Mar 07 10:12:40.271: 00:19:70:7a:e0:85 DHCP selected relay 1 - 10.125.10.2 (local address 10.125.54.37, gateway 10.125.54.240, VLAN 334, port 13)
*DHCP Socket Task: Mar 07 10:12:40.271: 00:19:70:7a:e0:85 DHCP transmitting DHCP DISCOVER (1)
*DHCP Socket Task: Mar 07 10:12:40.271: 00:19:70:7a:e0:85 DHCP   op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 1
*DHCP Socket Task: Mar 07 10:12:40.271: 00:19:70:7a:e0:85 DHCP   xid: 0x8f0 (2288), secs: 0, flags: 0
*DHCP Socket Task: Mar 07 10:12:40.271: 00:19:70:7a:e0:85 DHCP   chaddr: 00:19:70:7a:e0:85
*DHCP Socket Task: Mar 07 10:12:40.271: 00:19:70:7a:e0:85 DHCP   ciaddr: 0.0.0.0,  yiaddr: 0.0.0.0
*DHCP Socket Task: Mar 07 10:12:40.271: 00:19:70:7a:e0:85 DHCP   siaddr: 0.0.0.0,  giaddr: 10.125.54.37
*DHCP Socket Task: Mar 07 10:12:40.272: 00:19:70:7a:e0:85 DHCP sending REQUEST to 10.125.54.240 (len 350, port 13, vlan 334)
*DHCP Socket Task: Mar 07 10:12:40.272: 00:19:70:7a:e0:85 DHCP selecting relay 2 - control block settings:
   dhcpServer: 0.0.0.0, dhcpNetmask: 0.0.0.0,
   dhcpGateway: 0.0.0.0, dhcpRelay: 10.125.54.37  VLAN: 334
*DHCP Socket Task: Mar 07 10:12:40.272: 00:19:70:7a:e0:85 DHCP selected relay 2 - 10.125.10.3 (local address 10.125.54.37, gateway 10.125.54.240, VLAN 334, port 13)
*DHCP Socket Task: Mar 07 10:12:40.272: 00:19:70:7a:e0:85 DHCP transmitting DHCP DISCOVER (1)
*DHCP Socket Task: Mar 07 10:12:40.272: 00:19:70:7a:e0:85 DHCP   op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 2
*DHCP Socket Task: Mar 07 10:12:40.272: 00:19:70:7a:e0:85 DHCP   xid: 0x8f0 (2288), secs: 0, flags: 0
*DHCP Socket Task: Mar 07 10:12:40.272: 00:19:70:7a:e0:85 DHCP   chaddr: 00:19:70:7a:e0:85
*DHCP Socket Task: Mar 07 10:12:40.272: 00:19:70:7a:e0:85 DHCP   ciaddr: 0.0.0.0,  yiaddr: 0.0.0.0
*DHCP Socket Task: Mar 07 10:12:40.272: 00:19:70:7a:e0:85 DHCP   siaddr: 0.0.0.0,  giaddr: 10.125.54.37
*DHCP Socket Task: Mar 07 10:12:40.272: 00:19:70:7a:e0:85 DHCP sending REQUEST to 10.125.54.240 (len 350, port 13, vlan 334)
*DHCP Socket Task: Mar 07 10:12:40.272: 00:19:70:7a:e0:85 DHCP received op BOOTREPLY (2) (len 329,vlan 334, port 13, encap 0xec00)
*DHCP Socket Task: Mar 07 10:12:40.272: 00:19:70:7a:e0:85 DHCP setting server from OFFER (server 10.125.10.2, yiaddr 10.125.54.121)
*DHCP Socket Task: Mar 07 10:12:40.272: 00:19:70:7a:e0:85 DHCP sending REPLY to STA (len 438, port 13, vlan 0)
*DHCP Socket Task: Mar 07 10:12:40.272: 00:19:70:7a:e0:85 DHCP transmitting DHCP OFFER (2)
*DHCP Socket Task: Mar 07 10:12:40.272: 00:19:70:7a:e0:85 DHCP   op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0
*DHCP Socket Task: Mar 07 10:12:40.272: 00:19:70:7a:e0:85 DHCP   xid: 0x8f0 (2288), secs: 0, flags: 0
*DHCP Socket Task: Mar 07 10:12:40.272: 00:19:70:7a:e0:85 DHCP   chaddr: 00:19:70:7a:e0:85
*DHCP Socket Task: Mar 07 10:12:40.272: 00:19:70:7a:e0:85 DHCP   ciaddr: 0.0.0.0,  yiaddr: 10.125.54.121
*DHCP Socket Task: Mar 07 10:12:40.272: 00:19:70:7a:e0:85 DHCP   siaddr: 0.0.0.0,  giaddr: 0.0.0.0
*DHCP Socket Task: Mar 07 10:12:40.272: 00:19:70:7a:e0:85 DHCP   server id: 2.2.2.2  rcvd server id: 10.125.10.2
*DHCP Socket Task: Mar 07 10:12:40.272: 00:19:70:7a:e0:85 DHCP received op BOOTREPLY (2) (len 329,vlan 334, port 13, encap 0xec00)
*DHCP Socket Task: Mar 07 10:12:40.272: 00:19:70:7a:e0:85 DHCP dropping OFFER from 10.125.10.3 (yiaddr 10.125.54.2)
*DHCP Socket Task: Mar 07 10:12:40.287: 00:19:70:7a:e0:85 DHCP received op BOOTREQUEST (1) (len 556,vlan 0, port 13, encap 0xec03)
*DHCP Socket Task: Mar 07 10:12:40.287: 00:19:70:7a:e0:85 DHCP selecting relay 1 - control block settings:
   dhcpServer: 10.125.10.2, dhcpNetmask: 0.0.0.0,
   dhcpGateway: 0.0.0.0, dhcpRelay: 10.125.54.37  VLAN: 334
*DHCP Socket Task: Mar 07 10:12:40.287: 00:19:70:7a:e0:85 DHCP selected relay 1 - 10.125.10.2 (local address 10.125.54.37, gateway 10.125.54.240, VLAN 334, port 13)
*DHCP Socket Task: Mar 07 10:12:40.287: 00:19:70:7a:e0:85 DHCP transmitting DHCP REQUEST (3)
*DHCP Socket Task: Mar 07 10:12:40.287: 00:19:70:7a:e0:85 DHCP   op: BOOTREQUEST, htype: Ethernet, hlen: 6, hops: 1
*DHCP Socket Task: Mar 07 10:12:40.287: 00:19:70:7a:e0:85 DHCP   xid: 0x8f0 (2288), secs: 0, flags: 0
*DHCP Socket Task: Mar 07 10:12:40.287: 00:19:70:7a:e0:85 DHCP   chaddr: 00:19:70:7a:e0:85
*DHCP Socket Task: Mar 07 10:12:40.287: 00:19:70:7a:e0:85 DHCP   ciaddr: 0.0.0.0,  yiaddr: 0.0.0.0
*DHCP Socket Task: Mar 07 10:12:40.287: 00:19:70:7a:e0:85 DHCP   siaddr: 0.0.0.0,  giaddr: 10.125.54.37
*DHCP Socket Task: Mar 07 10:12:40.287: 00:19:70:7a:e0:85 DHCP   requested ip: 10.125.54.121
*DHCP Socket Task: Mar 07 10:12:40.287: 00:19:70:7a:e0:85 DHCP   server id: 10.125.10.2  rcvd server id: 2.2.2.2
*DHCP Socket Task: Mar 07 10:12:40.287: 00:19:70:7a:e0:85 DHCP sending REQUEST to 10.125.54.240 (len 350, port 13, vlan 334)
*DHCP Socket Task: Mar 07 10:12:40.288: 00:19:70:7a:e0:85 DHCP selecting relay 2 - control block settings:
   dhcpServer: 10.125.10.2, dhcpNetmask: 0.0.0.0,
   dhcpGateway: 0.0.0.0, dhcpRelay: 10.125.54.37  VLAN: 334
*DHCP Socket Task: Mar 07 10:12:40.288: 00:19:70:7a:e0:85 DHCP selected relay 2 - NONE
*DHCP Socket Task: Mar 07 10:12:40.288: 00:19:70:7a:e0:85 DHCP received op BOOTREPLY (2) (len 329,vlan 334, port 13, encap 0xec00)
*DHCP Socket Task: Mar 07 10:12:40.288: 00:19:70:7a:e0:85 apfMsRunStateInc
*DHCP Socket Task: Mar 07 10:12:40.288: 00:19:70:7a:e0:85 10.125.54.121 DHCP_REQD (7) Change state to RUN (20) last state RUN (20)

*DHCP Socket Task: Mar 07 10:12:40.288: 00:19:70:7a:e0:85 10.125.54.121 RUN (20) Reached PLUMBFASTPATH: from line 5273
*DHCP Socket Task: Mar 07 10:12:40.288: 00:19:70:7a:e0:85 10.125.54.121 RUN (20) Replacing Fast Path rule
  type = Airespace AP Client
  on AP 0c:85:25:69:fd:90, slot 0, interface = 13, QOS = 0
  ACL Id = 255, Jumbo Frames =
*DHCP Socket Task: Mar 07 10:12:40.288: 00:19:70:7a:e0:85 10.125.54.121 RUN (20) Fast Path rule (contd...) 802.1P = 0, DSCP = 0, TokenID = 7006  IPv6 Vlan = 334, IPv6 intf id = 14
*DHCP Socket Task: Mar 07 10:12:40.288: 00:19:70:7a:e0:85 10.125.54.121 RUN (20) Successfully plumbed mobile rule (ACL ID 255)
*DHCP Socket Task: Mar 07 10:12:40.289: 00:19:70:7a:e0:85 Assigning Address 10.125.54.121 to mobile
*DHCP Socket Task: Mar 07 10:12:40.289: 00:19:70:7a:e0:85 DHCP success event for client. Clearing dhcp failure count for interface wprint_group.
*DHCP Socket Task: Mar 07 10:12:40.289: 00:19:70:7a:e0:85 DHCP sending REPLY to STA (len 438, port 13, vlan 0)
*DHCP Socket Task: Mar 07 10:12:40.289: 00:19:70:7a:e0:85 DHCP transmitting DHCP ACK (5)
*DHCP Socket Task: Mar 07 10:12:40.289: 00:19:70:7a:e0:85 DHCP   op: BOOTREPLY, htype: Ethernet, hlen: 6, hops: 0
*DHCP Socket Task: Mar 07 10:12:40.289: 00:19:70:7a:e0:85 DHCP   xid: 0x8f0 (2288), secs: 0, flags: 0
*DHCP Socket Task: Mar 07 10:12:40.289: 00:19:70:7a:e0:85 DHCP   chaddr: 00:19:70:7a:e0:85
*DHCP Socket Task: Mar 07 10:12:40.289: 00:19:70:7a:e0:85 DHCP   ciaddr: 0.0.0.0,  yiaddr: 10.125.54.121
*DHCP Socket Task: Mar 07 10:12:40.289: 00:19:70:7a:e0:85 DHCP   siaddr: 0.0.0.0,  giaddr: 0.0.0.0
*DHCP Socket Task: Mar 07 10:12:40.289: 00:19:70:7a:e0:85 DHCP   server id: 2.2.2.2  rcvd server id: 10.125.10.2
*pemReceiveTask: Mar 07 10:12:40.289: 00:19:70:7a:e0:85 10.125.54.121 Added NPU entry of type 1, dtlFlags 0x0
*pemReceiveTask: Mar 07 10:12:40.289: 00:19:70:7a:e0:85 Sending a gratuitous ARP for 10.125.54.121, VLAN Id 334
*dot1xMsgTask: Mar 07 10:13:04.910: 00:19:70:7a:e0:85 Key exchange done, data packets from mobile 00:19:70:7a:e0:85 should be forwarded shortly
*dot1xMsgTask: Mar 07 10:13:04.910: 00:19:70:7a:e0:85 Sending EAPOL-Key Message to mobile 00:19:70:7a:e0:85
   state PTKINITDONE (message 5 - group), replay counter 00.00.00.00.00.00.00.02
*dot1xMsgTask: Mar 07 10:13:04.910: 00:19:70:7a:e0:85 Updated broadcast key sent to mobile 00:19:70:7A:E0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:13:04.924: 00:19:70:7a:e0:85 Received EAPOL-Key from mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:13:04.924: 00:19:70:7a:e0:85 Ignoring invalid EAPOL version (1) in EAPOL-key message from mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:13:04.924: 00:19:70:7a:e0:85 Received EAPOL-key in REKEYNEGOTIATING state (message 6) from mobile 00:19:70:7a:e0:85
*Dot1x_NW_MsgTask_5: Mar 07 10:13:04.924: 00:19:70:7a:e0:85 Stopping retransmission timer for mobile 00:19:70:7a:e0:85

I will add the others as and when i can today

Manyt thanks

Simon

airframes Wed, 03/07/2012 - 20:05

Simon,

Looking through the debug everything seems to be in order, but the debug output didn't show any activity from the client wanting to continue to authenticate after the initial attempt (so you may be onto something about it being the ACS). I went back and looked at your earlier screengrabs and noticed that the rejections are in pattern -- one auth accept followed by 12 rejects, each 2 seconds apart (almost exactly).

Can you click on the details of both a success auth and a failed auth and post (or PM) a more detailed screenshot of each, and please include the authentication details and steps from the bottom of the details screen?

Justin

s.vosper Thu, 03/08/2012 - 01:32

Hi Justin

Looking at the details for the passed and failed attempts I am noticing one thing. The Called Id staion for failed attempts has the devices IP address, where as the Called ID staion for the passed attempts have the MAC address that relates to that SSID and the SSID name its self. So why would the device make repeated attempts with its IP address in this field?

I will PM you the screen grabs.

Thanks

Simon

s.vosper Thu, 03/08/2012 - 02:18

BINGO!!

The RADIUS type field of the failed attempts was "AccountingRequest". I unchecked the accounting box on each WLAN and the failed attempts have stopped.

What is the "Accounting Server" field for exactly?

Nicholas Poole Thu, 03/08/2012 - 02:23

its to allow the recording of who has done something, rather than just asking are they authorised to have access

airframes Thu, 03/08/2012 - 22:01

Simon,

Glad to hear you've licked the issue. You could use accounting if you wanted--you'd just need to set up service selection on ACS to deal with accounting request packets properly.

Accounting is used for tracking client session lengths, session start/stop times, upload/download volumes, and with TACACS+ I belive you can use accounting to track which commands users have issued during a management session.

As a service provider, you can use accounting to figure out how to charge customers for time online or for volume of data moved. I don't run into it much, and I rarely see it implemented for eap/dot1x, but it happens.

Justin

s.vosper Fri, 03/09/2012 - 00:18

Justin

A colleague has helped me get the accounting to work.

Thank you very much for taking the time to help and for leading me down the patch to resolution, +5

THanks

Simon

brenoandre Tue, 07/02/2013 - 06:51

Justin, I would make this procedure using the NPS. Could you help me?

Actions

Login or Register to take actions

This Discussion

Posted February 23, 2012 at 12:02 PM
Stats:
Replies:34 Avg. Rating:5
Views:3280 Votes:0
Shares:0
Tags: No tags.

Discussions Leaderboard