net_ratelimit issue on AC87 and 384.9

[GeneM]

Hi folks,

I don't post lightly here, but I'm at the end of my rope. A few days ago, I'm seeing that my System Log receives an entry every minute:

Feb 22 23:52:08 kernel: net_ratelimit: 42 callbacks suppressed
Feb 22 23:53:08 kernel: net_ratelimit: 26 callbacks suppressed
Feb 22 23:54:08 kernel: net_ratelimit: 41 callbacks suppressed
Feb 22 23:55:08 kernel: net_ratelimit: 36 callbacks suppressed
Feb 22 23:56:08 kernel: net_ratelimit: 68 callbacks suppressed
Feb 22 23:57:08 kernel: net_ratelimit: 47 callbacks suppressed​

These are just about the only records I see in that 6k line log.

My last firmware update of the RT-AC87U was back on Feb 2nd and all was fine. I don't think this started right away.

I've spend two days now trying to learn about this error, and per this thread, I'm not getting any other kernel error (like time wait bucket table overflow) and I don't have systems on all the time so am discounting the browser was flooding the router during the flash. I've power-cycled several times.

I'm wondering if there's a (temporary) telnet command I can issue that will allow me to see what's being suppressed? My biggest concern is I may have something in the house going haywire.

A factory reset is the obvious next step, but that will take me hours given all the settings I have in here. I don't even know how to start recording all my settings - for manual reentry. I'm assuming that after a factory reset, I should NOT restore my last settings file? Is that a correct assumption?

I'd appreciate some guidance, folks.
Gene

 

[ColinTaylor]

The net_ratelimit message should be proceeded by the actual error that is causing the problem. So you need to find that error message. If your log is full up with only net_ratelimit messages then it sounds like the original message may have "fallen off" the end of the log file.

I suggest that you reboot your router to restart the syslog. Then watch the syslog until the messages start appearing. Then save the log file for analysis, hopefully catching the original error message.

 

[ColinTaylor]

I'm assuming that after a factory reset, I should NOT restore my last settings file? Is that a correct assumption?

That's correct. Doing so would defeat the purpose of doing the factory reset.

 

[GeneM]

That's correct. Doing so would defeat the purpose of doing the factory reset.

I've just finished getting familiar with, and running, the NVRAM Save Restore Utility. I'm about ready to factory reset and restore via that backup. I'm thinking this ascii-based-parameter restore is what I'm wanting. Correct?

 

[GeneM]

The net_ratelimit message should be proceeded by the actual error ...

I suggest that you reboot your router to restart the syslog. Then watch the syslog until the messages start appearing.

Not seeing it...
Anything stand out to you?


Feb 23 14:15:59 inadyn[559]: Update forced for alias all.dnsomatic.com, new IP# xx.xxx.xxx.xxx
Feb 23 14:15:59 rc_service: ntp 375:notify_rc restart_diskmon
Feb 23 14:15:59 disk_monitor: Finish
Feb 23 14:16:00 disk_monitor: be idle
Feb 23 14:16:00 rc_service: hotplug 531:notify_rc restart_nasapps
Feb 23 14:16:00 iTunes: daemon is stopped
Feb 23 14:16:00 FTP_Server: daemon is stopped
Feb 23 14:16:02 Samba_Server: smb daemon is stopped
Feb 23 14:16:02 kernel: gro disabled
Feb 23 14:16:03 inadyn[559]: Updating cache for all.dnsomatic.com
Feb 23 14:16:03 Timemachine: daemon is stopped
Feb 23 14:16:03 miniupnpd[542]: shutting down MiniUPnPd
Feb 23 14:16:03 kernel: gro enabled with interval 2
Feb 23 14:16:03 avahi-daemon[615]: WARNING: No NSS support for mDNS detected, consider installing nss-mdns!
Feb 23 14:16:04 avahi-daemon[615]: Alias name "RT-AC87U" successfully established.
Feb 23 14:16:05 Samba_Server: daemon is started
Feb 23 14:16:05 miniupnpd[631]: HTTP listening on port 34977
Feb 23 14:16:05 miniupnpd[631]: Listening for NAT-PMP/PCP traffic on port 5351
Feb 23 14:16:16 kernel: SHN Release Version: 2.0.1 890c91d
Feb 23 14:16:16 kernel: UDB Core Version: 0.2.18
Feb 23 14:16:16 kernel: sizeof forward pkt param = 192
Feb 23 14:16:16 BWDPI: fun bitmap = ff
Feb 23 14:16:18 A.QoS: qos_count=0, qos_check=0
Feb 23 14:16:18 kernel: ERR[qos_start:3364] qos_ops is not registered!
Feb 23 14:16:18 kernel: ioctl_iqos_op_switch(1) fail!
Feb 23 14:16:18 A.QoS: set_qos_on fails
Feb 23 14:16:18 A.QoS: restart A.QoS because set_qos_conf / set_qos_on / setup rule fail
Feb 23 14:16:20 A.QoS: qos_count=0, qos_check=1
Feb 23 14:16:21 qtn: bootcfg.tgz exists
Feb 23 14:16:24 channel_scan: start scan[1]
Feb 23 14:16:24 channel_scan: scan not complete
Feb 23 14:16:27 crond[222]: time disparity of 424391 minutes detected
Feb 23 14:16:29 rc_service: udhcpc 350:notify_rc start_firewall
Feb 23 14:16:30 miniupnpd[631]: shutting down MiniUPnPd
Feb 23 14:16:30 rc_service: udhcpc 350:notify_rc start_vpnserver1
Feb 23 14:16:30 rc_service: waitting "start_firewall" via udhcpc ...
Feb 23 14:16:31 nat: apply nat rules (/tmp/nat_rules_eth0_eth0)
Feb 23 14:16:31 miniupnpd[1616]: HTTP listening on port 49583
Feb 23 14:16:31 miniupnpd[1616]: Listening for NAT-PMP/PCP traffic on port 5351
Feb 23 14:16:36 dhcp_client: bound xx.xxx.xxx.218 via xx.xxx.xxx.1 during 254316 seconds.
Feb 23 14:16:37 ovpn-server1[2297]: OpenVPN 2.4.6 arm-unknown-linux-gnu [SSL (OpenSSL)] [LZO] [LZ4] [EPOLL] [MH/PKTINFO] [AEAD] built on Feb 2 2019
Feb 23 14:16:37 ovpn-server1[2297]: library versions: OpenSSL 1.0.2q 20 Nov 2018, LZO 2.08
Feb 23 14:16:37 ovpn-server1[2311]: Diffie-Hellman initialized with 2048 bit key
Feb 23 14:16:37 ovpn-server1[2311]: TUN/TAP device tun21 opened
Feb 23 14:16:37 ovpn-server1[2311]: TUN/TAP TX queue length set to 100
Feb 23 14:16:37 ovpn-server1[2311]: do_ifconfig, tt->did_ifconfig_ipv6_setup=0
Feb 23 14:16:37 ovpn-server1[2311]: /usr/sbin/ip link set dev tun21 up mtu 1500
Feb 23 14:16:37 ovpn-server1[2311]: /usr/sbin/ip addr add dev tun21 10.8.0.1/24 broadcast 10.8.0.255
Feb 23 14:16:37 ovpn-server1[2311]: Could not determine IPv4/IPv6 protocol. Using AF_INET6
Feb 23 14:16:37 ovpn-server1[2311]: Socket Buffers: R=[122880->122880] S=[122880->122880]
Feb 23 14:16:37 ovpn-server1[2311]: setsockopt(IPV6_V6ONLY=0)
Feb 23 14:16:37 ovpn-server1[2311]: UDPv6 link local (bound): [AF_INET6][undef]:1194
Feb 23 14:16:37 ovpn-server1[2311]: UDPv6 link remote: [AF_UNSPEC]
Feb 23 14:16:37 ovpn-server1[2311]: MULTI: multi_init called, r=256 v=256
Feb 23 14:16:37 ovpn-server1[2311]: IFCONFIG POOL: base=10.8.0.2 size=252, ipv6=0
Feb 23 14:16:37 ovpn-server1[2311]: Initialization Sequence Completed
Feb 23 14:17:31 kernel: net_ratelimit: 64 callbacks suppressed

 

[ColinTaylor]

I've just finished getting familiar with, and running, the NVRAM Save Restore Utility. I'm about ready to factory reset and restore via that backup. I'm thinking this ascii-based-parameter restore is what I'm wanting. Correct?

That utility was/is designed to work with the earlier firmware versions, 380 and before. It is not compatible with later firmware versions.

 

[GeneM]

Firewall>General> Is "Enable DoS protection" Yes

Are you hosting something on your router....
That's what I've been fretting over for two days now. I do not believe so. However, I recently added a Rasp Pi with Home Assistant. But, I shut that down, and this doesn't stop.

 

[GeneM]

That utility was/is designed to work with the earlier firmware versions, 380 and before. It is not compatible with later firmware versions.

What! OMG. What are my options? All this config, VPNs, certificates, .... I'd live with the log issue rather than doing all this reconfig from scratch (if I wasn't hosting a bot!).

Is this really what's expected of everyone at (each | major) firmware upgrade?

 

[EmeraldDeer]

What! OMG. What are my options? All this config, VPNs, certificates, .... I'd live with the log issue rather than doing all this reconfig from scratch (if I wasn't hosting a bot!).

Is this really what's expected of everyone at (each | major) firmware upgrade?

Do you think if may be caused by your Wemo devices?
Do you notice anything unusual in output of Network Tools>Netstat>{Click Netstat button} such as many connections from specific devices?

 

[GeneM]

I'm considering editing the files:

/proc/sys/net/core/message_cost
/proc/sys/net/core/message_burst​

to limit suppression. A simple reboot should get them back to 5 and 10.
(Linux: Getting rid of “net_ratelimit: N callbacks suppressed” messages)

 

[ColinTaylor]

Is this really what's expected of everyone at (each | major) firmware upgrade?

A reset and manual configuration would normally only required when going from stock Asus firmware to Merlin's for the first time, or when going between major releases (i.e. 380 to 382, or 382 to 384). Very very rarely there might be an exception to this that will be detailed in the release notes. That said, if the router is misbehaving and the problem cannot be determined then a reset and reconfigure usually sorts it out.

Not seeing it...
Anything stand out to you?

Can't see anything obvious. Do you have IPv6 enabled on your WAN interface?

 

[ColinTaylor]

I'm considering editing the files:

/proc/sys/net/core/message_cost
/proc/sys/net/core/message_burst​

to limit suppression. A simple reboot should get them back to 5 and 10.
(Linux: Getting rid of “net_ratelimit: N callbacks suppressed” messages)

I was just about to post the same suggestion. Try printk_ratelimit as well.

 

[ColinTaylor]

Firewall>General> Is "Enable DoS protection" Yes

Try disabling that.

 

[GeneM]

Try printk_ratelimit as well.

SSH to the router w/admin is not letting me edit the files.
The site I found that suggests: sysctl -w net.core.message_cost=0
sysctl isn't there (or isn't there for me) either.
I haven't used Linux since HP-UX in the early 90s!

Not seeing anything strange in WireShark. Maybe I should just live with this.

Or: Given the nvram utility is not an option, I'm wondering whether to factory reset and just restore my settings and jffs partition.
As I see you're on that nvram page, what do you think? Is this settings file just a memory map dump that may still effect me?
I guess I could see these stop before I do the settings restore...
Of course, it will, then the restore will start them, and .... you know how it goes.

 

[ColinTaylor]

Use this format:

echo 0 > /proc/sys/net/core/message_cost

 

[GeneM]

Do you think if may be caused by your Wemo devices?

I'm starting to think that. I can go yank the 6 of them...

Do you notice anything unusual in output of Network Tools>Netstat>{Click Netstat button} such as many connections from specific devices?

(I think) big time... Attaching a txt file.

 

[GeneM]

Use this format:

echo 0 > /proc/sys/net/core/message_cost

LMAO Getting too old.

You gotta love-it when trying to trace a log message has you moving furniture.
Ok, yanked all 6 Wemos - and that appears to have stopped the logging.

Now - off to put one back at a time.

 

[EmeraldDeer]

I'm starting to think that. I can go yank the 6 of them...



(I think) big time... Attaching a txt file.

So what is miniupnpd? Is that a music server? What would that have to do with a Wemo?

tcp        0      0 0.0.0.0:49583           0.0.0.0:*               LISTEN      1616/miniupnpd
tcp        0      0 router.asus.com:49583   WemoMini193:33730       TIME_WAIT   -
tcp        0      0 router.asus.com:49583   WemoMini93F:57588       TIME_WAIT   -
tcp        0      0 router.asus.com:49583   WemoMini93F:57585       TIME_WAIT   -
tcp        0      0 router.asus.com:49583   WemoMini618:59344       TIME_WAIT   -

 

[ColinTaylor]

So what is miniupnpd? Is that a music server? What would that have to do with a Wemo?

Nothing to do with music. It's the UPnP IGD, perfectly normal.

 

[EmeraldDeer]

Nothing to do with music or Wemo. It's the UPnP IGD, perfectly normal.

So we are back to trying to see what the repeated error messages actually are, not just how many of them there are in bunches.