On Sun, Apr 19, 2020 at 04:48:58PM +0100, Russell King - ARM Linux admin wrote:
> On Sun, Apr 19, 2020 at 09:28:35AM +0100, Russell King - ARM Linux admin wrote:
> > Hi,
> >
> > I'm seeing a problem running hostapd with a BCM4330 on a SolidRun
> > Hummingboard with 5.6 kernels - I can't get WPA2 authentication to
> > complete with any client station. 5.3 on the same hardware was
> > working fine.
> >
> > Monitoring the wifi network using another machine, I see:
> >
> > 02:31:53.753856 1.0 Mb/s 2412 MHz 11b -45dBm signal antenna 3 BSSID:ap:ap:ap:ap:ap:ap (oui Unknown) DA:ap:ap:ap:ap:ap:ap (oui Unknown) SA:sm:ar:tp:ho:ne:07 (oui Unknown) Authentication (Open System)-1: Successful
> > 02:31:53.754159 1.0 Mb/s 2412 MHz 11b -38dBm signal antenna 3 RA:sm:ar:tp:ho:ne:07 (oui Unknown) Acknowledgment
> > 02:31:53.754781 1.0 Mb/s 2412 MHz 11b -39dBm signal antenna 3 BSSID:ap:ap:ap:ap:ap:ap (oui Unknown) DA:sm:ar:tp:ho:ne:07 (oui Unknown) SA:ap:ap:ap:ap:ap:ap (oui Unknown) Authentication (Open System)-2:
> > 02:31:53.755097 1.0 Mb/s 2412 MHz 11b -46dBm signal antenna 3 RA:ap:ap:ap:ap:ap:ap (oui Unknown) Acknowledgment
> > 02:31:53.785688 1.0 Mb/s 2412 MHz 11b -44dBm signal antenna 3 BSSID:ap:ap:ap:ap:ap:ap (oui Unknown) DA:ap:ap:ap:ap:ap:ap (oui Unknown) SA:sm:ar:tp:ho:ne:07 (oui Unknown) Assoc Request (My-SSID) [1.0 2.0 5.5 11.0 6.0 9.0 12.0 18.0 Mbit]
> > 02:31:53.785993 1.0 Mb/s 2412 MHz 11b -38dBm signal antenna 3 RA:sm:ar:tp:ho:ne:07 (oui Unknown) Acknowledgment
> > 02:31:53.787462 1.0 Mb/s 2412 MHz 11b -39dBm signal antenna 3 BSSID:ap:ap:ap:ap:ap:ap (oui Unknown) DA:sm:ar:tp:ho:ne:07 (oui Unknown) SA:ap:ap:ap:ap:ap:ap (oui Unknown) Assoc Response AID(1) : PRIVACY : Successful
> > 02:31:53.787777 1.0 Mb/s 2412 MHz 11b -44dBm signal antenna 3 RA:ap:ap:ap:ap:ap:ap (oui Unknown) Acknowledgment
> > 02:31:53.803124 1.0 Mb/s 2412 MHz 11b -38dBm signal antenna 3 BSSID:ap:ap:ap:ap:ap:ap (oui Unknown) DA:sm:ar:tp:ho:ne:07 (oui Unknown) SA:ap:ap:ap:ap:ap:ap (oui Unknown) Action: BA ADDBA Request
> > 02:31:53.803423 1.0 Mb/s 2412 MHz 11b -44dBm signal antenna 3 RA:ap:ap:ap:ap:ap:ap (oui Unknown) Acknowledgment
> > 02:31:53.804871 1.0 Mb/s 2412 MHz 11b -37dBm signal antenna 3 CF +QoS DA:sm:ar:tp:ho:ne:07 (oui Unknown) BSSID:ap:ap:ap:ap:ap:ap (oui Unknown) SA:ap:ap:ap:ap:ap:ap (oui Unknown) LLC, dsap SNAP (0xaa) Individual, ssap SNAP (0xaa) Command, ctrl 0x03: oui Ethernet (0x000000), ethertype EAPOL (0x888e), length 99: EAPOL key (3) v2, len 95
> > 02:31:53.805181 1.0 Mb/s 2412 MHz 11b -44dBm signal antenna 3 RA:ap:ap:ap:ap:ap:ap (oui Unknown) Acknowledgment
> > 02:31:53.831347 54.0 Mb/s 2412 MHz 11g -50dBm signal antenna 3 BSSID:ap:ap:ap:ap:ap:ap (oui Unknown) SA:sm:ar:tp:ho:ne:07 (oui Unknown) DA:ap:ap:ap:ap:ap:ap (oui Unknown)
> > 02:31:53.833079 24.0 Mb/s 2412 MHz 11g -51dBm signal antenna 3 RA:sm:ar:tp:ho:ne:07 (oui Unknown) Acknowledgment
> > 02:31:53.833082 1.0 Mb/s 2412 MHz 11b -45dBm signal antenna 3 CF +QoS BSSID:ap:ap:ap:ap:ap:ap (oui Unknown) SA:sm:ar:tp:ho:ne:07 (oui Unknown) DA:ap:ap:ap:ap:ap:ap (oui Unknown) LLC, dsap SNAP (0xaa) Individual, ssap SNAP (0xaa) Command, ctrl 0x03: oui Ethernet (0x000000), ethertype EAPOL (0x888e), length 121: EAPOL key (3) v1, len 117
> > 02:31:53.833390 1.0 Mb/s 2412 MHz 11b -37dBm signal antenna 3 RA:sm:ar:tp:ho:ne:07 (oui Unknown) Acknowledgment
> > 02:31:53.833910 1.0 Mb/s 2412 MHz 11b -45dBm signal antenna 3 BSSID:ap:ap:ap:ap:ap:ap (oui Unknown) DA:ap:ap:ap:ap:ap:ap (oui Unknown) SA:sm:ar:tp:ho:ne:07 (oui Unknown) Action: BA ADDBA Response
> > 02:31:53.834222 1.0 Mb/s 2412 MHz 11b -37dBm signal antenna 3 RA:sm:ar:tp:ho:ne:07 (oui Unknown) Acknowledgment
> > 02:31:53.834646 1.0 Mb/s 2412 MHz 11b -37dBm signal antenna 3 RA:sm:ar:tp:ho:ne:07 (oui Unknown) TA:ap:ap:ap:ap:ap:ap (oui Unknown) CTL(4) SEQ(16) BAR
> > 02:31:53.835105 1.0 Mb/s 2412 MHz 11b -45dBm signal antenna 3 RA:ap:ap:ap:ap:ap:ap (oui Unknown) BA
> >
> > 02:31:54.805391 1.0 Mb/s 2412 MHz 11b -37dBm signal antenna 3 CF +QoS DA:sm:ar:tp:ho:ne:07 (oui Unknown) BSSID:ap:ap:ap:ap:ap:ap (oui Unknown) SA:ap:ap:ap:ap:ap:ap (oui Unknown) LLC, dsap SNAP (0xaa) Individual, ssap SNAP (0xaa) Command, ctrl 0x03: oui Ethernet (0x000000), ethertype EAPOL (0x888e), length 99: EAPOL key (3) v2, len 95
> >
> > and it repeats.
> >
> > However, turning on debug in hostapd shows that hostapd sends the
> > EAPOL 1/4 message as expected, but never receives a response - it
> > seems the EAPOL response that we can see above in tcpdump is getting
> > dropped somewhere between the BCM4330 and hostapd.
> >
> > nl80211: Drv Event 19 (NL80211_CMD_NEW_STATION) received for wlan0
> > nl80211: New station sm:ar:tp:ho:ne:07
> > wlan0: Event ASSOC (0) received
> > wlan0: STA sm:ar:tp:ho:ne:07 IEEE 802.11: associated
> > STA included RSN IE in (Re)AssocReq
> > New STA
> > ap_sta_add: register ap_handle_timer timeout for sm:ar:tp:ho:ne:07 (300 seconds
> > - ap_max_inactivity)
> > nl80211: Set STA flags - ifname=wlan0 addr=sm:ar:tp:ho:ne:07 total_flags=0x60 flags_or=0x0 flags_and=0xfffffff1 authorized=0
> > wlan0: STA sm:ar:tp:ho:ne:07 WPA: event 1 notification
> > wpa_driver_nl80211_set_key: ifindex=3 (wlan0) alg=0 addr=0x20190a8 key_idx=0 set_tx=1 seq_len=0 key_len=0
> > addr=sm:ar:tp:ho:ne:07
> > nl80211: set_key failed; err=-22 Invalid argument)
> > RSN: PTK removal from the driver failed
> > IEEE 802.1X: Ignore STA - 802.1X not enabled or forced for WPS
> > wlan0: STA sm:ar:tp:ho:ne:07 WPA: start authentication
> > WPA: sm:ar:tp:ho:ne:07 WPA_PTK entering state INITIALIZE
> > wpa_driver_nl80211_set_key: ifindex=3 (wlan0) alg=0 addr=0x20190a8 key_idx=0 set_tx=1 seq_len=0 key_len=0
> > addr=sm:ar:tp:ho:ne:07
> > nl80211: set_key failed; err=-22 Invalid argument)
> > RSN: PTK removal from the driver failed
> > nl80211: Set STA flags - ifname=wlan0 addr=sm:ar:tp:ho:ne:07 total_flags=0x60 flags_or=0x0 flags_and=0xfffffffe authorized=0
> > wlan0: STA sm:ar:tp:ho:ne:07 IEEE 802.1X: unauthorizing port
> > WPA: sm:ar:tp:ho:ne:07 WPA_PTK_GROUP entering state IDLE
> > WPA: sm:ar:tp:ho:ne:07 WPA_PTK entering state AUTHENTICATION
> > WPA: sm:ar:tp:ho:ne:07 WPA_PTK entering state AUTHENTICATION2
> > WPA: Re-initialize GMK/Counter on first station
> > GMK - hexdump(len=32): [REMOVED]
> > Key Counter - hexdump(len=32): [REMOVED]
> > GTK - hexdump(len=16): [REMOVED]
> > wpa_driver_nl80211_set_key: ifindex=3 (wlan0) alg=3 addr=0x60a9ac key_idx=1 set_tx=1 seq_len=0 key_len=16
> > nl80211: KEY_DATA - hexdump(len=16): [REMOVED]
> > broadcast key
> > Searching a PSK for sm:ar:tp:ho:ne:07 prev_psk=(nil)
> > Searching a PSK for sm:ar:tp:ho:ne:07 prev_psk=(nil)
> > WPA: sm:ar:tp:ho:ne:07 WPA_PTK entering state PTKSTART
> > wlan0: STA sm:ar:tp:ho:ne:07 WPA: sending 1/4 msg of 4-Way Handshake
> > WPA: Send EAPOL(version=2 secure=0 mic=0 ack=1 install=0 pairwise=1 kde_len=0 keyidx=0 encr=0)
> > WPA: Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 01
> > WPA: Use EAPOL-Key timeout of 1000 ms (retry counter 1)
> > wlan0: hostapd_new_assoc_sta: reschedule ap_handle_timer timeout for sm:ar:tp:ho:ne:07 (300 seconds - ap_max_inactivity)
> > wlan0: STA sm:ar:tp:ho:ne:07 WPA: EAPOL-Key timeout
> > WPA: sm:ar:tp:ho:ne:07 WPA_PTK entering state PTKSTART
> > wlan0: STA sm:ar:tp:ho:ne:07 WPA: sending 1/4 msg of 4-Way Handshake
> > WPA: Send EAPOL(version=2 secure=0 mic=0 ack=1 install=0 pairwise=1 kde_len=0 keyidx=0 encr=0)
> > ...
> >
> > I'm unable to add a monitor interface on the AP itself (hardware
> > doesn't support monitor + AP). How do I debug where the failure
> > is occuring?
>
> I've wound back to 5.3, and it fails there too now, which is really
> odd - it was working for around 270 days with that kernel version,
> and I'm ensuring I'm using the same broadcom firmware. That's
> including power cycling everything.
>
> I've just updated my other AP - again, using debian stable (so same
> hostapd version), it's also on the same kernel version (as in same
> kernel binary) but that machine uses a TI WL18 chipset for its WiFi,
> and that doesn't seem to have a problem.
>
> So, the problem appears to be specific to the BCM4330 in some way.
> Except maybe not according to further debug.
>
> Enabling debug in brcmfmac:
>
> echo 8 > /sys/module/brcmfmac/parameters/debug
>
> Shows:
>
> brcmfmac: brcmf_netdev_start_xmit Enter, bsscfgidx=0
> brcmfmac: brcmf_rx_frame Enter: mmc0:0001:1: rxp=c885cc00
> brcmfmac: brcmf_fws_hdrpull enter: ifidx 0, skblen 135, sig 0
> brcmfmac: brcmf_netif_rx rx proto=0x888E
>
> tcpdumping the wlan interface on the AP shows the EAPOL packets (both
> what we send and what is received) are present there.
>
> stracing hostapd, which is using device_ap_sme=1 use_monitor=0, I
> see:
>
> socket(AF_PACKET, SOCK_DGRAM, htons(ETH_P_PAE)) = 15
>
> So this socket is setup to receive packets of type 0x888e. I
> can't find anything further that manipulates this socket in the
> hostapd strace. However, I do see:
>
> write(3, "WPA: Send EAPOL(version=2 secure=0 mic=0 ack=1 install=0 pairwise=1 kde_len=0 keyidx=0 encr=0)\n", 95) = 95
> write(4, "wpas <2>: WPA: Send EAPOL(version=2 secure=0 mic=0 ack=1 install=0 pairwise=1 kde_len=0 keyidx=0 encr=0)\n", 105) = 105
> write(4, "wpas <2>: WPA: Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 01", 71) = 71
> write(3, "WPA: Replay Counter - hexdump(len=8): 00 00 00 00 00 00 00 01\n", 62)
> = 62
> sendto(13, "...", 99, 0, {sa_family=AF_PACKET, sll_protocol=htons(ETH_P_PAE), sll_ifindex=if_nametoindex("wlan0"), sll_hatype=ARPHRD_NETROM, sll_pkttype=PACKET_HOST, sll_halen=6, sll_addr=[...]}, 20) = 99
> write(3, "WPA: Use EAPOL-Key timeout of 1000 ms (retry counter 1)\n", 56) = 56
> write(4, "wpas <2>: WPA: Use EAPOL-Key timeout of 1000 ms (retry counter 1)\n", 66) = 66
> clock_gettime(CLOCK_BOOTTIME, {tv_sec=21874, tv_nsec=646076492}) = 0
> write(3, "wlan0: hostapd_new_assoc_sta: reschedule ap_handle_timer timeout for ... (300 seconds - ap_max_inactivity)\n", 121) = 121
> write(4, "wpas <2>: wlan0: hostapd_new_assoc_sta: reschedule ap_handle_timer timeout for ... (300 seconds - ap_max_inactivity)\n", 131) = 131
> clock_gettime(CLOCK_BOOTTIME, {tv_sec=21874, tv_nsec=647106886}) = 0
> clock_gettime(CLOCK_BOOTTIME, {tv_sec=21874, tv_nsec=647439906}) = 0
> _newselect(18, [5 7 9 10 11 12 15 16 17], [], [], {tv_sec=0, tv_usec=998637}) = 0 (Timeout)
> clock_gettime(CLOCK_BOOTTIME, {tv_sec=21875, tv_nsec=647977403}) = 0
> write(3, "wlan0: STA ... WPA: EAPOL-Key timeout\n", 52) = 52
>
> which clearly shows that the packets are not being received by socket
> fd 15. According to the man page for packet(7), that socket on fd 15
> _should_ be receiving the EAPOL frame. Yet, as I say, tcpdumping wlan0
> _does_ show them, but hostapd's AF_PACKET socket is not.
>
> I have no iptables rules, I have no ebtables rules. If I could work
> out how to use nft, I could check that as well, but it's got a most
> unhelpful command line and needs me to read the 'net every time I want
> to do anything with it - a most unfriendly program, seemingly designed
> to be very unfriendly.
>
> So, we're back to it looking like a kernel bug... yet I've no idea
> how 5.3 worked perfectly well for 270 odd days but now doesn't.
>
> Having now spent close to 12 hours time trying to get to the bottom of
> this, I think it's time to admit defeat.
Ah, a breakthrough.
If I remove "bridge=br0" from the hostapd file, hostapd can then
receive the EAPOL frames. Now if I add it back and re-run hostapd,
it's still able to receive the EAPOL frames. ?!?!?!?!?!?
That's the _only_ change I made. Merely commenting out that line
and then replacing it. And now it's working. I really don't
understand that. Same config file wasn't working for the last 18
odd hours, and, by just dropping the bridge device momentarily
from hostapd's configuration, it's started to work with it back
to the non-working configuration.
--
RMK's Patch system: https://www.armlinux.org.uk/developer/patches/
FTTC broadband for 0.8mile line in suburbia: sync at 10.2Mbps down 587kbps up
