3:49 p.m.
Hi,
After updating to master (f12cf1ab9db iwd, 43e99ec5f21 ell) I've
started seeing a few new errors which are causing the client to
disconnect and stay disconnected for a brief time. The previous
version I was running (1.21 iwd and 0.47 ell) didn't have these but
it's possible this is new functionality that was enabled and the AP
vendor doesn't support it properly. If there is anything else I can
gather to help debug what is going wrong please let me know.
The first error happens during an FT roam and the AP reports this
association failure: 802.11 STATUS (CODE 77) - Unsupported finite
cyclic group. Most FT roams happen fine so I'm not sure why this one
is different.
```
May 19 16:16:11.647803 r2-19105 iwd[462]:
src/station.c:station_enter_state() Old State: connected, new state:
roaming
May 19 16:16:11.647803 r2-19105 iwd[462]:
src/wiphy.c:wiphy_radio_work_done() Work item 201 done
May 19 16:16:11.647803 r2-19105 iwd[462]:
src/wiphy.c:wiphy_radio_work_next() Starting work item 202
May 19 16:16:11.692387 r2-19105 iwd[462]:
src/netdev.c:netdev_mlme_notify() MLME notification Del Station(20)
May 19 16:16:11.692387 r2-19105 iwd[462]:
src/netdev.c:netdev_link_notify() event 16 on ifindex 5
May 19 16:16:11.692387 r2-19105 iwd[462]:
src/netdev.c:netdev_mlme_notify() MLME notification Deauthenticate(39)
May 19 16:16:11.692588 r2-19105 iwd[462]:
src/netdev.c:netdev_deauthenticate_event()
May 19 16:16:11.692588 r2-19105 iwd[462]:
src/netdev.c:netdev_mlme_notify() MLME notification Disconnect(48)
May 19 16:16:11.692588 r2-19105 iwd[462]: src/netdev.c:netdev_disconnect_event()
May 19 16:16:11.692588 r2-19105 iwd[462]:
src/netdev.c:netdev_mlme_notify() MLME notification New Station(19)
May 19 16:16:11.692588 r2-19105 iwd[462]:
src/netdev.c:netdev_link_notify() event 16 on ifindex 5
May 19 16:16:11.692588 r2-19105 iwd[462]:
src/wiphy.c:wiphy_reg_notify() Notification of command Reg Change(36)
May 19 16:16:11.692588 r2-19105 iwd[462]:
src/wiphy.c:wiphy_update_reg_domain() New reg domain country code for
(global) is XX
May 19 16:16:11.696000 r2-19105 iwd[462]:
src/netdev.c:netdev_mlme_notify() MLME notification Authenticate(37)
May 19 16:16:11.696000 r2-19105 iwd[462]:
src/netdev.c:netdev_authenticate_event()
May 19 16:16:11.696723 r2-19105 iwd[462]:
src/netdev.c:netdev_mlme_notify() MLME notification Del Station(20)
May 19 16:16:11.696723 r2-19105 iwd[462]:
src/netdev.c:netdev_mlme_notify() MLME notification Deauthenticate(39)
May 19 16:16:11.696848 r2-19105 iwd[462]:
src/netdev.c:netdev_deauthenticate_event()
May 19 16:16:11.696848 r2-19105 iwd[462]:
src/wiphy.c:wiphy_radio_work_done() Work item 202 done
May 19 16:16:11.696848 r2-19105 iwd[462]:
src/station.c:station_fast_transition_cb() 5, result: 2
May 19 16:16:11.696848 r2-19105 iwd[462]: src/station.c:station_roam_failed() 5
May 19 16:16:11.696848 r2-19105 iwd[462]:
src/station.c:station_disassociated() 5
May 19 16:16:11.696848 r2-19105 iwd[462]:
src/resolve.c:resolve_systemd_revert() ifindex: 5
```
The second error is a CMD_ASSOCIATE timeout which happens when trying
to autoconnect after the first error and so is possibly related.
```
May 19 16:16:12.812461 r2-19105 iwd[462]:
src/wiphy.c:wiphy_select_akm() Network is WPA3-Personal...
May 19 16:16:12.812461 r2-19105 iwd[462]: src/sae.c:sae_sm_new() Using
SAE Hunting and Pecking
May 19 16:16:12.812461 r2-19105 iwd[462]: src/netdev.c:netdev_cqm_rssi_update()
May 19 16:16:12.812461 r2-19105 iwd[462]:
src/wiphy.c:wiphy_radio_work_insert() Inserting work item 204
May 19 16:16:12.812461 r2-19105 iwd[462]:
src/station.c:__station_connect_network() connecting to BSS
f6:9e:38:*:*:*
May 19 16:16:12.812461 r2-19105 iwd[462]:
src/station.c:station_enter_state() Old State: autoconnect_quick, new
state: connecting (auto)
May 19 16:16:12.812461 r2-19105 iwd[462]: src/scan.c:scan_cancel()
Trying to cancel scan id 203 for wdev 2
May 19 16:16:12.812461 r2-19105 iwd[462]:
src/wiphy.c:wiphy_radio_work_done() Work item 203 done
May 19 16:16:12.812461 r2-19105 iwd[462]:
src/wiphy.c:wiphy_radio_work_next() Starting work item 204
May 19 16:16:12.863949 r2-19105 iwd[462]:
src/netdev.c:netdev_mlme_notify() MLME notification New Station(19)
May 19 16:16:12.865712 r2-19105 iwd[462]:
src/netdev.c:netdev_mlme_notify() MLME notification Authenticate(37)
May 19 16:16:12.865712 r2-19105 iwd[462]:
src/netdev.c:netdev_authenticate_event()
May 19 16:16:12.865712 r2-19105 iwd[462]:
src/sae.c:sae_verify_packet() rx trans=1, state=committed
May 19 16:16:12.930662 r2-19105 iwd[462]:
src/netdev.c:netdev_mlme_notify() MLME notification Del Station(20)
May 19 16:16:12.930662 r2-19105 iwd[462]:
src/netdev.c:netdev_mlme_notify() MLME notification New Station(19)
May 19 16:16:12.946796 r2-19105 iwd[462]:
src/netdev.c:netdev_mlme_notify() MLME notification Authenticate(37)
May 19 16:16:12.946796 r2-19105 iwd[462]:
src/netdev.c:netdev_authenticate_event()
May 19 16:16:12.946796 r2-19105 iwd[462]:
src/sae.c:sae_verify_packet() rx trans=1, state=committed
May 19 16:16:12.950893 r2-19105 iwd[462]:
src/netdev.c:netdev_mlme_notify() MLME notification Authenticate(37)
May 19 16:16:12.950893 r2-19105 iwd[462]:
src/netdev.c:netdev_authenticate_event()
May 19 16:16:12.950893 r2-19105 iwd[462]:
src/sae.c:sae_verify_packet() rx trans=2, state=confirmed
May 19 16:16:14.234437 r2-19105 iwd[462]:
src/netdev.c:netdev_mlme_notify() MLME notification Del Station(20)
May 19 16:16:14.234749 r2-19105 iwd[462]:
src/netdev.c:netdev_mlme_notify() MLME notification Associate(38)
May 19 16:16:14.234749 r2-19105 iwd[462]: src/netdev.c:netdev_associate_event()
May 19 16:16:14.234749 r2-19105 iwd[462]: association timed out
May 19 16:16:14.234883 r2-19105 iwd[462]: Error sending CMD_ASSOCIATE (-2)
May 19 16:16:14.234883 r2-19105 iwd[462]:
src/wiphy.c:wiphy_radio_work_done() Work item 204 done
May 19 16:16:14.234883 r2-19105 iwd[462]:
src/station.c:station_connect_cb() 5, result: 2
```
Finally, after connecting (iwd eventually does the full eapol
handshake which reconnects) the request for the neighbor report times
out. This doesn't cause any disconnect but does cause another neighbor
request to be sent before roaming (which works).
```
May 19 16:50:54.229861 r2-19105 iwd[462]:
src/station.c:station_enter_state() Old State: roaming, new state:
connected
May 19 16:50:54.229861 r2-19105 iwd[462]:
src/wiphy.c:wiphy_radio_work_done() Work item 216 done
May 19 16:50:54.229861 r2-19105 iwd[462]:
src/netdev.c:netdev_link_notify() event 16 on ifindex 5
May 19 16:50:54.230062 r2-19105 iwd[462]:
src/netdev.c:netdev_mlme_notify() MLME notification Frame TX
Status(60)
May 19 16:50:54.623293 r2-19105 iwd[462]:
src/netdev.c:netdev_mlme_notify() MLME notification Notify CQM(64)
May 19 16:50:57.229499 r2-19105 iwd[462]:
src/station.c:station_early_neighbor_report_cb() ifindex: 5, error:
-110(Connection timed out)
...
May 19 17:00:54.060111 r2-19105 iwd[462]:
src/station.c:station_roam_trigger_cb() 5
May 19 17:00:54.060111 r2-19105 iwd[462]:
src/station.c:station_roam_trigger_cb() Requesting neighbor report for
roam
May 19 17:00:54.060492 r2-19105 iwd[462]:
src/netdev.c:netdev_mlme_notify() MLME notification Frame TX
Status(60)
May 19 17:00:54.061519 r2-19105 iwd[462]:
src/netdev.c:netdev_unicast_notify() Unicast notification Frame(59)
May 19 17:00:54.061519 r2-19105 iwd[462]:
src/station.c:station_neighbor_report_cb() ifindex: 5, error: 0()
May 19 17:00:54.061519 r2-19105 iwd[462]:
src/station.c:parse_neighbor_report() Neighbor report received for
f6:9e:38:*:*:*: ch 149 (oper class 3), MD not set
```
Regards,
Michael
5:09 p.m.
Hi Michael,
On 5/20/22 09:49, Michael Johnson wrote:
Hi,
After updating to master (f12cf1ab9db iwd, 43e99ec5f21 ell) I've
started seeing a few new errors which are causing the client to
disconnect and stay disconnected for a brief time. The previous
Hmm, so starting around ell 0.42 we started to prefer using P384 group for SAE
connections over P256.
version I was running (1.21 iwd and 0.47 ell) didn't have these
but
Since you're running 0.47, that should already be the default behavior.
it's possible this is new functionality that was enabled and the
AP
vendor doesn't support it properly. If there is anything else I can
gather to help debug what is going wrong please let me know.
Did anything change on the AP? iwd 1.21 wasn't that long ago, and there hasn't
been any notable SAE or FT changes since then.
The first error happens during an FT roam and the AP reports this
association failure: 802.11 STATUS (CODE 77) - Unsupported finite
cyclic group. Most FT roams happen fine so I'm not sure why this one
is different.
That is a weird error to get during FT since cyclic groups shouldn't even be
involved. Are you sure it is really trying to FT? Maybe it is trying a
simple Reassociate with SAE? Do you have an iwmon log by any chance?
Regards,
-Denis
5:56 p.m.
Hi Denis,
I'm fairly sure it was doing FT as it is set up for that and I don't
see a 4 way handshake in the log. I do see
`station_fast_transition_cb` being called as well so I guess it was
trying FT?
```
May 19 16:16:11.696848 r2-19105 iwd[462]:
src/station.c:station_fast_transition_cb() 5, result: 2
```
The AP hasn't changed for a while now so I don't think it is directly
that however it could be that the error it is giving is complete
nonsense. A second prior to the "finite cycle group" error it does
also say there was an "Invalid authentication" from the same client so
maybe it is a red herring if it doesn't make sense in the context.
Looking more into the difference between 1.21 and master clients,
oddly I actually see the failure to roam in both (looking for the
station_fast_transition with result 2) however the AP only reports
errors for the clients running master. Odd.
The other two errors which happen after this on master don't happen on
1.21. In that case iwd performs a passive scan (same) and then
connects fine without any "Error sending CMD_ASSOCIATE (-2)" error.
Likewise the neighbor report is fine in 1.21 but not master.
Sorry, I think I'm missing some hidden variable here so I'll see if I
can create a better bug report. I'll set up a capture of iwmon logging
to get more solid data to go on and narrow down what is happening in
what version.
Regards,
Michael
7:24 p.m.
Hi Michael,
On Fri, 2022-05-20 at 17:56 +0100, Michael Johnson wrote:
Hi Denis,
I'm fairly sure it was doing FT as it is set up for that and I don't
see a 4 way handshake in the log. I do see
`station_fast_transition_cb` being called as well so I guess it was
trying FT?
```
May 19 16:16:11.696848 r2-19105 iwd[462]:
src/station.c:station_fast_transition_cb() 5, result: 2
```
The AP hasn't changed for a while now so I don't think it is directly
that however it could be that the error it is giving is complete
nonsense. A second prior to the "finite cycle group" error it does
also say there was an "Invalid authentication" from the same client so
maybe it is a red herring if it doesn't make sense in the context.
Looking more into the difference between 1.21 and master clients,
oddly I actually see the failure to roam in both (looking for the
station_fast_transition with result 2) however the AP only reports
errors for the clients running master. Odd.
The other two errors which happen after this on master don't happen on
1.21. In that case iwd performs a passive scan (same) and then
connects fine without any "Error sending CMD_ASSOCIATE (-2)" error.
Likewise the neighbor report is fine in 1.21 but not master.
Sorry, I think I'm missing some hidden variable here so I'll see if I
can create a better bug report. I'll set up a capture of iwmon logging
to get more solid data to go on and narrow down what is happening in
what version.
This should be fixed in upstream now with:
https://git.kernel.org/pub/scm/network/wireless/iwd.git/commit/?id=7104e1...
It ended up being that you're AP was setting a bit IWD did not expect,
but was totally within the spec so we relaxed that check a bit.
Regards,
Michael
_______________________________________________
iwd mailing list -- iwd(a)lists.01.org
To unsubscribe send an email to iwd-leave(a)lists.01.org
88
days inactive
91
days old
3 comments
3 participants
participants (3)
-
Denis Kenzior -
James Prestwood -
Michael Johnson