Howto:How to Read WLAN Traces on IP72
Jump to navigation
Jump to search
Applies To
This information applies to
- IP72
Build V7 and later.
Activate WLAN Tracing with V8
WLAN tracing is activated by navigating to Diagnostics submenu, Tracing, and activating the WLAN checkbox.
It can also be activated by invoking
config add WLANMGR0 /xtrace config write reset
Deactivate trace with
config rem WLANMGR0 /xtrace config write reset
Activate WLAN Tracing with V7
From the command line:
Activate WLAN trace with
config add WLANMGR0 /xtrace config change ASCDEBUG0 /enable supp /enable wlan config write reset
Deactivate trace with
config rem WLANMGR0 /xtrace config change ASCDEBUG0 config write config activate
Fetching trace by HTTP
Activate WLAN trace and click on "Trace (continuous)".
Fetching trace by Wireshark via rpcap
Plese see http://wiki.innovaphone.com/index.php?title=Howto:Pcap for details.
Fetching trace by USB
Download USB utilities from http://download.innovaphone.com/. IP72.zip contains the IP72 USB driver (usbio.sys) and the usbload utility (usbload.exe). Place the IP72 in the USB cradle and ,ake sure IP72 is correctly recognized and installed by Windows OS. Activate WLAN Trace as described above.
Alternatively, if there is still no WLAN connection to the IP72, one can activate it through usbload:
>usbload usbload 1.5 [09-60034] user: admin password: **** $
Activate WLAN trace:
config add WLANMGR0 /xtrace config change ASCDEBUG0 /enable supp /enable wlan config write reset
After reboot start continuous trace by invoking:
usbload login usbload clog /file log.txt
When done, interrupt the command by hitting CTLR-C. The trace is stored to file log.txt.
Analyse the cryptic output (initial Association and Authentication)
Repeated configuration:
0:0000:821:5 - HEXDUMP
00000000 - 43 99 99 94 39 99 99 43 98 99 94 39 98 C...9..C...9.
0:0000:821:5 - wlan_mgr config: (trpz,4)(AES-CCMP,43999994399999439999943666,1[1-4])(wpa2,none)->(2,WPA2,NONE,,)
(passwordd,,)(uapsd,long-doze->long-doze)(0->world) (-70dBm)
Intial setup, powermode, regdoamin, channel-mask
0:0000:821:6 - wlan_mgr: powermode state -> s:0 (long-doze) 0:0000:821:7 - wlan_mgr config: regdomain: vars 1, config 1 0:0000:821:7 - wlan_mgr config: channel mask: vars 0x421, config 0x421
Initial setup, config WLAN Auth.
0:0000:926:7 - [WLAN] Updating WLAN driver security parameters; 0:0000:927:0 - [WLAN] Setting Authentication mode to WPA2 0:0000:927:0 - [WLAN] Setting Encryption to AES-CCMP 0:0000:927:1 - [WLAN] Setting passphrase ************** 0:0000:927:1 - [WLAN] Setting EssId trpz 0:0000:927:1 - [WLAN] EssId length = 4
Start joining the WLAN network:
0:0002:200:5 - [WLAN] here HAL_CTRL , INIT: whal_hwCtrl_StartJoin: Enable Tx, Rx and Start the Bss 0:0002:200:6 - [WLAN] here HAL_CTRL , INIT: ------------------------------------------------------------ 0:0002:200:7 - [WLAN] here HAL_CTRL , INIT: START/JOIN, SSID=trpz, BSSID=00-0B-0E-55-67-80, Chan=11 0:0002:201:0 - [WLAN] here HAL_CTRL , INIT: ------------------------------------------------------------
Periodic scan results:
0:0002:204:6 - wlan_mgr::serial_event IPC_EVENT_SCAN_COMPLETE 0:0002:205:4 - wlan_mgr: BSSID list-items=5 pending-reqs=0 0:0002:205:5 - wlan_mgr: AP 0:(mac=00:0b:0e:55:32:00, ssid=trpz, rssi=-64dBm, channel=1)(beacon=100ms)(ATIM=0) 0:0002:205:6 - wlan_mgr: AP 1:(mac=00:0f:f8:58:cd:07, ssid=dev, rssi=-67dBm, channel=6)(beacon=100ms)(ATIM=0) 0:0002:205:7 - wlan_mgr: AP 2:(mac=00:0b:0e:55:67:80, ssid=trpz, rssi=-59dBm, channel=11)(beacon=100ms)(ATIM=0) 0:0002:206:0 - wlan_mgr: AP 3:(mac=00:0b:0e:55:69:40, ssid=trpz, rssi=-88dBm, channel=6)(beacon=100ms)(ATIM=0) 0:0002:206:0 - wlan_mgr: AP 4:(mac=00:15:e9:0b:a6:bc, ssid=KatziL, rssi=-91dBm, channel=6)(beacon=100ms)(ATIM=0)
We have been associated, own MAC, MAC from AP.
0:0002:219:5 - [WLAN] Received ASSOCIATED event 0:0002:219:5 - [WLAN] nAssociationMode = 3 0:0002:219:6 - [WLAN] nAuthenticationType = 0 0:0002:219:6 - [WLAN] nKeyType = 1 0:0002:219:6 - [WLAN] nEncryptionType = 3 0:0002:219:7 - [WLAN] Mac Address of STA = 00:01:3e:10:22:b5 0:0002:220:0 - [WLAN] Mac Address of AP = 00:0b:0e:55:67:80
Received a beacon:
0:0002:220:4 - [SUPP] SUPP_SetNetworkInfo 0:0002:220:5 - [SUPP] 00000000: 00 04 74 72 70 7A 01 09 16 8C 12 18 24 30 48 60 ..trpz......$0H` 0:0002:220:5 - [SUPP] 00000010: 6C 02 05 00 00 00 00 01 03 01 0B 30 18 01 00 00 l..........0.... 0:0002:220:6 - [SUPP] 00000020: 0F AC 02 02 00 00 0F AC 02 00 0F AC 04 01 00 00 ................ 0:0002:220:6 - [SUPP] 00000030: 0F AC 02 00 00 DD 1C 00 50 F2 01 01 00 00 50 F2 ........P.....P. 0:0002:220:7 - [SUPP] 00000040: 02 02 00 00 50 F2 02 00 50 F2 04 01 00 00 50 F2 ....P...P.....P. 0:0002:220:7 - [SUPP] 00000050: 02 00 00 DD 18 00 50 F2 02 01 01 01 68 03 A4 00 ......P.....h... 0:0002:221:0 - [SUPP] 00000060: 00 27 A4 00 00 42 43 5E 00 62 32 2F 00 .'...BC^.b2/. 0:0002:221:7 - [SUPP] From Suppl: ODSTK_CB_LINK_STATUS 0:0002:222:0 - [SUPP] Link state = Unauthenticated key wait
Received EAPOL (ANonce, Msg1) from AP:
0:0002:238:3 - [WLAN] Received EAPOL event (size = 135) 0:0002:238:3 - [SUPP] SUPP_RecvEAPOL 0:0002:238:5 - [SUPP] [NRM] Received EAPOL packet 0:0002:238:6 - [SUPP] 00000000: 01 03 00 75 02 00 8A 00 10 00 00 00 00 00 00 00 ...u............ 0:0002:238:6 - [SUPP] 00000010: 00 F8 7E 0C D3 D6 22 DA 5D A9 63 5B 39 51 8A 19 ..~...".].c[9Q.. 0:0002:238:7 - [SUPP] 00000020: ED E8 63 7D ED D2 8B 45 5E 95 8A 0C 29 FD ED BF ..c}...E^...)... 0:0002:239:0 - [SUPP] 00000030: CC 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ 0:0002:239:0 - [SUPP] 00000040: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ 0:0002:239:1 - [SUPP] 00000050: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ 0:0002:239:1 - [SUPP] 00000060: 00 00 16 DD 14 00 0F AC 04 5F 04 6A C0 08 0B 64 ........._.j...d 0:0002:239:2 - [SUPP] 00000070: 30 85 23 99 B9 41 3B DE EF 0.#..A;..
Calculate and transmit EAPOL (Snonce+MIC) to AP:
0:0002:242:5 - [SUPP] [NRM] Sending EAPOL-Key 4-way handshake message 2 0:0002:243:1 - [SUPP] [NRM] Transmitting EAPOL-Key 0:0002:243:1 - [SUPP] 00000000: 01 03 00 75 02 01 0A 00 10 00 00 00 00 00 00 00 ...u............ 0:0002:243:2 - [SUPP] 00000010: 00 D5 D4 28 43 21 70 AA 13 77 0E 1F 74 AA 50 6F ...(C!p..w..t.Po 0:0002:243:2 - [SUPP] 00000020: 80 3B 8D F5 13 D5 94 FA 71 C4 C0 B5 B4 75 F6 7D .;......q....u.} 0:0002:243:3 - [SUPP] 00000030: 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ 0:0002:243:3 - [SUPP] 00000040: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ 0:0002:243:4 - [SUPP] 00000050: 00 A4 15 BE 0A 1B 58 65 41 46 E4 EF FE 02 15 C2 ......XeAF...... 0:0002:243:4 - [SUPP] 00000060: BE 00 16 30 14 01 00 00 0F AC 02 01 00 00 0F AC ...0............ 0:0002:243:5 - [SUPP] 00000070: 04 01 00 00 0F AC 02 00 00 .........
Receive EAPOL (GTK+MIC) from AP:
0:0002:253:2 - [SUPP] [NRM] Received EAPOL packet 0:0002:253:2 - [SUPP] 00000000: 01 03 00 AF 02 13 CA 00 10 00 00 00 00 00 00 00 ................ 0:0002:253:3 - [SUPP] 00000010: 01 F8 7E 0C D3 D6 22 DA 5D A9 63 5B 39 51 8A 19 ..~...".].c[9Q.. 0:0002:253:4 - [SUPP] 00000020: ED E8 63 7D ED D2 8B 45 5E 95 8A 0C 29 FD ED BF ..c}...E^...)... 0:0002:253:4 - [SUPP] 00000030: CC 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ 0:0002:253:5 - [SUPP] 00000040: 00 8A 19 82 01 00 00 00 00 00 00 00 00 00 00 00 ................ 0:0002:253:5 - [SUPP] 00000050: 00 3F 91 D8 81 D9 E6 4A A0 07 1D 0D D2 1A 4A 85 .?.....J......J. 0:0002:253:6 - [SUPP] 00000060: F6 00 50 1D 89 D3 2A DB ED E6 70 A0 E6 F9 84 3C ..P...*...p....< 0:0002:253:6 - [SUPP] 00000070: 5C 08 47 5A 89 16 59 79 EE 85 86 B0 14 25 F2 C6 \.GZ..Yy.....%.. 0:0002:253:7 - [SUPP] 00000080: 65 CF 4C 36 07 25 EC 1B A9 44 8D BC 74 A0 81 F7 e.L6.%...D..t... 0:0002:253:7 - [SUPP] 00000090: 43 BA 06 19 65 13 42 E2 3D B4 AD A0 B4 CC 6F DD C...e.B.=.....o. 0:0002:254:0 - [SUPP] [NRM] Processing EAPOL-Key message 0:0002:254:1 - [SUPP] [DTL] Received replay counter is 0000000000000001 0:0002:254:2 - [SUPP] [DTL] EAPOL-Key message version = 2 0:0002:254:2 - [SUPP] [NRM] Processing EAPOL-Key 4-way handshake message 3
Send EAPOL (ACK) to AP:
0:0002:257:7 - [SUPP] [NRM] Sending EAPOL-Key 4-way handshake message 4 0:0002:258:2 - [SUPP] [NRM] Transmitting EAPOL-Key 0:0002:258:2 - [SUPP] 00000000: 01 03 00 5F 02 03 0A 00 10 00 00 00 00 00 00 00 ..._............ 0:0002:258:3 - [SUPP] 00000010: 01 D5 D4 28 43 21 70 AA 13 77 0E 1F 74 AA 50 6F ...(C!p..w..t.Po 0:0002:258:3 - [SUPP] 00000020: 80 3B 8D F5 13 D5 94 FA 71 C4 C0 B5 B4 75 F6 7D .;......q....u.} 0:0002:258:4 - [SUPP] 00000030: 01 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ 0:0002:258:4 - [SUPP] 00000040: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 ................ 0:0002:258:5 - [SUPP] 00000050: 00 04 A3 78 65 FE D2 AE 33 BA 90 B3 F8 AE 29 E8 ...xe...3.....). 0:0002:258:5 - [SUPP] 00000060: B0 00 00 ...
Finalize:
0:0002:259:7 - [SUPP] [NRM] Instantiating WPA key, index E0000000, RSC = 0000000000000000 0:0002:259:7 - [SUPP] 00000000: 7A 88 55 AE 19 8C 86 07 DA 04 0C 3A 62 80 BF 79 z.U........:b..y 0:0002:260:0 - [SUPP] From Suppl: ODSTK_CB_ADD_KEY 0:0002:260:1 - [WLAN] here os_setKey OsContext=0x106a5384, keylength=16 0:0002:260:6 - [SUPP] [NRM] Instantiating WPA key, index 20000001, RSC = 000000000182198A 0:0002:260:7 - [SUPP] 00000000: B5 06 BC 63 81 35 F0 F5 BC D8 32 B2 42 BE F1 52 ...c.5....2.B..R 0:0002:260:7 - [SUPP] 00000010: D2 70 F3 F6 E7 3D AC B8 0B A9 04 71 B8 81 43 85 .p...=.....q..C. 0:0002:261:0 - [SUPP] From Suppl: ODSTK_CB_ADD_KEY 0:0002:261:1 - [WLAN] here os_setKey OsContext=0x106a5384, keylength=32 0:0002:261:7 - [WLAN] SendEvent: Queue Event to myself 0:0002:262:3 - [SUPP] From Suppl: ODSTK_CB_LINK_STATUS 0:0002:262:4 - [SUPP] Link state = Open/unauthenticated 0:0002:262:4 - [SUPP] From Suppl: ODSTK_CB_MEDIA_CONNECT
Analyse cryptic output (Roaming)
Rescan APs, received LOW_RSSI, join AP with better RSSI
21:1808:180:7 - wlan_mgr: BSSID list-items=2 pending-reqs=0 21:1808:181:0 - wlan_mgr: AP *0:(mac=00:0b:0e:55:32:00, ssid=trpz, rssi=-63dBm, channel=1)(beacon=100ms)(ATIM=0) 21:1808:181:1 - wlan_mgr: AP 1:(mac=00:0b:0e:55:67:80, ssid=trpz, rssi=-64dBm, channel=11)(beacon=100ms)(ATIM=0) 21:1810:021:2 - wlan_mgr: RSSI = -66 SNR = 0 21:1811:648:3 - wlan_mgr::serial_event IPC_EVENT_LOW_RSSI 21:1811:976:6 - wlan_mgr: RSSI = -70 SNR = 0 21:1812:010:5 - VOIP_CALL.4 -> PHONE_REG.1 : SIG_MEDIA_INFO xmit(8,43,9,4629) recv(8,8,95,0) 21:1812:010:6 - phone_app: call_update 0035 RECV_MEDIA_INFO 21:1812:011:5 - PHONE_REG.1 -> VOIP_CALL.4 : SIG_FACILITY 21:1812:014:1 - PHONE_APP.0 -> PHONE_APP.0 : APP_DISP_FLUSH 21:1812:158:6 - [WLAN] SendEvent: Queue Event to myself 21:1812:161:5 - [WLAN] here HAL_CTRL , INIT: whal_hwCtrl_StartJoin: Enable Tx, Rx and Start the Bss 21:1812:161:6 - [WLAN] here HAL_CTRL , INIT: ------------------------------------------------------------ 21:1812:162:0 - [WLAN] here HAL_CTRL , INIT: START/JOIN, SSID=trpz, BSSID=00-0B-0E-55-67-80, Chan=11 21:1812:162:1 - [WLAN] here HAL_CTRL , INIT: ------------------------------------------------------------ 21:1812:163:1 - [WLAN] HandleEvent: Event type = 0x13 21:1812:163:1 - [WLAN] Received ROAMING event, buffering tx packets 21:1812:163:3 - [SUPP] Restarting timer 60000 ms 21:1812:167:0 - wlan_mgr::serial_event IPC_EVENT_LOW_RSSI 21:1812:167:0 - wlan_mgr::serial_event IPC_EVENT_ROAMING_START 21:1812:173:4 - [WLAN] Add to SendQPrio (numof packets = 1) 21:1812:174:7 - [WLAN] SendEvent: Queue Event to myself 21:1812:175:4 - [WLAN] HandleEvent: Event type = 0x0 21:1812:175:5 - [WLAN] Received ASSOCIATED event
Then we have the 4-way handshake as described above, followed by
21:1812:223:4 - [SUPP] From Suppl: ODSTK_CB_MEDIA_CONNECT 21:1812:223:4 - [WLAN] Received media connect, stopped buffering 21:1812:223:5 - [WLAN] Send from SendQPrio (left in queue = 0) 21:1812:224:4 - [WLAN] Transmitting gratuitous ARP reply 21:1812:224:5 - [WLAN] Roamed from 00:0b:0e:55:32:00 (-71:1) to 00:0b:0e:55:67:80 (-60:11)
We can calculate approximate roaming time by subtracting the roam-begin and roam-end events:
21:1812:163:1 - [WLAN] Received ROAMING event, buffering tx packets ... 21:1812:224:5 - [WLAN] Roamed from 00:0b:0e:55:32:00 (-71:1) to 00:0b:0e:55:67:80 (-60:11)
Only 61ms. Usual and common roaming sequence lasts for approx. 100ms.
WLAN Managment Frames on Startup
After reboot, the observed message frame sequence on e.g. a Trapeze system looks like this:
IP72 --- Probe Request ---> AP IP72 <-- Probe Response --- AP IP72 <---- Beacon --------- AP IP72 - Auth. (open) ------> AP IP72 <--- Auth (ok) ------- AP IP72 -- Assoc. request ---> AP IP72 <--- Assoc. response - AP IP72 <--- EAPOL (1) ------- AP IP72 ---- EAPOL (2) ------> AP IP72 <--- EAPOL (3) ------- AP IP72 ---- EAPOL (4) ------> AP
After link layer acivation, IP requetst an IP-addr through DHCP.
WLAN Managment Frames when Roaming
IP72 --- Probe Request ---> AP IP72 <-- Probe Response --- AP IP72 <---- Beacon --------- AP IP72 - Auth. (open) ------> AP IP72 <--- Auth (ok) ------- AP IP72 - Reassoc. request --> AP IP72 <- Reassoc. response - AP IP72 <--- EAPOL (1) ------- AP IP72 ---- EAPOL (2) ------> AP IP72 <--- EAPOL (3) ------- AP IP72 ---- EAPOL (4) ------> AP
After link layer acivation, IP requetst an IP-addr through DHCP.