Subject: NetworkManager errors in system log when using shared connection

From: Maxim Cournoyer <[email-masked]>
Date: Thu, 23 Mar 2023 14:37:34 -0400

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