Vocera Smartphone deauth

Unanswered Question
Dec 27th, 2010

I am running into a problem with Vocera smartphones where they appear to be functioning fine but intermittently go into a Searching For Gateway on the readout and the logs show a deauth being sent from the controller.  I have been running some logs from WCS and captured the following:

Running controllers 5508 with 1142 LAPs.  code version 6.0.196.0

802.11 Initialization
12/27/2010 09:45:40 PST     ERROR     10.247.2.115     De-authentication sent to client. slot 0 (claller apf_ms.c:4511)
12/27/2010 09:45:40 PST     INFO     10.247.2.115     Controller association request message received.
12/27/2010 09:45:40 PST     INFO     10.247.2.115     Received reassociation request from client.
12/27/2010 09:45:40 PST     INFO     10.247.2.115     Client moved to associated state successfully.
12/27/2010 09:45:51 PST     INFO     10.247.2.115     Controller association request message received.
12/27/2010 09:45:51 PST     INFO     10.247.2.115     Received reassociation request from client.
12/27/2010 09:45:51 PST     INFO     10.247.2.115     Client moved to associated state successfully.

PEM Messages
12/27/2010 09:45:40 PST     INFO     10.247.2.115     Received reassociation request from client.
12/27/2010 09:45:51 PST     INFO     10.247.2.115     Received reassociation request from client.

All
12/27/2010 09:45:40 PST     ERROR     10.247.2.115     De-authentication sent to client. slot 0 (claller apf_ms.c:4511)
12/27/2010 09:45:40 PST     INFO     10.247.2.115     Controller association request message received.
12/27/2010 09:45:40 PST     INFO     10.247.2.115     Received reassociation request from client.
12/27/2010 09:45:40 PST     INFO     10.247.2.115     Client moved to associated state successfully.
12/27/2010 09:45:51 PST     INFO     10.247.2.115     Controller association request message received.
12/27/2010 09:45:51 PST     INFO     10.247.2.115     Received reassociation request from client.
12/27/2010 09:45:51 PST     INFO     10.247.2.115     Client moved to associated state successfully.

Runnning some debugs on the controller for more info and I'll post later.

Thanks in advance.

Charlie

I have this problem too.
0 votes
  • 1
  • 2
  • 3
  • 4
  • 5
Average Rating: 0 (0 ratings)
George Stefanick Mon, 12/27/2010 - 23:59

If you can reproduce this issue, do a client debug and post your results. Do you have vocera badges as well? If so, how are they performing?

luceroc Tue, 12/28/2010 - 08:37

Yes we have both badges and smartphones.  I captured this yesterday.

Smartphone mac: 00:23:a2:b0:69:f1
Version: 6.0.196.0
Hardware: 5508
AP name W021 mac address: a4:0c:c3:96:fe:90
AP name: w015 mac address a4:0c:c3:d0:75:00

WCS logging:
12/27/2010 10:28:02 PST     ERROR     10.247.2.115     De-authentication sent to client. slot 0 (claller apf_ms.c:4511)
12/27/2010 10:28:02 PST     INFO     10.247.2.115     Controller association request message received.
12/27/2010 10:28:02 PST     INFO     10.247.2.115     Received reassociation request from client.
12/27/2010 10:28:02 PST     INFO     10.247.2.115     Client moved to associated state successfully.
12/27/2010 10:28:15 PST     INFO     10.247.2.115     Controller association request message received.
12/27/2010 10:28:15 PST     INFO     10.247.2.115     Received reassociation request from client.
12/27/2010 10:28:15 PST     INFO     10.247.2.115     Client moved to associated state successfully.

Debug on the controller (DHCP and mac address)
*Dec 27 10:27:52.473: 00:23:a2:b0:69:f1 apfMsExpireCallback (apf_ms.c:418) Expiring Mobile!
*Dec 27 10:27:52.473: 00:23:a2:b0:69:f1 apfMsExpireMobileStation (apf_ms.c:4427) Changing state for mobile 00:23:a2:b0:69:f1 on AP a4:0c:c3:d0:75:00 from Associated to Disassociated
*Dec 27 10:27:52.473: 00:23:a2:b0:69:f1 Scheduling deletion of Mobile Station:  (callerId: 45) in 10 seconds
*Dec 27 10:28:02.477: 00:23:a2:b0:69:f1 apfMsExpireCallback (apf_ms.c:418) Expiring Mobile!
*Dec 27 10:28:02.477: 00:23:a2:b0:69:f1 Sent Deauthenticate to mobile on BSSID a4:0c:c3:d0:75:00 slot 0(caller apf_ms.c:4511)
*Dec 27 10:28:02.477: 00:23:a2:b0:69:f1 apfMsExpireMobileStation (apf_ms.c:4548) Changing state for mobile 00:23:a2:b0:69:f1 on AP a4:0c:c3:d0:75:00 from Disassociated to Idle
*Dec 27 10:28:02.478: 00:23:a2:b0:69:f1 Scheduling deletion of Mobile Station:  (callerId: 47) in 10 seconds

*Dec 27 10:28:02.590: 00:23:a2:b0:69:f1 Association received from mobile on AP a4:0c:c3:96:fe:90
*Dec 27 10:28:02.590: 00:23:a2:b0:69:f1 Applying site-specific IPv6 override for station 00:23:a2:b0:69:f1 - vapId 4, site 'default-group', interface 'vocera'
*Dec 27 10:28:02.591: 00:23:a2:b0:69:f1 Applying IPv6 Interface Policy for station 00:23:a2:b0:69:f1 - vlan 701, interface id 13, interface 'vocera'
*Dec 27 10:28:02.591: 00:23:a2:b0:69:f1 STA - rates (4): 2 4 139 150 12 18 24 36 48 72 96 108 0 0 0 0
*Dec 27 10:28:02.591: 00:23:a2:b0:69:f1 STA - rates (12): 2 4 139 150 12 18 24 36 48 72 96 108 0 0 0 0
*Dec 27 10:28:02.591: 00:23:a2:b0:69:f1 10.247.38.21 RUN (20) Deleted mobile LWAPP rule on AP [a4:0c:c3:d0:75:00]
*Dec 27 10:28:02.591: 00:23:a2:b0:69:f1 10.247.38.21 Removed NPU entry.
*Dec 27 10:28:02.591: 00:23:a2:b0:69:f1 Updated location for station old AP a4:0c:c3:d0:75:00-0, new AP a4:0c:c3:96:fe:90-0
*Dec 27 10:28:02.591: 00:23:a2:b0:69:f1 10.247.38.21 RUN (20) Applied RADIUS override policy
*Dec 27 10:28:02.591: 00:23:a2:b0:69:f1 10.247.38.21 RUN (20) Adding Fast Path rule  type = Airespace AP Client  on AP a4:0c:c3:96:fe:90, slot 0, interface = 13, QOS = 2  ACL Id = 255, Jumbo Frames = NO,
*Dec 27 10:28:02.591: 00:23:a2:b0:69:f1 10.247.38.21 RUN (20) Successfully plumbed mobile rule (ACL ID 255)
*Dec 27 10:28:02.591: 00:23:a2:b0:69:f1 10.247.38.21 RUN (20) Plumbed mobile LWAPP rule on AP a4:0c:c3:96:fe:90 vapId 4 apVapId 4
*Dec 27 10:28:02.591: 00:23:a2:b0:69:f1 10.247.38.21 RUN (20) Change state to RUN (20) last state RUN (20)
*Dec 27 10:28:02.591: 00:23:a2:b0:69:f1 apfPemAddUser2 (apf_policy.c:212) Changing state for mobile 00:23:a2:b0:69:f1 on AP a4:0c:c3:96:fe:90 from Idle to Associated
*Dec 27 10:28:02.591: 00:23:a2:b0:69:f1 Scheduling deletion of Mobile Station:  (callerId: 49) in 1800 seconds
*Dec 27 10:28:02.592: 00:23:a2:b0:69:f1 Sending Assoc Response to station on BSSID a4:0c:c3:96:fe:90 (status 0)
*Dec 27 10:28:02.592: 00:23:a2:b0:69:f1 apfProcessAssocReq (apf_80211.c:4361) Changing state for mobile 00:23:a2:b0:69:f1 on AP a4:0c:c3:96:fe:90 from Associated to Associated
*Dec 27 10:28:02.592: 00:23:a2:b0:69:f1 10.247.38.21 Added NPU entry of type 1, dtlFlags 0x0

*Dec 27 10:28:15.238: 00:23:a2:b0:69:f1 Reassociation received from mobile on AP a4:0c:c3:d0:75:00
*Dec 27 10:28:15.238: 00:23:a2:b0:69:f1 Applying site-specific IPv6 override for station 00:23:a2:b0:69:f1 - vapId 4, site 'default-group', interface 'vocera'
*Dec 27 10:28:15.238: 00:23:a2:b0:69:f1 Applying IPv6 Interface Policy for station 00:23:a2:b0:69:f1 - vlan 701, interface id 13, interface 'vocera'
*Dec 27 10:28:15.238: 00:23:a2:b0:69:f1 STA - rates (4): 2 4 139 150 12 18 24 36 48 72 96 108 0 0 0 0
*Dec 27 10:28:15.238: 00:23:a2:b0:69:f1 STA - rates (12): 2 4 139 150 12 18 24 36 48 72 96 108 0 0 0 0
*Dec 27 10:28:15.239: 00:23:a2:b0:69:f1 10.247.38.21 RUN (20) Deleted mobile LWAPP rule on AP [a4:0c:c3:96:fe:90]
*Dec 27 10:28:15.239: 00:23:a2:b0:69:f1 10.247.38.21 Removed NPU entry.
*Dec 27 10:28:15.239: 00:23:a2:b0:69:f1 Updated location for station old AP a4:0c:c3:96:fe:90-0, new AP a4:0c:c3:d0:75:00-0
*Dec 27 10:28:15.239: 00:23:a2:b0:69:f1 10.247.38.21 RUN (20) Applied RADIUS override policy
*Dec 27 10:28:15.240: 00:23:a2:b0:69:f1 10.247.38.21 RUN (20) Adding Fast Path rule  type = Airespace AP Client  on AP a4:0c:c3:d0:75:00, slot 0, interface = 13, QOS = 2  ACL Id = 255, Jumbo Frames = NO,
*Dec 27 10:28:15.240: 00:23:a2:b0:69:f1 10.247.38.21 RUN (20) Successfully plumbed mobile rule (ACL ID 255)
*Dec 27 10:28:15.240: 00:23:a2:b0:69:f1 10.247.38.21 RUN (20) Plumbed mobile LWAPP rule on AP a4:0c:c3:d0:75:00 vapId 4 apVapId 4
*Dec 27 10:28:15.240: 00:23:a2:b0:69:f1 10.247.38.21 RUN (20) Change state to RUN (20) last state RUN (20)
*Dec 27 10:28:15.240: 00:23:a2:b0:69:f1 apfPemAddUser2 (apf_policy.c:212) Changing state for mobile 00:23:a2:b0:69:f1 on AP a4:0c:c3:d0:75:00 from Associated to Associated
*Dec 27 10:28:15.240: 00:23:a2:b0:69:f1 Scheduling deletion of Mobile Station:  (callerId: 49) in 1800 seconds
*Dec 27 10:28:15.240: 00:23:a2:b0:69:f1 Sending Assoc Response to station on BSSID a4:0c:c3:d0:75:00 (status 0)
*Dec 27 10:28:15.240: 00:23:a2:b0:69:f1 apfProcessAssocReq (apf_80211.c:4361) Changing state for mobile 00:23:a2:b0:69:f1 on AP a4:0c:c3:d0:75:00 from Associated to Associated
*Dec 27 10:28:15.241: 00:23:a2:b0:69:f1 10.247.38.21 Added NPU entry of type 1, dtlFlags 0x0

luceroc Wed, 12/29/2010 - 11:38

Hi George.  I was advised to change the session timeout to a higher value to cover the shift a worker would use the smartphone.  I set the timeout for 10 hours instead of the default 30 mins.   So far things appear to be better and the error is not showing up in the logs anymore.  This seems more like a work around than a resolution but it seems to but it appears to be helping.  From my point of view it appears that the smartphones get an actual timeout from the access point they are connected to and sends a deauth but then find the reassociation on a neighboring access point and performs a successful reauth.  In this time I suspect the phones briefly lose connection to their server and throw up the SFG error. I'll update after a weeks worth of testing and getting feedback from the user community.

George Stefanick Thu, 12/30/2010 - 19:30

Makes sense. What I've found is clients all handle this session timeout different. So

no surpirse there...

Actions

Login or Register to take actions

This Discussion

Posted December 27, 2010 at 10:09 AM
Stats:
Replies:5 Avg. Rating:
Views:33182 Votes:0
Shares:0
Tags: No tags.

Discussions Leaderboard