GNU bug report logs - #60300
Premature networking started status with NetworkManager

Previous Next

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 60300 in the body.
You can then email your comments to 60300 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

Message #5 received at submit <at> debbugs.gnu.org (full text, mbox):

From: mirai <mirai <at> makinata.eu>
To: bug-guix <bug-guix <at> gnu.org>
Subject: Premature networking started status with NetworkManager
Date: Sat, 24 Dec 2022 16:23:09 +0000

If a service has a requirement on 'networking
(either from accepting a shepherd-requirements field from its configuration record-type or
from the service-type definition) and networking is provided by NetworkManager, it will not
work as intended. This is because networking is prematurely flagged as started before
NetworkManager can finish its startup.

Some of the visible consequences resulting from this is service startup failure
for OpenSMTPD when it's configured with a non-loopback interface and has a dependency on 'networking
placed using shepherd-requirement field.
A similar situation happens with nginx, failure to start the service or ignored directives that
want to resolve domains over DNS.

These failures do not happen if one creates a one-shot simple-service that puts a dependency on networking
and simply waits approx. 10-30 seconds and have nginx-service-type or opensmptd-service-type depend on it
instead.

From /var/log/messages (truncated to relevant parts):

--8<---------------cut here---------------start------------->8---
Dec 21 22:19:01 localhost shepherd[1]: Service networking has been started. 
Dec 21 22:19:01 localhost NetworkManager[473]: <info>  [1671661141.6330] NetworkManager (version 1.41.2) is starting... (asserts:100, boot:502a84f9-92cc-47a9-a86c-97ec819fb23a)
Dec 21 22:19:01 localhost NetworkManager[473]: <info>  [1671661141.6331] Read config: /gnu/store/3cp48fvxfivj2255bbxj7363qj33ajs9-NetworkManager.conf
Dec 21 22:19:01 localhost NetworkManager[473]: <info>  [1671661141.6340] bus-manager: acquired D-Bus service "org.freedesktop.NetworkManager"
Dec 21 22:19:01 localhost NetworkManager[473]: <info>  [1671661141.6353] manager[0xc85080]: monitoring kernel firmware directory '/lib/firmware'.
Dec 21 22:19:01 localhost NetworkManager[473]: <info>  [1671661141.6357] hostname: hostname: couldn't get property from hostnamed
Dec 21 22:19:01 localhost NetworkManager[473]: <info>  [1671661141.6358] hostname: static hostname changed from (none) to "doll"
Dec 21 22:19:01 localhost NetworkManager[473]: <info>  [1671661141.6363] dns-mgr: init: dns=default,systemd-resolved rc-manager=resolvconf (auto)
Dec 21 22:19:01 localhost NetworkManager[473]: <info>  [1671661141.6365] manager[0xc85080]: rfkill: Wi-Fi hardware radio set enabled
Dec 21 22:19:01 localhost NetworkManager[473]: <info>  [1671661141.6365] manager[0xc85080]: rfkill: WWAN hardware radio set enabled
[...]
Dec 21 22:19:30 localhost shepherd[1]: Service nscd has been started. 
Dec 21 22:19:30 localhost shepherd[1]: [NetworkManager] Service nscd has been stopped. 
Dec 21 22:19:30 localhost shepherd[1]: [NetworkManager] Service nscd has been started. 
Dec 21 22:19:30 localhost dbus-daemon[470]: [system] Activating service name='org.freedesktop.nm_dispatcher' requested by ':1.1' (uid=0 pid=473 comm="/gnu/store/ghf1miwbxfcz33mx9bccllgf257vvfhp-networ") (using servicehelper)
Dec 21 22:19:30 localhost NetworkManager[473]: <info>  [1671661170.2951] device (enp4s0): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Dec 21 22:19:30 localhost dbus-daemon[470]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Dec 21 22:19:30 localhost NetworkManager[473]: <info>  [1671661170.2995] device (enp4s0): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
Dec 21 22:19:30 localhost NetworkManager[473]: <info>  [1671661170.2996] device (enp4s0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
Dec 21 22:19:30 localhost NetworkManager[473]: <info>  [1671661170.2998] manager: NetworkManager state is now CONNECTED_SITE
Dec 21 22:19:30 localhost NetworkManager[473]: <info>  [1671661170.2999] device (enp4s0): Activation: successful, device activated.
Dec 21 22:19:30 localhost NetworkManager[473]: <info>  [1671661170.3001] manager: NetworkManager state is now CONNECTED_GLOBAL
Dec 21 22:19:30 localhost NetworkManager[473]: <info>  [1671661170.3003] manager: startup complete
--8<---------------cut here---------------end--------------->8---


It's apparent that 'networking should be flagged started only after NetworkManager logs "startup complete".

Message #8 received at 60300 <at> debbugs.gnu.org (full text, mbox):

From: mirai <mirai <at> makinata.eu>
To: 60300 <at> debbugs.gnu.org
Subject: Re: bug#60300: (Premature networking started status with
 NetworkManager)
Date: Tue, 27 Dec 2022 16:24:39 +0000

Looking into NetworkManager documentation, it looks like the 'networking service
provided by Guix does not implement the NetworkManager's systemd equivalent. [1]

Namely, NetworkManager has some specific steps until it can be considered up and running/"startup complete". [1]
This process seems mostly dependent on nm-online to query the actual NetworkManager state. [2]

[1]: https://networkmanager.dev/docs/api/latest/NetworkManager-wait-online.service.html
[2]: https://networkmanager.dev/docs/api/latest/nm-online.html

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.