Re: [REGRESSION] hostapd 2.4..2.7 broken with 4.18+

[Russell King - ARM Linux admin <linux@armlinux.org.uk>]

On Fri, Jan 18, 2019 at 09:36:17PM +0100, Arend van Spriel wrote:
> On 1/17/2019 11:03 AM, Russell King - ARM Linux admin wrote:> On Wed, Jan 16, 2019 at 02:21:32PM +0100, Arend Van Spriel wrote:
> >> The patch below works for me so can you provide the counters file contents
> >> after hitting the issue.
> > 
> > Okay, with the patch fixed, it seems to have failed last night for some
> > reason... I'm not sure exactly when it died, possibly about an hour
> > after bringing it up.  Here's the full log.
> 
> Sorry for the somewhat late response. I wanted to discuss the log with
> firmware engineer. Can you tell how many stations were connected to this
> AP before and/or when it died? What does "died" mean? From the log I can
> only conclude the firmware is not crashing. So I assume by "died" you
> mean no data is successfully exchanged between hostapd and stations. This
> is probably due to the failing send_key_to_dongle. Could you try the patch
> below to be sure about the key configuration that fails.

By "died" I mean that I've seen several things happen - not always
all of them:

1) the signal perceived by my phone has reduced to a very low level
   (like almost nothing) despite the AP being in direct line of sight
   in the same room, whereas normally it would be showing full signal.

2) the phone (and other devices) will not associate with the AP.
   They go through the initial authentication fine but fail to
   complete the WPA authentication.

Looking at hostapd's debug log, hostapd is aware of the station
attempting to authenticate.  For example, I've observed the following
from hostapd in debug mode:

wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: associated
wlan0: STA xx:xx:xx:xx:xx:xx WPA: event 1 notification
wlan0: STA xx:xx:xx:xx:xx:xx WPA: start authentication
wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.1X: unauthorizing port
wlan0: STA xx:xx:xx:xx:xx:xx WPA: sending 1/4 msg of 4-Way Handshake
wlan0: STA xx:xx:xx:xx:xx:xx WPA: EAPOL-Key timeout
wlan0: STA xx:xx:xx:xx:xx:xx WPA: sending 1/4 msg of 4-Way Handshake
wlan0: STA xx:xx:xx:xx:xx:xx WPA: EAPOL-Key timeout
wlan0: STA xx:xx:xx:xx:xx:xx WPA: sending 1/4 msg of 4-Way Handshake
wlan0: STA xx:xx:xx:xx:xx:xx WPA: EAPOL-Key timeout
wlan0: STA xx:xx:xx:xx:xx:xx WPA: sending 1/4 msg of 4-Way Handshake
wlan0: STA xx:xx:xx:xx:xx:xx WPA: EAPOL-Key timeout
wlan0: STA xx:xx:xx:xx:xx:xx WPA: PTKSTART: Retry limit 4 reached
wlan0: STA xx:xx:xx:xx:xx:xx WPA: event 3 notification
wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.1X: unauthorizing port
wlan0: STA xx:xx:xx:xx:xx:xx MLME: MLME-DEAUTHENTICATE.indication(xx:xx:xx:xx:xx:xx
wlan0: STA xx:xx:xx:xx:xx:xx MLME: MLME-DELETEKEYS.request(xx:xx:xx:xx:xx:xx)
wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.11: disassociated
wlan0: STA xx:xx:xx:xx:xx:xx WPA: event 2 notification
wlan0: STA xx:xx:xx:xx:xx:xx IEEE 802.1X: unauthorizing port

and that repeats.

I picked those out of a strace of hostapd I did on January 11.  Here's
the strace beween the EAPOL stuff:

13663 write(1, "wlan0: STA xx:xx:xx:xx:xx:xx WPA: EAPOL-Key timeout\n", 52) = 52
13663 write(1, "wlan0: STA xx:xx:xx:xx:xx:xx WPA: sending 1/4 msg of 4-Way Handshake\n", 69) = 69
13663 sendto(11, "<removed>", 99, 0, {sa_family=AF_PACKET, proto=0x888e, if14, pkttype=PACKET_HOST, addr(6)={0, 6069441db3a9}, 20) = 99
13663 clock_gettime(CLOCK_BOOTTIME, {244522, 12768606}) = 0
13663 clock_gettime(CLOCK_BOOTTIME, {244522, 13615672}) = 0
13663 _newselect(16, [4 6 8 9 10 12 13 14 15], [], [], {0, 999153}) = 0 (Timeout)
13663 clock_gettime(CLOCK_BOOTTIME, {244523, 16399625}) = 0
13663 write(1, "wlan0: STA xx:xx:xx:xx:xx:xx WPA: EAPOL-Key timeout\n", 52) = 52
13663 write(1, "wlan0: STA xx:xx:xx:xx:xx:xx WPA: sending 1/4 msg of 4-Way Handshake\n", 69) = 69

Hostapd is not getting a response to its 4-way handshake.

I'll try the patch out at some point during the next few days - and
I hope that doesn't result in lots of log spam.

> 
> Regards,
> Arend
> ---
>  drivers/net/wireless/broadcom/brcm80211/brcmfmac/cfg80211.c | 2 ++
>  1 file changed, 2 insertions(+)
> 
> diff --git a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/cfg80211.c b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/cfg80211.c
> index a62c48d..d43d4c0 100644
> --- a/drivers/net/wireless/broadcom/brcm80211/brcmfmac/cfg80211.c
> +++ b/drivers/net/wireless/broadcom/brcm80211/brcmfmac/cfg80211.c
> @@ -460,6 +460,8 @@ static void convert_key_from_CPU(struct brcmf_wsec_key *key,
>  	int err;
>  	struct brcmf_wsec_key_le key_le;
>  
> +	brcmf_err("idx %d algo %d flags %x\n",
> +		  key->index, key->algo, key->flags);
>  	convert_key_from_CPU(key, &key_le);
>  
>  	brcmf_netdev_wait_pend8021x(ifp);
> -- 
> 1.9.1
> 
> 

-- 
RMK's Patch system: https://www.armlinux.org.uk/developer/patches/
FTTC broadband for 0.8mile line in suburbia: sync at 12.1Mbps down 622kbps up
According to speedtest.net: 11.9Mbps down 500kbps up