[pkg-wpa-devel] Bug#814517: Acknowledgement (wpasupplicant: Unstable connection after laptop suspend)

Tue Apr 19 18:29:01 UTC 2016

I have made some progress.

The contents of /var/log/messages around one of these reauth cycles
shows:

Apr 19 19:19:48 shy wpa_action: WPA_IFACE=wlan0 WPA_ACTION=CONNECTED
Apr 19 19:19:48 shy wpa_action: WPA_ID=0 WPA_ID_STR=home WPA_CTRL_DIR=/var/run/wpa_supplicant
Apr 19 19:19:48 shy wpa_action: ifup wlan0=home
Apr 19 19:19:49 shy kernel: [545668.573644] wlan0: authenticate with 4a:d9:e7:47:bd:a6
Apr 19 19:19:49 shy kernel: [545668.575544] wlan0: send auth to 4a:d9:e7:47:bd:a6 (try 1/3)
Apr 19 19:19:49 shy kernel: [545668.580730] wlan0: authenticated
Apr 19 19:19:49 shy kernel: [545668.581004] wlan0: associate with 4a:d9:e7:47:bd:a6 (try 1/3)
Apr 19 19:19:49 shy kernel: [545668.585663] wlan0: RX AssocResp from 4a:d9:e7:47:bd:a6 (capab=0x431 status=0 aid=4)
Apr 19 19:19:49 shy kernel: [545668.610256] wlan0: associated
Apr 19 19:19:49 shy kernel: [545668.610358] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Apr 19 19:19:56 shy wpa_action: creating sendsigs omission pidfile: /run/sendsigs.omit.d/wpasupplicant.wpa_supplicant.wlan0.pid
Apr 19 19:19:56 shy wpa_action: bssid=4a:d9:e7:47:bd:a6
Apr 19 19:19:56 shy wpa_action: freq=0
Apr 19 19:19:56 shy wpa_action: ssid=leoair
Apr 19 19:19:56 shy wpa_action: id=0
Apr 19 19:19:56 shy wpa_action: id_str=home
Apr 19 19:19:56 shy wpa_action: mode=station
Apr 19 19:19:56 shy wpa_action: pairwise_cipher=CCMP
Apr 19 19:19:56 shy wpa_action: group_cipher=CCMP
Apr 19 19:19:56 shy wpa_action: key_mgmt=WPA2-PSK
Apr 19 19:19:56 shy wpa_action: wpa_state=COMPLETED
Apr 19 19:19:56 shy wpa_action: ip_address=192.168.43.25
Apr 19 19:19:56 shy wpa_action: address=8c:a9:82:c3:87:98
Apr 19 19:19:56 shy wpa_action: uuid=78bcb1d2-42b3-571f-a058-ee941a51415e
Apr 19 19:19:56 shy wpa_action: WPA_IFACE=wlan0 WPA_ACTION=DISCONNECTED
Apr 19 19:19:56 shy wpa_action: WPA_ID=0 WPA_ID_STR=home WPA_CTRL_DIR=/var/run/wpa_supplicant
Apr 19 19:19:56 shy wpa_action: ifdown wlan0
Apr 19 19:19:58 shy kernel: [545677.658750] wlan0: deauthenticating from 4a:d9:e7:47:bd:a6 by local choice (Reason: 3=DEAUTH_LEAVING)
Apr 19 19:20:08 shy wpa_action: removing sendsigs omission pidfile: /run/sendsigs.omit.d/wpasupplicant.wpa_supplicant.wlan0.pid

An interesting line in there

  wpa_action: ifdown wlan0

I'm not entirely sure what that line means, but it could mean that
wpa_action has itself decided to down the link. In any case, the kernel
then shuts the link down, and the reconnection cycle goes again.

But then later on, we get

Apr 19 19:20:26 shy wpa_action: WPA_IFACE=wlan0 WPA_ACTION=CONNECTED
Apr 19 19:20:26 shy wpa_action: WPA_ID=0 WPA_ID_STR=home WPA_CTRL_DIR=/var/run/wpa_supplicant
Apr 19 19:20:26 shy wpa_action: ifup wlan0=home
Apr 19 19:20:26 shy kernel: [545705.994298] wlan0: authenticate with 4a:d9:e7:47:bd:a6
Apr 19 19:20:26 shy kernel: [545705.996081] wlan0: send auth to 4a:d9:e7:47:bd:a6 (try 1/3)
Apr 19 19:20:26 shy kernel: [545705.998574] wlan0: authenticated
Apr 19 19:20:26 shy kernel: [545706.001017] wlan0: associate with 4a:d9:e7:47:bd:a6 (try 1/3)
Apr 19 19:20:26 shy kernel: [545706.004843] wlan0: RX AssocResp from 4a:d9:e7:47:bd:a6 (capab=0x431 status=0 aid=4)
Apr 19 19:20:26 shy kernel: [545706.007885] wlan0: associated
Apr 19 19:20:26 shy kernel: [545706.007982] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
Apr 19 19:20:30 shy wpa_action: creating sendsigs omission pidfile: /run/sendsigs.omit.d/wpasupplicant.wpa_supplicant.wlan0.pid
Apr 19 19:20:30 shy wpa_action: bssid=4a:d9:e7:47:bd:a6
Apr 19 19:20:30 shy wpa_action: freq=0
Apr 19 19:20:30 shy wpa_action: ssid=leoair
Apr 19 19:20:30 shy wpa_action: id=0
Apr 19 19:20:30 shy wpa_action: id_str=home
Apr 19 19:20:30 shy wpa_action: mode=station
Apr 19 19:20:30 shy wpa_action: pairwise_cipher=CCMP
Apr 19 19:20:30 shy wpa_action: group_cipher=CCMP
Apr 19 19:20:30 shy wpa_action: key_mgmt=WPA2-PSK
Apr 19 19:20:30 shy wpa_action: wpa_state=COMPLETED
Apr 19 19:20:30 shy wpa_action: ip_address=192.168.43.25
Apr 19 19:20:30 shy wpa_action: address=8c:a9:82:c3:87:98
Apr 19 19:20:30 shy wpa_action: uuid=78bcb1d2-42b3-571f-a058-ee941a51415e
Apr 19 19:20:30 shy wpa_action: WPA_IFACE=wlan0 WPA_ACTION=DISCONNECTED
Apr 19 19:20:30 shy wpa_action: WPA_ID=0 WPA_ID_STR=home WPA_CTRL_DIR=/var/run/wpa_supplicant
Apr 19 19:20:30 shy wpa_action: DISCONNECTED event blocked by hysteresis check
Apr 19 19:20:30 shy wpa_action: WPA_IFACE=wlan0 WPA_ACTION=CONNECTED
Apr 19 19:20:30 shy wpa_action: WPA_ID=0 WPA_ID_STR=home WPA_CTRL_DIR=/var/run/wpa_supplicant
Apr 19 19:20:30 shy wpa_action: CONNECTED event blocked by hysteresis check

At this point the link becomes stable and remains up.

I have no idea what wpa_action is or does, but reading over this log it
looks like the difference between the reconnect cycles and this
eventual success is that it blocks the "DISCONNECTED" event due to
hysteresis. I.e. that were it not for that hysteresis check, it would
continue to ifdown my link ad infinitum; and it's this hysteresis check
that's saving me from waiting until the heat-death of the universe and
eventually causes my link to actually work.

At this point I wish to turn attention to this "wpa_action" - what is
it, what's it supposed to be doing, and why does it take to "ifdown"ing
my link every time here?

This is now my fourth email on this bug in four months and nobody seems
to be listening. Is there anyone out there who is able to help me, or
am I going at this totally alone?

-- 
Paul "LeoNerd" Evans

leonerd at leonerd.org.uk
http://www.leonerd.org.uk/  |  https://metacpan.org/author/PEVANS