Wireless Access

We are seeing all our Macs running Lion and Mountain Lion dropping wifi several times a day. Our XP, Win7, and Win8 machines never drop. They all have beautiful signal when they drop. I have tried removing the wifi profile and adding it back. I have even went so far as to clear the PRAM as that seems to be the Mac equivalent to turning it off and on again. Has anyone run into this issue before? We are seeing this happen on all the controllers in our oragnization.

What Mac OS X version ? 

 

There's a couple known issues with 10.8.4 and 10.8.5 

 

What type of authentication ? open or 802.1x ?

 

Does this happens when those devices are roaming ?

 

Is the device able to maintain a wireless connection but can't pass any data ?

Most of our Lion machines are running 10.7.5 and our Mountain Lion machines are running 10.8.5. We are using WPA2 profiles manually added. It happens both while roaming as well as while sitting at their desks. What known issues are you talking about?

 

These are some of the cases currently open:

I'm assuming these are Aruba Case issues. So do they believe this is an Aruba problem or an Apple problem.

These are Apple related cases..

 

Supposedly those issues will be resolved with OS X 10.9.x

Do you have a link to these cases so I can look over them and pass them along to our support staff?

 

Unfortuntaly I don't , this were provided by TAC

I've seen our Mac clients drop off of our 802.1x networks if they switch APs. If I'm sitting in a room with numerous APs and my Mac decides with switch APs it will ask them to authenticate again and lose connection. However if I closet laptop and move to anothe part of the building then open my laptop again it will reconnect just fine. The computer just can't roam while it is not sleeping. My iOS devices roam freely on our 802.1x with no need to ever reauthenticate. Wish I could say the same about my Mac OS machines.

---

morrisch@alliancecityschools.org wrote:
I've seen our Mac clients drop off of our 802.1x networks if they switch APs. If I'm sitting in a room with numerous APs and my Mac decides with switch APs it will ask them to authenticate again and lose connection. However if I closet laptop and move to anothe part of the building then open my laptop again it will reconnect just fine. The computer just can't roam while it is not sleeping. My iOS devices roam freely on our 802.1x with no need to ever reauthenticate. Wish I could say the same about my Mac OS machines.

---

morrisch@alliancecityschools.org,

 

"If I am sitting in a room with numerous APs.."  -- Is that 3 or more access points?  How many rooms do you have numerous  APs in?.. Could wifi saturation be the key to your issue?

 

- Please open a ticket of your own.  Ticket numbers from other customers are not useful because Aruba needs to treat each situation individually.  In addition, we cannot pass personal information from one customer to another without their permission.  Lastly, the ticket numbers mentioned above are closed.

- Keep us updated on your progress.

 

 

I have a customer reporting the same issues on Mac OS X 10.8.4.  Intermittent drops from network.  I think the Mac diagnostics App is basic but maybe it will shed some light on the issue.  Give it a try:

 

open /System/Library/CoreServices/Wireless\ Diagnostics.app/ 

 

Also, TAC worked with my customer and did the actions below the break but the early feedback is that these changes made the problem worse not better.  Please let me know if anybody made these or different changes and have seen better results.  It is also highly reccomended that customers also open enterprise TAC tickets directly with Apple as well and with Aruba.

===== BREAK =====

1)      You had mentioned that the MAC OS 10.8.4 devices that were connecting to the Dot1X SSID were getting disconnected intermittently.

2)      Hence we had initiated a remote session and had enabled “logging level debugging user-debug <user-mac”

3)      Then we had disconnected the client and tried reconnecting and it connected without any problem.

4)      We had noticed that it was connecting in a-HT-40shi-2ss radio.

5)      It remained associated close to 15 mins without any problem.

6)      However, when it had disconnected we checked the user-debug logs and noticed the reason for disconnection was due to “STA has left and is deauthenticated.

7)      As it a known issue with the MAC OS 10.8.4 devices, in order to tweak some best practices on the controller for the MAC OS devices, we went ahead and did the following changes:-

1. We went ahead and disabled OKC in the “aaa authentication dot1x profile” that was being used.
2. We went ahead and enabled “BC/MC Rate Optimization” in the SSID profile.
3. We had enabled Band steering all the VAP’s that were in use.
4. For the dot1x profile, we had set the

i.      WPA/WPA2 Key Messages timer to 2000ms                                                    

ii.      Delay between WPA/WPA2 Unicast Key and Group Key Exchange to 100ms

iii.      Delay between EAP-Success and WPA2 Unicast Key exchange to 100ms

 

This is just an example. There are two access points in a large library. If a Mac OS X client is in that room it will attempt to switch APs and then prompt for authentication randomly. It does not do this with non 802.1x clients.

This also happens when I pick my Mac OSX client up and move to another room in the building while it is awake. It prompts for authentication. Where my iOS device does not.

However I can put my Mac to sleep and move to another part of the building. Wake it up and it does not prompt for authentication and just keeps on working.

This happens from any build of 10.6 to 10.8

Does your 802.1x profile have Opportunistic Key Caching AND Validate PMKID enabled?  http://community.arubanetworks.com/t5/Unified-Wired-Wireless-Access/MAC-WLAN-Client-quot-Nuances-quot/m-p/1461/highlight/true#M11

I only have PKMID enabled and OKC disabled. I've seen that document and have attempted to implement everything in it.

The best thing to do is start user debugging on that client and get the output of "show auth-tracebuf mac <mac address>" when it happens so you can see what is happening with the radius exchanges.

 

Again, if this has been happening for awhile, it is much better that you open a TAC case, so that they can focus on a solution.  We can try here, but there is a limit to the private information we can ask for, and that will delay a solution considerably. 

 

Here is what it looks like when I roam with the client open.

 

Oct 17 08:19:29 station-up * 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 - - wpa2 aes
Oct 17 08:19:29 eap-id-req <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 1 5
Oct 17 08:19:34 eap-id-req <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 1 5
Oct 17 08:19:34 eap-id-resp -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 1 13 morrisch
Oct 17 08:19:34 rad-req -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 65417 227
Oct 17 08:19:34 rad-resp <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 65417 79
Oct 17 08:19:34 eap-req <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 2 6
Oct 17 08:19:34 eap-resp -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 2 128
Oct 17 08:19:34 rad-req -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 29 360
Oct 17 08:19:34 rad-resp <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 29 1090
Oct 17 08:19:34 eap-req <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 3 1024
Oct 17 08:19:34 eap-resp -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 3 6
Oct 17 08:19:34 rad-req -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 124 238
Oct 17 08:19:34 rad-resp <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 124 1090
Oct 17 08:19:34 eap-req <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 4 1024
Oct 17 08:19:34 eap-resp -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 4 6
Oct 17 08:19:34 rad-req -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 65422 238
Oct 17 08:19:34 rad-resp <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 65422 1090
Oct 17 08:19:34 eap-req <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 5 1024
Oct 17 08:19:34 eap-resp -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 5 6
Oct 17 08:19:34 rad-req -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 65454 238
Oct 17 08:19:34 rad-resp <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 65454 837
Oct 17 08:19:34 eap-req <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 6 773
Oct 17 08:19:38 eap-resp -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 6 336
Oct 17 08:19:38 rad-req -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 65425 570
Oct 17 08:19:38 rad-resp <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 65425 127
Oct 17 08:19:38 eap-req <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 7 69
Oct 17 08:19:42 station-down * 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 - -
Oct 17 08:19:47 station-up * 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 - - wpa2 aes
Oct 17 08:19:47 eap-id-req <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 1 5
Oct 17 08:19:47 eap-id-resp -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 1 13 morrisch
Oct 17 08:19:47 rad-req -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 120 227
Oct 17 08:19:47 rad-resp <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 120 79
Oct 17 08:19:47 eap-req <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 2 6
Oct 17 08:19:47 eap-resp -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 2 128
Oct 17 08:19:47 rad-req -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 65514 360
Oct 17 08:19:47 rad-resp <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 65514 1090
Oct 17 08:19:47 eap-req <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 3 1024
Oct 17 08:19:47 eap-resp -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 3 6
Oct 17 08:19:47 rad-req -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 65495 238
Oct 17 08:19:47 rad-resp <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 65495 1090
Oct 17 08:19:47 eap-req <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 4 1024
Oct 17 08:19:47 eap-resp -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 4 6
Oct 17 08:19:47 rad-req -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 20 238
Oct 17 08:19:47 rad-resp <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 20 1090
Oct 17 08:19:47 eap-req <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 5 1024
Oct 17 08:19:47 eap-resp -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 5 6
Oct 17 08:19:47 rad-req -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 40 238
Oct 17 08:19:47 rad-resp <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 40 837
Oct 17 08:19:47 eap-req <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 6 773
Oct 17 08:19:47 eap-resp -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 6 336
Oct 17 08:19:47 rad-req -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 65434 570
Oct 17 08:19:47 rad-resp <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 65434 127
Oct 17 08:19:47 eap-req <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 7 69
Oct 17 08:19:47 eap-resp -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 7 159
Oct 17 08:19:47 rad-req -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 65462 391
Oct 17 08:19:47 rad-resp <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 65462 153
Oct 17 08:19:47 eap-req <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 8 95
Oct 17 08:19:47 eap-resp -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 8 6
Oct 17 08:19:47 rad-req -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 65411 238
Oct 17 08:19:47 rad-accept <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 65411 185
Oct 17 08:19:47 eap-success <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 8 4
Oct 17 08:19:47 wpa2-key1 <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 - 117
Oct 17 08:19:47 wpa2-key2 -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 - 117
Oct 17 08:19:47 wpa2-key3 <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 - 151
Oct 17 08:19:47 wpa2-key4 -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 - 95

 

I can actually click cancel on the authentication window then go choose the network again without it asking for my username and password.

 

 

and here is the user-debug log.

 

 

 

Oct 17 08:19:29 :501109: <NOTI> |AP castlepdroomap@10.110.45.46 stm| Auth request: 58:b0:35:7c:8d:61: AP 10.110.45.46-00:24:6c:83:5d:18-castlepdroomap auth_alg 0
Oct 17 08:19:29 :501093: <NOTI> |AP castlepdroomap@10.110.45.46 stm| Auth success: 58:b0:35:7c:8d:61: AP 10.110.45.46-00:24:6c:83:5d:18-castlepdroomap
Oct 17 08:19:29 :501095: <NOTI> |stm| Assoc request @ 08:19:29.985300: 58:b0:35:7c:8d:61 (SN 396): AP 10.110.45.46-00:24:6c:83:5d:18-castlepdroomap
Oct 17 08:19:29 :501100: <NOTI> |stm| Assoc success @ 08:19:29.997052: 58:b0:35:7c:8d:61: AP 10.110.45.46-00:24:6c:83:5d:18-castlepdroomap
Oct 17 08:19:29 :522035: <INFO> |authmgr| MAC=58:b0:35:7c:8d:61 Station UP: BSSID=00:24:6c:83:5d:18 ESSID=ACS Wireless VLAN=1 AP-name=castlepdroomap
Oct 17 08:19:29 :522077: <DBUG> |authmgr| MAC=58:b0:35:7c:8d:61 ingress 0x0x1005b (tunnel 91), u_encr 64, m_encr 64, slotport 0x0x2000 , type: local, FW mode: 0, AP IP: 0.0.0.0 mdie 0 ft_complete 0
Oct 17 08:19:30 :522246: <DBUG> |authmgr| Idle timeout should be driven by STM for MAC 58:b0:35:7c:8d:61.
Oct 17 08:19:30 :522083: <DBUG> |authmgr| Skip User-Derivation, mba:0 udr_exist:0,default_role:logon,pDefRole:0x0x10992d64
Oct 17 08:19:30 :524124: <DBUG> |authmgr| dot1x_supplicant_up(): MAC:58:b0:35:7c:8d:61, pmkid_present:False, pmkid:N/A
Oct 17 08:19:30 :522128: <DBUG> |authmgr| download-L2: acl=1/0 role=logon, tunl=0x0x1005b, PA=0, HA=1, RO=0, VPN=0.
Oct 17 08:19:30 :522050: <INFO> |authmgr| MAC=58:b0:35:7c:8d:61,IP=N/A User data downloaded to datapath, new Role=logon/1, bw Contract=0/0,reason=layer 2 event driven download
Oct 17 08:19:30 :522242: <DBUG> |authmgr| MAC=58:b0:35:7c:8d:61 Station Created Update MMS: BSSID=00:24:6c:83:5d:18 ESSID=ACS Wireless VLAN=1 AP-name=castlepdroomap
Oct 17 08:19:30 :501095: <NOTI> |AP castlepdroomap@10.110.45.46 stm| Assoc request @ 08:19:29.980655: 58:b0:35:7c:8d:61 (SN 396): AP 10.110.45.46-00:24:6c:83:5d:18-castlepdroomap
Oct 17 08:19:30 :501100: <NOTI> |AP castlepdroomap@10.110.45.46 stm| Assoc success @ 08:19:30.004882: 58:b0:35:7c:8d:61: AP 10.110.45.46-00:24:6c:83:5d:18-castlepdroomap
Oct 17 08:19:43 :501102: <NOTI> |AP castlepdroomap@10.110.45.46 stm| Disassoc from sta: 58:b0:35:7c:8d:61: AP 10.110.45.46-00:24:6c:83:5d:18-castlepdroomap Reason STA has left and is disassociated
Oct 17 08:19:43 :501102: <NOTI> |stm| Disassoc from sta: 58:b0:35:7c:8d:61: AP 10.110.45.46-00:24:6c:83:5d:18-castlepdroomap Reason STA has left and is disassociated
Oct 17 08:19:43 :501000: <DBUG> |AP castlepdroomap@10.110.45.46 stm| Station 58:b0:35:7c:8d:61: Clearing state
Oct 17 08:19:43 :522036: <INFO> |authmgr| MAC=58:b0:35:7c:8d:61 Station DN: BSSID=00:24:6c:83:5d:18 ESSID=ACS Wireless VLAN=1 AP-name=castlepdroomap
Oct 17 08:19:43 :522077: <DBUG> |authmgr| MAC=58:b0:35:7c:8d:61 ingress 0x0x1005b (tunnel 91), u_encr 64, m_encr 64, slotport 0x0x2000 , type: local, FW mode: 0, AP IP: 0.0.0.0 mdie 0 ft_complete 0
Oct 17 08:19:43 :522234: <DBUG> |authmgr| Setting idle timer for user 58:b0:35:7c:8d:61 to 300 seconds (idle timeout: 300 ageout: 0).
Oct 17 08:19:43 :522152: <DBUG> |authmgr| station free: bssid=00:24:6c:83:5d:18, @=0x0x10d65c04.
Oct 17 08:19:43 :522244: <DBUG> |authmgr| MAC=58:b0:35:7c:8d:61 Station Deleted Update MMS
Oct 17 08:19:43 :501000: <DBUG> |stm| Station 58:b0:35:7c:8d:61: Clearing state
Oct 17 08:19:48 :501109: <NOTI> |AP castlepdroomap@10.110.45.46 stm| Auth request: 58:b0:35:7c:8d:61: AP 10.110.45.46-00:24:6c:83:5d:18-castlepdroomap auth_alg 0
Oct 17 08:19:48 :501095: <NOTI> |stm| Assoc request @ 08:19:48.436669: 58:b0:35:7c:8d:61 (SN 513): AP 10.110.45.46-00:24:6c:83:5d:18-castlepdroomap
Oct 17 08:19:48 :501093: <NOTI> |AP castlepdroomap@10.110.45.46 stm| Auth success: 58:b0:35:7c:8d:61: AP 10.110.45.46-00:24:6c:83:5d:18-castlepdroomap
Oct 17 08:19:48 :501095: <NOTI> |AP castlepdroomap@10.110.45.46 stm| Assoc request @ 08:19:48.432293: 58:b0:35:7c:8d:61 (SN 513): AP 10.110.45.46-00:24:6c:83:5d:18-castlepdroomap
Oct 17 08:19:48 :501100: <NOTI> |AP castlepdroomap@10.110.45.46 stm| Assoc success @ 08:19:48.433568: 58:b0:35:7c:8d:61: AP 10.110.45.46-00:24:6c:83:5d:18-castlepdroomap
Oct 17 08:19:48 :501100: <NOTI> |stm| Assoc success @ 08:19:48.440690: 58:b0:35:7c:8d:61: AP 10.110.45.46-00:24:6c:83:5d:18-castlepdroomap
Oct 17 08:19:48 :522035: <INFO> |authmgr| MAC=58:b0:35:7c:8d:61 Station UP: BSSID=00:24:6c:83:5d:18 ESSID=ACS Wireless VLAN=1 AP-name=castlepdroomap
Oct 17 08:19:48 :522077: <DBUG> |authmgr| MAC=58:b0:35:7c:8d:61 ingress 0x0x1005b (tunnel 91), u_encr 64, m_encr 64, slotport 0x0x2000 , type: local, FW mode: 0, AP IP: 0.0.0.0 mdie 0 ft_complete 0
Oct 17 08:19:48 :522246: <DBUG> |authmgr| Idle timeout should be driven by STM for MAC 58:b0:35:7c:8d:61.
Oct 17 08:19:48 :522083: <DBUG> |authmgr| Skip User-Derivation, mba:0 udr_exist:0,default_role:logon,pDefRole:0x0x10992d64
Oct 17 08:19:48 :524124: <DBUG> |authmgr| dot1x_supplicant_up(): MAC:58:b0:35:7c:8d:61, pmkid_present:False, pmkid:N/A
Oct 17 08:19:48 :522128: <DBUG> |authmgr| download-L2: acl=1/0 role=logon, tunl=0x0x1005b, PA=0, HA=1, RO=0, VPN=0.
Oct 17 08:19:48 :522050: <INFO> |authmgr| MAC=58:b0:35:7c:8d:61,IP=N/A User data downloaded to datapath, new Role=logon/1, bw Contract=0/0,reason=layer 2 event driven download
Oct 17 08:19:48 :522242: <DBUG> |authmgr| MAC=58:b0:35:7c:8d:61 Station Created Update MMS: BSSID=00:24:6c:83:5d:18 ESSID=ACS Wireless VLAN=1 AP-name=castlepdroomap
Oct 17 08:19:48 :522038: <INFO> |authmgr| username=morrisch MAC=58:b0:35:7c:8d:61 IP=0.0.0.0 Authentication result=Authentication Successful method=802.1x server=Campus
Oct 17 08:19:48 :522044: <INFO> |authmgr| MAC=58:b0:35:7c:8d:61 Station authenticate(start): method=802.1x, role=logon///logon, VLAN=1/1/0/0/0/0, Derivation=0/0, Value Pair=1
Oct 17 08:19:48 :522017: <INFO> |authmgr| MAC=58:b0:35:7c:8d:61 IP=?? Derived role 'NetworkManagement' from server rules: server-group=ACSWirelessSecureServerGroup, authentication=802.1x
Oct 17 08:19:48 :522127: <DBUG> |authmgr| {L2} Update role from logon to NetworkManagement for IP=0.0.0.0.
Oct 17 08:19:48 :522049: <INFO> |authmgr| MAC=58:b0:35:7c:8d:61,IP=N/A User role updated, existing Role=logon/none, new Role=NetworkManagement/none, reason=Station Authenticated with auth type: 4
Oct 17 08:19:48 :522128: <DBUG> |authmgr| download-L2: acl=76/0 role=NetworkManagement, tunl=0x0x1005b, PA=0, HA=1, RO=0, VPN=0.
Oct 17 08:19:48 :522050: <INFO> |authmgr| MAC=58:b0:35:7c:8d:61,IP=N/A User data downloaded to datapath, new Role=NetworkManagement/76, bw Contract=0/0,reason=Download driven by user role setting
Oct 17 08:19:48 :522159: <DBUG> |authmgr| Station authenticate has l2 role :NetworkManagement default role logon logon role logon.
Oct 17 08:19:48 :522161: <DBUG> |authmgr| Valid Dot1xct, remote:0, assigned:1, default:1, current:1,termstate:0, wired:0, dot1x enabled:1, psk:0 static:0 bssid=00:24:6c:83:5d:18.
Oct 17 08:19:48 :522029: <INFO> |authmgr| MAC=58:b0:35:7c:8d:61 Station authenticate: method=802.1x, role=NetworkManagement///logon, VLAN=1/1/0/0/0/0, Derivation=2/0, Value Pair=1
Oct 17 08:19:48 :522053: <DBUG> |authmgr| PMK Cache getting updated for 58:b0:35:7c:8d:61, (def, cur, assigned) = (1, 1, 0) with vlan=0 vlanhow=0 essid=ACS Wireless role=NetworkManagement
Oct 17 08:19:48 :522026: <INFO> |authmgr| MAC=58:b0:35:7c:8d:61 IP=0.0.0.0 User miss: ingress=0x1005b, VLAN=1 flags=0xe049
Oct 17 08:19:48 :522216: <DBUG> |authmgr| MAC 58:b0:35:7c:8d:61, dhcp option 55, signature 370103060F775FFC2C2E.
Oct 17 08:19:48 :522216: <DBUG> |authmgr| MAC 58:b0:35:7c:8d:61, dhcp option 57, signature 3905DC.
Oct 17 08:19:48 :522216: <DBUG> |authmgr| MAC 58:b0:35:7c:8d:61, dhcp option 61, signature 3D0158B0357C8D61.
Oct 17 08:19:48 :522216: <DBUG> |authmgr| MAC 58:b0:35:7c:8d:61, dhcp option 50, signature 320A6E2F9F.
Oct 17 08:19:48 :522216: <DBUG> |authmgr| MAC 58:b0:35:7c:8d:61, dhcp option 51, signature 330076A700.
Oct 17 08:19:48 :522216: <DBUG> |authmgr| MAC 58:b0:35:7c:8d:61, dhcp option 12, signature 0C6163736D6F72726973.
Oct 17 08:19:48 :522026: <INFO> |authmgr| MAC=58:b0:35:7c:8d:61 IP=10.110.47.159 User miss: ingress=0x1005b, VLAN=1 flags=0x40
Oct 17 08:19:48 :522127: <DBUG> |authmgr| {L3} Update role from NetworkManagement to logon for IP=0.0.0.0.
Oct 17 08:19:48 :522049: <INFO> |authmgr| MAC=58:b0:35:7c:8d:61,IP=0.0.0.0 User role updated, existing Role=NetworkManagement/none, new Role=NetworkManagement/logon, reason=First IP user created
Oct 17 08:19:48 :522122: <DBUG> |authmgr| Reset BWM contract: IP=0.0.0.0 role=logon, contract= (0/0), type=Per role.
Oct 17 08:19:48 :522125: <DBUG> |authmgr| Could not create/find bandwidth-contract for user, return code (-11).
Oct 17 08:19:48 :522122: <DBUG> |authmgr| Reset BWM contract: IP=0.0.0.0 role=logon, contract= (0/0), type=Per role.
Oct 17 08:19:48 :522125: <DBUG> |authmgr| Could not create/find bandwidth-contract for user, return code (-11).
Oct 17 08:19:48 :522006: <INFO> |authmgr| MAC=58:b0:35:7c:8d:61 IP=10.110.47.159 User entry added: reason=Sibtye
Oct 17 08:19:48 :522169: <DBUG> |authmgr| Station inherit: IP=10.110.47.159 start bssid:00:24:6c:83:5d:18 essid: ACS Wireless port:0x0x1005b (0x0x1005b).
Oct 17 08:19:48 :522127: <DBUG> |authmgr| {L3} Update role from logon to NetworkManagement for IP=10.110.47.159.
Oct 17 08:19:48 :522049: <INFO> |authmgr| MAC=58:b0:35:7c:8d:61,IP=10.110.47.159 User role updated, existing Role=NetworkManagement/logon, new Role=NetworkManagement/NetworkManagement, reason=User authenticated with auth type:4 role derivation:2 l3 assigned role:NetworkManagement
Oct 17 08:19:48 :522122: <DBUG> |authmgr| Reset BWM contract: IP=10.110.47.159 role=NetworkManagement, contract= (0/0), type=Per role.
Oct 17 08:19:48 :522125: <DBUG> |authmgr| Could not create/find bandwidth-contract for user, return code (-11).
Oct 17 08:19:48 :522122: <DBUG> |authmgr| Reset BWM contract: IP=10.110.47.159 role=NetworkManagement, contract= (0/0), type=Per role.
Oct 17 08:19:48 :522125: <DBUG> |authmgr| Could not create/find bandwidth-contract for user, return code (-11).
Oct 17 08:19:48 :522008: <NOTI> |authmgr| User Authentication Successful: username=morrisch MAC=58:b0:35:7c:8d:61 IP=10.110.47.159 role=NetworkManagement VLAN=1 AP=castlepdroomap SSID=ACS Wireless AAA profile=ACS Wireless-aaa_prof auth method=802.1x auth server=Campus
Oct 17 08:19:48 :522171: <DBUG> |authmgr| station inherit IP=10.110.47.159 bssid:00:24:6c:83:5d:18 essid: ACS Wireless auth:1 type:802.1x role:NetworkManagement port:0x0x1005b.
Oct 17 08:19:48 :522128: <DBUG> |authmgr| download-L2: acl=76/0 role=NetworkManagement, tunl=0x0x1005b, PA=0, HA=1, RO=0, VPN=0.
Oct 17 08:19:48 :522050: <INFO> |authmgr| MAC=58:b0:35:7c:8d:61,IP=10.110.47.159 User data downloaded to datapath, new Role=NetworkManagement/76, bw Contract=0/0,reason=New user IP processing
Oct 17 08:19:49 :522137: <DBUG> |authmgr| 58:b0:35:7c:8d:61 : User-Agent: ocspd/1.0.
Oct 17 08:19:59 :522137: <DBUG> |authmgr| 58:b0:35:7c:8d:61 : User-Agent: SRFeature/2.2.0.2 CFNetwork/596.5 Darwin/12.5.0 (x86_64) (MacBookPro6%2C2).

Looks like the client did not like something:

 

Oct 17 08:19:34 eap-req <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 5 1024
Oct 17 08:19:34 eap-resp -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 5 6
Oct 17 08:19:34 rad-req -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 65454 238
Oct 17 08:19:34 rad-resp <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 65454 837
Oct 17 08:19:34 eap-req <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 6 773
Oct 17 08:19:38 eap-resp -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 6 336
Oct 17 08:19:38 rad-req -> 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 65425 570
Oct 17 08:19:38 rad-resp <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18/Campus 65425 127
Oct 17 08:19:38 eap-req <- 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 7 69
Oct 17 08:19:42 station-down * 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 - -
Oct 17 08:19:47 station-up * 58:b0:35:7c:8d:61 00:24:6c:83:5d:18 - - wpa2 aes

 You should turn on debugging on that mac to see what the client sees from its perspective:

 

sudo /System/Library/PrivateFrameworks/Apple80211.framework/Versions/Current/Resources/airport debug

 You should then be able to see what is happening in the Console under the System log.

 

 

Okay so I turned on debugging and then picked up and walked from room to room.  It prompted me for username and password just before I clicked the cancel button as I showed in bold.  

 

Oct 17 11:55:17 --- last message repeated 1 time ---
Oct 17 11:55:18 acsmorris kernel[0]: MacAuthEvent en1 Auth result for: 00:24:6c:83:5d:18 MAC AUTH succeeded
Oct 17 11:55:18 acsmorris kernel[0]: wlEvent: en1 en1 Link UP virtIf = 0
Oct 17 11:55:18 acsmorris kernel[0]: wl0: Roamed or switched channel, reason #1, bssid 00:24:6c:83:5d:18
Oct 17 11:55:18 acsmorris kernel[0]: en1: BSSID changed to 00:24:6c:83:5d:18
Oct 17 11:55:18 acsmorris kernel[0]: en1::IO80211Interface::postMessage bssid changed
Oct 17 11:55:27 acsmorris.flyers.stark.k12.oh.us vpnagent[103]: The network interface for the VPN connection has gone down.
Oct 17 11:55:27 acsmorris.flyers.stark.k12.oh.us vpnagent[103]: Function: logInterfaces File: RouteMgr.cpp Line: 2074 Invoked Function: logInterfaces Return Code: 0 (0x00000000) Description: IP Address Interface List:
Oct 17 11:55:27 acsmorris.flyers.stark.k12.oh.us vpnagent[103]: Function: applyHostConfigForNoVpn File: MainThread.cpp Line: 7512 No network interface is available, will not apply the noVPN host configuration.
Oct 17 11:55:27 acsmorris.flyers.stark.k12.oh.us vpnagent[103]: Current network state: No network interface
Oct 17 11:55:27 acsmorris.flyers.stark.k12.oh.us vpnagent[103]: Function: applyHostConfigForNoVpn File: MainThread.cpp Line: 7512 No network interface is available, will not apply the noVPN host configuration.
Oct 17 11:55:27 acsmorris.flyers.stark.k12.oh.us configd[17]: network changed: v4(en1-:10.110.47.159) DNS- Proxy- SMB-
Oct 17 11:55:27 acsmorris.local configd[17]: setting hostname to "acsmorris.local"
Oct 17 11:55:29 acsmorris.local CalendarAgent[392]: [com.apple.calendar.store.log.caldav.queue] [Account refresh failed with error: Error Domain=NSURLErrorDomain Code=-1009 "The Internet connection appears to be offline." UserInfo=0x7fd6923f7fd0 {NSUnderlyingError=0x7fd690d71da0 "The Internet connection appears to be offline.", NSErrorFailingURLStringKey=https://morrisch%40alliancecityschools.org@www.google.com/calendar/dav/morrisch%40alliancecityschools.org/user/, NSErrorFailingURLKey=https://morrisch%40alliancecityschools.org@www.google.com/calendar/dav/morrisch%40alliancecityschools.org/user/, AccountName=morrisch@alliancecityschools.org, CalDAVErrFromRefresh=YES, NSLocalizedDescription=The Internet connection appears to be offline.}]
Oct 17 11:55:32 acsmorris.local vpnagent[103]: Function: applyHostConfigForNoVpn File: MainThread.cpp Line: 7512 No network interface is available, will not apply the noVPN host configuration.
Oct 17 11:55:32 acsmorris.local digest-service[72472]: label: default
Oct 17 11:55:32 acsmorris.local digest-service[72472]: dbname: od:/Local/Default
Oct 17 11:55:32 acsmorris.local digest-service[72472]: mkey_file: /var/db/krb5kdc/m-key
Oct 17 11:55:32 acsmorris.local digest-service[72472]: acl_file: /var/db/krb5kdc/kadmind.acl
Oct 17 11:55:32 acsmorris.local digest-service[72472]: digest-request: uid=0
Oct 17 11:55:32 acsmorris.local digest-service[72472]: digest-request: init request
Oct 17 11:55:32 acsmorris.local digest-service[72472]: digest-request: init return domain: ACSMORRIS server: ACSMORRIS
Oct 17 11:55:33 acsmorris.local eapolclient[72196]: en1 TTLS: authentication failed with status 1
Oct 17 11:55:34 acsmorris kernel[0]: wlEvent: en1 en1 Link DOWN virtIf = 0
Oct 17 11:55:34 acsmorris kernel[0]: AirPort: Link Down on en1. Reason 8 (Disassociated because station leaving).
Oct 17 11:55:34 acsmorris kernel[0]: en1::IO80211Interface::postMessage bssid changed
Oct 17 11:55:34 acsmorris kernel[0]: MacAuthEvent en1 Auth result for: 00:24:6c:83:5d:18 MAC AUTH succeeded
Oct 17 11:55:34 acsmorris kernel[0]: wlEvent: en1 en1 Link UP virtIf = 0
Oct 17 11:55:34 acsmorris kernel[0]: AirPort: Link Up on en1
Oct 17 11:55:34 acsmorris kernel[0]: en1: BSSID changed to 00:24:6c:83:5d:18
Oct 17 11:55:34 acsmorris kernel[0]: en1::IO80211Interface::postMessage bssid changed
Oct 17 11:55:36 acsmorris.local netbiosd[76]: name servers down?
Oct 17 11:55:40 acsmorris.local eapolclient[72196]: en1: user cancelled
Oct 17 11:55:40 acsmorris.local eapolclient[72196]: en1 STOP
Oct 17 11:55:41 acsmorris kernel[0]: wlEvent: en1 en1 Link DOWN virtIf = 0
Oct 17 11:55:41 acsmorris kernel[0]: AirPort: Link Down on en1. Reason 8 (Disassociated because station leaving).
Oct 17 11:55:41 acsmorris kernel[0]: en1::IO80211Interface::postMessage bssid changed
Oct 17 11:55:45 acsmorris.local eapolclient[72497]: en1 START
Oct 17 11:55:46 acsmorris kernel[0]: MacAuthEvent en1 Auth result for: 00:24:6c:83:5d:18 MAC AUTH succeeded
Oct 17 11:55:46 acsmorris kernel[0]: wlEvent: en1 en1 Link UP virtIf = 0
Oct 17 11:55:46 acsmorris kernel[0]: AirPort: Link Up on en1
Oct 17 11:55:46 acsmorris kernel[0]: en1: BSSID changed to 00:24:6c:83:5d:18
Oct 17 11:55:46 acsmorris kernel[0]: en1::IO80211Interface::postMessage bssid changed
Oct 17 11:55:46 acsmorris.local eapolclient[72497]: en1 TTLS: successfully authenticated
Oct 17 11:55:46 acsmorris.local vpnagent[103]: A new network interface has been detected.
Oct 17 11:55:46 acsmorris.local vpnagent[103]: Function: logInterfaces File: RouteMgr.cpp Line: 2074 Invoked Function: logInterfaces Return Code: 0 (0x00000000) Description: IP Address Interface List: 10.110.47.159
Oct 17 11:55:46 acsmorris.local Splashtop Streamer[44235]: going to close SRFeature.
Oct 17 11:55:46 acsmorris kernel[0]: AirPort: RSN handshake complete on en1
Oct 17 11:55:46 acsmorris.local configd[17]: network changed: v4(en1+:10.110.47.159) DNS+ Proxy+ SMB+
Oct 17 11:55:46 acsmorris.local mDNSResponder[38]: mDNS_RegisterInterface: Frequent transitions for interface en1 (FE80:0000:0000:0000:5AB0:35FF:FE7C:8D61)
Oct 17 11:55:46 acsmorris.local mDNSResponder[38]: mDNS_RegisterInterface: Frequent transitions for interface en1 (10.110.47.159)
Oct 17 11:55:46 acsmorris.flyers.stark.k12.oh.us configd[17]: setting hostname to "acsmorris.flyers.stark.k12.oh.us"
Oct 17 11:55:47 acsmorris.flyers.stark.k12.oh.us UserEventAgent[11]: Captive: en1: Not probing 'ACS Wireless' (protected network)
Oct 17 11:55:47 acsmorris.flyers.stark.k12.oh.us configd[17]: network changed: v4(en1!:10.110.47.159) DNS Proxy SMB
Oct 17 11:55:47 acsmorris.flyers.stark.k12.oh.us airportd[72450]: _doAutoJoin: Already associated to “ACS Wireless”. Bailing on auto-join.
Oct 17 11:55:49 --- last message repeated 1 time ---
Oct 17 11:55:49 acsmorris.flyers.stark.k12.oh.us racoon[283]: Connecting.
Oct 17 11:55:49 acsmorris.flyers.stark.k12.oh.us racoon[283]: IPSec Phase1 started (Initiated by me).
Oct 17 11:55:49 acsmorris.flyers.stark.k12.oh.us racoon[283]: IKE Packet: transmit success. (Initiator, Aggressive-Mode message 1).
Oct 17 11:55:51 acsmorris.flyers.stark.k12.oh.us vpnagent[103]: AlwaysOn preferences for client system configuration without a VPN session (after successful VPN connection): AlwaysOn: disabled ConnectFailurePolicy: closed ApplyLastVPNLocalResourceRules: disabled
Oct 17 11:55:51 acsmorris.flyers.stark.k12.oh.us vpnagent[103]: getting ipv4 route table.
Oct 17 11:55:51 acsmorris.flyers.stark.k12.oh.us vpnagent[103]: The client's public address is now set to 10.110.47.159
Oct 17 11:55:52 acsmorris.flyers.stark.k12.oh.us digest-service[72472]: digest-request: uid=0
Oct 17 11:55:52 acsmorris.flyers.stark.k12.oh.us digest-service[72472]: digest-request: init request
Oct 17 11:55:52 acsmorris.flyers.stark.k12.oh.us digest-service[72472]: digest-request: init return domain: ACSMORRIS server: ACSMORRIS
Oct 17 11:55:52 acsmorris.flyers.stark.k12.oh.us racoon[283]: IKE Packet: transmit success. (Phase1 Retransmit).

Time for you to call Apple.  I don't want to speculate and they need to explain what is going on here.

 

What version of MAC OS is this?

 

This is 10.8.5.  I've seen this same behavior happen on all Macbook, Macbook Pro lines all the way from 10.6 to 10.8.5 now.

 

we have hundreds of them.

If you have a problem with All of them, you should open a case with Apple so that they can guide you.

We've seen this before also.  We continue to see slow roam times, but I think we've seen the problem you're having.  I'm trying to remember the fix, but it had something to to with the Certificate.  

Are you using a Self Signed Cert?  

Are they connecting using a system profile in the 802.1x section of Network-Advanced?

 

 

We are currently running 8.3.1.0 seeing mac clients take about 10-20 seconds when they roam to a new AP via Clientmatch.  They don't get the prompt to login again, just disconnect and reconnect.  

 

I'm really curious to what the solution to your problem is.  Great logs, and feedback in the thread!

 

 

Thanks for your response. 

 

We are not using a Self Signed Cert.  and yes I'm using 802.1x login window profiles on all my clients.  

 

I will definitely look in to what I can do with my Certs!  The Certs are only on my Radius server.  I don't have them anywhere in my Aruba controller.  I have to admit.  I don't know a whole lot about Certs....

I wanted to update on this issue.

 

I've verified that it has to do with the profile that I've installed on all my clients to connect them to the WPA2 Network.  If I remove the profile the clients roam just fine.

 

I'm still trying to determine what to put in the configuration profile.  Trial and error from here on out.

 

 

I've had a case open with Apple about this for a couple of months now.  Hasn't really been helpful.  

Johnkilpatrick,

 

What you could try is enabling "Rate Optimization for delivering EAPOL frames" in the Advanced Portion of the SSID profile you are having issues with.  That ensures that all 802.1x traffic will be sent at the management rate, which makes it more likely to succeed, than the negotiated data rate.

 

---

@cjoseph wrote:

Johnkilpatrick,

 

What you could try is enabling "Rate Optimization for delivering EAPOL frames" in the Advanced Portion of the SSID profile you are having issues with.  That ensures that all 802.1x traffic will be sent at the management rate, which makes it more likely to succeed, than the negotiated data rate.

 

---

Tried that.  It did not help.

Anything else you tried and your symptoms JohnKilpatrick?

John, I know this is a stretch, but did Apple assign a Bug ID or case #?

We do have an Apple Care case open under our corporate support agreement.  But they have yet to acknowledge an issue or assign an actual Bug ID.

I've also tried to enable the above setting and no luck. Like I said though. In my situation is has to do with the profile I install. If I uninstall the loginwindow profile for the user it will authenticate and keep authenticated just fine as I roam.

morrisch,

 

Any further background on why the loginwindow profile causes these issues?  I am not sure that all users configure a loginwindow profile...

No I don't have any background info. In fact it doesn't even have to be a loginwindow profile. It can simply be an 802.1x profile compatible with Mac OS X Lion or above that causes this behavior.

My issue may not be the same as others. I configure the profile with the cert and auth type and have tried this termination on the aruba controller as well and it still does not allow users to roam without losing connection and prompting for authentication again.