Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Run service after network-online.target #129

Open
wants to merge 1 commit into
base: main
Choose a base branch
from

Conversation

jorti
Copy link

@jorti jorti commented Dec 8, 2020

The service has to run after the network has been configured, so change
the ordering of the systemd unit after network-online.target.

@jorti jorti force-pushed the start-after-network branch from f3ee4d9 to b68ffdb Compare December 8, 2020 19:48
@tohojo
Copy link
Owner

tohojo commented Dec 8, 2020

"The service has to run after the network has been configured" - why? What is the problem you are seeing that this fixes?

@jorti
Copy link
Author

jorti commented Dec 8, 2020

In my Fedora system with NetworkManager, the vlan interface on which I run the sqm scripts doesn't exist before network.target, and even if the dependency After=sys-subsystem-net-devices-%i.device makes the service to run after the device appears, it fails to properly configure the layer_cake settings.

# systemctl status [email protected][email protected] - SQM scripts for iface enp4s0.20
     Loaded: loaded (/etc/systemd/system/[email protected]; enabled; vendor preset: disabled)
     Active: inactive (dead) since Tue 2020-12-08 20:32:18 CET; 21s ago
    Process: 909 ExecStart=/usr/lib/sqm/start-sqm (code=exited, status=0/SUCCESS)
    Process: 1252 ExecStop=/usr/lib/sqm/stop-sqm (code=exited, status=0/SUCCESS)
   Main PID: 909 (code=exited, status=0/SUCCESS)
        CPU: 117ms

dic 08 20:32:17 helium start-sqm[909]: layer_cake.qos was started on enp4s0.20 successfully
dic 08 20:32:17 helium systemd[1]: Finished SQM scripts for iface enp4s0.20.
dic 08 20:32:18 helium systemd[1]: Stopping SQM scripts for iface enp4s0.20...
dic 08 20:32:18 helium stop-sqm[1252]: Stopping SQM on enp4s0.20
dic 08 20:32:18 helium stop-sqm[1252]: ERROR: cmd_wrapper: tc: FAILURE (2): /usr/sbin/tc qdisc del dev enp4s0.20 ingress
dic 08 20:32:18 helium stop-sqm[1252]: ERROR: cmd_wrapper: tc: LAST ERROR: Error: Cannot find specified qdisc on specified device.
dic 08 20:32:18 helium stop-sqm[1252]: ERROR: cmd_wrapper: tc: FAILURE (2): /usr/sbin/tc qdisc del dev enp4s0.20 root
dic 08 20:32:18 helium stop-sqm[1252]: ERROR: cmd_wrapper: tc: LAST ERROR: Error: Cannot delete qdisc with handle of zero.
dic 08 20:32:18 helium systemd[1]: [email protected]: Succeeded.
dic 08 20:32:18 helium systemd[1]: Stopped SQM scripts for iface enp4s0.20.

# tc -s qdisc show dev enp4s0.20
qdisc noqueue 0: root refcnt 2 
 Sent 0 bytes 0 pkt (dropped 0, overlimits 0 requeues 0) 
 backlog 0b 0p requeues 0

With my patch, the layer_cake is configured correctly at startup.

Do you want me to open an issue?

@tohojo
Copy link
Owner

tohojo commented Dec 8, 2020

We can keep the discussion here, no need to open a separate issue. I'd just like to understand a bit more what's causing the failure (and get this documented in the commit message) before changing this. So a couple more questions:

  • What distro are you running, and how are you configuring the interfaces (systemd-networkd, something else)?
  • Can you share the full log output for the unit since boot? I.e., the output of journalctl -b [email protected].
  • Do you have a .device unit for that device on your system at all, and if so is it called sys-subsystem-net-devices-enp4s0.20.device or something else?

And lastly, but a bit tangential, why are you running sqm-scripts on the VLAN device and not the physical device in the first place? :)

@jorti
Copy link
Author

jorti commented Dec 9, 2020

This is a x86_64 box that acts as my router and I'm running Fedora 33 on it. The interfaces are configured by NetworkManager, and I use shorewall to configure the iptables rules (I've disabled the traffic shaping capabilities of shorewall with CLEAR_TC=No and TC_ENABLED=No).

My WAN interface is enp4s0 over VLAN 20. There's no other VLAN on this physical interface. Should I apply the SQM on enp4s0 only? am I doing this wrong?

The .device units are autogenerated and they do exist:

# systemctl status sys-subsystem-net-devices-enp4s0.20.device
● sys-subsystem-net-devices-enp4s0.20.device - /sys/subsystem/net/devices/enp4s0.20
     Loaded: loaded
     Active: active (plugged) since Wed 2020-12-09 10:37:13 CET; 13min ago
     Device: /sys/devices/virtual/net/enp4s0.20

# systemctl status sys-subsystem-net-devices-enp4s0.device
● sys-subsystem-net-devices-enp4s0.device - I211 Gigabit Network Connection
     Loaded: loaded
     Active: active (plugged) since Wed 2020-12-09 10:36:48 CET; 13min ago
     Device: /sys/devices/pci0000:00/0000:00:04.0/0000:04:00.0/net/enp4s0

This is the journal of the service unit with the default settings of Before=network.target and debug logging:

# journalctl -b --no-hostname -u [email protected]
-- Logs begin at Mon 2020-12-07 22:50:59 CET, end at Wed 2020-12-09 10:52:57 CET. --
dic 09 10:37:10 systemd[1]: Starting SQM scripts for iface enp4s0.20...
dic 09 10:37:10 start-sqm[885]: mié 09 dic 2020 10:37:10 CET: Starting.
dic 09 10:37:10 start-sqm[885]: Starting SQM script: layer_cake.qos on enp4s0.20, in: 550000 Kbps, out: 550000 Kbps
dic 09 10:37:10 start-sqm[885]: fn_exists: function candidate name: sqm_start
dic 09 10:37:10 start-sqm[924]: /usr/lib/sqm/functions.sh: line 84: type: sqm_start: not found
dic 09 10:37:10 start-sqm[885]: fn_exists: TYPE_OUTPUT:
dic 09 10:37:10 start-sqm[885]: fn_exists: return value: 1
dic 09 10:37:10 start-sqm[885]: Using generic sqm_start_default function.
dic 09 10:37:10 start-sqm[885]: fn_exists: function candidate name: sqm_prepare_script
dic 09 10:37:10 start-sqm[885]: fn_exists: TYPE_OUTPUT: sqm_prepare_script is a function
dic 09 10:37:10 start-sqm[885]: sqm_prepare_script ()
dic 09 10:37:10 start-sqm[885]: {
dic 09 10:37:10 start-sqm[885]:     do_modules;
dic 09 10:37:10 start-sqm[885]:     verify_qdisc $QDISC "cake" || return 1
dic 09 10:37:10 start-sqm[885]: }
dic 09 10:37:10 start-sqm[885]: fn_exists: return value: 0
dic 09 10:37:10 start-sqm[885]: sqm_start_default: starting sqm_prepare_script
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: COMMAND: /usr/sbin/ip link add name TMP_IFB_4_SQM type ifb
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: ip: SUCCESS: /usr/sbin/ip link add name TMP_IFB_4_SQM type ifb
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: COMMAND: /usr/sbin/tc qdisc replace dev TMP_IFB_4_SQM root cake
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: tc: SUCCESS: /usr/sbin/tc qdisc replace dev TMP_IFB_4_SQM root cake
dic 09 10:37:10 start-sqm[885]: QDISC cake is useable.
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: COMMAND: /usr/sbin/ip link set dev TMP_IFB_4_SQM down
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: ip: SUCCESS: /usr/sbin/ip link set dev TMP_IFB_4_SQM down
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: COMMAND: /usr/sbin/ip link delete TMP_IFB_4_SQM type ifb
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: ip: SUCCESS: /usr/sbin/ip link delete TMP_IFB_4_SQM type ifb
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: COMMAND: /usr/sbin/ip link add name TMP_IFB_4_SQM type ifb
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: ip: SUCCESS: /usr/sbin/ip link add name TMP_IFB_4_SQM type ifb
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: COMMAND: /usr/sbin/tc qdisc replace dev TMP_IFB_4_SQM root cake
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: tc: SUCCESS: /usr/sbin/tc qdisc replace dev TMP_IFB_4_SQM root cake
dic 09 10:37:10 start-sqm[885]: QDISC cake is useable.
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: COMMAND: /usr/sbin/ip link set dev TMP_IFB_4_SQM down
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: ip: SUCCESS: /usr/sbin/ip link set dev TMP_IFB_4_SQM down
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: COMMAND: /usr/sbin/ip link delete TMP_IFB_4_SQM type ifb
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: ip: SUCCESS: /usr/sbin/ip link delete TMP_IFB_4_SQM type ifb
dic 09 10:37:10 start-sqm[885]: sqm_start_default: Starting layer_cake.qos
dic 09 10:37:10 start-sqm[992]: ifb associated with interface enp4s0.20:
dic 09 10:37:10 start-sqm[992]: Currently no ifb is associated with enp4s0.20, this is normal during starting of the sqm system.
dic 09 10:37:10 start-sqm[997]: cmd_wrapper: COMMAND: /usr/sbin/ip link add name ifb4enp4s0.20 type ifb
dic 09 10:37:10 start-sqm[997]: cmd_wrapper: ip: SUCCESS: /usr/sbin/ip link add name ifb4enp4s0.20 type ifb
dic 09 10:37:10 start-sqm[885]: fn_exists: function candidate name: egress
dic 09 10:37:10 start-sqm[885]: fn_exists: TYPE_OUTPUT: egress is a function
dic 09 10:37:10 start-sqm[885]: egress ()
dic 09 10:37:10 start-sqm[885]: {
dic 09 10:37:10 start-sqm[885]:     SILENT=1 $TC qdisc del dev $IFACE root;
dic 09 10:37:10 start-sqm[885]:     $TC qdisc add dev $IFACE root $( get_stab_string ) cake bandwidth ${UPLINK}kbit $( get_cake_lla_string ) ${EGRESS_CAKE_OPTS} ${EQDISC_OPT>
dic 09 10:37:10 start-sqm[885]: }
dic 09 10:37:10 start-sqm[885]: fn_exists: return value: 0
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: tc: invocation silenced by request, FAILURE either expected or acceptable.
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: COMMAND: /usr/sbin/tc qdisc del dev enp4s0.20 root
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: tc: FAILURE (2): /usr/sbin/tc qdisc del dev enp4s0.20 root
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: tc: LAST ERROR: Error: Cannot delete qdisc with handle of zero.
dic 09 10:37:10 start-sqm[1020]: LLA: default link layer adjustment method for cake is cake
dic 09 10:37:10 start-sqm[1020]: cake link layer adjustments:  overhead 38 mpu 84
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: COMMAND: /usr/sbin/tc qdisc add dev enp4s0.20 root cake bandwidth 550000kbit overhead 38 mpu 84 diffserv3
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: tc: SUCCESS: /usr/sbin/tc qdisc add dev enp4s0.20 root cake bandwidth 550000kbit overhead 38 mpu 84 diffserv3
dic 09 10:37:10 start-sqm[885]: sqm_start_default: egress shaping activated
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: COMMAND: /usr/sbin/ip link add name TMP_IFB_4_SQM type ifb
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: ip: SUCCESS: /usr/sbin/ip link add name TMP_IFB_4_SQM type ifb
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: COMMAND: /usr/sbin/tc qdisc replace dev TMP_IFB_4_SQM ingress
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: tc: SUCCESS: /usr/sbin/tc qdisc replace dev TMP_IFB_4_SQM ingress
dic 09 10:37:10 start-sqm[885]: QDISC ingress is useable.
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: COMMAND: /usr/sbin/ip link set dev TMP_IFB_4_SQM down
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: ip: SUCCESS: /usr/sbin/ip link set dev TMP_IFB_4_SQM down
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: COMMAND: /usr/sbin/ip link delete TMP_IFB_4_SQM type ifb
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: ip: SUCCESS: /usr/sbin/ip link delete TMP_IFB_4_SQM type ifb
dic 09 10:37:10 start-sqm[885]: fn_exists: function candidate name: ingress
dic 09 10:37:10 start-sqm[885]: fn_exists: TYPE_OUTPUT: ingress is a function
dic 09 10:37:10 start-sqm[885]: ingress ()
dic 09 10:37:10 start-sqm[885]: {
dic 09 10:37:10 start-sqm[885]:     SILENT=1 $TC qdisc del dev $IFACE handle ffff: ingress;
dic 09 10:37:10 start-sqm[885]:     $TC qdisc add dev $IFACE handle ffff: ingress;
dic 09 10:37:10 start-sqm[885]:     SILENT=1 $TC qdisc del dev $DEV root;
dic 09 10:37:10 start-sqm[885]:     [ "$IGNORE_DSCP_INGRESS" -eq "1" ] && INGRESS_CAKE_OPTS="$INGRESS_CAKE_OPTS besteffort";
dic 09 10:37:10 start-sqm[885]:     [ "$ZERO_DSCP_INGRESS" -eq "1" ] && INGRESS_CAKE_OPTS="$INGRESS_CAKE_OPTS wash";
dic 09 10:37:10 start-sqm[885]:     $TC qdisc add dev $DEV root $( get_stab_string ) cake bandwidth ${DOWNLINK}kbit $( get_cake_lla_string ) ${INGRESS_CAKE_OPTS} ${IQDISC_OP>
dic 09 10:37:10 start-sqm[885]:     $IP link set dev $DEV up;
dic 09 10:37:10 start-sqm[885]:     $TC filter add dev $IFACE parent ffff: protocol all prio 10 u32 match u32 0 0 flowid 1:1 action mirred egress redirect dev $DEV
dic 09 10:37:10 start-sqm[885]: }
dic 09 10:37:10 start-sqm[885]: fn_exists: return value: 0
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: tc: invocation silenced by request, FAILURE either expected or acceptable.
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: COMMAND: /usr/sbin/tc qdisc del dev enp4s0.20 handle ffff: ingress
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: tc: FAILURE (2): /usr/sbin/tc qdisc del dev enp4s0.20 handle ffff: ingress
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: tc: LAST ERROR: Error: Cannot find specified qdisc on specified device.
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: COMMAND: /usr/sbin/tc qdisc add dev enp4s0.20 handle ffff: ingress
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: tc: SUCCESS: /usr/sbin/tc qdisc add dev enp4s0.20 handle ffff: ingress
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: tc: invocation silenced by request, FAILURE either expected or acceptable.
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: COMMAND: /usr/sbin/tc qdisc del dev ifb4enp4s0.20 root
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: tc: FAILURE (2): /usr/sbin/tc qdisc del dev ifb4enp4s0.20 root
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: tc: LAST ERROR: Error: Cannot delete qdisc with handle of zero.
dic 09 10:37:10 start-sqm[1060]: LLA: default link layer adjustment method for cake is cake
dic 09 10:37:10 start-sqm[1060]: cake link layer adjustments:  overhead 38 mpu 84
dic 09 10:37:10 start-sqm[885]: cmd_wrapper: COMMAND: /usr/sbin/tc qdisc add dev ifb4enp4s0.20 root cake bandwidth 550000kbit overhead 38 mpu 84 diffserv3 besteffort wash
dic 09 10:37:11 start-sqm[885]: cmd_wrapper: tc: SUCCESS: /usr/sbin/tc qdisc add dev ifb4enp4s0.20 root cake bandwidth 550000kbit overhead 38 mpu 84 diffserv3 besteffort wash
dic 09 10:37:11 start-sqm[885]: cmd_wrapper: COMMAND: /usr/sbin/ip link set dev ifb4enp4s0.20 up
dic 09 10:37:11 start-sqm[885]: cmd_wrapper: ip: SUCCESS: /usr/sbin/ip link set dev ifb4enp4s0.20 up
dic 09 10:37:11 start-sqm[885]: cmd_wrapper: COMMAND: /usr/sbin/tc filter add dev enp4s0.20 parent ffff: protocol all prio 10 u32 match u32 0 0 flowid 1:1 action mirred egre>
dic 09 10:37:11 start-sqm[885]: cmd_wrapper: tc: SUCCESS: /usr/sbin/tc filter add dev enp4s0.20 parent ffff: protocol all prio 10 u32 match u32 0 0 flowid 1:1 action mirred >
dic 09 10:37:11 start-sqm[885]: sqm_start_default: ingress shaping activated
dic 09 10:37:11 start-sqm[885]: layer_cake.qos was started on enp4s0.20 successfully
dic 09 10:37:11 systemd[1]: Finished SQM scripts for iface enp4s0.20.
dic 09 10:37:13 systemd[1]: Stopping SQM scripts for iface enp4s0.20...
dic 09 10:37:13 stop-sqm[1225]: mié 09 dic 2020 10:37:13 CET: Stopping.
dic 09 10:37:13 stop-sqm[1225]: Stopping SQM on enp4s0.20
dic 09 10:37:13 stop-sqm[1242]: ifb associated with interface enp4s0.20:
dic 09 10:37:13 stop-sqm[1242]: Currently no ifb is associated with enp4s0.20, this is normal during starting of the sqm system.
dic 09 10:37:13 stop-sqm[1225]: cmd_wrapper: COMMAND: /usr/sbin/tc qdisc del dev enp4s0.20 ingress
dic 09 10:37:13 stop-sqm[1225]: ERROR: cmd_wrapper: tc: FAILURE (2): /usr/sbin/tc qdisc del dev enp4s0.20 ingress
dic 09 10:37:13 stop-sqm[1225]: ERROR: cmd_wrapper: tc: LAST ERROR: Error: Cannot find specified qdisc on specified device.
dic 09 10:37:13 stop-sqm[1225]: cmd_wrapper: COMMAND: /usr/sbin/tc qdisc del dev enp4s0.20 root
dic 09 10:37:13 stop-sqm[1225]: ERROR: cmd_wrapper: tc: FAILURE (2): /usr/sbin/tc qdisc del dev enp4s0.20 root
dic 09 10:37:13 stop-sqm[1225]: ERROR: cmd_wrapper: tc: LAST ERROR: Error: Cannot delete qdisc with handle of zero.
dic 09 10:37:13 stop-sqm[1225]: cmd_wrapper: COMMAND: /usr/sbin/tc qdisc del dev ifb4enp4s0.20 root
dic 09 10:37:13 stop-sqm[1225]: cmd_wrapper: tc: SUCCESS: /usr/sbin/tc qdisc del dev ifb4enp4s0.20 root
dic 09 10:37:13 stop-sqm[1225]: /usr/lib/sqm/stop-sqm: ifb4enp4s0.20 shaper deleted
dic 09 10:37:13 stop-sqm[1225]: cmd_wrapper: COMMAND: /usr/sbin/ip link set dev ifb4enp4s0.20 down
dic 09 10:37:13 stop-sqm[1225]: cmd_wrapper: ip: SUCCESS: /usr/sbin/ip link set dev ifb4enp4s0.20 down
dic 09 10:37:13 stop-sqm[1225]: cmd_wrapper: COMMAND: /usr/sbin/ip link delete ifb4enp4s0.20 type ifb
dic 09 10:37:13 stop-sqm[1225]: cmd_wrapper: ip: SUCCESS: /usr/sbin/ip link delete ifb4enp4s0.20 type ifb
dic 09 10:37:13 stop-sqm[1225]: /usr/lib/sqm/stop-sqm: ifb4enp4s0.20 interface deleted
dic 09 10:37:13 systemd[1]: [email protected]: Succeeded.
dic 09 10:37:13 systemd[1]: Stopped SQM scripts for iface enp4s0.20.

@tohojo
Copy link
Owner

tohojo commented Dec 9, 2020 via email

@jorti
Copy link
Author

jorti commented Dec 9, 2020

Thanks for your comments.

Looking at the log in more detail, I see that NetworkManager tries to mangle the qdiscs and fails with this error:
platform-linux: do-delete-tfilter[9: -65536]: failure 22 (Invalid argument - Parent Qdisc doesn't exists).

After that, NetworkManager marks the connection as failed and brings the interface down. This is the cause of sqm stopping on the interface.

dic 09 12:25:23 NetworkManager[820]: <info>  [1607513123.8564] manager: (enp4s0): new Ethernet device (/org/freedesktop/NetworkManager/Devices/9)
dic 09 12:25:23 NetworkManager[820]: <info>  [1607513123.8602] device (enp4s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
dic 09 12:25:23 NetworkManager[820]: <info>  [1607513123.8993] manager: (enp4s0.20): new VLAN device (/org/freedesktop/NetworkManager/Devices/10)
dic 09 12:25:23 NetworkManager[820]: <info>  [1607513123.9074] device (enp4s0.20): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
dic 09 12:25:23 systemd[1]: Starting SQM scripts for iface enp4s0.20...
dic 09 12:25:24 start-sqm[882]: Starting SQM script: layer_cake.qos on enp4s0.20, in: 550000 Kbps, out: 550000 Kbps
dic 09 12:25:24 start-sqm[919]: /usr/lib/sqm/functions.sh: line 84: type: sqm_start: not found
dic 09 12:25:24 start-sqm[882]: Using generic sqm_start_default function.
dic 09 12:25:24 NetworkManager[820]: <info>  [1607513124.4275] manager: (TMP_IFB_4_SQM): new Generic device (/org/freedesktop/NetworkManager/Devices/18)
dic 09 12:25:24 NetworkManager[820]: <info>  [1607513124.8093] manager: (ifb4enp4s0.20): new Generic device (/org/freedesktop/NetworkManager/Devices/19)
dic 09 12:25:24 NetworkManager[820]: <info>  [1607513124.8494] manager: (TMP_IFB_4_SQM): new Generic device (/org/freedesktop/NetworkManager/Devices/20)
dic 09 12:25:25 start-sqm[882]: layer_cake.qos was started on enp4s0.20 successfully
dic 09 12:25:25 systemd[1]: Finished SQM scripts for iface enp4s0.20.
dic 09 12:25:26 NetworkManager[820]: <info>  [1607513126.9221] device (enp4s0): carrier: link connected
dic 09 12:25:26 NetworkManager[820]: <info>  [1607513126.9227] device (enp4s0): state change: unavailable -> disconnected (reason 'carrier-changed', sys-iface-state: 'managed')
dic 09 12:25:26 NetworkManager[820]: <info>  [1607513126.9455] device (enp4s0.20): carrier: link connected
dic 09 12:25:26 NetworkManager[820]: <info>  [1607513126.9460] device (enp4s0.20): state change: unavailable -> disconnected (reason 'carrier-changed', sys-iface-state: 'managed')
dic 09 12:25:26 NetworkManager[820]: <info>  [1607513126.9481] policy: auto-activating connection 'wan' (7535e90e-0b82-40a9-8dfb-a12408de3d69)
dic 09 12:25:26 NetworkManager[820]: <info>  [1607513126.9496] device (enp4s0.20): Activation: starting connection 'wan' (7535e90e-0b82-40a9-8dfb-a12408de3d69)
dic 09 12:25:26 NetworkManager[820]: <info>  [1607513126.9503] device (enp4s0.20): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
dic 09 12:25:26 NetworkManager[820]: <info>  [1607513126.9522] manager: NetworkManager state is now CONNECTING
dic 09 12:25:26 NetworkManager[820]: <info>  [1607513126.9535] device (enp4s0.20): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
dic 09 12:25:26 NetworkManager[820]: <warn>  [1607513126.9708] platform-linux: do-delete-tfilter[9: -65536]: failure 22 (Argumento inválido - Parent Qdisc doesn't exists)
dic 09 12:25:26 NetworkManager[820]: <warn>  [1607513126.9710] device (enp4s0.20): failed applying traffic control rules
dic 09 12:25:26 NetworkManager[820]: <info>  [1607513126.9710] device (enp4s0.20): state change: config -> failed (reason 'config-failed', sys-iface-state: 'managed')
dic 09 12:25:26 NetworkManager[820]: <info>  [1607513126.9724] manager: NetworkManager state is now CONNECTED_LOCAL
dic 09 12:25:26 NetworkManager[820]: <warn>  [1607513126.9757] device (enp4s0.20): Activation: failed for connection 'wan'
dic 09 12:25:26 NetworkManager[820]: <info>  [1607513126.9809] device (enp4s0.20): state change: failed -> disconnected (reason 'none', sys-iface-state: 'managed')
dic 09 12:25:27 systemd[1]: Stopping SQM scripts for iface enp4s0.20...
dic 09 12:25:27 NetworkManager[820]: <info>  [1607513127.0140] device (enp4s0.20): state change: disconnected -> unmanaged (reason 'user-requested', sys-iface-state: 'managed')
dic 09 12:25:27 NetworkManager[820]: <info>  [1607513127.0167] policy: auto-activating connection 'wan' (7535e90e-0b82-40a9-8dfb-a12408de3d69)
dic 09 12:25:27 NetworkManager[820]: <info>  [1607513127.0217] device (enp4s0.20): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
dic 09 12:25:27 NetworkManager[820]: <info>  [1607513127.0235] device (enp4s0.20): carrier: link connected
dic 09 12:25:27 NetworkManager[820]: <info>  [1607513127.0411] device (enp4s0.20): state change: unavailable -> disconnected (reason 'user-requested', sys-iface-state: 'managed')
dic 09 12:25:27 NetworkManager[820]: <info>  [1607513127.0513] device (enp4s0.20): Activation: starting connection 'wan' (7535e90e-0b82-40a9-8dfb-a12408de3d69)
dic 09 12:25:27 NetworkManager[820]: <info>  [1607513127.0584] device (enp4s0.20): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
dic 09 12:25:27 NetworkManager[820]: <info>  [1607513127.0593] manager: NetworkManager state is now CONNECTING
dic 09 12:25:27 NetworkManager[820]: <info>  [1607513127.0602] device (enp4s0.20): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
dic 09 12:25:27 NetworkManager[820]: <info>  [1607513127.0616] device (enp4s0.20): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
dic 09 12:25:27 NetworkManager[820]: <info>  [1607513127.0624] dhcp4 (enp4s0.20): activation: beginning transaction (timeout in 45 seconds)
dic 09 12:25:27 stop-sqm[1225]: Stopping SQM on enp4s0.20
dic 09 12:25:27 stop-sqm[1225]: ERROR: cmd_wrapper: tc: FAILURE (2): /usr/sbin/tc qdisc del dev enp4s0.20 ingress
dic 09 12:25:27 stop-sqm[1225]: ERROR: cmd_wrapper: tc: LAST ERROR: Error: Cannot find specified qdisc on specified device.
dic 09 12:25:27 stop-sqm[1225]: ERROR: cmd_wrapper: tc: FAILURE (2): /usr/sbin/tc qdisc del dev enp4s0.20 root
dic 09 12:25:27 stop-sqm[1225]: ERROR: cmd_wrapper: tc: LAST ERROR: Error: Cannot delete qdisc with handle of zero.
dic 09 12:25:27 systemd[1]: [email protected]: Succeeded.
dic 09 12:25:27 systemd[1]: Stopped SQM scripts for iface enp4s0.20.
dic 09 12:25:27 NetworkManager[820]: <info>  [1607513127.5532] dhcp4 (enp4s0.20): state changed unknown -> bound
dic 09 12:25:27 NetworkManager[820]: <info>  [1607513127.5606] device (enp4s0.20): state change: ip-config -> ip-check (reason 'none', sys-iface-state: 'managed')
dic 09 12:25:27 NetworkManager[820]: <info>  [1607513127.5697] device (enp4s0.20): state change: ip-check -> secondaries (reason 'none', sys-iface-state: 'managed')
dic 09 12:25:27 NetworkManager[820]: <info>  [1607513127.5703] device (enp4s0.20): state change: secondaries -> activated (reason 'none', sys-iface-state: 'managed')
dic 09 12:25:27 NetworkManager[820]: <info>  [1607513127.5714] manager: NetworkManager state is now CONNECTED_LOCAL
dic 09 12:25:27 NetworkManager[820]: <info>  [1607513127.5746] manager: NetworkManager state is now CONNECTED_SITE
dic 09 12:25:27 NetworkManager[820]: <info>  [1607513127.5752] policy: set 'wan' (enp4s0.20) as default for IPv4 routing and DNS
dic 09 12:25:27 NetworkManager[820]: <info>  [1607513127.5756] device (enp4s0.20): Activation: successful, device activated.
dic 09 12:25:27 NetworkManager[820]: <info>  [1607513127.5772] manager: NetworkManager state is now CONNECTED_GLOBAL

If sqm starts before NetworkManager has finished configuring the network
interfaces, it can cause NetworkManager to fail with the following error:

    platform-linux: do-delete-tfilter[9: -65536]: failure 22 (Invalid
    argument - Parent Qdisc doesn't exists)

After that, the interface is torn down, causing sqm to stop.

To avoid that problem, wait until the network interfaces have been fully
configured ordering the systemd unit after network-online.target.

Signed-off-by: Juan Orti Alcaine <[email protected]>
@jorti jorti force-pushed the start-after-network branch from b68ffdb to 9651f57 Compare December 9, 2020 12:10
@tohojo
Copy link
Owner

tohojo commented Dec 9, 2020 via email

@jorti
Copy link
Author

jorti commented Dec 9, 2020

FYI I've opened this bug to NetworkManager: https://bugzilla.redhat.com/show_bug.cgi?id=1906024

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants