Premature networking started status with NetworkManager

  • Done
  • quality assurance status badge
Details
One participant
  • mirai
Owner
unassigned
Submitted by
mirai
Severity
normal
M
(name . bug-guix)(address . bug-guix@gnu.org)
e5e14d3e-cec8-d55d-ccf7-6708c415ff08@makinata.eu
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):

Toggle snippet (26 lines)
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


It's apparent that 'networking should be flagged started only after NetworkManager logs "startup complete".
M
Re: bug#60300: (Premature networking started status with NetworkManager)
(address . 60300@debbugs.gnu.org)
40f5d929-e64b-dc4e-673b-97ff88ae21ed@makinata.eu
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]

B
B
Bruno Victal wrote on 11 Mar 2023 00:28
control-msg
(name . control)(address . control@debbugs.gnu.org)
e856200f-9f2a-2248-db1f-40fa842f56d8@makinata.eu
close 47253
close 60300

quit

---

Fixed with commit d04955972e42bd85ba6137625e09e9e31de52f72.
?