Re: Permanent disconnect when deauthenticated during a roam

[Denis Kenzior <denkenz@gmail.com>]

Hi Michael,

On 11/9/22 10:42, Michael Johnson wrote:
> Hey all,
> 
> I've just had an issue with a client being permanently disconnected
> after a failed roam. iwd detects the disconnect and prints a message
> but doesn't seem to attempt to reconnect again. I don't see anything
> about blacklists mentioned either.
> Any idea why this isn't attempting to reconnect?

Hmm, see if commit 8758cc89487b3 fixes this:

https://git.kernel.org/pub/scm/network/wireless/iwd.git/commit/src?id=8758cc89487b3304e4b96179a464fff3201e690d

> 
> ```
> # Normal roam
> Nov 08 17:59:41.880934 p3-3478 iwd[426]:
> src/netdev.c:netdev_authenticate_event()
> Nov 08 17:59:41.881248 p3-3478 kernel: wlan0: send auth to
> ac:3a:67:5d:8b:2c (try 1/3)
> Nov 08 17:59:41.881324 p3-3478 kernel: wlan0: authenticated
> Nov 08 17:59:41.881374 p3-3478 iwd[426]:
> src/netdev.c:netdev_get_oci_cb() Obtained OCI: freq: 5560, width: 1,
> center1: 5560, center2: 0
> Nov 08 17:59:41.889035 p3-3478 kernel: wlan0: associate with
> ac:3a:67:5d:8b:2c (try 1/3)
> Nov 08 17:59:41.889232 p3-3478 kernel: wlan0: RX ReassocResp from
> ac:3a:67:5d:8b:2c (capab=0x1111 status=0 aid=10)
> Nov 08 17:59:41.892719 p3-3478 iwd[426]:
> src/netdev.c:netdev_mlme_notify() MLME notification Associate(38)
> Nov 08 17:59:41.892719 p3-3478 iwd[426]: src/netdev.c:netdev_associate_event()
> Nov 08 17:59:41.892719 p3-3478 iwd[426]: src/netdev.c:netdev_set_gtk() 5
> Nov 08 17:59:41.892719 p3-3478 iwd[426]:
> src/station.c:station_handshake_event() Setting keys
> Nov 08 17:59:41.892719 p3-3478 iwd[426]: src/netdev.c:netdev_set_tk() 5
> Nov 08 17:59:41.892719 p3-3478 iwd[426]:
> src/netdev.c:netdev_mlme_notify() MLME notification Connect(46)
> Nov 08 17:59:41.892719 p3-3478 iwd[426]: src/netdev.c:netdev_connect_event()
> Nov 08 17:59:41.893224 p3-3478 kernel: wlan0: associated
> Nov 08 17:59:41.893271 p3-3478 kernel: ath: EEPROM regdomain: 0x8348
> Nov 08 17:59:41.893307 p3-3478 kernel: ath: EEPROM indicates we should
> expect a country code
> Nov 08 17:59:41.893337 p3-3478 kernel: ath: doing EEPROM
> country->regdmn map search
> Nov 08 17:59:41.893363 p3-3478 kernel: ath: country maps to regdmn code: 0x3a
> Nov 08 17:59:41.893390 p3-3478 kernel: ath: Country alpha2 being used: US
> Nov 08 17:59:41.893416 p3-3478 kernel: ath: Regpair used: 0x3a
> Nov 08 17:59:41.893457 p3-3478 kernel: ath: regdomain 0x8348
> dynamically updated by country element
> Nov 08 17:59:41.893483 p3-3478 kernel: wlan0: deauthenticated from
> ac:3a:67:5d:8b:2c (Reason: 34=DISASSOC_LOW_ACK)

Looks like we deauthenticate very shortly after associated where the roam is 
still in progress.

> Nov 08 17:59:41.895990 p3-3478 iwd[426]:
> src/netdev.c:netdev_link_notify() event 16 on ifindex 5
> Nov 08 17:59:41.896099 p3-3478 iwd[426]:
> src/wiphy.c:wiphy_reg_notify() Notification of command Reg Change(36)
> Nov 08 17:59:41.896099 p3-3478 iwd[426]:
> src/wiphy.c:wiphy_update_reg_domain() New reg domain country code for
> (global) is US
> Nov 08 17:59:41.896099 p3-3478 iwd[426]:
> src/netdev.c:netdev_link_notify() event 16 on ifindex 5
> Nov 08 17:59:41.896282 p3-3478 iwd[426]:
> src/netdev.c:netdev_mlme_notify() MLME notification Del Station(20)
> Nov 08 17:59:41.896282 p3-3478 iwd[426]:
> src/netdev.c:netdev_link_notify() event 16 on ifindex 5
> Nov 08 17:59:41.896282 p3-3478 iwd[426]:
> src/netdev.c:netdev_mlme_notify() MLME notification Deauthenticate(39)
> Nov 08 17:59:41.896282 p3-3478 iwd[426]:
> src/netdev.c:netdev_deauthenticate_event()
> Nov 08 17:59:41.896282 p3-3478 iwd[426]:
> src/netdev.c:netdev_link_notify() event 16 on ifindex 5
> Nov 08 17:59:41.896282 p3-3478 iwd[426]:
> src/netdev.c:netdev_mlme_notify() MLME notification Disconnect(48)
> Nov 08 17:59:41.896282 p3-3478 iwd[426]: src/netdev.c:netdev_disconnect_event()
> Nov 08 17:59:41.896282 p3-3478 iwd[426]: Received Deauthentication
> event, reason: 34, from_ap: true
> Nov 08 17:59:41.896282 p3-3478 iwd[426]:
> src/wiphy.c:wiphy_radio_work_done() Work item 493 done
> Nov 08 17:59:41.896282 p3-3478 iwd[426]:
> src/station.c:station_disconnect_event() 5
> Nov 08 17:59:41.896282 p3-3478 iwd[426]: Unexpected disconnect event

And we erroneously think that such an event can't happen (in 1.30).

> Nov 08 17:59:41.896282 p3-3478 iwd[426]:
> src/netdev.c:netdev_link_notify() event 16 on ifindex 5
> Nov 08 17:59:41.896867 p3-3478 iwd[426]:
> src/wiphy.c:wiphy_reg_notify() Notification of command Reg Change(36)
> Nov 08 17:59:41.896867 p3-3478 iwd[426]:
> src/wiphy.c:wiphy_update_reg_domain() New reg domain country code for
> (global) is XX
> Nov 08 17:59:42.893123 p3-3478 iwd[426]:
> src/netdev.c:netdev_link_notify() event 16 on ifindex 5
> # Doesn't reconnect and needs to be rebooted ...
> ```
> 

Regards,
-Denis