So, We've been noticing some troubles, and I'm curious if anyone has seen
anything like this lately. It'll happen to mobile devices, laptops, just about
anything that connects to our enterprise wireless (wpa2-enterprise).
We're running Aruba 3.4.4.3 across three controllers (sup2), Bradford
4.1.1.280.P13, and IAS on Windows 2003 server. Once clients associate to an
access point (within 2 seconds), it takes anywhere from 15-40 seconds to
successfully authenticate. We haven't found anything consistent per device if
it takes longer or shorter to pass auth, and even the same device might
associate/auth in 5 seconds, and then associate/auth in 40 seconds.
On Bradford, the log turned over recently, and in the last 26 hours, there have
been clients with 4200 radius requests, and the top 25 clients have between
1200-3500 radius requests. Looking at the debug on the controller, we see 14
eap requests and 14 radius requests for one client, and on the 14th radius
request, there is a radius/eap accept/success. This one took about 15 seconds
to pass auth:
Oct 18 16:06:51 station-up * 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
- - wpa2 aes
Oct 18 16:06:51 eap-id-req <- 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
1 5
Oct 18 16:06:51 eap-id-resp -> 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
1 12 jsmith
Oct 18 16:06:51 rad-req -> 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
19 165
Oct 18 16:06:53 rad-resp <- 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 19 77
Oct 18 16:06:53 eap-req <- 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
2 6
Oct 18 16:06:53 eap-resp -> 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
2 136
Oct 18 16:06:53 rad-req -> 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 94 314
Oct 18 16:06:54 rad-resp <- 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 94 1175
Oct 18 16:06:54 eap-req <- 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
3 1096
Oct 18 16:06:54 eap-resp -> 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
3 6
Oct 18 16:06:54 rad-req -> 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 127 184
Oct 18 16:06:56 rad-resp <- 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 127 1175
Oct 18 16:06:56 eap-req <- 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
4 1096
Oct 18 16:06:56 eap-resp -> 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
4 6
Oct 18 16:06:56 rad-req -> 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 81 184
Oct 18 16:06:57 rad-resp <- 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 81 1175
Oct 18 16:06:57 eap-req <- 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
5 1096
Oct 18 16:06:57 eap-resp -> 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
5 6
Oct 18 16:06:57 rad-req -> 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 223 184
Oct 18 16:06:58 rad-resp <- 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 223 1175
Oct 18 16:06:58 eap-req <- 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
6 1096
Oct 18 16:06:58 eap-resp -> 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
6 6
Oct 18 16:06:58 rad-req -> 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 215 184
Oct 18 16:06:59 rad-resp <- 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 215 1175
Oct 18 16:06:59 eap-req <- 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
7 1096
Oct 18 16:06:59 eap-resp -> 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
7 6
Oct 18 16:06:59 rad-req -> 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 233 184
Oct 18 16:07:00 rad-resp <- 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 233 1175
Oct 18 16:07:00 eap-req <- 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
8 1096
Oct 18 16:07:00 eap-resp -> 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
8 6
Oct 18 16:07:00 rad-req -> 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 191 184
Oct 18 16:07:00 rad-resp <- 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 191 1006
Oct 18 16:07:00 eap-req <- 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
9 929
Oct 18 16:07:00 eap-resp -> 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
9 332
Oct 18 16:07:00 rad-req -> 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 54 512
Oct 18 16:07:01 rad-resp <- 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 54 124
Oct 18 16:07:01 eap-req <- 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
10 53
Oct 18 16:07:01 eap-resp -> 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
10 6
Oct 18 16:07:01 rad-req -> 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 15 184
Oct 18 16:07:01 rad-resp <- 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 15 99
Oct 18 16:07:01 eap-req <- 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
11 28
Oct 18 16:07:01 eap-resp -> 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
11 35
Oct 18 16:07:01 rad-req -> 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 197 213
Oct 18 16:07:02 rad-resp <- 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 197 123
Oct 18 16:07:02 eap-req <- 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
12 52
Oct 18 16:07:02 eap-resp -> 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
12 89
Oct 18 16:07:02 rad-req -> 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 196 267
Oct 18 16:07:03 rad-resp <- 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 196 145
Oct 18 16:07:03 eap-req <- 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
13 74
Oct 18 16:07:03 eap-resp -> 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
13 29
Oct 18 16:07:03 rad-req -> 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 227 207
Oct 18 16:07:03 rad-resp <- 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 227 109
Oct 18 16:07:03 eap-req <- 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
14 38
Oct 18 16:07:03 eap-resp -> 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
14 38
Oct 18 16:07:03 rad-req -> 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 194 216
Oct 18 16:07:05 rad-accept <- 04:1e:64:AA:AA:AA
00:0b:86:BB:BB:BB/Bradford-PRI 194 330
Oct 18 16:07:05 eap-success <- 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
15 4
Oct 18 16:07:05 assg-vlan-req * 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
208 200
Oct 18 16:07:05 assg-vlan-resp * 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
- 200
Oct 18 16:07:05 station-data-ready * 04:1e:64:AA:AA:AA 00:00:00:00:00:00
208 200
Oct 18 16:07:05 wpa2-key1 <- 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
- 117
Oct 18 16:07:05 wpa2-key2 -> 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
- 117
Oct 18 16:07:05 wpa2-key3 <- 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
- 175
Oct 18 16:07:05 wpa2-key4 -> 04:1e:64:AA:AA:AA 00:0b:86:BB:BB:BB
- 95
On the Bradford server, I see four radius proxy requests during that period I
am trying to associate, and then on the IAS server there is terrible logging to
boot. On one previous attempt, I did get a message from the IAS server:
Access request for user jsmith was discarded. Fully-Qualified-User-Name =
NAS-IP-Address = 172.30.65.10 NAS-Identifier = 172.30.65.10
Called-Station-Identifier = 000B86BBBBBB Calling-Station-Identifier =
041E64AAAAAA Client-Friendly-Name = Bradford Client-IP-Address = 172.25.5.23
NAS-Port-Type = Wireless - IEEE 802.11 NAS-Port = 1 Proxy-Policy-Name = Use
Windows authentication for all users Authentication-Provider = Windows
Authentication-Server = Reason-Code = 3 Reason = The Remote Authentication
Dial-In User Service (RADIUS) request was not properly formatted.
Has anybody run into this, or have an idea(s) where to dig further?
Regards,
David
**********
Participation and subscription information for this EDUCAUSE Constituent Group
discussion list can be found at http://www.educause.edu/groups/.
