In a previous post I talked about the WiFi Protected Access (WPA) Supplicant logs for PreShared Key (PSK) authentication and how to make sense of them. The reality is that although the logs are useful, you will be intimidated if you don’t know what to look for.
This post builds on top of the previous one, covering some additional details around the Extensible Authentication Protocol (EAP) WPA Supplicant logs. The EAP logs include the PSK states of the authentication/association process as well as the EAP authentication method.
WPA Supplicant Configuration
As an example, I connected my Linux client to my WPA-EAP network through my RADIUS server. For reference, here are the contents of the wpa_supplicant.conf configuration file:
root@raspberrypi:/var/log/netbeez# cat /etc/wpa_supplicant/wpa_supplicant.conf
ctrl_interface=DIR=/var/run/wpa_supplicant
update_config=1
network={
ssid="netbeez_wpa2_2.4"
scan_ssid=1
key_mgmt=WPA-EAP
eap=TTLS
identity="panos"
password="very_strong_password"
phase2="auth=MSCHAPV2"
ca_cert="/etc/ssl/certs/wpa_ca_cert.pem"
}
Log Parser
If you follow the WPA Supplicant daemon from my previous post, you should have the logs saved in the file “/var/log/wpa_supplicant.log”. From this point forward we are working under the assumption that you have this file in your system.
In order to filter the contents of the logs we will use a grep command with the appropriate filters. The lines we want to see must include the WiFi interface name followed by colon (e.g. “wlan0:”) From these lines, we only want to keep the lines that include the tokens “State:” and “EAP”. “wlan0”, in this case, is the name of the WiFi interface on my machine. You can get a list of all available interfaces on your machine with the command “ip link.”
The logs also include some low level debugging information about the EAP Over LAN (EAPOL) that are not useful in this case. For that reason we’ll filter out lines that include the “EAPOL” token.
Here is the command that achieves this filtering together with its output:
netbeez.net $ cat /var/log/wpa_supplicant.log | grep -v EAPOL | grep "wlan0\:" | grep "EAP\|State\:" 1571090340.307372: wlan0: State: DISCONNECTED -> DISCONNECTED 1571090340.310401: wlan0: State: DISCONNECTED -> SCANNING 1571090340.957566: wlan0: State: SCANNING -> ASSOCIATING 1571090341.191686: wlan0: State: ASSOCIATING -> ASSOCIATED 1571090341.194212: wlan0: CTRL-EVENT-EAP-STARTED EAP authentication started 1571090344.244824: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=4 -> NAK 1571090344.289299: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=21 1571090344.292642: wlan0: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 21 (TTLS) selected 1571090344.577911: wlan0: CTRL-EVENT-EAP-PEER-CERT depth=3 subject='/C=US/O=The Go Daddy Group, Inc./OU=Go Daddy Class 2 Certification Authority' hash=c3846bf24b9e93ca64274c0ec67c1ecc5e024ffcacd2d74019350e81fe546ae4 1571090344.579596: wlan0: CTRL-EVENT-EAP-PEER-CERT depth=2 subject='/C=US/ST=Arizona/L=Scottsdale/O=GoDaddy.com, Inc./CN=Go Daddy Root Certificate Authority - G2' hash=3a2fbe92891e57fe05d57087f48e730f17e5a5f53ef403d618e5b74d7a7e6ecb 1571090344.581975: wlan0: CTRL-EVENT-EAP-PEER-CERT depth=1 subject='/C=US/ST=Arizona/L=Scottsdale/O=GoDaddy.com, Inc./OU=http://certs.godaddy.com/repository//CN=Go Daddy Secure Certificate Authority - G2' hash=973a41276ffd01e027a2aad49e34c37846d3e976ff6a620b6712e33832041aa6 1571090344.584364: wlan0: CTRL-EVENT-EAP-PEER-CERT depth=0 subject='/OU=Domain Control Validated/CN=radius.jumpcloud.com' hash=e8362d749e5c5dbe8779edfdfc74bb1089709431d9b979116cecf712f1bb992b 1571090344.585463: wlan0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:radius.jumpcloud.com 1571090344.585497: wlan0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:www.radius.jumpcloud.com 1571090344.721185: wlan0: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully 1571090344.723334: wlan0: State: ASSOCIATED -> 4WAY_HANDSHAKE 1571090344.731201: wlan0: State: 4WAY_HANDSHAKE -> 4WAY_HANDSHAKE 1571090344.732023: wlan0: State: 4WAY_HANDSHAKE -> GROUP_HANDSHAKE 1571090344.732678: wlan0: State: GROUP_HANDSHAKE -> COMPLETED
You can see the scanning, followed by the association events; once the association is successful, the WPA Supplicant daemon moves on to the EAP authentication phase. Once that is successful it performs the 4-way handshake step, and then the whole process is completed. You can also see that along the way it prints information about the certificate used and its signing authority (GoDaddy in this case).
I simulated a case where the certificate was wrong and it couldn’t pass the EAP authentication phase. Here is what the logs look like:
netbeez.net $ cat /var/log/wpa_supplicant.log | grep -v EAPOL | grep "wlan0\:" | grep "EAP\|State\:" 1571092721.353293: wlan0: State: DISCONNECTED -> DISCONNECTED 1571092721.387817: wlan0: State: DISCONNECTED -> SCANNING 1571092722.027113: wlan0: State: SCANNING -> ASSOCIATING 1571092722.212795: wlan0: State: ASSOCIATING -> ASSOCIATED 1571092722.214347: wlan0: CTRL-EVENT-EAP-STARTED EAP authentication started 1571092725.261306: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=4 -> NAK 1571092725.300966: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=21 1571092725.304174: wlan0: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 21 (TTLS) selected 1571092725.585704: wlan0: CTRL-EVENT-EAP-TLS-CERT-ERROR reason=1 depth=3 subject='/C=US/O=The Go Daddy Group, Inc./OU=Go Daddy Class 2 Certification Authority' err='self signed certificate in certificate chain' 1571092726.624839: wlan0: CTRL-EVENT-EAP-FAILURE EAP authentication failed 1571092726.664268: wlan0: State: ASSOCIATED -> DISCONNECTED
WPA Supplicant prints the error “err=’self signed certificate in certificate chain’” which helps us identify the cause of the failed authentication.
WPA Supplicant Timing
A very useful piece of information you can extract from the WPA Supplicant logs is the time it takes for each step: scanning, association, authentication.
Below is a script that it takes as input a log file, prints the steps for the connection and the timing for each step:
#!/bin/bash
INTERFACE_NAME="wlan0"
input_file=${1}
if [ -z ${input_file} ]; then
echo "Mising input argument"
echo "Usage: ${0} <wpa_supplicant_log file>"
exit 1
fi
if ! which bc > /dev/null ; then
echo "The \"bc\" packet is required to get timing information (\"sudo apt-get install bc\")"
bc_found=false
else
bc_found=true
fi
previous_state_timestamp=""
while read line
do
if echo ${line} | grep -v EAPOL | grep "${INTERFACE_NAME}\:" | grep -q "EAP\|State\:" ; then
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}"
if [ "${bc_found}" = true ] ; then
if [ -z ${previous_state_timestamp} ]; then
previous_state_timestamp=${epoch}
elif echo ${line} | grep -q "State\:" ; then
diff=$(echo ${epoch} - ${previous_state_timestamp} | bc)
echo " STEP TIME: ${epoch} - ${previous_state_timestamp} = ${diff}"
previous_state_timestamp=${epoch}
fi
fi
fi
done < ${input_file}
exit 0
I saved the script in file “parse_wpa_logs.sh” and I made it executable with “chmod +x parse_wpa_logs.sh”. Here is a sample output:
root@raspberrypi:/var/log/netbeez# ./parse_wpa_logs.sh wpa_supplicant_eap_success.log
Mon 14 Oct 17:59:00.307372000 EDT 2019: wlan0: State: DISCONNECTED -> DISCONNECTED
Mon 14 Oct 17:59:00.310401000 EDT 2019: wlan0: State: DISCONNECTED -> SCANNING
STEP TIME: 1571090340.310401 - 1571090340.307372 = .003029
Mon 14 Oct 17:59:00.957566000 EDT 2019: wlan0: State: SCANNING -> ASSOCIATING
STEP TIME: 1571090340.957566 - 1571090340.310401 = .647165
Mon 14 Oct 17:59:01.191686000 EDT 2019: wlan0: State: ASSOCIATING -> ASSOCIATED
STEP TIME: 1571090341.191686 - 1571090340.957566 = .234120
Mon 14 Oct 17:59:01.194212000 EDT 2019: wlan0: CTRL-EVENT-EAP-STARTED EAP authentication started
Mon 14 Oct 17:59:04.244824000 EDT 2019: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=4 -> NAK
Mon 14 Oct 17:59:04.289299000 EDT 2019: wlan0: CTRL-EVENT-EAP-PROPOSED-METHOD vendor=0 method=21
Mon 14 Oct 17:59:04.292642000 EDT 2019: wlan0: CTRL-EVENT-EAP-METHOD EAP vendor 0 method 21 (TTLS) selected
Mon 14 Oct 17:59:04.577911000 EDT 2019: wlan0: CTRL-EVENT-EAP-PEER-CERT depth=3 subject='/C=US/O=The Go Daddy Group, Inc./OU=Go Daddy Class 2 Certification Authority' hash=c3846bf24b9e93ca64274c0ec67c1ecc5e024ffcacd2d74019350e81fe546ae4
Mon 14 Oct 17:59:04.579596000 EDT 2019: wlan0: CTRL-EVENT-EAP-PEER-CERT depth=2 subject='/C=US/ST=Arizona/L=Scottsdale/O=GoDaddy.com, Inc./CN=Go Daddy Root Certificate Authority - G2' hash=3a2fbe92891e57fe05d57087f48e730f17e5a5f53ef403d618e5b74d7a7e6ecb
Mon 14 Oct 17:59:04.581975000 EDT 2019: wlan0: CTRL-EVENT-EAP-PEER-CERT depth=1 subject='/C=US/ST=Arizona/L=Scottsdale/O=GoDaddy.com, Inc./OU=http://certs.godaddy.com/repository//CN=Go Daddy Secure Certificate Authority - G2' hash=973a41276ffd01e027a2aad49e34c37846d3e976ff6a620b6712e33832041aa6
Mon 14 Oct 17:59:04.584364000 EDT 2019: wlan0: CTRL-EVENT-EAP-PEER-CERT depth=0 subject='/OU=Domain Control Validated/CN=radius.jumpcloud.com' hash=e8362d749e5c5dbe8779edfdfc74bb1089709431d9b979116cecf712f1bb992b
Mon 14 Oct 17:59:04.585463000 EDT 2019: wlan0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:radius.jumpcloud.com
Mon 14 Oct 17:59:04.585497000 EDT 2019: wlan0: CTRL-EVENT-EAP-PEER-ALT depth=0 DNS:www.radius.jumpcloud.com
Mon 14 Oct 17:59:04.721185000 EDT 2019: wlan0: CTRL-EVENT-EAP-SUCCESS EAP authentication completed successfully
Mon 14 Oct 17:59:04.723334000 EDT 2019: wlan0: State: ASSOCIATED -> 4WAY_HANDSHAKE
STEP TIME: 1571090344.723334 - 1571090341.191686 = 3.531648
Mon 14 Oct 17:59:04.731201000 EDT 2019: wlan0: State: 4WAY_HANDSHAKE -> 4WAY_HANDSHAKE
STEP TIME: 1571090344.731201 - 1571090344.723334 = .007867
Mon 14 Oct 17:59:04.732023000 EDT 2019: wlan0: State: 4WAY_HANDSHAKE -> GROUP_HANDSHAKE
STEP TIME: 1571090344.732023 - 1571090344.731201 = .000822
Mon 14 Oct 17:59:04.732678000 EDT 2019: wlan0: State: GROUP_HANDSHAKE -> COMPLETED
STEP TIME: 1571090344.732678 - 1571090344.732023 = .000655
The connection timing is broken down as follows:
- Scanning: 0.64 seconds
- Association: 0.23 seconds
- EAP Authentication: 3.53 seconds
- 4 Way Handshake: 0.007+0.00082+0.0006=0.08 seconds
With this post I have completed the review of WPA supplicant logs! I hope you will find this information useful when troubleshooting failed or slow connections.
