Router fails at 2PM

Installing and Using OpenWrt
1

Hi there,
My router often (though not always) fails around 2PM EST, with what seems to be increasing regularity. I didn't think too much about the pattern, until I got fed up and bought a brand-new router and on day 1 it, too, failed around 2PM EST. Most of the time, a soft reboot (logging into Luci) fixes it; sometimes I've had to reboot the cable modem too. One time, toggling the wi-fi switch on the back of the old router fixed it; I hadn't thought to try that any other time though. Both ethernet and wi-fi fail when it fails.

The old router is a TP-Link WDR-4300 v1 and the new one is a TP-Link Archer C7 1750 v5. Both running OpenWRT 19.07.4. The old one failed from time to time on older builds too, which provided motivation to keep it up to date. But the fact that a new router fails with the same pattern has me WTFing all over the place.

Any suggestions on diagnosing this issue?

Thanks for hearing me out!

2

wow, this is interesting, a computational mystery.

when setting up the new router, did you copy configs from the old router?

are both routers plugged into a same UPS?

3

What does "fail" mean in this context? Try to be as specific as possible.

Also, is this one of those things where your ISP is requiring a DHCP renewal every day at this time, and then failing to actually answer your router's DHCP request or something similar?

2 Likes
4

Thanks for the replies!

I configured the new router fresh; however, following the same guides, and using the same public key. So they're very similar; the biggest difference probably being old one having had a few automatic upgrades.

Definition of fail is a good question! All clients (via Ethernet, 2.4g, 5g; a mac, 3 windows laptops, some iOS, some androids) report that they have no internet. I can still browse to luci or ssh in, so the LAN is still up. I don't see any obvious errors on the status page. I didn't think to check logs until after rebooting; are there any persistent logs I could check?

Is there any way I can test the DHCP hypothesis? Or setup a cron job to re-up the DHCP automatically? I was thinking at one point that if the clients can detect no internet, surely the router could, but that's beyond my network skills.

5

There are no automatic upgrades in standard OpenWrt so wondering what this means. You should not be doing opkg upgrade that's generally unsafe.

Next time you have this happen you should grab the logs, and screenshot the summary pages in Luci.

It sounds like a problem on the WAN since LAN and Luci still work. So I'm guessing the logs and summary stats will help a lot

1 Like
6

What i would have guessed too.
ifstatus wan should show the leasetime? Might be worth looking and seeing if it is 12/24 hours and that keeps landing on 2pm.

7

By automatic upgrades, what I meant there was upgrading the firmware using the sysupgrade firmware images and the option to preserve config. Seemed to work a treat. Automatic was the wrong word to use there.

For logs, will the System and Kernel logs exposed in luci be enough (if I capture before rebooting)? Any log settings I should make in anticipation? Will screenshot the summary pages too.

Finally, ifstatus wan shows a leasetime of what I interpret as ~30h:
"leasetime": 109579
and fwiw: "uptime": 69567 (last boot was ~19 hours ago)

8

Normally a DHCP client tries to renew about halfway through the lease if I remember correctly, and then continues to try if it doesn't work.

Rather than reboot your router, next time it happens try disabling and then reenabling your WAN interface.

9

Hi again!
Unfortunately, I didn't see the last message before it happened again, so I didn't try the WAN re-enable trick. This time, it happened in the morning and rebooting the router didn't solve it. Nor did unplugging/replugging the power from the cable modem. Power cycling the whole shebang (via the power bar they're both attached to) did solve it.

My colleague I was on zoom with at the time had also been having internet issues today, as have others, so I suspect the fundamental issue is local ISPs struggling to keep up with all us WFH types on Zoom all day. So, what I hope to get from this thread is a mitigation; maybe there's something OpenWRT can do, either in response to the hiccup, or preventatively every morning. To that end I'll attach the tail of the system.log I captured today. It is a bit alarming actually (jump to end of post). possible DNS-rebind attack detected! I was in meetings all morning, so its possible the timings reported are because I stopped trying to fix it (and switched to my phone). Anyway, hope someone can make sense of this!

Thanks again for your time!

System.log (partial due to post size):

Wed Dec  2 08:02:08 2020 daemon.info dnsmasq-dhcp[2064]: DHCPREQUEST(br-lan) 192.168.1.157 9c:eb:e8:c8:e5:c3
Wed Dec  2 08:02:08 2020 daemon.info dnsmasq-dhcp[2064]: DHCPACK(br-lan) 192.168.1.157 9c:eb:e8:c8:e5:c3 CAN05-Esler
Wed Dec  2 08:02:08 2020 daemon.info dnsmasq[2064]: read /etc/hosts - 4 addresses
Wed Dec  2 08:02:08 2020 daemon.info dnsmasq[2064]: read /tmp/hosts/odhcpd - 1 addresses
Wed Dec  2 08:02:08 2020 daemon.info dnsmasq[2064]: read /tmp/hosts/dhcp.cfg01411c - 2 addresses
Wed Dec  2 08:02:08 2020 daemon.info dnsmasq-dhcp[2064]: read /etc/ethers - 0 addresses
Wed Dec  2 08:02:09 2020 daemon.info dnsmasq[2064]: read /etc/hosts - 4 addresses
Wed Dec  2 08:02:09 2020 daemon.info dnsmasq[2064]: read /tmp/hosts/odhcpd - 2 addresses
Wed Dec  2 08:02:09 2020 daemon.info dnsmasq[2064]: read /tmp/hosts/dhcp.cfg01411c - 2 addresses
Wed Dec  2 08:02:09 2020 daemon.info dnsmasq-dhcp[2064]: read /etc/ethers - 0 addresses
Wed Dec  2 08:07:48 2020 daemon.info dnsmasq-dhcp[2064]: DHCPREQUEST(br-lan) 192.168.1.173 5c:f7:e6:89:9a:4d
Wed Dec  2 08:07:48 2020 daemon.info dnsmasq-dhcp[2064]: DHCPACK(br-lan) 192.168.1.173 5c:f7:e6:89:9a:4d PeterMahySI0303
Wed Dec  2 08:13:10 2020 daemon.info dnsmasq-dhcp[2064]: DHCPREQUEST(br-lan) 192.168.1.235 1c:dc:f9:df:25:86
Wed Dec  2 08:13:10 2020 daemon.info dnsmasq-dhcp[2064]: DHCPACK(br-lan) 192.168.1.235 1c:dc:f9:df:25:86
Wed Dec  2 08:13:23 2020 daemon.info dnsmasq-dhcp[2064]: DHCPREQUEST(br-lan) 192.168.1.203 34:c3:d2:f8:9f:8b
Wed Dec  2 08:13:23 2020 daemon.info dnsmasq-dhcp[2064]: DHCPACK(br-lan) 192.168.1.203 34:c3:d2:f8:9f:8b android-b4ce4cfe98681d91
Wed Dec  2 08:40:28 2020 daemon.info hostapd: wlan1: STA 8c:85:90:bf:e9:b1 IEEE 802.11: authenticated
Wed Dec  2 08:40:28 2020 daemon.info hostapd: wlan1: STA 8c:85:90:bf:e9:b1 IEEE 802.11: associated (aid 4)
Wed Dec  2 08:40:28 2020 daemon.notice hostapd: wlan1: AP-STA-CONNECTED 8c:85:90:bf:e9:b1
Wed Dec  2 08:40:28 2020 daemon.info hostapd: wlan1: STA 8c:85:90:bf:e9:b1 WPA: pairwise key handshake completed (RSN)
Wed Dec  2 08:40:29 2020 daemon.info dnsmasq-dhcp[2064]: DHCPREQUEST(br-lan) 192.168.1.173 5c:f7:e6:89:9a:4d
Wed Dec  2 08:40:29 2020 daemon.info dnsmasq-dhcp[2064]: DHCPACK(br-lan) 192.168.1.173 5c:f7:e6:89:9a:4d PeterMahySI0303
Wed Dec  2 08:40:29 2020 daemon.info dnsmasq-dhcp[2064]: DHCPREQUEST(br-lan) 192.168.1.124 8c:85:90:bf:e9:b1
Wed Dec  2 08:40:29 2020 daemon.info dnsmasq-dhcp[2064]: DHCPACK(br-lan) 192.168.1.124 8c:85:90:bf:e9:b1 PeterMahySI0303
Wed Dec  2 08:44:38 2020 daemon.info dnsmasq-dhcp[2064]: DHCPREQUEST(br-lan) 192.168.1.157 9c:eb:e8:c8:e5:c3
Wed Dec  2 08:44:38 2020 daemon.info dnsmasq-dhcp[2064]: DHCPACK(br-lan) 192.168.1.157 9c:eb:e8:c8:e5:c3 CAN05-Esler
Wed Dec  2 08:44:38 2020 daemon.info dnsmasq[2064]: read /etc/hosts - 4 addresses
Wed Dec  2 08:44:38 2020 daemon.info dnsmasq[2064]: read /tmp/hosts/odhcpd - 1 addresses
Wed Dec  2 08:44:38 2020 daemon.info dnsmasq[2064]: read /tmp/hosts/dhcp.cfg01411c - 2 addresses
Wed Dec  2 08:44:38 2020 daemon.info dnsmasq-dhcp[2064]: read /etc/ethers - 0 addresses
Wed Dec  2 08:44:39 2020 daemon.info dnsmasq[2064]: read /etc/hosts - 4 addresses
Wed Dec  2 08:44:39 2020 daemon.info dnsmasq[2064]: read /tmp/hosts/odhcpd - 2 addresses
Wed Dec  2 08:44:39 2020 daemon.info dnsmasq[2064]: read /tmp/hosts/dhcp.cfg01411c - 2 addresses
Wed Dec  2 08:44:39 2020 daemon.info dnsmasq-dhcp[2064]: read /etc/ethers - 0 addresses
Wed Dec  2 08:46:02 2020 daemon.info dnsmasq-dhcp[2064]: DHCPREQUEST(br-lan) 192.168.1.169 5c:c1:d7:ab:73:17
Wed Dec  2 08:46:02 2020 daemon.info dnsmasq-dhcp[2064]: DHCPACK(br-lan) 192.168.1.169 5c:c1:d7:ab:73:17 Samsung
Wed Dec  2 08:46:10 2020 daemon.notice hostapd: wlan1: AP-STA-DISCONNECTED 8c:85:90:bf:e9:b1
Wed Dec  2 08:46:10 2020 daemon.info hostapd: wlan1: STA 8c:85:90:bf:e9:b1 IEEE 802.11: disassociated due to inactivity
Wed Dec  2 08:46:11 2020 daemon.info hostapd: wlan1: STA 8c:85:90:bf:e9:b1 IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)
Wed Dec  2 08:52:47 2020 daemon.info hostapd: wlan1: STA 8c:85:90:bf:e9:b1 IEEE 802.11: authenticated
Wed Dec  2 08:52:47 2020 daemon.info hostapd: wlan1: STA 8c:85:90:bf:e9:b1 IEEE 802.11: associated (aid 4)
Wed Dec  2 08:52:47 2020 daemon.notice hostapd: wlan1: AP-STA-CONNECTED 8c:85:90:bf:e9:b1
Wed Dec  2 08:52:47 2020 daemon.info hostapd: wlan1: STA 8c:85:90:bf:e9:b1 WPA: pairwise key handshake completed (RSN)
Wed Dec  2 08:52:49 2020 daemon.info dnsmasq-dhcp[2064]: DHCPREQUEST(br-lan) 192.168.1.124 8c:85:90:bf:e9:b1
Wed Dec  2 08:52:49 2020 daemon.info dnsmasq-dhcp[2064]: DHCPACK(br-lan) 192.168.1.124 8c:85:90:bf:e9:b1 PeterMahySI0303
Wed Dec  2 08:52:52 2020 daemon.info dnsmasq-dhcp[2064]: DHCPREQUEST(br-lan) 192.168.1.173 5c:f7:e6:89:9a:4d
Wed Dec  2 08:52:52 2020 daemon.info dnsmasq-dhcp[2064]: DHCPACK(br-lan) 192.168.1.173 5c:f7:e6:89:9a:4d PeterMahySI0303
Wed Dec  2 08:53:48 2020 daemon.info dnsmasq-dhcp[2064]: DHCPREQUEST(br-lan) 192.168.1.173 5c:f7:e6:89:9a:4d
Wed Dec  2 08:53:48 2020 daemon.info dnsmasq-dhcp[2064]: DHCPACK(br-lan) 192.168.1.173 5c:f7:e6:89:9a:4d PeterMahySI0303
Wed Dec  2 08:53:50 2020 daemon.notice hostapd: wlan1: AP-STA-DISCONNECTED 8c:85:90:bf:e9:b1
Wed Dec  2 08:53:50 2020 daemon.info hostapd: wlan1: STA 8c:85:90:bf:e9:b1 IEEE 802.11: disassociated
Wed Dec  2 08:53:51 2020 daemon.info hostapd: wlan1: STA 8c:85:90:bf:e9:b1 IEEE 802.11: deauthenticated due to inactivity (timer DEAUTH/REMOVE)
Wed Dec  2 08:57:23 2020 daemon.info dnsmasq-dhcp[2064]: DHCPREQUEST(br-lan) 192.168.1.173 5c:f7:e6:89:9a:4d
Wed Dec  2 08:57:23 2020 daemon.info dnsmasq-dhcp[2064]: DHCPACK(br-lan) 192.168.1.173 5c:f7:e6:89:9a:4d PeterMahySI0303
Wed Dec  2 08:58:22 2020 daemon.info hostapd: wlan1: STA 60:67:20:2c:58:f4 IEEE 802.11: authenticated
Wed Dec  2 08:58:22 2020 daemon.info hostapd: wlan1: STA 60:67:20:2c:58:f4 IEEE 802.11: associated (aid 4)
Wed Dec  2 08:58:22 2020 daemon.notice hostapd: wlan1: STA-OPMODE-SMPS-MODE-CHANGED 60:67:20:2c:58:f4 off
Wed Dec  2 08:58:22 2020 daemon.notice hostapd: wlan1: AP-STA-CONNECTED 60:67:20:2c:58:f4
Wed Dec  2 08:58:22 2020 daemon.info hostapd: wlan1: STA 60:67:20:2c:58:f4 WPA: pairwise key handshake completed (RSN)
Wed Dec  2 08:58:27 2020 daemon.info dnsmasq-dhcp[2064]: DHCPDISCOVER(br-lan) 192.168.1.151 60:67:20:2c:58:f4
Wed Dec  2 08:58:27 2020 daemon.info dnsmasq-dhcp[2064]: DHCPOFFER(br-lan) 192.168.1.151 60:67:20:2c:58:f4
Wed Dec  2 08:58:27 2020 daemon.info dnsmasq[2064]: read /etc/hosts - 4 addresses
Wed Dec  2 08:58:27 2020 daemon.info dnsmasq[2064]: read /tmp/hosts/odhcpd - 3 addresses
Wed Dec  2 08:58:27 2020 daemon.info dnsmasq[2064]: read /tmp/hosts/dhcp.cfg01411c - 2 addresses
Wed Dec  2 08:58:27 2020 daemon.info dnsmasq-dhcp[2064]: read /etc/ethers - 0 addresses
Wed Dec  2 08:58:27 2020 daemon.info dnsmasq-dhcp[2064]: DHCPREQUEST(br-lan) 192.168.1.151 60:67:20:2c:58:f4
Wed Dec  2 08:58:27 2020 daemon.info dnsmasq-dhcp[2064]: DHCPACK(br-lan) 192.168.1.151 60:67:20:2c:58:f4 Mk-III
Wed Dec  2 09:03:23 2020 daemon.info dnsmasq[2064]: read /etc/hosts - 4 addresses
Wed Dec  2 09:03:23 2020 daemon.info dnsmasq[2064]: read /tmp/hosts/odhcpd - 2 addresses
Wed Dec  2 09:03:23 2020 daemon.info dnsmasq[2064]: read /tmp/hosts/dhcp.cfg01411c - 2 addresses
Wed Dec  2 09:03:23 2020 daemon.info dnsmasq-dhcp[2064]: read /etc/ethers - 0 addresses
Wed Dec  2 09:03:24 2020 daemon.info dnsmasq[2064]: read /etc/hosts - 4 addresses
Wed Dec  2 09:03:24 2020 daemon.info dnsmasq[2064]: read /tmp/hosts/odhcpd - 3 addresses
Wed Dec  2 09:03:24 2020 daemon.info dnsmasq[2064]: read /tmp/hosts/dhcp.cfg01411c - 2 addresses
Wed Dec  2 09:03:24 2020 daemon.info dnsmasq-dhcp[2064]: read /etc/ethers - 0 addresses
Wed Dec  2 09:08:45 2020 authpriv.info dropbear[4801]: Child connection from 192.168.1.151:55842
Wed Dec  2 09:08:46 2020 authpriv.notice dropbear[4801]: Pubkey auth succeeded for 'root' with key sha1!! b3:93:45:1e:ba:5f:8d:6d:00:3a:8b:84:a3:37:db:3e:6d:cf:f1:f3 from 192.168.1.151:55842
Wed Dec  2 09:20:44 2020 daemon.err uhttpd[1416]: luci: accepted login on / for root from 192.168.1.151
Wed Dec  2 09:36:46 2020 daemon.warn dnsmasq[2064]: possible DNS-rebind attack detected: canaryeast1.eastus.cloudapp.azure.com
Wed Dec  2 09:36:46 2020 daemon.warn dnsmasq[2064]: possible DNS-rebind attack detected: canaryeast3.eastus.cloudapp.azure.com
Wed Dec  2 09:41:02 2020 daemon.info dnsmasq-dhcp[2064]: DHCPREQUEST(br-lan) 192.168.1.169 5c:c1:d7:ab:73:17
Wed Dec  2 09:41:02 2020 daemon.info dnsmasq-dhcp[2064]: DHCPACK(br-lan) 192.168.1.169 5c:c1:d7:ab:73:17 Samsung
Wed Dec  2 10:29:18 2020 daemon.err uhttpd[1416]: luci: accepted login on /admin/status/syslog for root from 192.168.1.151
10

I'm assuming this log is from after you experienced the problem and rebooted? In which case it's useless. In any case I don't see anything in these logs.

Any problem that isn't solved by a reboot is a fairly serious problem I'd think. hard for a router to do much about it's connection if the ISP won't talk to it even after a reboot. If it is solved by power cycling the router without power cycling the ISP equipment then it's probably some kind of hardware/driver interaction where the hardware is in an inconsistent state. You might look at just replacing the router. Of course another option might be to use a power timer to turn it off every morning between 2:00 and 2:15

11

Blockquote I'm assuming this log is from after you experienced the problem and rebooted?

These are from before I rebooted. I'll also attach the kernel log below. Although, your description suggests it doesn't matter.

Blockquote You might look at just replacing the router.

This already is the replacement router :frowning:
I did restart this morning and no problems, so will look into the power timer and manually restart daily for now.
Cheers!

[    0.000000] Linux version 4.14.195 (builder@buildhost) (gcc version 7.5.0 (OpenWrt GCC 7.5.0 r11208-ce6496d796)) #0 Sun Sep 6 16:19:39 2020
[    0.000000] bootconsole [early0] enabled
[    0.000000] CPU0 revision is: 00019750 (MIPS 74Kc)
[    0.000000] MIPS: machine is TP-Link Archer C7 v5
[    0.000000] SoC: Qualcomm Atheros QCA956X ver 1 rev 0
[    0.000000] Determined physical RAM map:
[    0.000000]  memory: 08000000 @ 00000000 (usable)
[    0.000000] Initrd not found or empty - disabling initrd
[    0.000000] Primary instruction cache 64kB, VIPT, 4-way, linesize 32 bytes.
[    0.000000] Primary data cache 32kB, 4-way, VIPT, cache aliases, linesize 32 bytes
[    0.000000] Zone ranges:
[    0.000000]   Normal   [mem 0x0000000000000000-0x0000000007ffffff]
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000000000000-0x0000000007ffffff]
[    0.000000] Initmem setup node 0 [mem 0x0000000000000000-0x0000000007ffffff]
[    0.000000] On node 0 totalpages: 32768
[    0.000000] free_area_init_node: node 0, pgdat 804fbf70, node_mem_map 810090a0
[    0.000000]   Normal zone: 256 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 32768 pages, LIFO batch:7
[    0.000000] random: get_random_bytes called from 0x804ff740 with crng_init=0
[    0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
[    0.000000] pcpu-alloc: [0] 0 
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 32512
[    0.000000] Kernel command line: console=ttyS0,115200n8 rootfstype=squashfs,jffs2
[    0.000000] PID hash table entries: 512 (order: -1, 2048 bytes)
[    0.000000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
[    0.000000] Inode-cache hash table entries: 8192 (order: 3, 32768 bytes)
[    0.000000] Writing ErrCtl register=00000000
[    0.000000] Readback ErrCtl register=00000000
[    0.000000] Memory: 123296K/131072K available (4031K kernel code, 160K rwdata, 532K rodata, 1220K init, 212K bss, 7776K reserved, 0K cma-reserved)
[    0.000000] SLUB: HWalign=32, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] NR_IRQS: 51
[    0.000000] CPU clock: 775.000 MHz
[    0.000000] clocksource: MIPS: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 4932285024 ns
[    0.000008] sched_clock: 32 bits at 387MHz, resolution 2ns, wraps every 5541893118ns
[    0.008236] Calibrating delay loop... 385.84 BogoMIPS (lpj=1929216)
[    0.074782] pid_max: default: 32768 minimum: 301
[    0.079802] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.086787] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.097896] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.108295] futex hash table entries: 256 (order: -1, 3072 bytes)
[    0.114786] pinctrl core: initialized pinctrl subsystem
[    0.122329] NET: Registered protocol family 16
[    0.129824] PCI host bridge /ahb/pcie-controller@18250000 ranges:
[    0.136298]  MEM 0x0000000012000000..0x0000000013ffffff
[    0.141801]   IO 0x0000000000000000..0x0000000000000000
[    0.162000] PCI host bridge to bus 0000:00
[    0.166328] pci_bus 0000:00: root bus resource [mem 0x12000000-0x13ffffff]
[    0.173613] pci_bus 0000:00: root bus resource [io  0x0000]
[    0.179483] pci_bus 0000:00: root bus resource [??? 0x00000000 flags 0x0]
[    0.186647] pci_bus 0000:00: No busn resource found for root bus, will use [bus 00-ff]
[    0.195018] pci 0000:00:00.0: [168c:003c] type 00 class 0x028000
[    0.195071] pci 0000:00:00.0: reg 0x10: [mem 0x00000000-0x001fffff 64bit]
[    0.195122] pci 0000:00:00.0: reg 0x30: [mem 0x00000000-0x0000ffff pref]
[    0.195195] pci 0000:00:00.0: supports D1 D2
[    0.195366] pci_bus 0000:00: busn_res: [bus 00-ff] end is updated to 00
[    0.195389] pci 0000:00:00.0: BAR 0: assigned [mem 0x12000000-0x121fffff 64bit]
[    0.203143] pci 0000:00:00.0: BAR 6: assigned [mem 0x12200000-0x1220ffff pref]
[    0.213304] clocksource: Switched to clocksource MIPS
[    0.219513] NET: Registered protocol family 2
[    0.224875] TCP established hash table entries: 1024 (order: 0, 4096 bytes)
[    0.232231] TCP bind hash table entries: 1024 (order: 0, 4096 bytes)
[    0.238984] TCP: Hash tables configured (established 1024 bind 1024)
[    0.245823] UDP hash table entries: 256 (order: 0, 4096 bytes)
[    0.251991] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
[    0.258847] NET: Registered protocol family 1
[    0.263514] PCI: CLS 0 bytes, default 32
[    0.266046] Crashlog allocated RAM at address 0x3f00000
[    0.272677] workingset: timestamp_bits=30 max_order=15 bucket_order=0
[    0.283785] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    0.289927] jffs2: version 2.2 (NAND) (SUMMARY) (LZMA) (RTIME) (CMODE_PRIORITY) (c) 2001-2006 Red Hat, Inc.
[    0.308545] io scheduler noop registered
[    0.312683] io scheduler deadline registered (default)
[    0.318449] ar7200-usb-phy usb-phy: phy reset is missing
[    0.325575] pinctrl-single 1804002c.pinmux: 544 pins at pa b804002c size 68
[    0.333394] gpio-export gpio-export: 1 gpio(s) exported
[    0.339621] Serial: 8250/16550 driver, 16 ports, IRQ sharing enabled
[    0.348400] console [ttyS0] disabled
[    0.352204] 18020000.uart: ttyS0 at MMIO 0x18020000 (irq = 9, base_baud = 1562500) is a 16550A
[    0.361335] console [ttyS0] enabled
[    0.368905] bootconsole [early0] disabled
[    0.394551] m25p80 spi0.0: w25q128 (16384 Kbytes)
[    0.399463] 8 fixed-partitions partitions found on MTD device spi0.0
[    0.406053] Creating 8 MTD partitions on "spi0.0":
[    0.411005] 0x000000000000-0x000000020000 : "factory-uboot"
[    0.417458] 0x000000020000-0x000000040000 : "u-boot"
[    0.423192] 0x000000040000-0x000000050000 : "partition-table"
[    0.429813] 0x000000050000-0x000000060000 : "art"
[    0.435368] 0x000000060000-0x000000080000 : "info"
[    0.440947] 0x000000080000-0x0000000c0000 : "user-config"
[    0.447211] 0x0000000c0000-0x000000fc0000 : "firmware"
[    0.456890] 2 uimage-fw partitions found on MTD device firmware
[    0.463010] Creating 2 MTD partitions on "firmware":
[    0.468185] 0x000000000000-0x000000190000 : "kernel"
[    0.473961] 0x000000190000-0x000000f00000 : "rootfs"
[    0.479655] mtd: device 8 (rootfs) set to be root filesystem
[    0.485580] 1 squashfs-split partitions found on MTD device rootfs
[    0.491969] 0x000000450000-0x000000f00000 : "rootfs_data"
[    0.498171] 0x000000ff0000-0x000001000000 : "default-config"
[    0.505664] libphy: Fixed MDIO Bus: probed
[    1.183658] libphy: ag71xx_mdio: probed
[    1.190623] switch0: Atheros AR8337 rev. 2 switch registered on mdio-bus.0
[    1.844825] ag71xx 19000000.eth: connected to PHY at mdio-bus.0:00 [uid=004dd036, driver=Atheros AR8216/AR8236/AR8316]
[    1.856416] eth0: Atheros AG71xx at 0xb9000000, irq 4, mode: sgmii
[    1.865467] NET: Registered protocol family 10
[    1.875288] Segment Routing with IPv6
[    1.879155] NET: Registered protocol family 17
[    1.883838] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
[    1.897237] 8021q: 802.1Q VLAN Support v1.8
[    1.903573] hctosys: unable to open rtc device (rtc0)
[    1.914233] VFS: Mounted root (squashfs filesystem) readonly on device 31:8.
[    1.928155] Freeing unused kernel memory: 1220K
[    1.932834] This architecture does not have kernel memory protection.
[    2.548488] init: Console is alive
[    2.552203] init: - watchdog -
[    2.563345] random: fast init done
[    3.595744] kmodloader: loading kernel modules from /etc/modules-boot.d/*
[    3.826794] usbcore: registered new interface driver usbfs
[    3.832548] usbcore: registered new interface driver hub
[    3.838167] usbcore: registered new device driver usb
[    3.848889] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    3.857058] ehci-platform: EHCI generic platform driver
[    3.862673] ehci-platform 1b000000.usb: EHCI Host Controller
[    3.868599] ehci-platform 1b000000.usb: new USB bus registered, assigned bus number 1
[    3.876792] ehci-platform 1b000000.usb: irq 13, io mem 0x1b000000
[    3.903331] ehci-platform 1b000000.usb: USB 2.0 started, EHCI 1.00
[    3.910438] hub 1-0:1.0: USB hub found
[    3.914677] hub 1-0:1.0: 1 port detected
[    3.919758] kmodloader: done loading kernel modules from /etc/modules-boot.d/*
[    3.937657] init: - preinit -
[    4.413387] usb 1-1: new high-speed USB device number 2 using ehci-platform
[    4.676230] random: procd: uninitialized urandom read (4 bytes read)
[    5.067616] random: jshn: uninitialized urandom read (4 bytes read)
[    5.307855] random: jshn: uninitialized urandom read (4 bytes read)
[    5.708952] urandom_read: 2 callbacks suppressed
[    5.708959] random: jshn: uninitialized urandom read (4 bytes read)
[    5.766751] random: jshn: uninitialized urandom read (4 bytes read)
[    5.877863] random: jshn: uninitialized urandom read (4 bytes read)
[    6.875339] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[    6.881424] IPv6: ADDRCONF(NETDEV_UP): eth0.1: link is not ready
[    7.954676] eth0: link up (1000Mbps/Full duplex)
[    7.959539] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[    7.968349] IPv6: ADDRCONF(NETDEV_CHANGE): eth0.1: link becomes ready
[   10.139221] jffs2: notice: (511) jffs2_build_xattr_subsystem: complete building xattr subsystem, 6 of xdatum (3 unchecked, 3 orphan) and 63 of xref (3 dead, 2 orphan) found.
[   10.166383] mount_root: loading kmods from internal overlay
[   10.454572] kmodloader: loading kernel modules from /tmp/overlay/upper/etc/modules-boot.d/*
[   11.188454] SCSI subsystem initialized
[   11.233050] usb-storage 1-1:1.0: USB Mass Storage device detected
[   11.240014] scsi host0: usb-storage 1-1:1.0
[   11.244828] usbcore: registered new interface driver usb-storage
[   11.252042] kmodloader: done loading kernel modules from /tmp/overlay/upper/etc/modules-boot.d/*
[   11.604957] block: attempting to load /tmp/jffs_cfg/upper/etc/config/fstab
[   11.614856] block: extroot: not configured
[   11.619951] mount_root: switching to jffs2 overlay
[   11.646121] overlayfs: upper fs does not support tmpfile.
[   11.655735] urandom-seed: Seeding with /etc/urandom.seed
[   11.755249] eth0: link down
[   11.775666] procd: - early -
[   11.778728] procd: - watchdog -
[   12.275189] scsi 0:0:0:0: Direct-Access     Seagate  FA GoFlex Desk   0158 PQ: 0 ANSI: 4
[   12.286348] sd 0:0:0:0: [sda] 2930277167 512-byte logical blocks: (1.50 TB/1.36 TiB)
[   12.313392] sd 0:0:0:0: [sda] Write Protect is off
[   12.318386] sd 0:0:0:0: [sda] Mode Sense: 1c 00 00 00
[   12.318990] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[   12.361992]  sda: sda1
[   12.368362] sd 0:0:0:0: [sda] Attached SCSI disk
[   12.817276] EXT4-fs (sda1): recovery complete
[   12.821800] EXT4-fs (sda1): mounted filesystem with ordered data mode. Opts: 
[   12.865130] procd: - watchdog -
[   12.868642] procd: - ubus -
[   12.998461] random: ubusd: uninitialized urandom read (4 bytes read)
[   13.041672] random: ubusd: uninitialized urandom read (4 bytes read)
[   13.049489] procd: - init -
[   14.120270] kmodloader: loading kernel modules from /etc/modules.d/*
[   14.145606] ip6_tables: (C) 2000-2006 Netfilter Core Team
[   14.172234] Loading modules backported from Linux version v4.19.137-0-gc076c79e03c6
[   14.180194] Backport generated by backports.git v4.19.137-1-0-g60c3a249
[   14.205381] ip_tables: (C) 2000-2006 Netfilter Core Team
[   14.230464] nf_conntrack version 0.5.0 (2048 buckets, 8192 max)
[   14.331584] urngd: v1.0.2 started.
[   14.341254] xt_time: kernel timezone is -0000
[   14.447678] PPP generic driver version 2.4.2
[   14.464340] NET: Registered protocol family 24
[   14.525974] ath10k 4.19 driver, optimized for CT firmware, probing pci device: 0x3c.
[   14.545004] PCI: Enabling device 0000:00:00.0 (0000 -> 0002)
[   14.551014] ath10k_pci 0000:00:00.0: pci irq legacy oper_irq_mode 1 irq_mode 0 reset_mode 0
[   14.589793] random: crng init done
[   14.864033] ath10k_pci 0000:00:00.0: Direct firmware load for ath10k/fwcfg-pci-0000:00:00.0.txt failed with error -2
[   14.874944] ath10k_pci 0000:00:00.0: Falling back to user helper
[   15.062496] firmware ath10k!fwcfg-pci-0000:00:00.0.txt: firmware_loading_store: map pages failed
[   15.071873] ath10k_pci 0000:00:00.0: Direct firmware load for ath10k/pre-cal-pci-0000:00:00.0.bin failed with error -2
[   15.082956] ath10k_pci 0000:00:00.0: Falling back to user helper
[   15.464058] firmware ath10k!pre-cal-pci-0000:00:00.0.bin: firmware_loading_store: map pages failed
[   15.475159] ath10k_pci 0000:00:00.0: Direct firmware load for ath10k/QCA988X/hw2.0/ct-firmware-5.bin failed with error -2
[   15.486526] ath10k_pci 0000:00:00.0: Falling back to user helper
[   15.848446] firmware ath10k!QCA988X!hw2.0!ct-firmware-5.bin: firmware_loading_store: map pages failed
[   15.858868] ath10k_pci 0000:00:00.0: Direct firmware load for ath10k/QCA988X/hw2.0/ct-firmware-2.bin failed with error -2
[   15.870231] ath10k_pci 0000:00:00.0: Falling back to user helper
[   16.149999] firmware ath10k!QCA988X!hw2.0!ct-firmware-2.bin: firmware_loading_store: map pages failed
[   16.159820] ath10k_pci 0000:00:00.0: Direct firmware load for ath10k/QCA988X/hw2.0/firmware-6.bin failed with error -2
[   16.170907] ath10k_pci 0000:00:00.0: Falling back to user helper
[   16.351328] firmware ath10k!QCA988X!hw2.0!firmware-6.bin: firmware_loading_store: map pages failed
[   16.360904] ath10k_pci 0000:00:00.0: Direct firmware load for ath10k/QCA988X/hw2.0/firmware-5.bin failed with error -2
[   16.371989] ath10k_pci 0000:00:00.0: Falling back to user helper
[   16.557511] firmware ath10k!QCA988X!hw2.0!firmware-5.bin: firmware_loading_store: map pages failed
[   16.567062] ath10k_pci 0000:00:00.0: Direct firmware load for ath10k/QCA988X/hw2.0/firmware-4.bin failed with error -2
[   16.578149] ath10k_pci 0000:00:00.0: Falling back to user helper
[   16.757865] firmware ath10k!QCA988X!hw2.0!firmware-4.bin: firmware_loading_store: map pages failed
[   16.767420] ath10k_pci 0000:00:00.0: Direct firmware load for ath10k/QCA988X/hw2.0/firmware-3.bin failed with error -2
[   16.778508] ath10k_pci 0000:00:00.0: Falling back to user helper
[   16.961050] firmware ath10k!QCA988X!hw2.0!firmware-3.bin: firmware_loading_store: map pages failed
[   16.974564] ath10k_pci 0000:00:00.0: qca988x hw2.0 target 0x4100016c chip_id 0x043202ff sub 0000:0000
[   16.984142] ath10k_pci 0000:00:00.0: kconfig debug 0 debugfs 1 tracing 0 dfs 1 testmode 0
[   16.996574] ath10k_pci 0000:00:00.0: firmware ver 10.1-ct-8x-__fW-022-538f0906 api 2 features wmi-10.x,has-wmi-mgmt-tx,mfp,txstatus-noack,wmi-10.x-CT,ratemask-CT,txrate-CT,get-temp-CT,tx-rc-CT,cust-stats-CT,retry-gt2-CT,txrate2-CT,beacon-cb-CT,wmi-block-ack-CT crc32 e1c91a74
[   17.126255] ath10k_pci 0000:00:00.0: Direct firmware load for ath10k/QCA988X/hw2.0/board-2.bin failed with error -2
[   17.137068] ath10k_pci 0000:00:00.0: Falling back to user helper
[   17.240482] firmware ath10k!QCA988X!hw2.0!board-2.bin: firmware_loading_store: map pages failed
[   17.249965] ath10k_pci 0000:00:00.0: board_file api 1 bmi_id N/A crc32 bebc7c08
[   18.206072] ath10k_pci 0000:00:00.0: 10.1 wmi init: vdevs: 16  peers: 127  tid: 256
[   18.223678] ath10k_pci 0000:00:00.0: wmi print 'P 128 V 8 T 410'
[   18.230094] ath10k_pci 0000:00:00.0: wmi print 'msdu-desc: 1424  sw-crypt: 0 ct-sta: 0'
[   18.238397] ath10k_pci 0000:00:00.0: wmi print 'alloc rem: 20984 iram: 25656'
[   18.307186] ath10k_pci 0000:00:00.0: htt-ver 2.1 wmi-op 2 htt-op 2 cal file max-sta 128 raw 0 hwcrypto 1
[   18.320225] ath10k_pci 0000:00:00.0: NOTE:  Firmware DBGLOG output disabled in debug_mask: 0x10000000
[   18.456544] ath: EEPROM regdomain: 0x0
[   18.456551] ath: EEPROM indicates default country code should be used
[   18.456554] ath: doing EEPROM country->regdmn map search
[   18.456566] ath: country maps to regdmn code: 0x3a
[   18.456571] ath: Country alpha2 being used: US
[   18.456574] ath: Regpair used: 0x3a
[   18.535234] ath: EEPROM regdomain: 0x0
[   18.535241] ath: EEPROM indicates default country code should be used
[   18.535244] ath: doing EEPROM country->regdmn map search
[   18.535256] ath: country maps to regdmn code: 0x3a
[   18.535261] ath: Country alpha2 being used: US
[   18.535264] ath: Regpair used: 0x3a
[   18.547575] ieee80211 phy1: Selected rate control algorithm 'minstrel_ht'
[   18.549195] ieee80211 phy1: Atheros AR9561 Rev:0 mem=0xb8100000, irq=2
[   18.603711] kmodloader: done loading kernel modules from /etc/modules.d/*
[   27.966632] IPv6: ADDRCONF(NETDEV_UP): eth0: link is not ready
[   27.974079] eth0: link up (1000Mbps/Full duplex)
[   27.983382] IPv6: ADDRCONF(NETDEV_CHANGE): eth0: link becomes ready
[   27.996706] br-lan: port 1(eth0.1) entered blocking state
[   28.002349] br-lan: port 1(eth0.1) entered disabled state
[   28.008238] device eth0.1 entered promiscuous mode
[   28.013190] device eth0 entered promiscuous mode
[   28.052951] br-lan: port 1(eth0.1) entered blocking state
[   28.058589] br-lan: port 1(eth0.1) entered forwarding state
[   28.064659] IPv6: ADDRCONF(NETDEV_UP): br-lan: link is not ready
[   29.031302] IPv6: ADDRCONF(NETDEV_CHANGE): br-lan: link becomes ready
[   34.180757] ath10k_pci 0000:00:00.0: 10.1 wmi init: vdevs: 16  peers: 127  tid: 256
[   34.198400] ath10k_pci 0000:00:00.0: wmi print 'P 128 V 8 T 410'
[   34.204696] ath10k_pci 0000:00:00.0: wmi print 'msdu-desc: 1424  sw-crypt: 0 ct-sta: 0'
[   34.213362] ath10k_pci 0000:00:00.0: wmi print 'alloc rem: 20984 iram: 25656'
[   34.288274] ath10k_pci 0000:00:00.0: pdev param 0 not supported by firmware
[   34.318928] IPv6: ADDRCONF(NETDEV_UP): wlan0: link is not ready
[   34.356676] IPv6: ADDRCONF(NETDEV_UP): wlan1: link is not ready
[   34.393847] br-lan: port 2(wlan0) entered blocking state
[   34.399498] br-lan: port 2(wlan0) entered disabled state
[   34.405373] device wlan0 entered promiscuous mode
[   34.439558] br-lan: port 3(wlan1) entered blocking state
[   34.445113] br-lan: port 3(wlan1) entered disabled state
[   34.450863] device wlan1 entered promiscuous mode
[   34.455874] br-lan: port 3(wlan1) entered blocking state
[   34.461380] br-lan: port 3(wlan1) entered forwarding state
[   35.393389] br-lan: port 3(wlan1) entered disabled state
[   35.690067] IPv6: ADDRCONF(NETDEV_CHANGE): wlan0: link becomes ready
[   35.696864] br-lan: port 2(wlan0) entered blocking state
[   35.702351] br-lan: port 2(wlan0) entered forwarding state
[   35.777815] IPv6: ADDRCONF(NETDEV_CHANGE): wlan1: link becomes ready
[   35.784756] br-lan: port 3(wlan1) entered blocking state
[   35.790264] br-lan: port 3(wlan1) entered forwarding state
12

Then it's not your router that's the problem.

I suspect ISP failing to do its job either due to modem acting up or some misconfiguration on the DHCP server or some such. Also check the cable between modem and router.

Next time it happens, log in via LUCI and tell it to disable and then re-enable the WAN interface. If that doesn't fix it, leave your router running and try turning the ISP modem off and on again, and if that doesn't fix it, try disabling and reenabling the WAN interface again. If that doesn't fix it, replace the ethernet cable between the modem and the router. if that doesn't fix it, grab all the log files... then do

"the dance":

turn the modem and router both off
turn the router on, wait 30 seconds to a minute (for openwrt to get things booted and the switch chip to not leak packets to WAN)
turn the modem on, wait about 1 minute for it to sync up to the ISP, and give your openwrt a DHCP response

things should be working.

Come back and tell us at which stage did things work? show us the log files from your trials.

1 Like
13

This is great, thank you, will try all that!

14

So! Despite restarting every weekday morning, it happened again, around 2PM again. This time, I tried the following (as it turns out, due to being in a hurry, misremembering dlakelan's suggestion, but close):

  1. grabbed logs. here
  2. power cycled the modem (only). No dice, at this point
  3. From luci, hit "Restart" on all 3 interfaces (I wasn't sure which & was in a hurry so took the shotgun approach)
    That worked! Next time hopefully I'll have the presence of mind to first just Restart "WAN".
15

The logs had this in there which was a little weird:

Mon Dec 14 19:04:29 2020 daemon.warn dnsmasq[2038]: Maximum number of concurrent DNS queries reached (max: 150)

why is something simultaneously looking up 150 DNS entries at once? Maybe some kind of malware on your network? But also very possibly not.

In any case, glad you got it working again. The fact that simply restarting the interfaces fixed it makes me think that the ISP is not doing something right, and that restarting the WAN causes a reset on their end which gets packets flowing again. But I didn't see in the logs any complaints that make it clear what's up.

One suggestion is to set your timezone correctly. You talked about "around 2pm" but the last log entries were at "19:00:00" or so which is 7pm, so I'm guessing maybe your timezone is wrong. It can definitely help to have the logs timed properly so you can figure out exactly when things happened.

16

Good catch about the DNS queries. That's creepy & I'll have to investigate; malware or not, something's behaving badly. Maybe the ISP is cutting me off for the same reason and I should lower my max queries in the meantime so only a couple dozen get forwarded.

I'd thought I'd fixed the timezone. Turns out, I'd just set the time, rather than configuring it. This time I think I have it, via Luci.

Thanks again!

17

If the DHCP lease from the ISP is at issue, you should be able to see a pattern in the logs. SSH into your router and issue the following command:

logread | grep dhcpc

post the output of that, but be sure to sanitize the actual IP address information first (you can just obscure one or two of the octets).

If you suspect that there might be an issue with the modem hardware or the service/signal itself, you can look at the modem's status/logs to see if there are any reported errors or high retransmit counts (on an Arris cable modem operating in bridge mode and the router getting a DHCP lease from the ISP, the modem status page can be reached at 192.168.100.1 -- no special config is necessary to see this).

1 Like
18

I've had a C7 V5 for some time and I can tell you what happened. I had an extender connected to the router that extends the network to my home. Every now and then I lost the link between the extender and the router and consequently all the devices connected to the extender did not access the internet. Later I saw that the router for no apparent reason was changing the radio channel in a way that the repeater could not follow. When does this problem happen to you. Try pinging an external il via ping command from both a PC and router via SSH and see what happens. Do this test both wifi and wired in order to rule out possible causes. To conclude, the C7 is an inexpensive router that if you don't give it too many tasks to perform does not give particular problems but has that defect on the wifi that I described earlier. Check if this is for you too.

19

The only log line he had above was obtaining one lease with a ~26hr duration. However the time did jump forward multiple days

Sat Dec  5 17:37:55 2020 daemon.notice netifd: Network device 'wlan0' link is up
Mon Dec 14 12:37:56 2020 daemon.info hostapd: wlan1: STA da:88:47:58:33:e9 IEEE 802.11: authenticated

I wonder if this is related... The renewal time basically never occurred because time instability?

20

So I think this is a modem issue. Happened again today, about the same time as usual. Restarting the WAN interface didn't fix it. I tried to log into the modem as psherman suggested, but couldn't. Next, I powercycled the modem, after which I could log into it on .100.1, but still didn't have internet access. Restarting the WAN interface (and nothing else, this time) got me back online.

Did a bit of digging and the modem firmware is pretty old, yet apparently up to date -- far as I can tell from some 7 year old threads anyway. Presumably off topic here, but if anyone has any pointers to cable modem troubleshooting, please do share.