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 leon...@leonerd.org.uk http://www.leonerd.org.uk/ | https://metacpan.org/author/PEVANS
