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

FS#3907 - TL-WDR4310 v1 random reboots #8906

Open
openwrt-bot opened this issue Jun 29, 2021 · 5 comments
Open

FS#3907 - TL-WDR4310 v1 random reboots #8906

openwrt-bot opened this issue Jun 29, 2021 · 5 comments
Labels

Comments

@openwrt-bot
Copy link

bright357:

Device Model TP-Link TL-WDR4310 v1
Firmware Version OpenWrt SNAPSHOT r17053-76cc8a036c / LuCI Master git-21.163.60157-1bcb125(The same problem exists in other versions,Firmware Version 15.5/18.06/19.0.7/SNAPSHOT)
Kernel Version 5.4.128

1.The second router (TL-WDR4310) is wirelessly set to client mode to connect to the first router.

  1. By observing the Netlink Bandwidth Monitor, when the number of concurrent connections of the second route (TL-WDR4310) connected to the device reaches more than 400K, the second route may restart randomly (observe data before failure, such as upload The total traffic is about 20GB, and the total download traffic is about 20GB).
    When the upload speed is greater than 1MB and for a long time, the higher the frequency of failures, and the download speed is greater than 1MB and for a long time, it seems that there is no problem.

3.system.log

Mon Jun 28 14:44:25 2021 daemon.info dnsmasq[2775]: reading /tmp/resolv.conf.d/resolv.conf.auto
Mon Jun 28 14:44:25 2021 daemon.info dnsmasq[2775]: using only locally-known addresses for domain test
Mon Jun 28 14:44:25 2021 daemon.info dnsmasq[2775]: using only locally-known addresses for domain onion
Mon Jun 28 14:44:25 2021 daemon.info dnsmasq[2775]: using only locally-known addresses for domain localhost
Mon Jun 28 14:44:25 2021 daemon.info dnsmasq[2775]: using only locally-known addresses for domain local
Mon Jun 28 14:44:25 2021 daemon.info dnsmasq[2775]: using only locally-known addresses for domain invalid
Mon Jun 28 14:44:25 2021 daemon.info dnsmasq[2775]: using only locally-known addresses for domain bind
Mon Jun 28 14:44:25 2021 daemon.info dnsmasq[2775]: using only locally-known addresses for domain lan
Mon Jun 28 14:44:25 2021 daemon.info dnsmasq[2775]: using nameserver 192.168.3.1#53
Mon Jun 28 14:44:26 2021 daemon.info procd: - init complete -
Mon Jun 28 14:44:26 2021 user.notice firewall: Reloading firewall due to ifup of wlan1 (wlan1)
Mon Jun 28 14:44:27 2021 daemon.err odhcp6c[2064]: Failed to send SOLICIT message to ff02::1:2 (Operation not permitted)
------------------- rebootting ----------------------
Tue Jun 29 11:18:57 2021 user.notice nlbwmon: Reloading nlbwmon due to ifup of wlan1 (wlan1)
Tue Jun 29 11:18:59 2021 daemon.notice miniupnpd[2979]: shutting down MiniUPnPd
Tue Jun 29 11:18:59 2021 daemon.err nmbd[3276]: [2021/06/29 11:18:59.898309, 0] ../../lib/util/become_daemon.c:136(daemon_ready)
Tue Jun 29 11:18:59 2021 daemon.err nmbd[3276]: daemon_ready: daemon 'nmbd' finished starting up and ready to serve connections
Tue Jun 29 11:19:00 2021 user.info adblock-4.1.3[3739]: backup directory '/tmp/adblock-Backup' created
Tue Jun 29 11:19:00 2021 user.info adblock-4.1.3[3739]: adblock instance started ::: action: start, priority: 0, pid: 3739
Tue Jun 29 11:19:00 2021 daemon.notice miniupnpd[3845]: HTTP listening on port 5000
Tue Jun 29 11:19:00 2021 daemon.notice miniupnpd[3845]: HTTP IPv6 address given to control points : [fd02:1653:346d::1]
Tue Jun 29 11:19:00 2021 daemon.notice miniupnpd[3845]: Listening for NAT-PMP/PCP traffic on port 5351

PS:CPU load average and memory are normal.

@attila-lendvai
Copy link

i've also seen some random reboots on 22.03.0-rc4 (WDR4300 running kernel 5.10.120).

not sure about the load, but:

 3840     1 root     R     1956   2%  54% /usr/sbin/miniupnpd -f /var/etc/miniupnpd.conf
    8     2 root     SW       0   0%  30% [ksoftirqd/0]
 9291     2 root     IW       0   0%   7% [kworker/u2:3-ph]
 4559  1536 root     S     1228   1%   3% /usr/sbin/dropbear -F -P /var/run/dropbear.1.pid -p 22 -K 300 -T 3 -2
 1140     1 root     S     1464   1%   1% /sbin/logread -f -F /var/log/syslog -p /var/run/logread.1.pid -S 0
  350     2 root     IW<      0   0%   1% [kworker/0:1H-ev]
10501     2 root     IW       0   0%   1% [kworker/0:1-eve]
11974  4560 root     R     1324   1%   1% top
  122     2 root     SW       0   0%   1% [kcompactd0]

miniupnpd has a headache:

Thu Jun 30 15:38:27 2022 daemon.err miniupnpd[12260]: send_batch: mnl_cb_run returned -1
Thu Jun 30 15:38:27 2022 daemon.err miniupnpd[12260]: nft_send_rule(0x77ebebd0, 8, 2) send_batch failed -4
Thu Jun 30 15:38:32 2022 daemon.err miniupnpd[12260]: send_batch: mnl_cb_run returned -1
Thu Jun 30 15:38:32 2022 daemon.err miniupnpd[12260]: nft_send_rule(0x77d4c030, 8, 2) send_batch failed -4
Thu Jun 30 15:38:41 2022 authpriv.info dropbear[12447]: Child connection from 121.167.42.20:55870
Thu Jun 30 15:38:46 2022 daemon.err miniupnpd[12260]: send_batch: mnl_cb_run returned -1
Thu Jun 30 15:38:46 2022 daemon.err miniupnpd[12260]: nft_send_rule(0x77d5a030, 8, 2) send_batch failed -4
Thu Jun 30 15:38:48 2022 daemon.err miniupnpd[12260]: send_batch: mnl_cb_run returned -1
Thu Jun 30 15:38:48 2022 daemon.err miniupnpd[12260]: nft_send_rule(0x77d6f9d0, 8, 2) send_batch failed -4
Thu Jun 30 15:39:02 2022 authpriv.warn dropbear[12447]: Login attempt for nonexistent user
Thu Jun 30 15:39:04 2022 authpriv.info dropbear[12447]: Exit before auth from <121.167.42.20:55870>: Exited normally
Thu Jun 30 15:39:06 2022 daemon.err miniupnpd[12260]: send_batch: mnl_cb_run returned -1
Thu Jun 30 15:39:06 2022 daemon.err miniupnpd[12260]: nft_send_rule(0x77d6f9d0, 8, 2) send_batch failed -4
Thu Jun 30 15:39:06 2022 daemon.err miniupnpd[12260]: send_batch: mnl_cb_run returned -1
Thu Jun 30 15:39:06 2022 daemon.err miniupnpd[12260]: nft_send_rule(0x77ebedc0, 8, 2) send_batch failed -4
Thu Jun 30 15:39:27 2022 daemon.err miniupnpd[12260]: send_batch: mnl_cb_run returned -1
Thu Jun 30 15:39:27 2022 daemon.err miniupnpd[12260]: nft_send_rule(0x77ebebd0, 8, 2) send_batch failed -4
Thu Jun 30 15:39:27 2022 daemon.err miniupnpd[12260]: send_batch: mnl_cb_run returned -1
Thu Jun 30 15:39:27 2022 daemon.err miniupnpd[12260]: nft_send_rule(0x77ebe9d0, 8, 2) send_batch failed -4
Thu Jun 30 15:39:46 2022 daemon.err miniupnpd[12260]: send_batch: mnl_cb_run returned -1
Thu Jun 30 15:39:46 2022 daemon.err miniupnpd[12260]: nft_send_rule(0x77ebebd0, 8, 2) send_batch failed -4
Thu Jun 30 15:39:46 2022 daemon.err miniupnpd[12260]: send_batch: mnl_cb_run returned -1
Thu Jun 30 15:39:46 2022 daemon.err miniupnpd[12260]: nft_send_rule(0x77ebedc0, 8, 2) send_batch failed -4
Thu Jun 30 15:40:00 2022 cron.err crond[1826]: USER root pid 12493 cmd /root/upstream-watchdog.sh
Thu Jun 30 15:40:06 2022 daemon.err miniupnpd[12260]: send_batch: mnl_cb_run returned -1
Thu Jun 30 15:40:06 2022 daemon.err miniupnpd[12260]: nft_send_rule(0x77d6f9e0, 8, 2) send_batch failed -4
Thu Jun 30 15:40:06 2022 daemon.err miniupnpd[12260]: send_batch: mnl_cb_run returned -1
Thu Jun 30 15:40:06 2022 daemon.err miniupnpd[12260]: nft_send_rule(0x77d4c030, 8, 2) send_batch failed -4

@attila-lendvai
Copy link

i have left a logread -f open, and this is what i see at the next reboot (not very useful):

Thu Jun 30 17:30:36 2022 daemon.err miniupnpd[12260]: refresh_nft_cache: mnl_cb_run returned -1
Thu Jun 30 17:30:36 2022 daemon.err miniupnpd[12260]: ioctl(s, SIOCGIFADDR, ...): Address not available
Thu Jun 30 17:30:36 2022 daemon.err miniupnpd[12260]: refresh_nft_cache: mnl_cb_run returned -1
Thu Jun 30 17:30:36 2022 daemon.err miniupnpd[12260]: send_batch: mnl_cb_run returned -1
Thu Jun 30 17:30:36 2022 daemon.err miniupnpd[12260]: nft_send_rule(0x77d55d30, 6, 2) send_batch failed -4
Thu Jun 30 17:30:36 2022 daemon.err miniupnpd[12260]: refresh_nft_cache: mnl_cb_run returned -1
Thu Jun 30 17:30:36 2022 daemon.err miniupnpd[12260]: ioctl(s, SIOCGIFADDR, ...): Address not available
Thu Jun 30 17:30:36 2022 daemon.err miniupnpd[12260]: refresh_nft_cache: mnl_cb_run returned -1
Thu Jun 30 17:30:36 2022 daemon.err miniupnpd[12260]: refresh_nft_cache: mnl_cb_run returned -1
Thu Jun 30 17:30:36 2022 daemon.err miniupnpd[12260]: send_batch: mnl_cb_run returned -1
Thu Jun 30 17:30:36 2022 daemon.err miniupnpd[12260]: nft_send_rule(0x77d43f30, 6, 2) send_batch failed -4
Thu Jun 30 17:30:36 2022 daemon.err miniupnpd[12260]: Failed to add NAT-PMP 36721 tcp->10.0.8.103:22000 'NAT-PMP 36721 tcp'
Thu Jun 30 17:30:36 2022 daemon.err miniupnpd[12260]: ioctl(s, SIOCGIFADDR, ...): Address not available
Thu Jun 30 17:30:36 2022 daemon.err miniupnpd[12260]: Failed to get ip address for interface eth0.2
Thu Jun 30 17:30:36 2022 daemon.err miniupnpd[12260]: refresh_nft_cache: mnl_cb_run returned -1
Thu Jun 30 17:30:36 2022 daemon.err miniupnpd[12260]: ioctl(s, SIOCGIFADDR, ...): Address not available
Thu Jun 30 17:30:36 2022 daemon.err miniupnpd[12260]: refresh_nft_cache: mnl_cb_run returned -1
Thu Jun 30 17:30:36 2022 daemon.err miniupnpd[12260]: refresh_nft_cache: mnl_cb_run returned -1
Thu Jun 30 17:30:36 2022 daemon.err miniupnpd[12260]: send_batch: mnl_cb_run returned -1
Thu Jun 30 17:30:36 2022 daemon.err miniupnpd[12260]: nft_send_rule(0x77d45480, 6, 2) send_batch failed -4
Thu Jun 30 17:30:36 2022 daemon.err miniupnpd[12260]: Failed to add NAT-PMP 36721 tcp->10.0.8.103:22000 'NAT-PMP 36721 tcp'
Thu Jun 30 17:30:36 2022 daemon.err miniupnpd[12260]: refresh_nft_cache: mnl_cb_run returned -1
Thu Jun 30 17:30:36 2022 daemon.err miniupnpd[12260]: ioctl(s, SIOCGIFADDR, ...): Address not available
Thu Jun 30 17:30:37 2022 daemon.err miniupnpd[12260]: refresh_nft_cache: mnl_cb_run returned -1
Thu Jun 30 17:30:37 2022 daemon.err miniupnpd[12260]: refresh_nft_cache: mnl_cb_run returned -1
Thu Jun 30 17:30:37 2022 daemon.err miniupnpd[12260]: send_batch: mnl_cb_run returned -1
Thu Jun 30 17:30:37 2022 daemon.err miniupnpd[12260]: nft_send_rule(0x77d70960, 6, 0) send_batch failed -4
Thu Jun 30 17:30:37 2022 daemon.err miniupnpd[12260]: Failed to add NAT-PMP 16703 tcp->10.0.8.103:22000 'NAT-PMP 16703 tcp'
Thu Jun 30 17:30:37 2022 daemon.err miniupnpd[12260]: refresh_nft_cache: mnl_cb_run returned -1
Thu Jun 30 17:30:37 2022 daemon.err miniupnpd[12260]: ioctl(s, SIOCGIFADDR, ...): Address not available
Thu Jun 30 17:30:37 2022 daemon.notice netifd: Interface 'wan' is now up
Thu Jun 30 17:30:37 2022 daemon.info dnsmasq[1]: reading /tmp/resolv.conf.d/resolv.conf.auto
Thu Jun 30 17:30:37 2022 daemon.info dnsmasq[1]: using nameserver 8.8.4.4#53
Thu Jun 30 17:30:37 2022 daemon.info dnsmasq[1]: using nameserver 213.46.246.53#53
Thu Jun 30 17:30:37 2022 daemon.err miniupnpd[12260]: refresh_nft_cache: mnl_cb_run returned -1
Thu Jun 30 17:30:37 2022 daemon.info dnsmasq[1]: using nameserver 1.1.1.1#53
Thu Jun 30 17:30:37 2022 daemon.info dnsmasq[1]: using nameserver 80.244.99.36#53
Thu Jun 30 17:30:37 2022 daemon.info dnsmasq[1]: using nameserver 80.244.99.37#53
Thu Jun 30 17:30:37 2022 daemon.info dnsmasq[1]: using only locally-known addresses for test
Thu Jun 30 17:30:37 2022 daemon.info dnsmasq[1]: using only locally-known addresses for onion
Thu Jun 30 17:30:37 2022 daemon.info dnsmasq[1]: using only locally-known addresses for localhost
Thu Jun 30 17:30:37 2022 daemon.info dnsmasq[1]: using only locally-known addresses for local
Thu Jun 30 17:30:37 2022 daemon.info dnsmasq[1]: using only locally-known addresses for invalid
Thu Jun 30 17:30:37 2022 daemon.info dnsmasq[1]: using only locally-known addresses for bind
Thu Jun 30 17:30:37 2022 daemon.info dnsmasq[1]: using only locally-known addresses for lan
Thu Jun 30 17:30:37 2022 daemon.err miniupnpd[12260]: send_batch: mnl_cb_run returned -1
Thu Jun 30 17:30:37 2022 daemon.err miniupnpd[12260]: nft_send_rule(0x77d1bb40, 6, 0) send_batch failed -4
Thu Jun 30 17:30:37 2022 daemon.err miniupnpd[12260]: refresh_nft_cache: mnl_cb_run returned -1
Thu Jun 30 17:30:37 2022 daemon.err miniupnpd[12260]: refresh_nft_cache: mnl_cb_run returned -1
Thu Jun 30 17:30:37 2022 daemon.err miniupnpd[12260]: refresh_nft_cache: mnl_cb_run returned -1
Thu Jun 30 17:30:37 2022 daemon.err miniupnpd[12260]: send_batch: mnl_cb_run returned -1
Thu Jun 30 17:30:37 2022 daemon.err miniupnpd[12260]: nft_send_rule(0x77d54400, 6, 2) send_batch failed -4
Thu Jun 30 17:30:37 2022 daemon.err miniupnpd[12260]: Failed to add NAT-PMP 16703 tcp->10.0.8.103:22000 'NAT-PMP 16703 tcp'
Thu Jun 30 17:31:49 2022 daemon.err miniupnpd[12260]: refresh_nft_cache: mnl_cb_run returned -1
Thu Jun 30 17:31:49 2022 daemon.err miniupnpd[12260]: refresh_nft_cache: mnl_cb_run returned -1
Thu Jun 30 17:31:49 2022 daemon.err miniupnpd[12260]: refresh_nft_cache: mnl_cb_run returned -1
Thu Jun 30 17:31:49 2022 daemon.err miniupnpd[12260]: send_batch: mnl_cb_run returned -1
Thu Jun 30 17:31:49 2022 daemon.err miniupnpd[12260]: nft_send_rule(0x77d44cc0, 6, 0) send_batch failed -4
Thu Jun 30 17:31:49 2022 daemon.err miniupnpd[12260]: Failed to add NAT-PMP 16703 tcp->10.0.8.103:22000 'NAT-PMP 16703 tcp'
Thu Jun 30 17:31:49 2022 daemon.err miniupnpd[12260]: refresh_nft_cache: mnl_cb_run returned -1
Thu Jun 30 17:31:49 2022 daemon.err miniupnpd[12260]: refresh_nft_cache: mnl_cb_run returned -1
Thu Jun 30 17:31:49 2022 daemon.err miniupnpd[12260]: send_batch: mnl_cb_run returned -1
Thu Jun 30 17:31:49 2022 daemon.err miniupnpd[12260]: nft_send_rule(0x77d1a220, 6, 0) send_batch failed -4
Thu Jun 30 17:31:54 2022 daemon.err miniupnpd[12260]: refresh_nft_cache: mnl_cb_run returned -1
Thu Jun 30 17:31:54 2022 daemon.err miniupnpd[12260]: refresh_nft_cache: mnl_cb_run returned -1
Failed to find log object: Not found
Failed to find log object: Not found
Failed to find log object: Not found
Failed to find log object: Not found
Failed to find log object: Not found

i have watchcat set up, but i don't think it's involved, because nothing is visible in the log.

@yuklin
Copy link

yuklin commented Jul 26, 2022

@attila-lendvai

I find my device restart every 12 hour in 43200 secs too, than i check service list, i find this quite watchcat running happily background.

i cat /etc/config/watchcat, it will reboot device if ping 8.8.8.8 not works every 2 6hour period

what a good cat, if it may put some log in dmesg to save some poor guy a lof of debug time

@yuklin
Copy link

yuklin commented Jul 26, 2022

service watchcat stop !

@attila-lendvai
Copy link

meanwhile i realized that i also had not only watchcat running, but even a script that i wrote previously.

it's just that there was so much noise in the log from the unrelated miniupnp bug that i haven't seen the watchdogs barking before they rebooted the router.

@yuklin thanks for the heads up, though!

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

No branches or pull requests

3 participants