We have covered many different aspects of WPA Supplicant. In this blog, however, an overlooked aspect of it is what information it logs and how to read it.
Let’s discuss some very useful insight based off of my findings when working with it hands-on.
When troubleshooting client WiFi connectivity issues, WPA Supplicant logs can be of help. Unfortunately, it’s easy to be either overwhelmed or underwhelmed by the amount of information that is presented to you. Let’s start by how to enable logging.
One way to set up WPA Supplicant is in the /etc/network/interfaces file as follows:
auto wlan0
allow-hotplug wlan0
iface wlan0 inet dhcp
wpa-ssid netbeez-enterprise-wireless
pre-up wpa_supplicant -B -Dwext,nl80211 -i wlan0 -c/etc/wpa_supplicant/wpa_supplicant.conf -f /var/log/wpa_supplicant.log -t -d
post-down wpa_cli -i wlan0 terminate
As you can see before the Linux host tries to get an IP, it executes the pre-up wpa_supplicant command. In this blog post about WPA supplicant options. Up next, we’ll talk about the last three options:
-f /var/log/wpa_supplicant.log: specifies the file that wpa_supplicant will logs any messages
-t: for every log message it prints the epoch time it occured
-d: controls the verbosity of the logs (if omitted the logs are minimal, -d/-dd/-ddd increase the verbosity)
WPA Supplicant Minimum Logs
If the “-d” option is omitted and you pull up the wireless interface, you will see the following logs in /var/log/wpa_supplicant.log:
1555435443.013798: Successfully initialized wpa_supplicant 1555435444.393362: wlan0: Trying to associate with 38:3b:c8:3e:d4:31 (SSID='netbeez' freq=2462 MHz) 1555435444.539731: wlan0: Associated with 38:3b:c8:3e:d4:31 1555435444.556641: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US 1555435445.554016: wlan0: WPA: Key negotiation completed with 38:3b:c8:3e:d4:31 [PTK=CCMP GTK=TKIP] 1555435445.554092: wlan0: CTRL-EVENT-CONNECTED - Connection to 38:3b:c8:3e:d4:31 completed [id=0 id_str=]
Each line begins with the epoch timestamp of the message and you will see these important events:
- 1555435443.013798: Successfully initialized wpa_supplicant: The wpa_supplicant process started
- 1555435444.393362: wlan0: Trying to associate with 38:3b:c8:3e:d4:31 (SSID=’netbeez’ freq=2462 MHz): wpa_supplicant starts the association process with the AP
- 1555435444.539731: wlan0: Associated with 38:3b:c8:3e:d4:31: Association completed
- 1555435445.554016: wlan0: WPA: Key negotiation completed with 38:3b:c8:3e:d4:31 [PTK=CCMP GTK=TKIP]: Key negotiation completed
By having the epoch timestamps we can easily do the math and calculate how long it takes for each step of the process. For example, the association took approximately 146 mseconds.
Something to keep in mind here is that the terminology shown in the logs doesn’t always correspond to the actual WiFi terminology that is commonly used. For example, when a client tries to join a WiFi network it goes through the authentication and association steps. However, wpa_supplicant calls this whole process “association.”
Increasing WPA supplicant logs verbosity
By increasing the verbosity by only one level with the “-d” option, we get the following sample output:
1554225851.374782: wpa_supplicant v2.4 1554225851.375317: random: Trying to read entropy from /dev/random 1554225851.375399: Successfully initialized wpa_supplicant 1554225851.375438: Initializing interface 'wlan0' conf '/etc/wpa_supplicant/wpa_supplicant.conf' driver 'nl80211,wext' ctrl_interface 'N/A' bridge 'N/A' 1554225851.375471: Configuration file '/etc/wpa_supplicant/wpa_supplicant.conf' -> '/etc/wpa_supplicant/wpa_supplicant.conf' 1554225851.375500: Reading configuration file '/etc/wpa_supplicant/wpa_supplicant.conf' 1554225851.375597: ctrl_interface='DIR=/var/run/wpa_supplicant' 1554225851.375635: update_config=1 1554225851.444974: Priority group 0 1554225851.444995: id=0 ssid='netbeez' 1554225851.445931: rfkill: initial event: idx=0 type=1 op=0 soft=0 hard=0 1554225851.446353: nl80211: Supported cipher 00-0f-ac:1 1554225851.446371: nl80211: Supported cipher 00-0f-ac:5 1554225851.446385: nl80211: Supported cipher 00-0f-ac:2 …. 1554225851.494927: wpa_driver_nl80211_set_key: ifindex=3 (wlan0) alg=0 addr=(nil) key_idx=0 set_tx=0 seq_len=0 key_len=0 1554225851.495031: wpa_driver_nl80211_set_key: ifindex=3 (wlan0) alg=0 addr=(nil) key_idx=1 set_tx=0 seq_len=0 key_len=0 1554225851.495088: wpa_driver_nl80211_set_key: ifindex=3 (wlan0) alg=0 addr=(nil) key_idx=2 set_tx=0 seq_len=0 key_len=0 1554225851.495144: wpa_driver_nl80211_set_key: ifindex=3 (wlan0) alg=0 addr=(nil) key_idx=3 set_tx=0 seq_len=0 key_len=0 …. . 1554225851.543376: wlan0: State: DISCONNECTED -> DISCONNECTED 1554225851.543388: nl80211: Set wlan0 operstate 0->0 (DORMANT) 1554225851.543402: netlink: Operstate: ifindex=3 linkmode=-1 (no change), operstate=5 (IF_OPER_DORMANT) 1554225851.543442: Daemonize.. 1554225851.544360: random: Got 20/20 bytes from /dev/random 1554225851.544609: RTM_NEWLINK: ifi_index=3 ifname=wlan0 operstate=2 linkmode=0 ifi_family=0 ifi_flags=0x11003 ([UP][LOWER_UP]) 1554225851.544710: RTM_NEWLINK: ifi_index=3 ifname=wlan0 operstate=6 linkmode=0 ifi_family=0 ifi_flags=0x11043 ([UP][RUNNING][LOWER_UP]) 1554225851.544751: RTM_NEWLINK: ifi_index=3 ifname=wlan0 operstate=5 linkmode=0 ifi_family=0 ifi_flags=0x11003 ([UP][LOWER_UP]) 1554225851.544789: RTM_NEWLINK: ifi_index=3 ifname=wlan0 operstate=5 linkmode=1 ifi_family=0 ifi_flags=0x11003 ([UP][LOWER_UP]) 1554225851.595586: wlan0: State: DISCONNECTED -> SCANNING …. 1554244747.081250: wlan0: CTRL-EVENT-DISCONNECTED bssid=38:3b:c8:3e:d4:3a reason=3 locally_generated=1
And it keeps going … To give a level of comparison without “-d” we had less than 10 log lines. On the other hand, if you include the “-d” option we got more than 500.
Filtering WPA supplicant logs
The logs after the timestamp have a number of different keywords, such as nl80211, wpa_driver_nl80211_set_key, netlin, RTM_NEWLINK, etc. This level of logging can be used to debug different functionalities of the wpa_supplicant process. Some of these functionalities include:
- Drivers information
- Internal debugging and informational messages that don’t necessarily relate to the WiFi connection protocol
In other cases, there are messages (such as the one in the last line) that tells us that there was a disconnection event and the reason was “reason=3” without any further explanation. Unless you search the source code, you will have no idea what that means. You can find a reference of the different reasons here.
My advice would be to focus on the messages that start with the “wlan0” keyword which is the name of the wireless interface on the Linux host.
WPA supplicant states
One of the most interesting logging information is the one that starts with “wlan0: State:” If you follow these specific logs then you will see the following sequence in the file:
1554246802.464067: wlan0: State: SCANNING -> ASSOCIATING 1554246802.682082: wlan0: State: ASSOCIATING -> ASSOCIATED 1554246803.781478: wlan0: State: ASSOCIATED -> 4WAY_HANDSHAKE 1554246803.826661: wlan0: State: 4WAY_HANDSHAKE -> 4WAY_HANDSHAKE 1554246803.827943: wlan0: State: 4WAY_HANDSHAKE -> GROUP_HANDSHAKE 1554246803.828603: wlan0: State: GROUP_HANDSHAKE -> COMPLETED
In this case, wpa_supplicant separates nicely each step of the connection process and you can easily derive the timing of each step from the timestamps that go down to the microsecond resolution.
However, even among these logs we see some messages that may not make sense such ash “1554246803.826661: wlan0: State: 4WAY_HANDSHAKE -> 4WAY_HANDSHAKE”
In general, this is a shortcoming of the wpa_supplicang logs: they are not the most user friendly, and unless you are a wpa_supplicant developer or look at the source code you may not be able to make sense of everything.
I am not even going to discuss the logs for the “-dd” and “-ddd” options because they are far beyond what you may find useful. I believe those are designed for the WPA supplicant project developers to troubleshoot the code.
Converting logs timestamps
The timestamps are useful when you are trying to find and correlate errors in wpa_supplicant logs with other logs you may have or when trying to time the WiFi connectivity. However, they are not in a human-readable format.
For that reason I have written this short bash script that takes as input a wpa_supplicant log file and converts the epoch timestamp to a human-readable format.
#!/bin/bash
input_file=${1}
while read line
do
epoch=$(echo ${line} | cut -f1 -d":")
message="$(cut -d ':' -f 2- <<< "${line}")"
date=$(date +"%a %d %b %T.%N %Z %Y" -d @${epoch})
echo "${date}:${message}"
done < ${input_file}
I named the file epoch2date.sh. If I give it as input the wpa_supplicant.log file shown in the “Minimum Logs” section above the output appears as follows:
ubuntu@ip-10-0-0-16:~/wifi$ bash epoch2date.sh wpa_supplicant.log Tue 16 Apr 17:24:03.013798000 UTC 2019: Successfully initialized wpa_supplicant Tue 16 Apr 17:24:04.393362000 UTC 2019: wlan0: Trying to associate with 38:3b:c8:3e:d4:31 (SSID='netbeez' freq=2462 MHz) Tue 16 Apr 17:24:04.539731000 UTC 2019: wlan0: Associated with 38:3b:c8:3e:d4:31 Tue 16 Apr 17:24:04.556641000 UTC 2019: wlan0: CTRL-EVENT-REGDOM-CHANGE init=COUNTRY_IE type=COUNTRY alpha2=US Tue 16 Apr 17:24:05.554016000 UTC 2019: wlan0: WPA: Key negotiation completed with 38:3b:c8:3e:d4:31 [PTK=CCMP GTK=TKIP] Tue 16 Apr 17:24:05.554092000 UTC 2019: wlan0: CTRL-EVENT-CONNECTED - Connection to 38:3b:c8:3e:d4:31 completed [id=0 id_str=]
As you can see, it’s much easier to read the timestamp and know when each event happened compared to having to convert epochs to dates on websites such as https://www.epochconverter.com/.
Conclusion on WPA supplicant
The WPA Supplicant logs can be useful if you know what you are looking for and how to interpret it. Unfortunately, there is very little documentation online and the logs are not designed to be really user friendly. I hope I have shed some light on this topic, although I am sure there is much more to it that I need to learn.
