wireless reconnection issue and explain the debug client

Unanswered Question
Apr 29th, 2012

hi i have WLC5508 and many 1142 AP . client have authenticated by ACS .

but sometimes client's PC has occurred this pheonomenon.

and has reconnectioned.

ss.png

i attached debug client file

please check and explaine debug file.

thanks

I have this problem too.
0 votes
  • 1
  • 2
  • 3
  • 4
  • 5
Average Rating: 5 (4 ratings)
Amjad Abdullah Sun, 04/29/2012 - 22:55

Hi SU,

looking into the debug client file, I can see the only thing cause

*Apr 27 17:25:43.774: 18:3d:a2:0a:0a:4c Received Idle-Timeout from AP 00:17:0f:e7:b2:10, slot 0 for STA 18:3d:a2:0a:0a:4c

*Apr 27 17:25:43.774: 18:3d:a2:0a:0a:4c apfMsDeleteByMscb Scheduling mobile for deletion with deleteReason 4, reasonCode 4

It looks the Idle-Timeout timer expires! this happens when the AP stops hearing from the station for a specific time (300 seconds = 5 minutes by default. value is configurable under Controller->General).

in your case it seems the PC is up but the AP stops hearing anything from the AP for a specific time. This could happen if you are not doing anything wiht your PC (no send or receive over the network) or if your PC moved out of the network, got shutdown immedietly or went immediately to sleep/hibernate without sending deauthentication to the AP.

If your laptops never went though the poinst above, then it could possibly a problem with your client specifically that it stops sending/receiving for a specific time and the AP consider it removed and delete it from its DB.

Is the problem happening with your 1 laptops only? or with all clients?

I suggest that you update the client's wireless adapter's driver to latest one. this usually helps solving this kind of problems if it is a client issue.

HTH

Amjad

nikhilcherian Mon, 04/30/2012 - 00:58

Amjad,

I can see

"Apr 30 07:44:46.473: 1c:65:9d:64:91:7e Initiating 802.1x due to PMK Timeout Event for STA "

re-occuring every 30 minutes

It looks like he has session time-out configured for every 30 minutes (1800 seconds)

Thanks for the tip on Reason code 4.. New info for me

Thanks

NikhiL

Amjad Abdullah Tue, 05/01/2012 - 23:30

Hi NikhiL,

You are right. PMK timeout is configured with same value as session timeout and no track for re-auth timeout is taken because when PMK expires reauth will happen anyway.

"Disabling re-auth since PMK lifetime can take care of same."

However, after each PMK timeout in the logs It direclty does authenticaiton again and Access-Accept is also received and process continues. nothing indicate any kind of problem after the session times out.

I suppose that the user stopped the debugs when the problem happens; and that where idle-timeout is appearing.

It looks like a problem with the client it self because it stops exchanging data with the AP and the AP delete it from it's DB.

In my life I've seen such problems where all clients work fine except one or two. I try usually disable or increase session timeout without hope. Increasing idle-timeout shows better performance but this is not a final solution because the problem is usually with the client itself and not with the WLAN infrastructure. The best thing to do IMHO is to upgrade adapter's driver on the station hoping this is going to stop the issue.

Amjad

sudeokeom Tue, 05/01/2012 - 19:23

hi team~~

thanks for your reply.

that happened  with onother client's are too.

and that's happen occurred on working time.

nikhilcherian Tue, 05/01/2012 - 21:36

Thanks for the Ratings George

Su Deok Eom,

Can you disable the session timeout configured on the WLAN. You can see the same in WLAN>WLAN ID>Advanced settings,

It will be configured for 1800 seconds, uncheck the same

Regards

NikhiL

sudeokeom Wed, 05/02/2012 - 02:42

hi nikhilcherian

i can change to session timeout .

i want to know  under's debug inform.. ( why client's has change to associated to disassociated )

*Apr 27 12:38:04.053: 18:3d:a2:0a:0a:4c Cleaning up state for STA 18:3d:a2:0a:0a:4c due to event for AP 00:1a:30:33:b9:40(0)

*Apr 27 12:38:04.054: 18:3d:a2:0a:0a:4c apfSendDisAssocMsgDebug (apf_80211.c:1682) Changing state for mobile 18:3d:a2:0a:0a:4c on AP 00:1a:30:33:b9:40 from Associated to Disassociated

*Apr 27 12:38:04.055: 18:3d:a2:0a:0a:4c Sent Disassociate to mobile on AP 00:1a:30:33:b9:40-0 (reason 1, caller apf_ms.c:4401)

*Apr 27 12:38:04.055: 18:3d:a2:0a:0a:4c Scheduling deletion of Mobile Station:  (callerId: 45) in 10 seconds

*Apr 27 12:38:05.228: 18:3d:a2:0a:0a:4c Association received from mobile on AP c4:7d:4f:52:9e:f0

*Apr 27 12:38:05.228: 18:3d:a2:0a:0a:4c Applying site-specific IPv6 override for station 18:3d:a2:0a:0a:4c - vapId 5, site 'AMOREPACIFIC', interface 'amorepacific_backup'

*Apr 27 12:38:05.228: 18:3d:a2:0a:0a:4c Applying IPv6 Interface Policy for station 18:3d:a2:0a:0a:4c - vlan 196, interface id 11, interface 'amorepacific_backup'

*Apr 27 12:38:05.228: 18:3d:a2:0a:0a:4c Applying site-specific override for station 18:3d:a2:0a:0a:4c - vapId 5, site 'AMOREPACIFIC', interface 'amorepacific_backup'

*Apr 27 12:38:05.228: 18:3d:a2:0a:0a:4c 10.129.67.161 RUN (20) Changing ACL 'none' (ACL ID 255) ===> 'none' (ACL ID 255) --- (caller apf_policy.c:1276)

*Apr 27 12:38:05.228: 18:3d:a2:0a:0a:4c STA - rates (8): 140 18 152 36 176 72 96 108 48 72 96 108 0 0 0 0

*Apr 27 12:38:05.228: 18:3d:a2:0a:0a:4c Processing RSN IE type 48, length 38 for mobile 18:3d:a2:0a:0a:4c

*Apr 27 12:38:05.228: 18:3d:a2:0a:0a:4c Received RSN IE with 1 PMKIDs from mobile 18:3d:a2:0a:0a:4c

*Apr 27 12:38:05.228: Received PMKID:  (16)

*Apr 27 12:38:05.228:      [0000] 61 e8 86 f3 e3 2a e6 a4 0d 0d 5e 3b ce 40 05 0b

*Apr 27 12:38:05.228: 18:3d:a2:0a:0a:4c Searching for PMKID in MSCB PMKID cache for mobile 18:3d:a2:0a:0a:4c

*Apr 27 12:38:05.228: 18:3d:a2:0a:0a:4c No valid PMKID found in the MSCB PMKID cache for mobile 18:3d:a2:0a:0a:4c

*Apr 27 12:38:05.228: 18:3d:a2:0a:0a:4c Trying to compute a PMKID from MSCB PMK cache for mobile 18:3d:a2:0a:0a:4c

Scott Fella Wed, 05/02/2012 - 04:03

I agree with George... good job guys!

Well looking at the log you posted, it seems the client roamed from one ap to another. So you see the client disassociate from one ap and re-associate to a different one.

Sent from Cisco Technical Support iPhone App

Amjad Abdullah Wed, 05/02/2012 - 04:24

Thank you Scott.

I can see in the debugs:

*Apr 27 12:38:04.055: 18:3d:a2:0a:0a:4c Sent Disassociate to mobile on AP 00:1a:30:33:b9:40-0 (reason 1, caller apf_ms.c:4401)

*Apr 27 12:38:04.055: 18:3d:a2:0a:0a:4c Scheduling deletion of Mobile Station:  (callerId: 45) in 10 seconds

*Apr 27 12:38:05.228: 18:3d:a2:0a:0a:4c Association received from mobile on AP c4:7d:4f:52:9e:f0

If disassociation will be due roamign there should be reassociation packet before the association to the target AP. However, in the logs it is normal association that follows the disassociation. am I correct? or there are some hidden points that I am not seeing?

Disassociation can possibly be due user normally disconnecting the station manually. So the user could possibly disconnected and tried (either manyally or automatically) to connect again.

I can also see some weird messages like:

*Apr 27 11:27:33.934: Ignoring 802.11 assoc request from mobileradio is NOT enabled

which I don't know what could trigger this kind of messages.

nikhilcherian Wed, 05/02/2012 - 04:35

Once the client reaches session time-out, the Controller will de-authenticate the client

Actions

Login or Register to take actions

This Discussion

Posted April 29, 2012 at 9:18 PM
Stats:
Replies:11 Avg. Rating:5
Views:1790 Votes:0
Shares:0

Related Content

Discussions Leaderboard