[Networkmanager] Does "startup complete" imply connection activation?

[Thomas Haller]

Hi,

On Wed, Apr 26, 2023 at 1:44 PM Andrei Borzenkov <arvidjaar at gmail.com> wrote:
>
> Yes, I know the nm-online manual :)

`nm-online` is only an implementation detail of
NetworkManager-wait-online.service. It's not very relevant to consider
directly.
More relevant is `man NetworkManager-wait-online.service`

> I recently helped in troubleshooting startup issues and was rather
> surprised that NetworkManager reports "startup complete" before it
> starts activating any connection.
>
> Full log is here:
>
> https://paste.opensuse.org/pastes/840930d8954d

This contains no debug logs. See the DEBUGGING section in `man NetworkManager`.

Presumably, after the first Wi-Fi scan completed, the Wi-Fi network
was not yet in range and startup-complete was declared. Shortly after,
the network appeared in the scan result and autoconnect happened. The
scan result comes from wpa_supplicant. Probably debug logs from
supplicant would also be a good idea.

> Apr 25 20:37:07 smolevo NetworkManager[1079]: <info>
> [1682451427.6067] NetworkManager (version 1.32.12) is starting... (for
> the first time)
> ...
> Apr 25 20:37:08 smolevo NetworkManager[1079]: <info>
> [1682451428.3381] manager: (p2p-dev-wlan0): new 802.11 Wi-Fi P2P
> device (/org/freedesktop/NetworkManager/Devices/3)
> Apr 25 20:37:08 smolevo NetworkManager[1079]: <info>
> [1682451428.3384] device (p2p-dev-wlan0): state change: unmanaged ->
> unavailable (reason 'managed', sys-iface-state: 'external')
> Apr 25 20:37:08 smolevo NetworkManager[1079]: <info>
> [1682451428.3390] device (wlan0): state change: unavailable ->
> disconnected (reason 'supplicant-available', sys-iface-state:
> 'managed')
> Apr 25 20:37:08 smolevo NetworkManager[1079]: <info>
> [1682451428.3423] device (p2p-dev-wlan0): state change: unavailable ->
> disconnected (reason 'none', sys-iface-state: 'managed')
> Apr 25 20:37:11 smolevo NetworkManager[1079]: <info>
> [1682451431.7623] manager: startup complete
> Apr 25 20:37:12 smolevo NetworkManager[1079]: <info>
> [1682451432.7434] policy: auto-activating connection 'wlan0'
> (6dd63429-8bcc-39f2-9f0d-f639a8419cc8)
>
> That is not the first time I see reports that
> NetworkManager-wait-online was not enough. It sounds like it probably
> should not be using "-s" in the first place.

`nm-online`'s `-s` option has only one point, to be called by and
block NetworkManager-wait-online.service. Whatever the problem, not
using "-s" is not the solution. The solution is to understand what
happens and make startup-complete (and in turn `nm-online -s` and
`NetworkManager-wait-online.service`) behave as desired.

Of course, you are welcome to replace
NetworkManager-wait-online.service with a similar systemd service that
is `Before=network-online.service`. Then you can implement whatever
blocking is suitable for your environment, including `nm-online`
without the `-s` option. That then is not NetworkManager-wait-online
and not what NetworkManager currently ships by default.


Thomas