sqm-scripts icon indicating copy to clipboard operation
sqm-scripts copied to clipboard

Published 20 hours ago • verified publisher icon tohojo

Run service after network-online.target

Open jorti opened this issue 4 years ago • 8 comments

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

jorti avatar Dec 08 '20 19:12 jorti

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

tohojo avatar Dec 08 '20 21:12 tohojo

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?

jorti avatar Dec 08 '20 21:12 jorti

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? :)

tohojo avatar Dec 08 '20 22:12 tohojo

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.

jorti avatar Dec 09 '20 09:12 jorti

Juan Orti Alcaine [email protected] writes:

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?

Well with that setup you can do either, as long as you adjust the overhead appropriately. If you run it on the VLAN interface, CAKE won't see the VLAN tag, so it needs to be accounted in the 'overhead' parameter. Whereas if you run it on the physical interface, it sees the tagged packets and won't need any adjustments. From the log it looks like you're using the default 38-byte overhead which corresponds to an ethernet header without VLAN tags. So with this setup, CAKE will slightly underestimate the size of packets on the wire, so the shaping bandwidth will be slightly off. So I'd suggest either running sqm-scripts on the physical interface, or adding another four bytes of overhead (by adding the 'ether-vlan' keyword to the CAKE config, or just manually setting 'overhead 42').

(And if you had different VLANs going to different destinations, running on the physical interface would mean you were shaping them all, which would likely not have been appropriate; but with only one VLAN there's no difference, really).

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:

Right, so this looks like sqm-scripts is started and the immediately stopped again two seconds later? The stop-sqm timestamps correspond to the time the device unit appeared. That's a bit odd, but maybe there's some kind of flip-flop as networkmanager is setting up the VLAN device? In which case maybe your suggestion of just changing to run after the network is configured is not a bad one.

Could you post a corresponding log with your change, please?

tohojo avatar Dec 09 '20 11:12 tohojo

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

jorti avatar Dec 09 '20 11:12 jorti

Juan Orti Alcaine [email protected] writes:

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.

Ah, I see. This sounds like a bug in NetworkManager triggered by the vlan interface using 'noqueue' by default. I guess you can work around it by moving the sqm-scripts instance to the physical interface? It does indicate that changing the run order is not necessarily the right fix, though...

tohojo avatar Dec 09 '20 13:12 tohojo

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

jorti avatar Dec 09 '20 14:12 jorti