David, I saw similar RADIUS issues when I upgraded from 3.4.3.1 to 3.4.5.0 I would get RADIUS time outs. Very few authenticaiton requests got through. So as a temporary fix I increased the timeout setting for the AAA authentication. At least now the authentication goes through, but I still get errors in the logs that the RADIUS servers "time out" I find your log entry very interesting that it thinks the RADIUS request is not properly formatted. We also use Win2003 IAS. This problem showed up the morning after I upgraded the Aruba OS. We had not touched the IAS, only the Aruba controller. I was forced to upgrade to deal with a VLAN pool issue ... and this was the prize... I doubt that your problem is your Bradford IAS servers. I suspect some RADIUS bug in the later versions of the 3.4.x.x OS
I will have to pull together my debug logs and open a ticket with support cheers Joe Joe Guenther | Sr. Network Administrator | Olds College<http://www.oldscollege.ca/> | 4500-50th Street | Olds, Alberta | T4H 1R6 | 403-507-7923 - Office | 403-559-8340 – cell ________________________________ From: David Ziemba [[email protected]] Sent: Tuesday, October 18, 2011 4:31 PM Subject: Problem with auth, Aruba, Bradford, and IAS 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/. ********** Participation and subscription information for this EDUCAUSE Constituent Group discussion list can be found at http://www.educause.edu/groups/.
