SQM stops in System Log

Installing and Using OpenWrt
1

Very often I see the following behaviour of SQM in System Log:

Sun Jan 26 08:21:19 2025 daemon.info dnsmasq[1]: using only locally-known addresses for invalid
Sun Jan 26 08:21:19 2025 daemon.info dnsmasq[1]: using only locally-known addresses for bind
Sun Jan 26 08:21:19 2025 daemon.info dnsmasq[1]: using only locally-known addresses for lan
Sun Jan 26 08:21:19 2025 user.notice SQM: Stopping SQM on pppoe-wan
Sun Jan 26 08:21:19 2025 user.notice SQM: ERROR: cmd_wrapper: tc: FAILURE (2): /sbin/tc qdisc del dev pppoe-wan ingress
Sun Jan 26 08:21:19 2025 user.notice SQM: ERROR: cmd_wrapper: tc: LAST ERROR: RTNETLINK answers: No such file or directory
Sun Jan 26 08:21:19 2025 user.notice SQM: ERROR: cmd_wrapper: tc: FAILURE (2): /sbin/tc qdisc del dev pppoe-wan root
Sun Jan 26 08:21:19 2025 user.notice SQM: ERROR: cmd_wrapper: tc: LAST ERROR: RTNETLINK answers: No such file or directory
Sun Jan 26 08:21:19 2025 daemon.notice ttyd[5245]: [2025/01/26 08:21:19:5988] N: rops_handle_POLLIN_netlink: DELADDR
Sun Jan 26 08:21:19 2025 kern.debug kernel: [172826.914590] {natflow}:vline_fwd_map_unregister_handle(): handle event for dev=ifb4pppoe-wan
Sun Jan 26 08:21:19 2025 kern.debug kernel: [172826.923093] {natflow}:natflow_netdev_event(): catch NETDEV_UNREGISTER event for dev=ifb4pppoe-wan
Sun Jan 26 08:21:19 2025 user.notice SQM: Starting SQM script: piece_of_cake.qos on pppoe-wan, in: 9500 Kbps, out: 9500 Kbps
Sun Jan 26 08:21:19 2025 kern.debug kernel: [172827.106148] {natflow}:vline_fwd_map_unregister_handle(): handle event for dev=SQM_IFB_9de34
Sun Jan 26 08:21:19 2025 kern.debug kernel: [172827.114692] {natflow}:natflow_netdev_event(): catch NETDEV_UNREGISTER event for dev=SQM_IFB_9de34
Sun Jan 26 08:21:19 2025 kern.debug kernel: [172827.218086] {natflow}:vline_fwd_map_unregister_handle(): handle event for dev=SQM_IFB_d8ebb
Sun Jan 26 08:21:19 2025 kern.debug kernel: [172827.226569] {natflow}:natflow_netdev_event(): catch NETDEV_UNREGISTER event for dev=SQM_IFB_d8ebb
Sun Jan 26 08:21:20 2025 kern.debug kernel: [172827.344316] {natflow}:vline_fwd_map_unregister_handle(): handle event for dev=SQM_IFB_fcf58
Sun Jan 26 08:21:20 2025 kern.debug kernel: [172827.352825] {natflow}:natflow_netdev_event(): catch NETDEV_UNREGISTER event for dev=SQM_IFB_fcf58
Sun Jan 26 08:21:20 2025 kern.debug kernel: [172827.426217] {natflow}:vline_fwd_map_ifup_handle(): handle event for dev=ifb4pppoe-wan
Sun Jan 26 08:21:20 2025 kern.debug kernel: [172827.434219] {natflow}:natflow_netdev_event(): catch NETDEV_UP event for dev=ifb4pppoe-wan(tso=1,1,hw_csum=1,1), add ingress hook
Sun Jan 26 08:21:20 2025 user.notice SQM: piece_of_cake.qos was started on pppoe-wan successfully
Sun Jan 26 08:21:20 2025 user.notice firewall: Reloading firewall due to ifup of wan (pppoe-wan)
Sun Jan 26 08:21:20 2025 user.notice natflow: Reloading natflow-zone due to ifup of wan (pppoe-wan)
Sun Jan 26 08:21:20 2025 user.notice nlbwmon: Reloading nlbwmon due to ifup of wan (pppoe-wan)

Why it's stopping by itself and restarts then?

2

There's a hint:

2 Likes
3

What does it mean? Is it normal behaviour? Sorry if it is a stupid question :pray:

4

If wan goes down and comes back up, SQM reloads the config.

2 Likes
5

It's mean at that moment there was an internet connection cut from my ISP?

6

Or something in your router caused wan interface to get reloaded.

1 Like
7

Is it possible to understand? Because I see this in the log very often

8

Well, we do not see your logs, nor do we know your config.
So likely so educated guesses coming from others without more details from you...

If you add here the log details, a few dozen lines earlier that the SQM restart, you might get some responses.

(And naturally we know nothing about your ISPs behaviour.)

2 Likes
9

Here is mine ect/config/network:

config interface 'loopback'
	option device 'lo'
	option proto 'static'
	option ipaddr '127.0.0.1'
	option netmask '255.0.0.0'

config globals 'globals'
	option ula_prefix 'fdb9:a3be:d100::/48'

config device
	option name 'br-lan'
	option type 'bridge'
	list ports 'lan1'
	list ports 'lan2'
	list ports 'lan3'

config interface 'lan'
	option device 'br-lan'
	option proto 'static'
	option ipaddr '192.168.1.1'
	option netmask '255.255.255.0'
	option delegate '0'

config device
	option name 'wan'
	option macaddr '5c:02:14:31:b9:7d'

config interface 'wan'
	option device 'wan'
	option proto 'pppoe'
	option username '*****'
	option password '*****'
	option ipv6 'auto'
	option delegate '0'

The full log of wan down:

Sun Jan 26 06:38:54 2025 daemon.info dnsmasq-dhcp[1]: DHCPACK(br-lan) 192.168.1.115 34:08:a6:ef:c8:12 DESKTOP-LV5TPDK
Sun Jan 26 08:21:11 2025 daemon.info hostapd: wl1-ap0: STA ce:1e:c1:18:1e:ee WPA: group key handshake completed (RSN)
Sun Jan 26 08:21:18 2025 daemon.info pppd[27855]: LCP terminated by peer
Sun Jan 26 08:21:18 2025 daemon.info pppd[27855]: Connect time 1440.1 minutes.
Sun Jan 26 08:21:18 2025 daemon.info pppd[27855]: Sent 214191770 bytes, received 3742476834 bytes.
Sun Jan 26 08:21:18 2025 daemon.notice netifd: Network device 'pppoe-wan' link is down
Sun Jan 26 08:21:18 2025 daemon.notice ttyd[5245]: [2025/01/26 08:21:18:7439] N: rops_handle_POLLIN_netlink: DELADDR
Sun Jan 26 08:21:18 2025 daemon.notice pppd[27855]: Modem hangup
Sun Jan 26 08:21:18 2025 daemon.notice pppd[27855]: Connection terminated.
Sun Jan 26 08:21:18 2025 kern.debug kernel: [172826.070541] {natflow}:vline_fwd_map_unregister_handle(): handle event for dev=pppoe-wan
Sun Jan 26 08:21:18 2025 kern.debug kernel: [172826.078714] {natflow}:natflow_netdev_event(): catch NETDEV_UNREGISTER event for dev=pppoe-wan
Sun Jan 26 08:21:18 2025 daemon.info pppd[27855]: Sent PADT
Sun Jan 26 08:21:18 2025 daemon.notice netifd: Interface 'wan' has lost the connection
Sun Jan 26 08:21:18 2025 daemon.warn dnsmasq[1]: no servers found in /tmp/resolv.conf.d/resolv.conf.auto, will retry
Sun Jan 26 08:21:18 2025 daemon.info pppd[27855]: Exit.
Sun Jan 26 08:21:19 2025 daemon.notice netifd: Interface 'wan' is now down
Sun Jan 26 08:21:19 2025 daemon.notice netifd: Interface 'wan' is setting up now
Sun Jan 26 08:21:19 2025 daemon.info pppd[10414]: Plugin pppoe.so loaded.
Sun Jan 26 08:21:19 2025 daemon.info pppd[10414]: PPPoE plugin from pppd 2.5.1
Sun Jan 26 08:21:19 2025 daemon.notice pppd[10414]: pppd 2.5.1 started by root, uid 0
Sun Jan 26 08:21:19 2025 daemon.info pppd[10414]: PPP session is 40868
Sun Jan 26 08:21:19 2025 daemon.warn pppd[10414]: Connected to 40:55:39:F7:CD:00 via interface wan
Sun Jan 26 08:21:19 2025 daemon.info pppd[10414]: Using interface pppoe-wan
Sun Jan 26 08:21:19 2025 daemon.notice pppd[10414]: Connect: pppoe-wan <--> wan
Sun Jan 26 08:21:19 2025 daemon.notice pppd[10414]: PAP authentication succeeded
Sun Jan 26 08:21:19 2025 daemon.notice pppd[10414]: peer from calling number 40:55:39:F7:CD:00 authorized
Sun Jan 26 08:21:19 2025 daemon.notice ttyd[5245]: [2025/01/26 08:21:19:2422] N: rops_handle_POLLIN_netlink: DELADDR
Sun Jan 26 08:21:19 2025 kern.debug kernel: [172826.557674] {natflow}:natflow_netdev_event(): catch event 1 for dev=pppoe-wan : set flags IFF_PPPOE
Sun Jan 26 08:21:19 2025 kern.debug kernel: [172826.566820] {natflow}:vline_fwd_map_ifup_handle(): handle event for dev=pppoe-wan
Sun Jan 26 08:21:19 2025 kern.debug kernel: [172826.574478] {natflow}:natflow_netdev_event(): catch NETDEV_UP event for dev=pppoe-wan(tso=0,0,hw_csum=0,0), add ingress hook
Sun Jan 26 08:21:19 2025 daemon.notice pppd[10414]: local  IP address 176.113.185.179
Sun Jan 26 08:21:19 2025 daemon.notice pppd[10414]: remote IP address 10.31.0.18
Sun Jan 26 08:21:19 2025 daemon.notice pppd[10414]: primary   DNS address 91.200.216.7
Sun Jan 26 08:21:19 2025 daemon.notice pppd[10414]: secondary DNS address 91.200.216.2
Sun Jan 26 08:21:19 2025 daemon.notice netifd: Network device 'pppoe-wan' link is up
Sun Jan 26 08:21:19 2025 daemon.notice netifd: Interface 'wan' is now up
Sun Jan 26 08:21:19 2025 daemon.info dnsmasq[1]: reading /tmp/resolv.conf.d/resolv.conf.auto
Sun Jan 26 08:21:19 2025 daemon.info dnsmasq[1]: using nameserver 91.200.216.7#53
Sun Jan 26 08:21:19 2025 daemon.info dnsmasq[1]: using nameserver 91.200.216.2#53
Sun Jan 26 08:21:19 2025 daemon.info dnsmasq[1]: using only locally-known addresses for test
Sun Jan 26 08:21:19 2025 daemon.info dnsmasq[1]: using only locally-known addresses for onion
Sun Jan 26 08:21:19 2025 daemon.info dnsmasq[1]: using only locally-known addresses for localhost
Sun Jan 26 08:21:19 2025 daemon.info dnsmasq[1]: using only locally-known addresses for local
Sun Jan 26 08:21:19 2025 daemon.info dnsmasq[1]: using only locally-known addresses for invalid
Sun Jan 26 08:21:19 2025 daemon.info dnsmasq[1]: using only locally-known addresses for bind
Sun Jan 26 08:21:19 2025 daemon.info dnsmasq[1]: using only locally-known addresses for lan
Sun Jan 26 08:21:19 2025 user.notice SQM: Stopping SQM on pppoe-wan
Sun Jan 26 08:21:19 2025 user.notice SQM: ERROR: cmd_wrapper: tc: FAILURE (2): /sbin/tc qdisc del dev pppoe-wan ingress
Sun Jan 26 08:21:19 2025 user.notice SQM: ERROR: cmd_wrapper: tc: LAST ERROR: RTNETLINK answers: No such file or directory
Sun Jan 26 08:21:19 2025 user.notice SQM: ERROR: cmd_wrapper: tc: FAILURE (2): /sbin/tc qdisc del dev pppoe-wan root
Sun Jan 26 08:21:19 2025 user.notice SQM: ERROR: cmd_wrapper: tc: LAST ERROR: RTNETLINK answers: No such file or directory
Sun Jan 26 08:21:19 2025 daemon.notice ttyd[5245]: [2025/01/26 08:21:19:5988] N: rops_handle_POLLIN_netlink: DELADDR
Sun Jan 26 08:21:19 2025 kern.debug kernel: [172826.914590] {natflow}:vline_fwd_map_unregister_handle(): handle event for dev=ifb4pppoe-wan
Sun Jan 26 08:21:19 2025 kern.debug kernel: [172826.923093] {natflow}:natflow_netdev_event(): catch NETDEV_UNREGISTER event for dev=ifb4pppoe-wan
Sun Jan 26 08:21:19 2025 user.notice SQM: Starting SQM script: piece_of_cake.qos on pppoe-wan, in: 9500 Kbps, out: 9500 Kbps
Sun Jan 26 08:21:19 2025 kern.debug kernel: [172827.106148] {natflow}:vline_fwd_map_unregister_handle(): handle event for dev=SQM_IFB_9de34
Sun Jan 26 08:21:19 2025 kern.debug kernel: [172827.114692] {natflow}:natflow_netdev_event(): catch NETDEV_UNREGISTER event for dev=SQM_IFB_9de34
Sun Jan 26 08:21:19 2025 kern.debug kernel: [172827.218086] {natflow}:vline_fwd_map_unregister_handle(): handle event for dev=SQM_IFB_d8ebb
Sun Jan 26 08:21:19 2025 kern.debug kernel: [172827.226569] {natflow}:natflow_netdev_event(): catch NETDEV_UNREGISTER event for dev=SQM_IFB_d8ebb
Sun Jan 26 08:21:20 2025 kern.debug kernel: [172827.344316] {natflow}:vline_fwd_map_unregister_handle(): handle event for dev=SQM_IFB_fcf58
Sun Jan 26 08:21:20 2025 kern.debug kernel: [172827.352825] {natflow}:natflow_netdev_event(): catch NETDEV_UNREGISTER event for dev=SQM_IFB_fcf58
Sun Jan 26 08:21:20 2025 kern.debug kernel: [172827.426217] {natflow}:vline_fwd_map_ifup_handle(): handle event for dev=ifb4pppoe-wan
Sun Jan 26 08:21:20 2025 kern.debug kernel: [172827.434219] {natflow}:natflow_netdev_event(): catch NETDEV_UP event for dev=ifb4pppoe-wan(tso=1,1,hw_csum=1,1), add ingress hook
Sun Jan 26 08:21:20 2025 user.notice SQM: piece_of_cake.qos was started on pppoe-wan successfully
Sun Jan 26 08:21:20 2025 user.notice firewall: Reloading firewall due to ifup of wan (pppoe-wan)
Sun Jan 26 08:21:20 2025 user.notice natflow: Reloading natflow-zone due to ifup of wan (pppoe-wan)
Sun Jan 26 08:21:20 2025 user.notice nlbwmon: Reloading nlbwmon due to ifup of wan (pppoe-wan)
Sun Jan 26 11:00:50 2025 daemon.info dnsmasq-dhcp[1]: DHCPREQUEST(br-lan) 192.168.1.181 ce:1e:c1:16:1e:ee
10

Your ISP hangs up after 24 hours. Such 24-hour disconnects are common with many ISPs and no need for alarm, your router just reconnects immediately.

3 Likes
11

That is exactly 24 hours...

2 Likes
12

Now you might ask, why do anything at all, the true wan interface (be it ethernet, be it DSL) is physically not going anywhere?
The problem is that the pppoe interface completely disappears and on reconnect later a new one is created, without any knowledge which qdiscs were attached to the old interface that went away.
So to make sure there is an working instance of sqm after a pppoe reconnect, sqm uses the hotplug system to detect interfaces going away (so it can clean up a bit) and interfaces coming into existence (so it can instantiate qdiscs if that interface is configured for sqm).

1 Like
13

Thank you very much guys for your quick and professional support!

14

Is it neccessary to do something with the following errors in System log?:

Sun Jan 26 15:19:37 2025 daemon.err collectd[3117]: rrdtool plugin: rrd_update_r failed: /tmp/rrd/OpenWrt/iwinfo-wl1-ap0/signal_power.rrd: opening '/tmp/rrd/OpenWrt/iwinfo-wl1-ap0/signal_power.rrd': No such file or directory
Sun Jan 26 15:19:39 2025 daemon.err collectd[3117]: rrdtool plugin: rrd_update_r failed: /tmp/rrd/OpenWrt/iwinfo-wl1-ap0/signal_power.rrd: opening '/tmp/rrd/OpenWrt/iwinfo-wl1-ap0/signal_power.rrd': No such file or directory
Sun Jan 26 15:20:09 2025 daemon.err collectd[3117]: rrdtool plugin: rrd_update_r failed: /tmp/rrd/OpenWrt/iwinfo-wl1-ap0/signal_power.rrd: opening '/tmp/rrd/OpenWrt/iwinfo-wl1-ap0/signal_power.rrd': No such file or directory
15

Unrelated to SQM or your WAN interface. rrdtool, the tool that creates the graph images for the statistics in LuCI, cannot find data for a statistic it is asked to display. Barked up the wrong tree here, see @hnyman below, thanks for the correction.

1 Like
16

Or actually, it fails to update some metrics to the database. Happens sometimes, especially at startup.

1 Like
17

This topic was automatically closed 10 days after the last reply. New replies are no longer allowed.