Technology Blog

Tools for Troubleshooting from the Client Revisited

by ‎07-27-2016 07:00 AM

A year and a half ago I wrote a post about some of the little-known tools I use to help troubleshoot wireless issues that happen to be built right in to iOS and OS X. The idea behind troubleshooting from client devices is that you’re able to get a view of the WLAN as they see it which can help when it everything looks fine and dandy from calibrated, specialized wireless tools. It turned out to be fairly popular and I’ve been asked a few times if I’ve added anything else to my Apple shaped toolbox lately and as it turns out, I have.

 

As with some of the tools from the previous post, this utility requires an active Apple Developer account to setup (and iTunes to sync the logs) but if you’re able to speed up troubleshooting of a critical problem or fix a nagging issue, that $99/year is a steal. Additionally, it would be helpful to have some basic CLI skills to manipulate and view the data quickly. To be completely honest, I’m not entirely sure how long this has been available having only discovered it been introduced to it by a good (and unnamed) friend just this past winter.

 

From Apple’s support docs:

 

The Wi-Fi Diagnostics Profile generates files that allow Apple to troubleshoot issues with your device and help Apple to improve its products and services.  The generated files may contain some of your personal information, including about your Wi-Fi connection, such as the hardware address of the wireless router you are connected to and content you transfer over the network while this profile is installed.

 

This profile is meant to be installed by developers and used to gather Wi-Fi information from the device so that Apple support can assist in troubleshooting remotely. But between you and me, since we’re all wireless engineers here, why not use it to troubleshoot or validate our own networks instead? Let’s run through the installation and subsequent logs to see what we can glean from them.

 

Step 1. Go to https://developer.apple.com/bug-reporting/profiles-and-logs/?platform=ios and scroll to the bottom until you see “Wi-Fi for iOS” 

 Wi-FiDiagTools-sm.gif

 

Step 2. Open the “Instructions” document and login to your Apple Developer account when prompted.

Wi-FiDiagTools-Doc-sm.gif

 

Step 3. On your computer or iOS device, download the .mobileconfig profile by clicking the “Profile” link and either send it to your iPhone or iPad or follow on-screen to complete the installation.

Wi-FiDiagTools-Profile-sm.gif

 

Step 4. Install the profile to your iOS device.

Wi-FiDiagTools-Profile-sm.gif

 

That’s it! Now that the profile is installed, your phone is logging all your Wi-Fi events. You can head into the Settings app and selectWi-Fi” where you’ll notice a new option underneath the Wi-Fi toggle labeled “Diagnostic Mode”.

Wifidiagsettings-sm.png

 

Now that diagnostic mode is enabled, the iPhone or iPad is storing logs of all Wi-Fi events. Give it some time, to connect, roam, scan, etc. before you pull the logs so you can get a good idea of what the data looks like and how you might want to use it.

 

In order to retrieve the logs, simply plug you iOS device into your computer and sync with iTunes. The new logs will be copied over to the ~/Library/Logs/CrashReporter/MobileDevice/{iOS Device Name}/WiFi folder. Open it up and you will see a file (or 3 in my case) as well as a folder but we’re ignoring that for now. You’ll notice the diagnostics I ran for this post are around 11MB - that’s after 24 hours (05/24/16 20:39:31.231 to 05/25/16 17:51:14.029) of Wi-Fi scanning through multiple large venues and a hotel. These files contain a plethora of great information but really don't take up that much space. The 63MB file from February is 4 days of logging (02/24/16 15:17:02.080 to 02/28/16 14:52:11.273).

Wi-FiDiagToolsTerm2.png

 

So now I have a way to generate logs on client devices that aren’t overall that awfully large, give me some great information (we’ll get there in a minute), and is always running in the background. That sounds like a great way to troubleshoot transient issues that move with the user and don’t appear on higher end Wi-Fi troubleshooting equipment to me.

 

So what exactly is in these files that’s so interesting and useful?

Screenshot 2016-05-25 18.01.48.png

 

It appears to be a lot and I definitely won’t go through it all here but I will pull out a few of the best samples of useful information to give you an idea. Using some CLI wizardry (mostly just cat and grep) you can find a ton of information about how your device is seeing and interacting with your network.

 

Interesting sample #1: “Hot Hot Spot”

Not exactly troubleshooting but interesting nonetheless. I had no idea T-Mobile was running HS2.0 on my iPhone in the background. Now I know.

 

05/24/16 20:39:31.241 <NOTICE>: WiFiDeviceManagerSetNetworks: Adding HS20 Account:
Domain name t-mobile.com
NAI Realm Name wlan.mnc260.mcc310.3gppnetwork.org
3GPP MCC&MNC 310260
Friendly Operator Name t-mobile
05/24/16 20:39:31.241 <NOTICE>: WiFiDeviceManagerSetNetworks: Adding HS20 Account:
Domain name t-mobile.com
NAI Realm Name wlan.mnc260.mcc310.3gppnetwork.org
3GPP MCC&MNC 310260
Friendly Operator Name t-mobile
05/24/16 20:39:31.241 <NOTICE>: __WiFiDeviceManagerPrepareHS20Queries: created queries <array> {
	0 : 268
	1 : 263
	2 : 264
	3 : 3
}

 

Interesting sample #2: “Are you my mommy?”

This is one of those things that gives a great user experience until someone nearby starts running karma on a Wi-Fi Pineapple and gets the device to associate and is able to quickly and easily run a MITM attack without the user ever taking their iPhone out of their pocket. None of these only one of these SSIDs was nearby at the time (hotel) but so weak and unstable that it appears my iPhone actually refused to join it (see #3). Not much we can do about this except keep petitioning all of the client device manufacturers to be a bit smarter for the sake of their less tech-savvy customers.

 

05/24/16 20:39:31.400 <NOTICE>: Auto join scan completed (0) with current state: Scanning Previous Network Channel
05/24/16 20:39:31.400 <NOTICE>: __WiFiDeviceManagerStateMachineRun: current state: Scanning Previous Network Channel
05/24/16 20:39:31.400 <NOTICE>: Scanning Previous Network Channel found:
05/24/16 20:39:31.400 <NOTICE>: multi-stage auto-join: Attempting to scan MRU network channels
05/24/16 20:39:31.400 <NOTICE>: Scanning for MRU Networks:  “MASKED-SSID-1“ on channels: 52  "MASKED-SSID-2" on channels: 1 11  "MASKED-SSID-3" on channels: 36
05/24/16 20:39:31.400 <NOTICE>: Performing auto-join broadcast scan on channels: 52 1 11 36
05/24/16 20:39:31.400 <NOTICE>: Enqueuing command type: "Scan" pending commands: 1
05/24/16 20:39:31.400 <NOTICE>: Dequeuing command type: "Scan" pending commands: 0
05/24/16 20:39:31.400 <NOTICE>: Attempting Apple80211ScanAsync on en0
05/24/16 20:39:31.705 <NOTICE>: Completed Apple80211ScanAsync on en0 (0x0)
05/24/16 20:39:31.707 <NOTICE>: Auto join scan completed (0) with current state: Scanning MRU Network Channels
05/24/16 20:39:31.707 <NOTICE>: __WiFiDeviceManagerStateMachineRun: current state: Scanning MRU Network Channels
05/24/16 20:39:31.707 <NOTICE>: Scanning MRU Network Channels found: ServiceMon, MASKED-SSID-4, , MASKED-SSID-2
05/24/16 20:39:31.712 <NOTICE>: multi-stage auto-join: Attempting to scan remaining channels
05/24/16 20:39:31.712 <NOTICE>: Scanning remaining channels: 2 3 4 5 7 8 9 10 12 13 40 44 48 56 60 64 100 104 108 112 116 120 124 128 132 136 140 144 149 153 157 161 165
05/24/16 20:39:31.712 <NOTICE>: Performing auto-join broadcast scan on channels: 2 3 4 5 7 8 9 10 12 13 40 44 48 56 60 64 100 104 108 112 116 120 124 128 132 136 140 144 149 153 157 161 165
05/24/16 20:39:31.712 <NOTICE>: Enqueuing command type: "Scan" pending commands: 1
05/24/16 20:39:31.712 <NOTICE>: Dequeuing command type: "Scan" pending commands: 0
05/24/16 20:39:31.712 <NOTICE>: Attempting Apple80211ScanAsync on en0
05/24/16 20:39:33.392 <NOTICE>: Leaky AP Stats Metric not configured
05/24/16 20:39:33.392 <NOTICE>: WiFiMetricsManagerSetLeakyAPMetricConfig: Leaky AP Config on en0 is disabled
05/24/16 20:39:33.435 <NOTICE>: Leaky AP Stats Metric not configured
05/24/16 20:39:33.435 <NOTICE>: WiFiMetricsManagerSetLeakyAPMetricConfig: Leaky AP Config on en0 is disabled
05/24/16 20:39:34.383 <NOTICE>: Completed Apple80211ScanAsync on en0 (0x0)
05/24/16 20:39:34.389 <NOTICE>: Auto join scan completed (0) with current state: Scanning Remaining Channels
05/24/16 20:39:34.390 <NOTICE>: __WiFiDeviceManagerStateMachineRun: current state: Scanning Remaining Channels
05/24/16 20:39:34.390 <NOTICE>: Scanning Remaining Channels found:
05/24/16 20:39:34.390 <NOTICE>: Preparing GAS queries for HS2.0 networks
05/24/16 20:39:34.390 <NOTICE>: No HS2.0 networks to query
05/24/16 20:39:34.390 <NOTICE>: __WiFiDeviceManagerDetermineNextAction: current state: Scanning Remaining Channels
05/24/16 20:39:34.390 <NOTICE>: ATJManager: atjEnabled=0 userInteractionMode=Interactive discovered 4 networks
05/24/16 20:39:34.390 <NOTICE>: ATJManager: device still at unmonitored atj point for 66.654448 seconds
05/24/16 20:39:34.390 <NOTICE>: ATJManager: no entries to purge
05/24/16 20:39:34.390 <NOTICE>: Performing next automatic assocation in 5.000000 seconds
05/24/16 20:39:34.390 <NOTICE>: __WiFiDeviceManagerScheduleNextRetry: in quick autojoin retry, 0 more remaining.

 

Interesting sample #3: “Can you hear me now?”

Hotel Wi-Fi is notoriously awful… so much so that there appears to be a way to categorized problematic and potentially problematic networks, and even an internal blacklist! This hotel had no problems making that list numerous times over log’s time period. This would be great to find dead spots in your network that may not appear to be so dead when you’re out there with a laptop and some external adapters.

 

05/24/16 20:39:36.120 <NOTICE>: problematic networks = MASKED-SSID-1  and potentially problematic networks =
05/24/16 20:39:36.120 <NOTICE>: Unblacklisting
05/24/16 20:39:36.120 <DEBUG>: Boolean __WiFiDeviceManagerIsBlackListedDueToTriggeredDisconnect(WiFiDeviceManagerRef, WiFiNetworkRef):__WiFiDeviceManagerIsBlackListedDueToTriggeredDisconnect: MASKED-SSID-1 Problematic only with triggerdisconnect
05/24/16 20:39:36.120 <NOTICE>: __WiFiDeviceManagerUnblacklistApplier: Skip unblacklisting network MASKED-SSID-1
05/24/16 20:39:36.120 <DEBUG>: Boolean __WiFiDeviceManagerIsBlackListedDueToTriggeredDisconnect(WiFiDeviceManagerRef, WiFiNetworkRef):__WiFiDeviceManagerIsBlackListedDueToTriggeredDisconnect: MASKED-SSID-1 Problematic only with triggerdisconnect
05/24/16 20:39:36.121 <DEBUG>: Boolean __WiFiDeviceManagerIsBlackListedDueToTriggeredDisconnect(WiFiDeviceManagerRef, WiFiNetworkRef):__WiFiDeviceManagerIsBlackListedDueToTriggeredDisconnect: MASKED-SSID-1 Problematic only with triggerdisconnect
05/24/16 20:39:36.121 <DEBUG>: Boolean __WiFiDeviceManagerIsBlackListedDueToTriggeredDisconnect(WiFiDeviceManagerRef, WiFiNetworkRef):__WiFiDeviceManagerIsBlackListedDueToTriggeredDisconnect: MASKED-SSID-1 Problematic only with triggerdisconnect
05/24/16 20:39:36.121 <NOTICE>: No Change in Background Scan Networks, Skip Re-Programming Background Scan
05/24/16 20:39:36.121 <NOTICE>: __WiFiManagerSetEnableState: state TRUE, manager->enable.setting TRUE, manager->unlockedSinceBoot TRUE
05/24/16 20:39:36.121 <DEBUG>: Boolean __WiFiDeviceManagerIsBlackListedDueToTriggeredDisconnect(WiFiDeviceManagerRef, WiFiNetworkRef):__WiFiDeviceManagerIsBlackListedDueToTriggeredDisconnect: MASKED-SSID-1 Problematic only with triggerdisconnect
05/24/16 20:39:36.121 <NOTICE>: Allow triggered disconnected network MASKED-SSID-1 for scan, RSSI: -80
05/24/16 20:39:36.121 <NOTICE>: __WiFiDeviceManagerStateMachineRun: current state: Idle
05/24/16 20:39:36.122 <NOTICE>: Attempting multi-stage auto join mStageAutoJoinAttempts=0
05/24/16 20:39:36.122 <NOTICE>: Starting multi-stage auto join sequence
05/24/16 20:39:36.122 <NOTICE>: multi-stage auto-join: Scanning for previous network MASKED-SSID-1 on channel 6
05/24/16 20:39:36.122 <NOTICE>: Performing auto-join broadcast scan with a modified dwell time of 110ms on channels: 6

 

Interesting sample #4: This just got interesting…

Ever wished you could use a client device directly for surveys instead of the “Compensate, don’t calibrate” method - nothing wrong with doing it that way and really, do we have any choice? But any time there’s room for error, there’s room for improvement… What if we could get down-to-the-millisecond data from our clients with information like RSSI, CCA, Tx Rate, Rx Rate, Noise, SNR, and more? What if some ingenious survey software company figured out a way to ingest that data? Now instead of compensating for the shortcomings of our clients and figuring out a way to adjust the information we gather to be more representative of the clients we deploy, what if we could just do the surveys with them? With no special hardware? With no special drivers? I think that might look something like this…

 

02/24/16 15:21:13.356 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -54 Cca: 41 TxPer: 0.1% (716) BcnPer: 0.0% (0) RxFrms 1138 TxRate: 130000 RxRate: 104000
02/24/16 15:21:18.374 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -53 Cca: 41 TxPer: 0.9% (1841) BcnPer: 4.2% (95) RxFrms 3251 TxRate: 104000 RxRate: 130000
02/24/16 15:21:28.375 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -52 Cca: 52 TxPer: 0.2% (1719) BcnPer: 5.1% (98) RxFrms 2774 TxRate: 130000 RxRate: 104000
02/24/16 15:21:38.379 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -52 Cca: 52 TxPer: 1.0% (887) BcnPer: 7.1% (98) RxFrms 1417 TxRate: 130000 RxRate: 117000
02/24/16 15:21:43.382 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -54 Cca: 40 TxPer: 0.2% (1086) BcnPer: 0.0% (0) RxFrms 1694 TxRate: 104000 RxRate: 104000
02/24/16 15:21:48.386 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -52 Cca: 40 TxPer: 0.5% (1830) BcnPer: 6.2% (97) RxFrms 2875 TxRate: 130000 RxRate: 104000
02/24/16 15:21:53.389 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -52 Cca: 40 TxPer: 0.4% (1831) BcnPer: 0.0% (0) RxFrms 2879 TxRate: 130000 RxRate: 104000
02/24/16 15:21:58.392 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -51 Cca: 40 TxPer: 0.5% (1777) BcnPer: 7.1% (98) RxFrms 2771 TxRate: 130000 RxRate: 117000
02/24/16 15:22:03.400 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -52 Cca: 40 TxPer: 0.2% (1000) BcnPer: 0.0% (0) RxFrms 1572 TxRate: 130000 RxRate: 104000
02/24/16 15:22:08.404 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -50 Cca: 20 TxPer: 0.4% (454) BcnPer: 3.2% (63) RxFrms 729 TxRate: 130000 RxRate: 104000
02/24/16 15:22:13.407 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -50 Cca: 41 TxPer: 0.5% (794) BcnPer: 0.0% (0) RxFrms 1358 TxRate: 130000 RxRate: 117000
02/24/16 15:22:18.414 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -50 Cca: 41 TxPer: 0.4% (2059) BcnPer: 6.2% (97) RxFrms 3188 TxRate: 117000 RxRate: 117000
02/24/16 15:22:23.416 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -50 Cca: 52 TxPer: 0.0% (2240) BcnPer: 0.0% (0) RxFrms 3609 TxRate: 104000 RxRate: 130000
02/24/16 15:22:28.420 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -50 Cca: 52 TxPer: 0.0% (2369) BcnPer: 4.1% (97) RxFrms 3773 TxRate: 130000 RxRate: 39000
02/24/16 15:22:33.425 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -51 Cca: 52 TxPer: 0.1% (2638) BcnPer: 0.0% (0) RxFrms 4145 TxRate: 104000 RxRate: 117000
02/24/16 15:22:38.429 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -53 Cca: 45 TxPer: 0.2% (2409) BcnPer: 6.1% (98) RxFrms 3781 TxRate: 104000 RxRate: 130000
02/24/16 15:22:43.437 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -51 Cca: 45 TxPer: 1.5% (588) BcnPer: 0.0% (0) RxFrms 895 TxRate: 117000 RxRate: 117000
02/24/16 15:22:48.441 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -52 Cca: 45 TxPer: 0.3% (1096) BcnPer: 5.1% (98) RxFrms 1656 TxRate: 117000 RxRate: 78000
02/24/16 15:22:53.445 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -52 Cca: 45 TxPer: 0.0% (902) BcnPer: 0.0% (0) RxFrms 1350 TxRate: 117000 RxRate: 104000
02/24/16 15:22:58.448 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -52 Cca: 45 TxPer: 0.0% (750) BcnPer: 9.3% (97) RxFrms 1148 TxRate: 117000 RxRate: 78000
02/24/16 15:23:03.452 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -51 Cca: 45 TxPer: 0.9% (1147) BcnPer: 0.0% (0) RxFrms 1807 TxRate: 104000 RxRate: 117000
02/24/16 15:23:08.454 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -51 Cca: 45 TxPer: 0.5% (215) BcnPer: 8.2% (98) RxFrms 345 TxRate: 130000 RxRate: 117000
02/24/16 15:23:13.457 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -51 Cca: 45 TxPer: 0.2% (890) BcnPer: 0.0% (0) RxFrms 1548 TxRate: 117000 RxRate: 78000
02/24/16 15:23:18.462 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -54 Cca: 45 TxPer: 0.6% (524) BcnPer: 8.2% (98) RxFrms 974 TxRate: 78000 RxRate: 78000
02/24/16 15:23:23.470 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -52 Cca: 45 TxPer: 0.0% (0) BcnPer: 0.0% (0) RxFrms 94 TxRate: 78000 RxRate: 78000
02/24/16 15:23:28.473 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -53 Cca: 7 TxPer: 0.0% (91) BcnPer: 7.2% (97) RxFrms 146 TxRate: 104000 RxRate: 78000
02/24/16 15:23:33.477 <NOTICE>: __WiFiLQAMgrLogStats: Rssi: -52 Cca: 28 TxPer: 1.7% (58) BcnPer: 0.0% (0) RxFrms 103 TxRate: 117000 RxRate: 78000

 

These are just a few examples I was able to pull from the logs in no more than a few minutes of scanning through them while watching TV. Imagine pulling periodic samples from actual client devices in your network with this sort of information. You could take it and build a script that could parse this out and show you the issues your clients face on a daily basis, ingest the information into a logging engine to look for trends you may not catch with the naked eye, or even walked around with a phone that had logging running in the background while you simply tapped the screen to signify where you were at that time with the logs getting rolled together and correlated after the fact. That company would probably have the affection of many, many engineers... Including myself.

Comments
darrelld25

 Great information. Glad to see someone writing about it!

Search Airheads
Showing results for 
Search instead for 
Did you mean: 
Announcements
Read all about it! If it’s happening now, it’s in the community.

Check out the latest blogs from your community team, the community experts and other industry sources.
Labels