Linux for Wireless Engineers: How to Read the WPA Supplicant Logs

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:

As you can see before the Linux host tries to get an IP, it executes the pre-up wpa_supplicant command. For more details about the options you can visit this post. 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)

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:

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.”

Increased Verbosity

By increasing the verbosity by only one level with the “-d” option, we get the following sample output:

And it keeps going… To give a level of comparison without “-d” we had less than 10 log lines, and if you include the “-d” option this goes to more than 500.

As you can see, the logs after the timestamp have a number of different keywords, such as nl80211, wpa_driver_nl80211_set_key, netlin, RTM_NEWLINK, etc. So, this level of logging can be used to debug and keep an eye on many different functionalities of the wpa_supplicant process. Some of these functionalities include: drivers, internal debugging and informational messages that don’t have to do necessarily with 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.

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:

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.

Timestamp Conversion

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.

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:

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/.

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.