Reconnect issues, still

Reconnect issues, still

[KeithG]

[-- Attachment #1: Type: text/plain, Size: 14604 bytes --]

The group at connman has re-written connman and it now leverages the
background scanning in iwd as it allows the setting of 'AutoConnect=true'
now. That definitely helps, but I am still struggling to get the RPIs to
effortlessly reconnect. As it is, I have to manipulate the interface to
force a reconnect (if down/up) by running a script to check if the
interface is up or down.

For whatever reason, a reconnect is never tried unless we restart the iwd
or connman process or restart the interface. What I see is my android
devices reconnect in < 1 minute if I force a disconnect from the router or
restart the radio or reboot. I am running the latest git of iwd
(r5144.074bc52). I force disconnect from the router at 18:32. Then I wait.
spg3 is my SSID. It scans and 'sees' it but never initiates or tries a
re-connect. If I do this with my phone (Android 10), it is reconnected in
less than 2 minutes. If I let iwd control it, it reconnects in < 2 minutes
as well. Is there something that connman is waiting for to let connman know
it is ready?

disconnect at 18:43:38 and reconnect@18:45:06
Feb 07 18:43:27 rune64 iwd[2387]:
src/station.c:station_early_neighbor_report_cb() ifindex: 3, error:
-110(Connection timed out)
Feb 07 18:43:38 rune64 iwd[2387]: src/netdev.c:netdev_link_notify() event
16 on ifindex 3
Feb 07 18:43:38 rune64 iwd[2387]: src/netdev.c:netdev_link_notify() event
16 on ifindex 3
Feb 07 18:43:38 rune64 iwd[2387]: src/netdev.c:netdev_mlme_notify() MLME
notification Disconnect(48)
Feb 07 18:43:38 rune64 iwd[2387]: src/netdev.c:netdev_disconnect_event()
Feb 07 18:43:38 rune64 iwd[2387]: Received Deauthentication event, reason:
5, from_ap: false
Feb 07 18:43:38 rune64 iwd[2387]: src/station.c:station_disconnect_event() 3
Feb 07 18:43:38 rune64 iwd[2387]: src/station.c:station_disassociated() 3
Feb 07 18:43:38 rune64 iwd[2387]: src/resolve.c:resolve_systemd_revert()
ifindex: 3
Feb 07 18:43:38 rune64 iwd[2387]: WARNING:
src/resolve.c:resolve_systemd_revert() condition !systemd_state.is_ready
failed
Feb 07 18:43:38 rune64 iwd[2387]: src/station.c:station_enter_state() Old
State: connected, new state: disconnected
Feb 07 18:43:38 rune64 iwd[2387]: src/station.c:station_enter_state() Old
State: disconnected, new state: autoconnect_quick
Feb 07 18:43:38 rune64 iwd[2387]: src/wiphy.c:wiphy_radio_work_insert()
Inserting work item 3
Feb 07 18:43:38 rune64 iwd[2387]: src/wiphy.c:wiphy_radio_work_next()
Starting work item 3
Feb 07 18:43:38 rune64 iwd[2387]:
src/netconfig.c:netconfig_ifaddr_deleted() ifaddr 192.168.2.41/24
Feb 07 18:43:38 rune64 iwd[2387]: src/wiphy.c:wiphy_reg_notify()
Notification of command Reg Change(36)
Feb 07 18:43:38 rune64 iwd[2387]: src/wiphy.c:wiphy_update_reg_domain() New
reg domain country code for (global) is XX
...
Feb 07 18:45:06 rune64 iwd[2387]: src/station.c:station_autoconnect_next()
Considering autoconnecting to BSS '08:02:8e:94:12:97' with SSID: spg3,
freq: 5180, rank: 13866, strength: -5000
Feb 07 18:45:06 rune64 iwd[2387]: src/wiphy.c:wiphy_radio_work_insert()
Inserting work item 10
Feb 07 18:45:06 rune64 iwd[2387]: src/station.c:__station_connect_network()
connecting to BSS 08:02:8e:94:12:97
Feb 07 18:45:06 rune64 iwd[2387]: src/station.c:station_enter_state() Old
State: autoconnect_full, new state: connecting
Feb 07 18:45:06 rune64 iwd[2387]: src/scan.c:scan_periodic_stop() Stopping
periodic scan for wdev 1
Feb 07 18:45:06 rune64 iwd[2387]: src/scan.c:scan_cancel() Trying to cancel
scan id 9 for wdev 1
Feb 07 18:45:06 rune64 iwd[2387]: src/wiphy.c:wiphy_radio_work_done() Work
item 9 done
Feb 07 18:45:06 rune64 iwd[2387]: src/wiphy.c:wiphy_radio_work_next()
Starting work item 10
Feb 07 18:45:06 rune64 iwd[2387]: src/station.c:station_netdev_event()
Associating
Feb 07 18:45:06 rune64 iwd[2387]: src/netdev.c:netdev_mlme_notify() MLME
notification Connect(46)
Feb 07 18:45:06 rune64 iwd[2387]: src/netdev.c:netdev_connect_event()
Feb 07 18:45:06 rune64 iwd[2387]: src/eapol.c:eapol_handle_ptk_1_of_4()
ifindex=3
Feb 07 18:45:06 rune64 iwd[2387]: src/netdev.c:netdev_link_notify() event
16 on ifindex 3
Feb 07 18:45:06 rune64 iwd[2387]: src/netdev.c:netdev_link_notify() event
16 on ifindex 3
Feb 07 18:45:06 rune64 iwd[2387]: src/netdev.c:netdev_link_notify() event
16 on ifindex 3
Feb 07 18:45:06 rune64 iwd[2387]: src/netdev.c:netdev_link_notify() event
16 on ifindex 3
Feb 07 18:45:06 rune64 iwd[2387]: src/eapol.c:eapol_handle_ptk_3_of_4()
ifindex=3
Feb 07 18:45:06 rune64 iwd[2387]: src/netdev.c:netdev_set_gtk() 3
Feb 07 18:45:06 rune64 iwd[2387]: src/netdev.c:netdev_set_igtk() 3
Feb 07 18:45:06 rune64 iwd[2387]: src/station.c:station_handshake_event()
Setting keys
Feb 07 18:45:06 rune64 iwd[2387]: src/netdev.c:netdev_set_tk() 3
Feb 07 18:45:06 rune64 iwd[2387]: src/station.c:station_connect_cb() 3,
result: 0
Feb 07 18:45:06 rune64 iwd[2387]:
src/netconfig.c:netconfig_ipv6_select_and_install() IPV6 configuration
disabled
Feb 07 18:45:06 rune64 iwd[2387]: src/wiphy.c:wiphy_radio_work_done() Work
item 10 done
Feb 07 18:45:06 rune64 iwd[2387]: src/netdev.c:netdev_mlme_notify() MLME
notification Frame TX Status(60)
Feb 07 18:45:06 rune64 iwd[2387]: src/frame-xchg.c:frame_xchg_mlme_notify()
Received no ACK
Feb 07 18:45:06 rune64 iwd[2387]: src/netdev.c:netdev_link_notify() event
16 on ifindex 3
Feb 07 18:45:06 rune64 iwd[2387]:
src/netconfig.c:netconfig_ipv4_dhcp_event_handler() DHCPv4 event 0
Feb 07 18:45:06 rune64 iwd[2387]: src/netconfig.c:netconfig_ifaddr_added()
wlan0: ifaddr 192.168.2.41/24 broadcast 192.168.2.255

If I try the same thing with connman controlling it, it 'sees' the SSID,
but never triggers connman to reconnect. Should connman be looking for
something? If I restart iwd, it immediately connects. I get a ton of:
 src/station.c:station_add_seen_bss()
and it even reports my SSID, but it never connects until I reset the
interface or restart iwd.
Feb 07 18:54:17 rune64 iwd[265]: src/scan.c:get_scan_callback()
get_scan_callback
Feb 07 18:54:17 rune64 iwd[265]: src/scan.c:get_scan_done() get_scan_done
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss()
Processing BSS '08:02:8e:94:12:97' with SSID: spg3, freq: 5180, rank:
15209, strength: -5100
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss()
Processing BSS '08:02:8e:94:12:98' with SSID: spg2, freq: 2462, rank: 5631,
strength: -4300
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss()
Processing BSS '10:da:43:a0:f5:a4' with SSID: NETGEAR63, freq: 2462, rank:
3317, strength: -6500
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss()
Processing BSS 'ac:3a:7a:0c:83:0b' with SSID: , freq: 2462, rank: 3009,
strength: -6100
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss() BSS
has hidden SSID
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss()
Processing BSS '24:4b:fe:24:a5:b8' with SSID: Virus, freq: 2412, rank:
2899, strength: -7100
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss()
Processing BSS '6c:19:8f:ce:6f:a2' with SSID: Edventures3, freq: 5785,
rank: 2448, strength: -7300
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss()
Processing BSS '6c:19:8f:ce:6f:a0' with SSID: Edventures, freq: 2412, rank:
2441, strength: -6800
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss()
Processing BSS '40:2b:50:95:61:60' with SSID: ATTXIXISpi, freq: 2412, rank:
2322, strength: -7000
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss()
Processing BSS '84:bb:69:71:19:30' with SSID: ElJefe, freq: 2437, rank:
2102, strength: -7200
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss()
Processing BSS 'a0:04:60:6c:4d:40' with SSID: HouseStark01, freq: 2442,
rank: 1571, strength: -8200
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss()
Processing BSS '06:93:97:4e:01:43' with SSID: ATTxZIQ4wa, freq: 5805, rank:
936, strength: -8700
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss()
Processing BSS '7e:ac:b9:55:92:a9' with SSID: , freq: 5745, rank: 792,
strength: -8900
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss() BSS
has hidden SSID
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss()
Processing BSS '04:d9:f5:bb:b4:58' with SSID: HANNA, freq: 2427, rank:
1941, strength: -7800
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss()
Processing BSS '06:93:97:09:ca:93' with SSID: ATTeHeTKI2, freq: 5765, rank:
1036, strength: -8800
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss()
Processing BSS '74:ac:b9:55:92:a9' with SSID: Loading..., freq: 5745, rank:
936, strength: -8700
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss()
Processing BSS '94:e3:6d:6a:96:aa' with SSID: Chime-6a96aa, freq: 2412,
rank: 270, strength: -8200
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss()
Processing BSS '10:93:97:4e:01:40' with SSID: ATTxZIQ4wa, freq: 2412, rank:
1858, strength: -7500
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss()
Processing BSS '10:da:43:a0:f5:a5' with SSID: NETGEAR63-5G, freq: 5765,
rank: 1577, strength: -8200
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss()
Processing BSS 'f4:c1:14:b2:4d:8e' with SSID: BidenHarris, freq: 5240,
rank: 1296, strength: -8500
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss()
Processing BSS 'f6:c1:14:ba:4d:8b' with SSID: , freq: 5240, rank: 1296,
strength: -8500
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss() BSS
has hidden SSID
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss()
Processing BSS 'f6:c1:14:ba:4d:89' with SSID: , freq: 5240, rank: 1296,
strength: -8500
Feb 07 18:54:17 rune64 iwd[265]: src/station.c:station_add_seen_bss() BSS
has hidden SSID
Feb 07 18:54:17 rune64 iwd[265]: src/wiphy.c:wiphy_radio_work_insert()
Inserting work item 19
Feb 07 18:54:17 rune64 iwd[265]: src/wiphy.c:wiphy_radio_work_done() Work
item 18 done
Feb 07 18:54:17 rune64 iwd[265]: src/wiphy.c:wiphy_radio_work_next()
Starting work item 19
Feb 07 18:54:17 rune64 iwd[265]: src/scan.c:scan_notify() Scan notification
Trigger Scan(33)
Feb 07 18:54:17 rune64 iwd[265]: src/scan.c:scan_request_triggered()
Passive scan triggered for wdev 1
Feb 07 18:54:17 rune64 iwd[265]:
src/station.c:station_dbus_scan_triggered() station_scan_triggered: 0
Feb 07 18:54:17 rune64 iwd[265]:
src/station.c:station_dbus_scan_triggered() Scan triggered for wlan0 subset
1
Feb 07 18:54:21 rune64 iwd[265]: src/scan.c:scan_notify() Scan notification
New Scan Results(34)
Feb 07 18:54:21 rune64 iwd[265]: src/scan.c:get_scan_callback()
get_scan_callback
Feb 07 18:54:21 rune64 iwd[265]:
src/scan.c:scan_parse_bss_information_elements() Load: 6/255
Feb 07 18:54:21 rune64 iwd[265]: src/scan.c:get_scan_callback()
get_scan_callback
Feb 07 18:54:21 rune64 iwd[265]:
src/scan.c:scan_parse_bss_information_elements() Load: 51/255
Feb 07 18:54:21 rune64 iwd[265]: src/scan.c:get_scan_callback()
get_scan_callback
Feb 07 18:54:21 rune64 iwd[265]:
src/scan.c:scan_parse_bss_information_elements() Load: 41/255
Feb 07 18:54:21 rune64 iwd[265]: src/scan.c:get_scan_callback()
get_scan_callback
Feb 07 18:54:21 rune64 iwd[265]:
src/scan.c:scan_parse_bss_information_elements() Load: 35/255
Feb 07 18:54:21 rune64 iwd[265]: src/scan.c:get_scan_callback()
get_scan_callback
Feb 07 18:54:21 rune64 iwd[265]: src/scan.c:get_scan_callback()
get_scan_callback
Feb 07 18:54:21 rune64 iwd[265]: src/scan.c:get_scan_callback()
get_scan_callback
Feb 07 18:54:21 rune64 iwd[265]:
src/scan.c:scan_parse_bss_information_elements() Load: 67/255
Feb 07 18:54:21 rune64 iwd[265]: src/scan.c:get_scan_callback()
get_scan_callback
Feb 07 18:54:21 rune64 iwd[265]:
src/scan.c:scan_parse_bss_information_elements() Load: 157/255
Feb 07 18:54:21 rune64 iwd[265]: src/scan.c:get_scan_callback()
get_scan_callback
Feb 07 18:54:21 rune64 iwd[265]:
src/scan.c:scan_parse_bss_information_elements() Load: 34/255
Feb 07 18:54:21 rune64 iwd[265]: src/scan.c:get_scan_callback()
get_scan_callback
Feb 07 18:54:21 rune64 iwd[265]: src/scan.c:get_scan_callback()
get_scan_callback
Feb 07 18:54:21 rune64 iwd[265]:
src/scan.c:scan_parse_bss_information_elements() Load: 65/255
Feb 07 18:54:21 rune64 iwd[265]: src/scan.c:get_scan_callback()
get_scan_callback
Feb 07 18:54:21 rune64 iwd[265]: src/scan.c:get_scan_callback()
get_scan_callback
Feb 07 18:54:21 rune64 iwd[265]: src/scan.c:get_scan_callback()
get_scan_callback
Feb 07 18:54:21 rune64 iwd[265]:
src/scan.c:scan_parse_bss_information_elements() Load: 102/255
Feb 07 18:54:21 rune64 iwd[265]: src/scan.c:get_scan_callback()
get_scan_callback
Feb 07 18:54:21 rune64 iwd[265]:
src/scan.c:scan_parse_bss_information_elements() Load: 28/255
Feb 07 18:54:21 rune64 iwd[265]: src/scan.c:get_scan_callback()
get_scan_callback
Feb 07 18:54:21 rune64 iwd[265]:
src/scan.c:scan_parse_bss_information_elements() Load: 31/255
Feb 07 18:54:21 rune64 iwd[265]: src/scan.c:get_scan_callback()
get_scan_callback
Feb 07 18:54:21 rune64 iwd[265]:
src/scan.c:scan_parse_bss_information_elements() Load: 31/255
Feb 07 18:54:21 rune64 iwd[265]: src/scan.c:get_scan_callback()
get_scan_callback
Feb 07 18:54:21 rune64 iwd[265]:
src/scan.c:scan_parse_bss_information_elements() Load: 31/255
Feb 07 18:54:21 rune64 iwd[265]:
src/scan.c:scan_parse_advertisement_protocol()
Feb 07 18:54:21 rune64 iwd[265]: src/scan.c:get_scan_callback()
get_scan_callback
Feb 07 18:54:21 rune64 iwd[265]:
src/scan.c:scan_parse_bss_information_elements() Load: 31/255
Feb 07 18:54:21 rune64 iwd[265]: src/scan.c:get_scan_callback()
get_scan_callback
Feb 07 18:54:21 rune64 iwd[265]:
src/scan.c:scan_parse_bss_information_elements() Load: 11/255
Feb 07 18:54:21 rune64 iwd[265]: src/scan.c:get_scan_callback()
get_scan_callback
Feb 07 18:54:21 rune64 iwd[265]:
src/scan.c:scan_parse_bss_information_elements() Load: 11/255
Feb 07 18:54:21 rune64 iwd[265]: src/scan.c:get_scan_done() get_scan_done

It just repeats this over and over again until I either reset the interface
or restart either connman or iwd. How can I help to debug this? Is it a
kernel issue? What is the trigger that is supposed to get an external
process to negotiate the interface connection?

Keith

[-- Attachment #2: attachment.htm --]
[-- Type: text/html, Size: 15189 bytes --]

Re: Reconnect issues, still

[Denis Kenzior]

[-- Attachment #1: Type: text/plain, Size: 2072 bytes --]

Hi Keith,

On 2/7/21 10:39 PM, KeithG wrote:
> The group at connman has re-written connman and it now leverages the background 
> scanning in iwd as it allows the setting of 'AutoConnect=true' now. That 
> definitely helps, but I am still struggling to get the RPIs to effortlessly 
> reconnect. As it is, I have to manipulate the interface to force a reconnect (if 
> down/up) by running a script to check if the interface is up or down.
> 
> For whatever reason, a reconnect is never tried unless we restart the iwd or 
> connman process or restart the interface. What I see is my android devices 
> reconnect in < 1 minute if I force a disconnect from the router or restart the 
> radio or reboot. I am running the latest git of iwd (r5144.074bc52). I force 
> disconnect from the router at 18:32. Then I wait. spg3 is my SSID. It scans and 
> 'sees' it but never initiates or tries a re-connect. If I do this with my phone 
> (Android 10), it is reconnected in less than 2 minutes. If I let iwd control it, 

If iwd reconnects properly, I'm not sure why you're asking this question here 
and not on the connman mailing list?

> it reconnects in < 2 minutes as well. Is there something that connman is waiting 
> for to let connman know it is ready?

Not really.  Once iwd 'sees' it, connman should as well.  Run monitor-iwd script 
from iwd.git/test to see all the communication going over d-bus.  Alternatively 
you can run dbus-monitor, but that is harder to parse.

> If I try the same thing with connman controlling it, it 'sees' the SSID, but 
> never triggers connman to reconnect. Should connman be looking for something? If 
> I restart iwd, it immediately connects. I get a ton of:

To me, it looks like scanning is being driven over D-Bus by invoking 
Station.Scan().  It also looks like autoconnect has been forced off, perhaps via 
Station.Disconnect() being invoked?  Hard to tell from this log, but looks iwd 
isn't trying to autoconnect and would instead rely on connman to trigger the 
connection.

Regards,
-Denis

Re: Reconnect issues, still

[KeithG]

[-- Attachment #1: Type: text/plain, Size: 980 bytes --]

On Mon, Feb 8, 2021 at 1:53 PM Denis Kenzior <denkenz@gmail.com> wrote:

>
> To me, it looks like scanning is being driven over D-Bus by invoking
> Station.Scan().  It also looks like autoconnect has been forced off,
> perhaps via
> Station.Disconnect() being invoked?  Hard to tell from this log, but looks
> iwd
> isn't trying to autoconnect and would instead rely on connman to trigger
> the
> connection.
>
> Regards,
> -Denis
>
Denis,

The /var/lib/iwd/*.psk file has "AutoConnect=true" set. I did notice that
last night it had been reset somehow to false after I sent those partial
logs, but I reset it to true today and still do not get a reconnect.

Running the dbus-monitor script shows exactly that. it gets a
{Station} [/net/connman/iwd/0/3] Scanning = True
then False periodically, but it never connects. I'll post again on connman
mail list to see what may need to be adjusted.

If I restart iwd, it connects right away.

Regards,
Keith

[-- Attachment #2: attachment.htm --]
[-- Type: text/html, Size: 1399 bytes --]

Re: Reconnect issues, still

[KeithG]

[-- Attachment #1: Type: text/plain, Size: 4181 bytes --]

Denis,

I see a similar result, though the mechanism may be different, on an x86
laptop also running Arch Linux. I use iwd with NetworkManager on this
computer and if I do the same thing (restart radio on router), it also does
not reconnect. NM is 1.28.1dev+7+g3f5df3cdc6 and iwd is v1.11. If it is
force disconnected from the router it never tries to reconnect. If I select
it from the drop down, it reconnects.

I noticed that NM did not set 'AutoConnect=true' in the
/var/lib/iwd/spg3.psk file, so I added it and verified that iwctl reports
that this feature is set (It did not before), but even after this was
added, it does not reconnect when it is forced off the network by
rebooting, disconnecting or cycling the radio.

The iwd-monitor log shows lots of this:
{Station} [/net/connman/iwd/0/4] Scanning = False
{Station} [/net/connman/iwd/0/4] Scanning = True
{Station} [/net/connman/iwd/0/4] Scanning = False
{Station} [/net/connman/iwd/0/4] Scanning = True
{Removed net.connman.iwd.Network}
[/net/connman/iwd/0/4/426964656e486172726973_psk]
{Added net.connman.iwd.Network}
[/net/connman/iwd/0/4/4e4554474541523336_psk]
      Name = NETGEAR36
      Connected = False
      Device = /net/connman/iwd/0/4
      Type = psk
{Station} [/net/connman/iwd/0/4] Scanning = False
{Station} [/net/connman/iwd/0/4] Scanning = True
{Added net.connman.iwd.Network}
[/net/connman/iwd/0/4/415454687a4366547869_psk]
      Name = ATThzCfTxi
      Connected = False
      Device = /net/connman/iwd/0/4
      Type = psk
{Added net.connman.iwd.Network} [/net/connman/iwd/0/4/5261676e6172_psk]
      Name = Ragnar
      Connected = False
      Device = /net/connman/iwd/0/4
      Type = psk
{Removed net.connman.iwd.Network}
[/net/connman/iwd/0/4/4d65617374657761_psk]
{Removed net.connman.iwd.Network}
[/net/connman/iwd/0/4/41545470666b766e4378_psk]
{Added net.connman.iwd.Network}
[/net/connman/iwd/0/4/4e4554474541523539_psk]
      Name = NETGEAR59
      Connected = False
      Device = /net/connman/iwd/0/4
      Type = psk
{Station} [/net/connman/iwd/0/4] Scanning = False
...

Interestingly, none of the logs I made actually showed that iwd had scanned
and found the network that it was just previously connected to in the list
of Network Names. While scanning, it sees the 2.5 network on the same
router, but not the 5Ghz that it knows the password to. If I do a 'iwctl
wlan0 get-networks', the 5Ghz radio is at the top of the list but it does
not connect to it. As soon as I select it in the drop down in NM it
connects.

My questions: With NM, is it supposed to have an 'AutoConnect=true' in the
psk file? If so, it does not appear that NM creates that in the psk file.
Why does the scan not pick up the previously connected SSID?

I just tried this again on the RPi and now, today, it reconnects when I
force a disconnect. I have no idea what changed. It absolutely did not
yesterday or the day before. I did  not even reboot the Pi. It also scanned
but never saw the SSID I was intending to use.

Regards,

Keith

On Mon, Feb 8, 2021 at 3:32 PM KeithG <ys3al35l@gmail.com> wrote:

> On Mon, Feb 8, 2021 at 1:53 PM Denis Kenzior <denkenz@gmail.com> wrote:
>
>>
>> To me, it looks like scanning is being driven over D-Bus by invoking
>> Station.Scan().  It also looks like autoconnect has been forced off,
>> perhaps via
>> Station.Disconnect() being invoked?  Hard to tell from this log, but
>> looks iwd
>> isn't trying to autoconnect and would instead rely on connman to trigger
>> the
>> connection.
>>
>> Regards,
>> -Denis
>>
> Denis,
>
> The /var/lib/iwd/*.psk file has "AutoConnect=true" set. I did notice that
> last night it had been reset somehow to false after I sent those partial
> logs, but I reset it to true today and still do not get a reconnect.
>
> Running the dbus-monitor script shows exactly that. it gets a
> {Station} [/net/connman/iwd/0/3] Scanning = True
> then False periodically, but it never connects. I'll post again on connman
> mail list to see what may need to be adjusted.
>
> If I restart iwd, it connects right away.
>
> Regards,
> Keith
>

[-- Attachment #2: attachment.htm --]
[-- Type: text/html, Size: 5194 bytes --]

Re: Reconnect issues, still

[Andrew Zaborowski]

[-- Attachment #1: Type: text/plain, Size: 3772 bytes --]

Hi Keith,

On Wed, 10 Feb 2021 at 00:11, KeithG <ys3al35l@gmail.com> wrote:
> I see a similar result, though the mechanism may be different, on an x86 laptop also running Arch Linux. I use iwd with NetworkManager on this computer and if I do the same thing (restart radio on router), it also does not reconnect. NM is 1.28.1dev+7+g3f5df3cdc6 and iwd is v1.11. If it is force disconnected from the router it never tries to reconnect. If I select it from the drop down, it reconnects.
>
> I noticed that NM did not set 'AutoConnect=true' in the /var/lib/iwd/spg3.psk file, so I added it and verified that iwctl reports that this feature is set (It did not before), but even after this was added, it does not reconnect when it is forced off the network by rebooting, disconnecting or cycling the radio.
>
> The iwd-monitor log shows lots of this:
> {Station} [/net/connman/iwd/0/4] Scanning = False
> {Station} [/net/connman/iwd/0/4] Scanning = True
> {Station} [/net/connman/iwd/0/4] Scanning = False
> {Station} [/net/connman/iwd/0/4] Scanning = True
> {Removed net.connman.iwd.Network} [/net/connman/iwd/0/4/426964656e486172726973_psk]
> {Added net.connman.iwd.Network} [/net/connman/iwd/0/4/4e4554474541523336_psk]
>       Name = NETGEAR36
>       Connected = False
>       Device = /net/connman/iwd/0/4
>       Type = psk
> {Station} [/net/connman/iwd/0/4] Scanning = False
> {Station} [/net/connman/iwd/0/4] Scanning = True
> {Added net.connman.iwd.Network} [/net/connman/iwd/0/4/415454687a4366547869_psk]
>       Name = ATThzCfTxi
>       Connected = False
>       Device = /net/connman/iwd/0/4
>       Type = psk
> {Added net.connman.iwd.Network} [/net/connman/iwd/0/4/5261676e6172_psk]
>       Name = Ragnar
>       Connected = False
>       Device = /net/connman/iwd/0/4
>       Type = psk
> {Removed net.connman.iwd.Network} [/net/connman/iwd/0/4/4d65617374657761_psk]
> {Removed net.connman.iwd.Network} [/net/connman/iwd/0/4/41545470666b766e4378_psk]
> {Added net.connman.iwd.Network} [/net/connman/iwd/0/4/4e4554474541523539_psk]
>       Name = NETGEAR59
>       Connected = False
>       Device = /net/connman/iwd/0/4
>       Type = psk
> {Station} [/net/connman/iwd/0/4] Scanning = False
> ...
>
> Interestingly, none of the logs I made actually showed that iwd had scanned and found the network that it was just previously connected to in the list of Network Names. While scanning, it sees the 2.5 network on the same router, but not the 5Ghz that it knows the password to. If I do a 'iwctl wlan0 get-networks', the 5Ghz radio is at the top of the list but it does not connect to it. As soon as I select it in the drop down in NM it connects.
>
> My questions: With NM, is it supposed to have an 'AutoConnect=true' in the psk file? If so, it does not appear that NM creates that in the psk file. Why does the scan not pick up the previously connected SSID?

A few data points:

* With NM 1.28 NM's own autoconnect mechanism is used, it doesn't
depend on IWD.  Starting with 1.30 IWD will control autoconnect by
default (can be turned off).  NM profies have their own "autoconnect"
property which also defaults to true.

* AutoConnect defaults to true so adding an AutoConnect=true to the
.psk file shouldn't have any effect.

* So far only IWD writes the .psk files, it does this the first time
NM commands IWD to connect to a specific network.

* I've seen different quirks with NM autoconnect that I don't fully
understand, but generally it works.  It seemed that network profiles
created by some previous NM versions on my distro had the owner,
permissions and/or local hardware MAC set in a way that prevented them
from ever autoactivating but they could be activated manually.

Best regards