For the last two weeks I've been having issues with an intermittent internet connection. It's not clear to me if the issue is on my side or the ISPs and when I call them to explain the problems the only answer I get is along the lines of "your modem is in bridge mode, we don't provide any help when that mode is enabled". I've been monitoring the system logs for the router (running OpenWrt 19.07.1 r10911-c155900f66) and the only weird thing I could find is dnsmasq printing what appears to be initialization info the the logs once every 30 minutes (when internet connection gets cut off)
A contiguous part of the log:
...
Sat Aug 29 00:17:18 2020 daemon.info dnsmasq-dhcp[2879]: DHCPREQUEST(br-lan) 192.168.110.243 50:5b:c2:a2:87:45
Sat Aug 29 00:17:18 2020 daemon.info dnsmasq-dhcp[2879]: DHCPACK(br-lan) 192.168.110.243 50:5b:c2:a2:87:45 lucia-nb
Sat Aug 29 00:17:19 2020 daemon.info dnsmasq[2879]: read /etc/hosts - 4 addresses
Sat Aug 29 00:17:19 2020 daemon.info dnsmasq[2879]: read /tmp/hosts/odhcpd - 9 addresses
Sat Aug 29 00:17:19 2020 daemon.info dnsmasq[2879]: read /tmp/hosts/dhcp.cfg01411c - 58 addresses
Sat Aug 29 00:17:19 2020 daemon.info dnsmasq-dhcp[2879]: read /etc/ethers - 0 addresses
Sat Aug 29 00:17:19 2020 daemon.err dnsmasq[2879]: cannot read /tmp/adb_list.overall: No such file or directory
Sat Aug 29 00:17:19 2020 daemon.info dnsmasq[2879]: using local addresses only for domain test
Sat Aug 29 00:17:19 2020 daemon.info dnsmasq[2879]: using local addresses only for domain onion
Sat Aug 29 00:17:19 2020 daemon.info dnsmasq[2879]: using local addresses only for domain localhost
Sat Aug 29 00:17:19 2020 daemon.info dnsmasq[2879]: using local addresses only for domain local
Sat Aug 29 00:17:19 2020 daemon.info dnsmasq[2879]: using local addresses only for domain invalid
Sat Aug 29 00:17:19 2020 daemon.info dnsmasq[2879]: using local addresses only for domain bind
Sat Aug 29 00:17:19 2020 daemon.info dnsmasq[2879]: using local addresses only for domain local
Sat Aug 29 00:17:19 2020 daemon.info dnsmasq[2879]: using nameserver 200.42.4.203#53
Sat Aug 29 00:17:19 2020 daemon.info dnsmasq[2879]: using nameserver 200.49.130.51#53
Sat Aug 29 00:17:20 2020 daemon.info dnsmasq[2879]: read /etc/hosts - 4 addresses
Sat Aug 29 00:17:20 2020 daemon.info dnsmasq[2879]: read /tmp/hosts/odhcpd - 10 addresses
Sat Aug 29 00:17:20 2020 daemon.info dnsmasq[2879]: read /tmp/hosts/dhcp.cfg01411c - 58 addresses
Sat Aug 29 00:17:20 2020 daemon.info dnsmasq-dhcp[2879]: read /etc/ethers - 0 addresses
Sat Aug 29 00:17:20 2020 daemon.err dnsmasq[2879]: cannot read /tmp/adb_list.overall: No such file or directory
Sat Aug 29 00:17:20 2020 daemon.info dnsmasq[2879]: using local addresses only for domain test
Sat Aug 29 00:17:20 2020 daemon.info dnsmasq[2879]: using local addresses only for domain onion
Sat Aug 29 00:17:20 2020 daemon.info dnsmasq[2879]: using local addresses only for domain localhost
Sat Aug 29 00:17:20 2020 daemon.info dnsmasq[2879]: using local addresses only for domain local
Sat Aug 29 00:17:20 2020 daemon.info dnsmasq[2879]: using local addresses only for domain invalid
Sat Aug 29 00:17:20 2020 daemon.info dnsmasq[2879]: using local addresses only for domain bind
Sat Aug 29 00:17:20 2020 daemon.info dnsmasq[2879]: using local addresses only for domain local
Sat Aug 29 00:17:20 2020 daemon.info dnsmasq[2879]: using nameserver 200.42.4.203#53
Sat Aug 29 00:17:20 2020 daemon.info dnsmasq[2879]: using nameserver 200.49.130.51#53
Sat Aug 29 00:17:33 2020 daemon.info dnsmasq-dhcp[2879]: DHCPREQUEST(br-lan) 192.168.110.2 14:cc:20:0e:94:56
Sat Aug 29 00:17:33 2020 daemon.info dnsmasq-dhcp[2879]: DHCPACK(br-lan) 192.168.110.2 14:cc:20:0e:94:56 dos-router
Sat Aug 29 00:20:16 2020 daemon.notice hostapd: wlan0: AP-STA-DISCONNECTED 4c:0f:6e:3c:82:4a
...
The entries seem to repeat every 17th line, the same pattern repeats every ~30 minutes. Could this indicate that the issue comes from my part or is it just dnsmasq "reconfiguring" itself when the connection the the ISPs dns server becomes available?
The continuous chunk of log I posted is the pattern, it repeats, but also in it there is some repetition. idk if that makes sense, here's an example:
--- Posted log starts ---
[30 minutes before now] a
[30 minutes before now] b
[30 minutes before now] c
[30 minutes before now] a
[30 minutes before now] b
[30 minutes before now] c
--- Posted log ends ---
...
[now] a
[now] b
[now] c
[now] a
[now] b
[now] c
Yes, I forgot to mention that the process id does not change, it just seems to be reinitializing.
6 hours
Extremely high ping times and lost packets at times without any correlation to the bandwidth usage, I don't think this is related to bufferbloat.
Nothing special. I just haven't had time to upgrade with the pandemic stuff and uni.
Based on your story, it sounds to me that dnsmasq just reacts to the interface getting up after the connectivity break. There is hotplug action for dnsmasq to reload config after new interfaces come online.
But naturally that offers no explanation to why your connectivity actually breaks down intermittently.
If it is about interface down/up type thing, there might be also some other indications in the log.
Note that also IPv6 addressing changes in LAN may trigger dnsmasq reload.
I have modified the odhcpd change notification script in my own builds so that I can see which dnsmasq reloads are due for ipv6 changes noticed by odhcpd (the ipv6 dhcp daemon):
Sun Aug 30 11:25:56 2020 daemon.notice netifd: Interface 'wan6' is now up
Sun Aug 30 11:25:56 2020 user.notice odhcpd: *** ODHCPD triggers DNSMASQ reload ***
Sun Aug 30 11:25:56 2020 daemon.info dnsmasq[3281]: reading /tmp/resolv.conf.d/resolv.conf.auto
Sun Aug 30 11:25:56 2020 daemon.info dnsmasq[3281]: using only locally-known addresses for domain test
Sun Aug 30 11:25:56 2020 daemon.info dnsmasq[3281]: using only locally-known addresses for domain onion
The script:
root@router1:~# cat /usr/sbin/odhcpd-update
#!/bin/sh
# Make dnsmasq reread hostfile by sending SIGHUP signal
logger -t odhcpd "*** ODHCPD triggers DNSMASQ reload ***"
. /lib/functions/procd.sh
procd_send_signal dnsmasq
I have this frequent restarting of dnsmasq too. I have a build from @hnyman for a Netgear R7800 running for about 2 years. In that build I saw the following message very, very often:
So far it all seems to running fine, except for the large amount of reloads of dnsmasq. Almost every second for about 20 minutes or so. And after a short break, dnsmasq will reload again almost every second for about 20 minutes. That's seems a bit too much for my taste. I haven't searched for a pattern yet. My best bet would be to start looking into why odhcpd is updated. I'm not so familiar with that, so I was hoping someone could give me a hint/clue to where to start looking?
I have enabled IPv6 on my R7800, my ISP doesn't support IPv6 yet, so it's only used on my LAN. I've also enabled Adblock (back in 2018).
I'm guessing a bit here, as to why odhcpd is updated so very frequently: I've also got a self built NAS that runs Ubuntu and a few docker containers. Some containers are assigned an IP address via a macvlan, so issues with discovery of services is not an issue for containers and the LAN itself.
But perhaps I'm just guessing in the wrong direction: how can I find out what causes a odhcpd to reload dnsmasq?
My guess is that some device/container/somthing of yours request new addresses frequently, does not see the answer, or something similar.
To my knowledge odchpd triggers dnsmasq config reload (not actually a full "restart") when new IPv6 enabled devices request and receive addresses or new interfaces get online. That is a way for odhcpd to notify dnssmasq about about new address assignments, as dnsmasq takes care of DNS functionality. Otherwise dnsmasq would not know that a new device name needs to be known for DNS.
(In case I am wrong, maybe @dedeckeh can figure out a better explanation)
I've disabled IPv6 for now. I'll keep that for a while and see how chatty the logs will be about dnsmasq reloads. First impression after an hour: a lot less.
As for docker and containers being the trigger, I'm thinking I can rule that out:
In /tmp/hosts/odhcpd I don't see any records of containers, only actual devices. I've checked my docker config and the running containers, none of it is configured to use IPv6 or has an IPv6 address active "by accident".
dnsmasq has very few means for runtime reconfiguration, therefore external services that require changes from dnsmasq don't have any other choice than to reload/ restart the dnsmasq dæmon - this is normal and expected behaviour.
Yeah, sorry for the even later necro (and the clever shortcut that made me submit a half completed reply ... deleted it).
Just wanted to chime in for future visitors to say that I was experiencing the exact issues as OP, connection drops seemingly due ip reassignments, seen by constant repetitions of these in the dnsmasq log
Sun Aug 22 10:43:27 2021 daemon.info dnsmasq-dhcp[1912]: DHCPREQUEST(br-lan) ...
Sun Aug 22 10:43:27 2021 daemon.info dnsmasq-dhcp[1912]: DHCPACK(br-lan) ...
The assumption from hnyman was on the spot for my issue.
A faulty switch power supply caused switch restarts at regular intervals, e.g. causing connection dropouts in zoom calls