Arch Linux

arbitarycounterfactual

Member

Registered: 2024-07-17

Posts: 20

NetworkManager-dispatcher being deactivated on startup with systemctl

I'm trying to enforce automatic backup with rsync using NetworkManager (following the wiki). I've never heard of running user scripts by a NetworkManager event. To understand how it runs the scripts, I've added a minimal "hello world" script in /etc/NetworkManager/dispatcher.d/10-script.sh. (the file is owned by root and is an executable)

echo $@ | tee /tmp/10-script 

NetworkManager-dispatcher is refusing to start.

$ journalctl -u NetworkManager-dispatcher -b 2
May 30 04:04:18 patxio systemd[1]: Starting Network Manager Script Dispatcher Service...
May 30 04:04:18 patxio systemd[1]: Started Network Manager Script Dispatcher Service.
May 30 04:04:28 patxio systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
May 30 04:04:34 patxio systemd[1]: Starting Network Manager Script Dispatcher Service...
May 30 04:04:34 patxio systemd[1]: Started Network Manager Script Dispatcher Service.
May 30 04:04:44 patxio systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
May 30 05:38:21 patxio systemd[1]: Starting Network Manager Script Dispatcher Service...
May 30 05:38:21 patxio systemd[1]: Started Network Manager Script Dispatcher Service.
May 30 05:38:31 patxio systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
May 30 05:38:40 patxio systemd[1]: Starting Network Manager Script Dispatcher Service...
May 30 05:38:40 patxio systemd[1]: Started Network Manager Script Dispatcher Service.
May 30 05:38:50 patxio systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
May 30 05:47:18 patxio systemd[1]: Starting Network Manager Script Dispatcher Service...
May 30 05:47:18 patxio systemd[1]: Started Network Manager Script Dispatcher Service.
May 30 05:47:28 patxio systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
May 30 05:47:33 patxio systemd[1]: Starting Network Manager Script Dispatcher Service...
May 30 05:47:33 patxio systemd[1]: Started Network Manager Script Dispatcher Service.
May 30 05:47:43 patxio systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
May 30 05:54:35 patxio systemd[1]: Starting Network Manager Script Dispatcher Service...
May 30 05:54:35 patxio systemd[1]: Started Network Manager Script Dispatcher Service.
May 30 05:54:45 patxio systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
May 30 05:54:46 patxio systemd[1]: Starting Network Manager Script Dispatcher Service...
May 30 05:54:46 patxio systemd[1]: Started Network Manager Script Dispatcher Service.
May 30 05:54:56 patxio systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
May 30 06:20:50 patxio systemd[1]: Starting Network Manager Script Dispatcher Service...
May 30 06:20:50 patxio systemd[1]: Started Network Manager Script Dispatcher Service.
May 30 07:24:50 patxio systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
May 30 08:44:36 patxio systemd[1]: Starting Network Manager Script Dispatcher Service...
May 30 08:44:36 patxio systemd[1]: Started Network Manager Script Dispatcher Service.
May 30 10:47:11 patxio systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
May 30 10:53:01 patxio systemd[1]: Starting Network Manager Script Dispatcher Service...
May 30 10:53:01 patxio systemd[1]: Started Network Manager Script Dispatcher Service.
May 30 10:53:11 patxio systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
May 30 10:53:50 patxio systemd[1]: Starting Network Manager Script Dispatcher Service...
May 30 10:53:50 patxio systemd[1]: Started Network Manager Script Dispatcher Service.
May 30 10:54:00 patxio systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
May 30 10:55:33 patxio systemd[1]: Starting Network Manager Script Dispatcher Service...
May 30 10:55:33 patxio systemd[1]: Started Network Manager Script Dispatcher Service.
May 30 10:55:43 patxio systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
May 30 10:55:44 patxio systemd[1]: Starting Network Manager Script Dispatcher Service...
May 30 10:55:44 patxio systemd[1]: Started Network Manager Script Dispatcher Service.
May 30 10:55:54 patxio systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.

What is going on?

cryptearth

Member

Registered: 2024-02-03

Posts: 1,024

Re: NetworkManager-dispatcher being deactivated on startup with systemctl

have you checked the output with

systemctl status NetworkManager

?

arbitarycounterfactual

Member

Registered: 2024-07-17

Posts: 20

Re: NetworkManager-dispatcher being deactivated on startup with systemctl

● NetworkManager.service - Network Manager
     Loaded: loaded (/usr/lib/systemd/system/NetworkManager.service; enabled; preset: disabled)
     Active: active (running) since Tue 2024-10-15 22:14:31 IST; 45min ago
 Invocation: 1037bdc2a2e3406c9015069016e0b61d
       Docs: man:NetworkManager(8)
   Main PID: 663 (NetworkManager)
      Tasks: 4 (limit: 18715)
     Memory: 15M (peak: 16.4M)
        CPU: 528ms
     CGroup: /system.slice/NetworkManager.service
             └─663 /usr/bin/NetworkManager --no-daemon

Oct 15 22:50:49 patxio NetworkManager[663]: <info>  [1729012849.6204] dhcp4 (wlan0): state changed new lease, address=192.168.1.10
Oct 15 22:50:49 patxio NetworkManager[663]: <info>  [1729012849.6213] policy: set 'Airtel_Nigger' (wlan0) as default for IPv4 routing and DNS
Oct 15 22:50:49 patxio NetworkManager[663]: <info>  [1729012849.6349] device (wlan0): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
Oct 15 22:50:49 patxio NetworkManager[663]: <info>  [1729012849.6386] device (wlan0): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
Oct 15 22:50:49 patxio NetworkManager[663]: <info>  [1729012849.6388] device (wlan0): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
Oct 15 22:50:49 patxio NetworkManager[663]: <info>  [1729012849.6391] manager: NetworkManager state is now CONNECTED_SITE
Oct 15 22:50:49 patxio NetworkManager[663]: <info>  [1729012849.6405] device (wlan0): Activation: successful, device activated.
Oct 15 22:50:50 patxio NetworkManager[663]: <info>  [1729012850.1383] manager: NetworkManager state is now CONNECTED_GLOBAL
Oct 15 22:50:51 patxio NetworkManager[663]: <info>  [1729012851.1891] dhcp6 (wlan0): activation: beginning transaction (timeout in 45 seconds)
Oct 15 22:50:51 patxio NetworkManager[663]: <info>  [1729012851.1906] policy: set 'Airtel_Nigger' (wlan0) as default for IPv6 routing and DNS

There's nothing relevant I could find in the current session from boot but

$journalctl -u NetworkManager -b 2 | grep dispatcher
  
May 30 11:13:31 patxio NetworkManager[640]: <warn>  [1717047811.1967] dispatcher: (56) failed (after 0.003 sec): Could not activate remote peer 'org.freedesktop.nm_dispatcher': activation request failed: unit is invalid

Although this is from months ago. And there's nothing related to nm-dispatcher in -b1 or -b0

Last edited by arbitarycounterfactual (2024-10-15 17:42:05)

cryptearth

Member

Registered: 2024-02-03

Posts: 1,024

Re: NetworkManager-dispatcher being deactivated on startup with systemctl

2nd previous boot was back in may?

arbitarycounterfactual

Member

Registered: 2024-07-17

Posts: 20

Re: NetworkManager-dispatcher being deactivated on startup with systemctl

Oops, positive offsets are in chronological order. Negative offsets actually represent journals from previous boot. so journalctl -u NetworkManager  -b -1  | grep -C3 dispatcher

Oct 15 23:16:22 patxio NetworkManager[663]: <info>  [1729014382.1251] dhcp6 (wlan0): activation: beginning transaction (timeout in 45 seconds)
Oct 15 23:16:22 patxio NetworkManager[663]: <info>  [1729014382.1251] dhcp6 (wlan0): state changed no lease
Oct 15 23:16:22 patxio NetworkManager[663]: <info>  [1729014382.1256] manager: NetworkManager state is now DISCONNECTING
Oct 15 23:16:22 patxio NetworkManager[663]: <warn>  [1729014382.1302] dispatcher: (23) failed (after 0.004 sec): Could not activate remote peer 'org.freedesktop.nm_dispatcher': activation request failed: unit is invalid
Oct 15 23:16:22 patxio NetworkManager[663]: <info>  [1729014382.1306] device (wlan0): state change: deactivating -> unmanaged (reason 'unmanaged-quitting', sys-iface-state: 'managed')
Oct 15 23:16:22 patxio NetworkManager[663]: <info>  [1729014382.2946] manager: NetworkManager state is now DISCONNECTED
Oct 15 23:16:22 patxio NetworkManager[663]: <info>  [1729014382.2965] device (p2p-dev-wlan0): state change: disconnected -> unmanaged (reason 'unmanaged-link-not-init', sys-iface-state: 'removed')

Is the warning normal? Does it suggest something that has to do with nm-dispatcher deactivating after being started with systemctl?

Last edited by arbitarycounterfactual (2024-10-15 18:38:44)

cryptearth

Member

Registered: 2024-02-03

Posts: 1,024

Re: NetworkManager-dispatcher being deactivated on startup with systemctl

as by https://bbs.archlinux.org/viewtopic.php … 9#p2176079 please post your script
does it start with a shebang?

arbitarycounterfactual

Member

Registered: 2024-07-17

Posts: 20

Re: NetworkManager-dispatcher being deactivated on startup with systemctl

Apologies for getting back to this so late. It's getting harder to maintain my system as my health declines .

does it start with a shebang?

A complete dump of the minimal script:
/etc/NetworkManager/dispatcher.d/10-scirpt.sh

#!/bin/bash
echo $@ > "/home/aissy/dispatcher"

-rwxr-xr-x 1 root root 48 Oct 15 21:53 /etc/NetworkManager/dispatcher.d/10-scirpt.sh

journalctl -u NetworkManager-dispatcher -b  and systemctl status NetworkManager-dispatcher both report the same deactivation status, that is systemd is refusing to start the unit (after few seconds from being started, it enters the "deactivated successfully" status).

The nm-dispatcher unit was enabled since my very first boot (back in 2022) and eyeing on the journal at the very first boot, it's apparent that the same behavior was present.

May 30 11:13:53 patxio systemd[1]: Starting Network Manager Script Dispatcher Service...
May 30 11:13:53 patxio systemd[1]: Started Network Manager Script Dispatcher Service.
May 30 11:14:03 patxio systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
May 30 11:23:01 patxio systemd[1]: Starting Network Manager Script Dispatcher Service...
May 30 11:23:01 patxio systemd[1]: Started Network Manager Script Dispatcher Service.
May 30 11:23:11 patxio systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
May 30 11:55:56 patxio systemd[1]: Starting Network Manager Script Dispatcher Service...
May 30 11:55:56 patxio systemd[1]: Started Network Manager Script Dispatcher Service.
May 31 19:46:12 patxio systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
May 31 19:46:52 patxio systemd[1]: Starting Network Manager Script Dispatcher Service...
May 31 19:46:52 patxio systemd[1]: Started Network Manager Script Dispatcher Service.
May 31 19:47:02 patxio systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
May 31 19:47:31 patxio systemd[1]: Starting Network Manager Script Dispatcher Service...
May 31 19:47:31 patxio systemd[1]: Started Network Manager Script Dispatcher Service.
May 31 19:47:41 patxio systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
May 31 19:50:53 patxio systemd[1]: Starting Network Manager Script Dispatcher Service...
May 31 19:50:53 patxio systemd[1]: Started Network Manager Script Dispatcher Service.
May 31 19:51:03 patxio systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
May 31 19:56:27 patxio systemd[1]: Starting Network Manager Script Dispatcher Service...
May 31 19:56:27 patxio systemd[1]: Started Network Manager Script Dispatcher Service.
May 31 19:56:37 patxio systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
May 31 19:59:51 patxio systemd[1]: Starting Network Manager Script Dispatcher Service...
May 31 19:59:51 patxio systemd[1]: Started Network Manager Script Dispatcher Service.
May 31 23:29:32 patxio systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.
May 31 23:51:53 patxio systemd[1]: Starting Network Manager Script Dispatcher Service...
May 31 23:51:53 patxio systemd[1]: Started Network Manager Script Dispatcher Service.
May 31 23:53:37 patxio systemd[1]: NetworkManager-dispatcher.service: Deactivated successfully.

Looking at journals for NM and filtering output by nm-dispatcher ends with this persistent Could not activate remote peer 'org.freedesktop.nm_dispatcher': activation request failed: unit is invalid warning in very boot.

Again the script is just dumping cmd line arguments in $@ in a file, so just to wrap my head around how it works. The script is never executed by NM which I suspect the cause to be NM-dispatcher never "starting" in the first place (or something is inhibiting it from being started). I can't figure out what exactly is that which is responsible for these few set of errors.