bug#62409: NetworkManager errors in system log when using shared connection

[Maxim Cournoyer]

Hi,

I have setup a 'share connection with other computers' type of
connection in NetworkManager, via 'sudo -E nm-connection-editor', and it
works, e.g. to allow a device connected to my 2nd Ethernet port to get a
dynamic IP address and have access to the Internet, but, in
/var/log/messages, I see:

--8<---------------cut here---------------start------------->8---

Mar 23 14:27:32 localhost NetworkManager[6477]: <info>  [1679596052.2463] 
policy: auto-activating connection 'shared' 
(668d9954-eac2-30da-8fc0-d986ab01a36c)
Mar 23 14:27:32 localhost NetworkManager[6477]: <info>  [1679596052.2500] 
device (enp4s0): Activation: starting connection 'shared' 
(668d9954-eac2-30da-8fc0-d986ab01a36c)
Mar 23 14:27:32 localhost NetworkManager[6477]: <info>  [1679596052.2504] 
device (enp4s0): state change: disconnected -> prepare (reason 'none', 
sys-iface-state: 'managed')
Mar 23 14:27:32 localhost NetworkManager[6477]: <info>  [1679596052.2512] 
device (enp4s0): state change: prepare -> config (reason 'none', 
sys-iface-state: 'managed')
Mar 23 14:27:32 localhost NetworkManager[6477]: <info>  [1679596052.2604] 
device (enp4s0): state change: config -> ip-config (reason 'none', 
sys-iface-state: 'managed')
Mar 23 14:27:32 localhost NetworkManager[6477]: <error> [1679596052.2739] 
modprobe: '/sbin/modprobe --use-blacklist ip_tables' failed: Failed to execute 
child process “/sbin/modprobe” (No such file or directory)
Mar 23 14:27:32 localhost NetworkManager[6477]: <error> [1679596052.2784] 
modprobe: '/sbin/modprobe --use-blacklist iptable_nat' failed: Failed to 
execute child process “/sbin/modprobe” (No such file or directory)
Mar 23 14:27:32 localhost NetworkManager[6477]: <warn>  [1679596052.2887] 
iptables: command 
/gnu/store/xz1arf5cd7ssck431wmfz5y1kgr5vyir-iptables-1.8.7/sbin/iptables 
failed: Child process exited with code 1
Mar 23 14:27:32 localhost NetworkManager[6477]: <warn>  [1679596052.3429] 
iptables: command 
/gnu/store/xz1arf5cd7ssck431wmfz5y1kgr5vyir-iptables-1.8.7/sbin/iptables 
failed: Child process exited with code 1
Mar 23 14:27:32 localhost NetworkManager[6477]: <warn>  [1679596052.3636] 
iptables: command 
/gnu/store/xz1arf5cd7ssck431wmfz5y1kgr5vyir-iptables-1.8.7/sbin/iptables 
failed: Child process exited with code 1
Mar 23 14:27:32 localhost NetworkManager[6477]: <warn>  [1679596052.5165] 
iptables: command 
/gnu/store/xz1arf5cd7ssck431wmfz5y1kgr5vyir-iptables-1.8.7/sbin/iptables 
failed: Child process exited with code 1
Mar 23 14:27:32 localhost dbus-daemon[407]: [system] Successfully activated 
service 'org.freedesktop.nm_dispatcher'
Mar 23 14:27:32 localhost NetworkManager[6477]: <warn>  [1679596052.5767] 
iptables: command 
/gnu/store/xz1arf5cd7ssck431wmfz5y1kgr5vyir-iptables-1.8.7/sbin/iptables 
failed: Child process exited with code 1
Mar 23 14:27:32 localhost NetworkManager[6477]: <warn>  [1679596052.5817] 
iptables: command 
/gnu/store/xz1arf5cd7ssck431wmfz5y1kgr5vyir-iptables-1.8.7/sbin/iptables 
failed: Child process exited with code 1
Mar 23 14:27:32 localhost NetworkManager[6477]: <info>  [1679596052.6717] 
dnsmasq-manager: starting dnsmasq...
Mar 23 14:27:32 localhost avahi-daemon[6618]: Joining mDNS multicast group on 
interface enp4s0.IPv4 with address 10.42.0.1.
Mar 23 14:27:32 localhost avahi-daemon[6618]: New relevant interface 
enp4s0.IPv4 for mDNS.
Mar 23 14:27:32 localhost avahi-daemon[6618]: Registering new address record 
for 10.42.0.1 on enp4s0.IPv4.
Mar 23 14:27:32 localhost NetworkManager[6477]: <info>  [1679596052.7182] 
device (enp4s0): state change: ip-config -> ip-check (reason 'none', 
sys-iface-state: 'managed')
Mar 23 14:27:32 localhost avahi-daemon[6618]: Joining mDNS multicast group on 
interface enp4s0.IPv6 with address fe80::f7c4:97a9:80a1:ae41.
Mar 23 14:27:32 localhost avahi-daemon[6618]: New relevant interface 
enp4s0.IPv6 for mDNS.
Mar 23 14:27:32 localhost avahi-daemon[6618]: Registering new address record 
for fe80::f7c4:97a9:80a1:ae41 on enp4s0.*.
Mar 23 14:27:32 localhost NetworkManager[6477]: <info>  [1679596052.7282] 
device (enp4s0): state change: ip-check -> secondaries (reason 'none', 
sys-iface-state: 'managed')
Mar 23 14:27:32 localhost NetworkManager[6477]: <info>  [1679596052.7289] 
device (enp4s0): state change: secondaries -> activated (reason 'none', 
sys-iface-state: 'managed')
Mar 23 14:27:32 localhost NetworkManager[6477]: <info>  [1679596052.7325] 
device (enp4s0): Activation: successful, device activated.
Mar 23 14:27:32 localhost dnsmasq[3868]: failed to create listening socket for 
10.42.0.1: Address already in use
Mar 23 14:27:32 localhost dnsmasq[3868]: FAILED to start up
Mar 23 14:27:32 localhost NetworkManager[6477]: <warn>  [1679596052.7926] 
dnsmasq-manager: dnsmasq exited with error: Network access problem (address in 
use, permissions) (2)
Mar 23 14:27:32 localhost shepherd[1]: [NetworkManager]  
Mar 23 14:27:32 localhost shepherd[1]: [NetworkManager] dnsmasq: failed to 
create listening socket for 10.42.0.1: Address already in use 
Mar 23 14:28:03 localhost NetworkManager[6477]: <info>  [1679596083.7771] 
device (enp4s0): state change: activated -> failed (reason 
'ip-config-unavailable', sys-iface-state: 'managed')
Mar 23 14:28:03 localhost NetworkManager[6477]: <warn>  [1679596083.7848] 
device (enp4s0): Activation: failed for connection 'shared'
Mar 23 14:28:03 localhost NetworkManager[6477]: <info>  [1679596083.7866] 
device (enp4s0): state change: failed -> disconnected (reason 'none', 
sys-iface-state: 'managed')
Mar 23 14:28:03 localhost dbus-daemon[407]: [system] Activating service 
name='org.freedesktop.nm_dispatcher' requested by ':1.20936' (uid=0 pid=6477 
comm="/gnu/store/aby04j5i1bzfgm6hzjb6qcqwz9f1lcfn-networ") (using servicehelper)
Mar 23 14:28:03 localhost avahi-daemon[6618]: Withdrawing address record for 
fe80::f7c4:97a9:80a1:ae41 on enp4s0.
Mar 23 14:28:03 localhost avahi-daemon[6618]: Leaving mDNS multicast group on 
interface enp4s0.IPv6 with address fe80::f7c4:97a9:80a1:ae41.
Mar 23 14:28:03 localhost avahi-daemon[6618]: Interface enp4s0.IPv6 no longer 
relevant for mDNS.
Mar 23 14:28:03 localhost NetworkManager[6477]: <warn>  [1679596083.8939] 
iptables: command 
/gnu/store/xz1arf5cd7ssck431wmfz5y1kgr5vyir-iptables-1.8.7/sbin/iptables 
failed: Child process exited with code 1
Mar 23 14:28:03 localhost NetworkManager[6477]: <warn>  [1679596083.9044] 
iptables: command 
/gnu/store/xz1arf5cd7ssck431wmfz5y1kgr5vyir-iptables-1.8.7/sbin/iptables 
failed: Child process exited with code 1
Mar 23 14:28:03 localhost avahi-daemon[6618]: Withdrawing address record for 
10.42.0.1 on enp4s0.
Mar 23 14:28:03 localhost avahi-daemon[6618]: Leaving mDNS multicast group on 
interface enp4s0.IPv4 with address 10.42.0.1.
Mar 23 14:28:03 localhost avahi-daemon[6618]: Interface enp4s0.IPv4 no longer 
relevant for mDNS.
Mar 23 14:28:03 localhost dbus-daemon[407]: [system] Successfully activated 
service 'org.freedesktop.nm_dispatcher'
--8<---------------cut here---------------end--------------->8---

This gets repeated spuriously in /var/log/messages.  There's at least a
problem with /sbin/modprobe not being looked at the right place.
Interestingly, it also seems to trigger a crash in Jami, which does some
connection refreshing work on events from NetworkManager [0].

[0]  https://git.jami.net/savoirfairelinux/jami-client-qt/-/issues/1044

-- 
Thanks,
Maxim