12-27-2010 10:09 AM - edited 07-03-2021 07:35 PM
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
12-27-2010 11:59 PM
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?
12-28-2010 08:37 AM
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
12-28-2010 08:38 AM
badges do not experience this.
12-29-2010 11:38 AM
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.
12-30-2010 07:30 PM
Makes sense. What I've found is clients all handle this session timeout different. So
no surpirse there...
Find answers to your questions by entering keywords or phrases in the Search bar above. New here? Use these resources to familiarize yourself with the community: