Re: Connection loss (IWD HEAD with latest OWE / BSS selection patches) - brcmfmac driver

Dear James,

Am 05.11.24 um 00:20 schrieb James Prestwood:
> Hi Martin,
>
> On 11/4/24 2:42 PM, Martin Petzold wrote:
>> Dear James,
>>
>> Am 04.11.24 um 13:36 schrieb James Prestwood:
>>>
>>> On 11/3/24 3:13 PM, Martin Petzold wrote:
>>>> Dear James,
>>>>
>>>> Am 25.10.24 um 17:17 schrieb James Prestwood:
>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>>
>>>>>>>>>>>>> I open a new thread for this one: During the last weeks I 
>>>>>>>>>>>>> have seen connection losses for 30+ minutes, sometimes 
>>>>>>>>>>>>> even hours or just now even forever (IWD HEAD with v2 OWE 
>>>>>>>>>>>>> / BSS selection patches). Driver is brcmfmac (NXP 6.1.36 
>>>>>>>>>>>>> kernel) and chip is BCM4339 (Laird LWB5).
>>>>>>>>>>>>>
>>>>>>>>>>>>> It happens in a) single router environment (WPA2-PSK; 
>>>>>>>>>>>>> Touchstone TG3442DE), and b) router + repeater environment 
>>>>>>>>>>>>> (WPA2 CCMP; Fritz!Box + Fritz!Repeater), and maybe also in 
>>>>>>>>>>>>> the WPA3 OWE Transition network (yesterday lost a 
>>>>>>>>>>>>> connection again).
>>>>>>>>>>>>
>>>>>>>>>>>> I lost now again 2 of 10 devices in the WPA3 OWE network 
>>>>>>>>>>>> (with roaming). However, now they don't disappear all after 
>>>>>>>>>>>> a shorter while. It seems to be later.
>>>>>>>>>>>>
>>>>>>>>>>>> I also lost one device in a Router+Repeater WPA2 (CCMP) 
>>>>>>>>>>>> network. It is confirmed here on router side, that the 
>>>>>>>>>>>> device is disconnected. Since more than a day.
>>>>>>>>>>>
>>>>>>>>>>> We can't do anything without logs. If you suspect its the 
>>>>>>>>>>> blacklist you can lower the blacklist time down in main.conf:
>>>>>>>>>>>
>>>>>>>>>>> [
>>>>
>>>> I am still losing devices. Sometimes they come back again, but 
>>>> mostly do not re-connect. I have observed the following:
>>>>
>>>> - Connection exists for several hours until about one day, or two. 
>>>> Then gone for several hours or mostly forever.
>>>> - For FritzBox+FritzRepeater I have seen the connection coming back 
>>>> after like a day (here connection loss was also confirmed on router 
>>>> side!)
>>>> - For the Aruba enterprise environment the connection never came 
>>>> back (until now no AP logs - waiting for an answer)
>>>> - After reboot the connection comes back
>>>> - It occurs only in an environment with multiple APs with same SSID 
>>>> (i.e. roaming environment), however my single AP environments have 
>>>> all strong signal
>>>> - Some devices with identical configuration in this environment DO 
>>>> NOT get lost, those seem to have quite strong signal (maybe they 
>>>> don't roam)
>>>> - Other devices in the same environment work without any problems 
>>>> (Intel+NetworkManager) and the APs are Aruba enterprise grade
>>>> - I see almost the same in the Aruba enterprise environment, but 
>>>> ALSO in a FritzBox + FritzRepeater environment
>>>> - We had a bug in our web socket connection, causing to many IWD 
>>>> requests. However, this was fixed. And why are all the other 
>>>> devices okay? Maybe co-incidence with roaming and anything related 
>>>> to dropping and re-connecting web socket connection.
>>>>
>>>> Please find attached my currently available debug logs (they are a 
>>>> few days old, but I am quite sure this is the connection loss 
>>>> situation). These logs are from the FritzBox+FritzRepeater 
>>>> environment. There are no brcmfmac messages (but also no special 
>>>> debug level configured here)!
>>>>
>>>> I have now also disabled WiFi power saving and will deploy to the 
>>>> environment...hoping the best.
>>>>
>>>> Maybe you could check the logs and have an idea?
>>>
>>> Looks like the same thing as the last logs you sent. IWD tries to 
>>> connect (sends CMD_CONNECT to the kernel) but gets no associated 
>>> CMD_CONNECT event after that which causes IWD to wait indefinitely 
>>> for that event. This, again, appears like a driver problem because 
>>> its expected that the kernel tells userspace the result of the 
>>> CMD_CONNECT request.
>>>
>>> Only similarity I can see between the two sets of logs is there is a 
>>> failed connection just prior to the hang. IWD then attempts to 
>>> connect again but the 4-way handshake is never started and this 
>>> results in a failure with status 16 (group key handshake timeout). 
>>> In your latest set of logs IWD actually again tries to connect to a 
>>> different BSS and gets status 16 before trying yet again and hanging.
>>>
>>> This actually seems similar to an issue I encountered with ath10k 
>>> where the network interface would time out being brought up. 
>>> Retrying would succeed but the driver would be in a similar state 
>>> where IWD could authenticate/associate but no data frames (i.e. 
>>> 4-way handshake) would be passed to userspace. Only solution (until 
>>> upstream fixed the bug) was to unload/reload the driver when we 
>>> detected this condition.
>>>
>>> If you are able to physically attach to a device currently in this 
>>> state you may be able to get more info. For example if IWD is stuck 
>>> like this try disconnecting/reconnecting with iwctl or restarting 
>>> IWD to see what happens. If you end up in the same state right away 
>>> I'm 99.9% sure the driver is the entire reason your running into this.
>>
>> Are you sure? Maybe you could double-check?
> I'm sure.
>>
>> Because my SOM vendor (Variscite) selling a few hundred thousand of 
>> these do not report any issue with this kernel, firmware, and 
>> NetworkManager (wpa_supplicant)...
>
> Because wpa_supplicant sets internal timers for these commands in case 
> the driver is broken. I would expect you would see this exact behavior 
> with wpa_supplicant, it would just disconnect/reconnect after 5 
> seconds of no response from the kernel. And something like this either 
> a) goes entirely unnoticed and/or b) works well enough for a hardware 
> vendor to ship it to customers and not care.
>
> This is the commit adding these timers to wpa_supplicant:
>
> commit e29853bbff1eef781099a9108e3b51f26b477ac3
> Author: Ben Greear <[email protected]>
> Date:   Thu Feb 24 16:59:46 2011 +0200
>
>     SME: Add timers for authentication and asscoiation
>
>     mac80211 authentication or association operation may get stuck for 
> some
>     reasons, so wpa_supplicant better use an internal timer to recover 
> from
>     this.
>
>     Signed-off-by: Ben Greear <[email protected]>
>
> I wish it surprised me that 13 years later this behavior still 
> happens... We don't like adding special driver workarounds like this 
> in IWD because a) it becomes difficult to maintain and b) it just 
> hides the root cause and nobody ever fixes it. But my opinions aside, 
> for a driver like brcmfmac which is very mainstream, I guess we have 
> no choice but to adapt IWD to work around it like wpa_supplicant does.

It seems to be better now, but I'm still investigating some instability.

Here some logs from AP (in this case we are in enterprise ARUBA WPA3 
Transition Mode (Open Network):

----- BEFORE patch and power save disabled (several of these negative 
events) - station mostly does not have carrier

2024-11-06 14:09:48 
CET,"006-WLANAP-070","XXX","XX:YY:ZZ:c9:40:06","XX:YY:ZZ:14:00:61","negative","Client 
Onboarding Failure - Deauthentication/Disassociation","Onboarding failed 
for client XX:YY:ZZ:8a:d6:42 in Deauthentication/Disassociation phase to 
BSSID XX:YY:ZZ:14:00:61 on channel 11 of AP hostname 006-WLANAP-070. 
Reason: SSID Age-out","SSID Age-out","XYZ-Gast","2.4 GHz 
(G)","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","",""

[...]

2024-11-06 11:37:54 
CET,"006-WLANAP-070","XXX","XX:YY:ZZ:c9:40:06","XX:YY:ZZ:14:00:61","neutral","802.11 
De-authentication to Client","De-authentication sent to 
client XX:YY:ZZ:8a:d6:42 from BSSID XX:YY:ZZ:14:00:61 on channel 11 of 
AP hostname 006-WLANAP-070. Reason: Station has roamed to another 
AP","Station has roamed to another AP","XYZ-Gast","2.4 GHz 
(G)","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","","",""

----- AFTER patch and power save disabled ("only" such negative events 
left) - station mostly has carrier, but still see some instability

"2024-11-06 13:47:02 
CET,""006-WLANAP-064"",""XXX"",""XX:YY:ZZ:c9:42:c4"",""XX:YY:ZZ:14:2c:43"",""negative"",""Client 
Onboarding Failure - Deauthentication/Disassociation"",""Onboarding 
failed for client XX:YY:ZZ:8e:22:8a in Deauthentication/Disassociation 
phase to BSSID XX:YY:ZZ:14:2c:43 on channel 6 of AP hostname 
006-WLANAP-064. Reason: Client left the access point"",""Client left the 
access point"",""XYZ-Gast"",""2.4 GHz 
(G)"","""",""37"",""220"","""","""","""","""","""","""","""","""","""",""61"","""","""","""","""","""","""","""","""","""","""","""","""","""","""","""","""","""","""","""","""","""","""",""HT"",""Short"",""20 
MHz"",""1ss"","""","""","""","""","""""

[...]

"2024-11-06 13:47:01 
CET,""006-WLANAP-064"",""XXX"",""XX:YY:ZZ:c9:42:c4"",""XX:YY:ZZ:14:2c:43"",""negative"",""Client 
DHCP Timeout"",""DHCP request from client XX:YY:ZZ:8e:22:8a timed 
out"","""","""","""","""","""","""","""","""","""","""","""","""","""","""","""","""","""","""","""","""","""","""",""10.119.40.10"",""8.8.8.8"",""172.22.0.1"","""","""",""81089"","""","""","""","""","""","""","""","""","""","""","""","""","""","""","""","""","""","""","""""
-----

Maybe you have some comment on the changes. And if these DHCP failures 
could still cause instability? (maybe some issues on AP / DHCP server side?)

Best regards,

Martin