Archiv für den Monat: Januar 2014

Troubleshooting Cisco Aironet Client Disconnectes

Gestern hatte ich Gelegenheit ein WLAN-Problem zu entstören, bei dem ca. 50% der angebundenen Clients sofort nach der erfolgreichen Assoziierung sich wieder getrennt haben.

Auf dem Access Point wurde z. B. folgendes gelogged (man achte auf dem Timecode!):

Jan 28 13:30:57.230: %DOT11-6-ASSOC: Interface Dot11Radio0, Station   aaaa.bbbb.cccc Associated KEY_MGMT[WPAv2 PSK]
Jan 28 13:30:57.294: %DOT11-6-DISASSOC: Interface Dot11Radio0, Deauthenticating Station aaaa.bbbb.cccc Reason: Sending station has left the BSS
Jan 28 13:30:57.294: Dot11Radio0: Going to delete client aaaa.bbbb.cccc Reason: request

Um sich dem Thema zu nähern habe ich erstmal geprüft, ob ggf. ein Störer existiert:

AP# debug dot11 dot11Radio 0 carrier busy
Jan 28 12:53:28.577: **disc_send_reset_event, event=1
Jan 28 12:53:28.581: %LINK-6-UPDOWN: Interface Dot11Radio0, changed state to down
Jan 28 12:53:28.589: %LINK-5-CHANGED: Interface Dot11Radio0, changed state to reset
Jan 28 12:53:29.581: %LINEPROTO-5-UPDOWN: Line protocol on Interface Dot11Radio0, changed state to down
Jan 28 12:53:29.585: DOT11 EVENT:disc_config: root set device to 9E
Frequency  Carrier Busy %
———  ————–
2412         18
2417         18
2422          4
2427          7
2432         16
2437          7
2442          9
2447          7
2452         13
2457          7
2462         58
2467         11
2472         43
dot11_build_allowed_power_levels 8764 8000 0
Jan 28 12:53:44.673: DOT11 EVENT: dot11_build_allowed_power_levels 8764 8000 0
Jan 28 12:53:49.461: %LINK-6-UPDOWN: Interface Dot11Radio0, changed state to up
Jan 28 12:53:50.461: %LINEPROTO-5-UPDOWN: Line protocol on Interface Dot11Radio0, changed state to up

Zu beachten ist hier, dass das Radio-Interface für den Zeitraum in einen Reset-Status geht. Auch der aktuell ausgewählte Kanal kann abgerufen werden:

AP# show controllers do 0
!
interface Dot11Radio0
Radio Ibiza 2.4, Base Address cccc.dddd.ffff, BBlock version 0.00, Software version 4.18.1
Serial number: FOCxxxxxxxx
Unused dynamic SQRAM memory: 0x0000C8F0 (50 KB)
Unused dynamic SDRAM memory: 0x00089264 (548 KB)
Spectrum FW version: 1.15.0
Number of supported simultaneous BSSID on Dot11Radio0: 16
Carrier Set: EMEA (EU) (-E)
Uniform Spreading Required: No
Configured Frequency: 2447 MHz  Channel 8 

Notfalls, kann man bei Bedarf den automatisch gewählten Kanal auch nochmals automatisch suchen lassen oder den Access-Point in einen Kanal zwingen:

AP(config)# interface Do0
AP(config-if)# channel least-congested
Jan 28 12:51:14.680: %LINK-6-UPDOWN: Interface Dot11Radio0, changed state to down
Jan 28 12:51:14.688: %LINK-5-CHANGED: Interface Dot11Radio0, changed state to reset
Jan 28 12:51:15.680: %LINEPROTO-5-UPDOWN: Line protocol on Interface Dot11Radio0, changed state to down
Jan 28 12:51:15.684: DOT11 EVENT:disc_config: root set device to 9E
Jan 28 12:51:15.688: %DOT11-6-FREQ_SCAN: Interface Dot11Radio0, Scanning frequencies for 13 seconds
Jan 28 12:51:28.955: DOT11 EVENT: dot11_build_allowed_power_levels 8764 8000 0
Jan 28 12:51:33.147: %DOT11-6-FREQ_USED: Interface Dot11Radio0, frequency 2447 selected
Jan 28 12:51:33.147: DOT11 EVENT: dot11_build_allowed_power_levels 8764 8000 0
Jan 28 12:51:38.039: %LINK-6-UPDOWN: Interface Dot11Radio0, changed state to up
Jan 28 12:51:39.039: %LINEPROTO-5-UPDOWN: Line protocol on Interface Dot11Radio0, changed state to up

Nun zurück zum Problem, dem sofortigen Trennen der Verbindung. Das Standardlog impliziert, dass der PC die Trennung forciert hat. Mit ein paar Debug-Befehlen kann man dies untermauern:

AP#deb dot11 mgmt interface
AP#deb dot11 mgmt msg
AP#deb dot11 mgmt ssid
AP#deb dot11 mgmt state-machine
AP#deb dot11 mgmt station
Jan 28 13:30:57.214: Dot11Radio0: Tx AssocResp client aaaa.bbbb.cccc
Jan 28 13:30:57.214: dot11_mgmt: dot11_mgmt_sta_deref (ref=3, sta_ptr=0x734648C, mac=aaaa.bbbb.cccc)
Jan 28 13:30:57.230: dot11_mgmt: recv AAA Auth resp for aaaa.bbbb.cccc, vlan name , id 10 and wnid 0
Jan 28 13:30:57.230: dot11_mgmt: same VLAN return from AAA
Jan 28 13:30:57.230: dot11_mgmt: dot11_mgmt_sta_ref (ref=2, sta_ptr=0x734648C, mac=aaaa.bbbb.cccc)
Jan 28 13:30:57.230: SM: —Open Authentication 0x734648C: AAA Auth OK (5)
Jan 28 13:30:57.230: SM:    AAA_Auth (6) –> Assoc (2)
Jan 28 13:30:57.230: %DOT11-6-ASSOC: Interface Dot11Radio0, Station   aaaa.bbbb.cccc Associated KEY_MGMT[WPAv2 PSK]
Jan 28 13:30:57.230: dot11_mgmt:aaaa.bbbb.cccc bss client assoc/reassoc updated stats curr_assoc 2 cur_bss_assoc 2 cur_rptrs 0 cur_bss_rptrs 0lwapp_session_timeout not starting for aaaa.bbbb.cccc
Jan 28 13:30:57.230: dot11_mgmt: dot11_mgmt_sta_deref (ref=3, sta_ptr=0x734648C, mac=aaaa.bbbb.cccc)
Jan 28 13:30:57.294: Dot11Radio0: Rx DisAssoc client aaaa.bbbb.cccc
Jan 28 13:30:57.294: dot11_mgmt:receive disassoc from aaaa.bbbb.cccc
Jan 28 13:30:57.294: Dot11Radio0: Tx Deauth client aaaa.bbbb.cccc
Jan 28 13:30:57.294:  dot11_mgmt: de-auth msg sent with reason = 2

Hier ist klar erkennbar, dass nach der erfolgreichen Assoziation zum WLAN sofort ein DisAssoc vom Client zum Access Point gesendet wird. Ab diesem Punkt habe ich dann gemeinsam mit dem x86-Plattformkollegen den Client „zerlegt“. Letztendlich konnte es auf ein fehlerhaftes verhalten des Virenscanners zurückgeführt werden bei dem eine Policy die Nutzung des WLANs versehentlicherweise geblockt hat.