[FS#1492] odhcpd triggered dnsmasq reloads spam system log

Sat Apr 14 02:36:28 PDT 2018

A new Flyspray task has been opened.  Details are below. 

User who did this - Hannu Nyman (hnyman) 

Attached to Project - OpenWrt/LEDE Project
Summary - odhcpd triggered dnsmasq reloads spam system log
Task Type - Bug Report
Category - Base system
Status - Unconfirmed
Assigned To - 
Operating System - All
Severity - Medium
Priority - Very Low
Reported Version - Trunk
Due in Version - Undecided
Due Date - Undecided
Details - odhcpd currently spams system log as it causes so many dnsmasq config reloads.

This log spam problem has been present in Openwrt/LEDE master since late 2017, when odhcpd (and/or netifd?) were changed so that the odhcpd more frequently signals dnsmasq to reload its hosts config via /usr/sbin/odhcpd-update script.

I have native ipv6 and most of my devices are ipv6 aware, so the problem is quite visible. There has been also some forum discussion about the problem, e.g. in the david wrt1900ac build thread, so others have noticed the problem, too.

As the RA lifetimes and DHCPv6 lifetimes are rather short by default, this reloading seems to happen every few minutes when a device joins or renews its address.

System log gets spammed with dnsmasq reload log lines whenever odhcpd writes the /tmp/hosts/odhcpd file and then triggers dnsmasq reload via /usr/sbin/odhcpd-update. 

I added a logger statement "**** ODHCPD event ****" to /usr/sbin/odhcpd-update and that pretty clearly indicates the additional problem that odhcpd can cause multiple reloads inside 1-2 seconds for a single device joining and getting an address.

I am not sure what is the best approach: 
  * Reduce dnsmasq reload log verbosity. Sounds more like a quick and dirty patch than an actual fix.
  * Reduce dnsmasq reloads via longer RA/DHCPv6 address lifetimes.
  * Reduce dnsmasq reloads via combining several events before triggering /usr/sbin/odhcpd-update. Currently a single device can cause multiple reloads inside a few seconds. Maybe there could be a "dirty flag" that is then evaluated once per minute and only then causes a /usr/sbin/odhcpd-update call.
  * Write /tmp/hosts/odhcpd less frequently. Evaluate the need to actually write it, or at least evaluate the need to trigger a dnsmasq reload. Currently the file gets the plain address allocations but also a # commented-out line with timestamp etc. debug info. AFAIK that is not really utilised by dnsmasq, so that is just for debug purposes. I general, if a device just renews its existing dhcpv6 address, there should be no need to reload dnsmasq because of /tmp/hosts/odhcpd (as the actual information does not change, although the debug timestamp changes)

Example of /tmp/hosts/odhcpd

2001:14ba:801f:9f00::180        Z97IW7
fd1b:7654:3210::180     Z97IW7
# br-lan 000100011b8be1ec7824af3a801c e7824af Z97IW7 -1 180 128 2001:14ba:801f:9f00::180/128 fd1b:7654:3210::180/128
2001:14ba:801f:9f00::67f        router2
fd1b:7654:3210::67f     router2
# br-lan 00030001c63dc7a33f50 1 router2 1523711242 67f 128 2001:14ba:801f:9f00::67f/128 fd1b:7654:3210::67f/128
2001:14ba:801f:9f00::dbd        Hannu650
fd1b:7654:3210::dbd     Hannu650
# br-lan 000100181e4723f200a0c6000000 d5cca1a Hannu650 1523711242 dbd 128 2001:14ba:801f:9f00::dbd/128 fd1b:7654:3210::dbd/128

odhcpd is not the only culprit for dnsmasq reloads, but it is very visible at least in my use case

Log below:

Sat Apr 14 11:19:36 2018 user.notice odhcpd: **** ODHCPD event ****
Sat Apr 14 11:19:36 2018 daemon.info dnsmasq[3409]: read /etc/hosts - 4 addresses
Sat Apr 14 11:19:36 2018 daemon.info dnsmasq[3409]: read /tmp/hosts/odhcpd - 4 addresses
Sat Apr 14 11:19:36 2018 daemon.info dnsmasq[3409]: read /tmp/hosts/dhcp.cfg01411c - 2 addresses
Sat Apr 14 11:19:36 2018 daemon.info dnsmasq-dhcp[3409]: read /etc/ethers - 0 addresses
Sat Apr 14 11:19:36 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zztxdown.com
Sat Apr 14 11:19:36 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zzshw.net
Sat Apr 14 11:19:36 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zzpxw.cn
Sat Apr 14 11:19:36 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zyjyyy.com
Sat Apr 14 11:19:36 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zwgoca.com
Sat Apr 14 11:19:36 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zw52.ru
Sat Apr 14 11:19:36 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zumobi.com
Sat Apr 14 11:19:36 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zum.mudmaggot.com
Sat Apr 14 11:19:36 2018 daemon.info dnsmasq[3409]: using nameserver 62.241.198.246#53
Sat Apr 14 11:19:36 2018 daemon.info dnsmasq[3409]: using nameserver 62.241.198.245#53
Sat Apr 14 11:19:36 2018 daemon.info dnsmasq[3409]: using nameserver 2001:14b8:1000::1#53
Sat Apr 14 11:19:36 2018 daemon.info dnsmasq[3409]: using nameserver 2001:14b8:1000::2#53
Sat Apr 14 11:19:36 2018 daemon.info dnsmasq[3409]: using 4651 more local addresses
Sat Apr 14 11:19:37 2018 daemon.warn odhcpd[1396]: DHCPV6 REQUEST IA_NA from 000100011b8be1ec7824af3a801c on br-lan: ok 2001:14ba:801f:9f00::180/128 fd1b:7654:3210::180/128
Sat Apr 14 11:19:37 2018 user.notice odhcpd: **** ODHCPD event ****
Sat Apr 14 11:19:37 2018 daemon.info dnsmasq[3409]: read /etc/hosts - 4 addresses
Sat Apr 14 11:19:37 2018 daemon.info dnsmasq[3409]: read /tmp/hosts/odhcpd - 6 addresses
Sat Apr 14 11:19:37 2018 daemon.info dnsmasq[3409]: read /tmp/hosts/dhcp.cfg01411c - 2 addresses
Sat Apr 14 11:19:37 2018 daemon.info dnsmasq-dhcp[3409]: read /etc/ethers - 0 addresses
Sat Apr 14 11:19:37 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zztxdown.com
Sat Apr 14 11:19:37 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zzshw.net
Sat Apr 14 11:19:37 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zzpxw.cn
Sat Apr 14 11:19:37 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zyjyyy.com
Sat Apr 14 11:19:37 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zwgoca.com
Sat Apr 14 11:19:37 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zw52.ru
Sat Apr 14 11:19:37 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zumobi.com
Sat Apr 14 11:19:37 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zum.mudmaggot.com
Sat Apr 14 11:19:37 2018 daemon.info dnsmasq[3409]: using nameserver 62.241.198.246#53
Sat Apr 14 11:19:37 2018 daemon.info dnsmasq[3409]: using nameserver 62.241.198.245#53
Sat Apr 14 11:19:37 2018 daemon.info dnsmasq[3409]: using nameserver 2001:14b8:1000::1#53
Sat Apr 14 11:19:37 2018 daemon.info dnsmasq[3409]: using nameserver 2001:14b8:1000::2#53
Sat Apr 14 11:19:37 2018 daemon.info dnsmasq[3409]: using 4651 more local addresses
Sat Apr 14 11:20:54 2018 daemon.info dnsmasq-dhcp[3409]: DHCPREQUEST(br-lan) 192.168.1.165 5c:ca:1a:2a:cd:c4
Sat Apr 14 11:20:54 2018 daemon.info dnsmasq-dhcp[3409]: DHCPACK(br-lan) 192.168.1.165 5c:ca:1a:2a:cd:c4 Hannu650
Sat Apr 14 11:20:55 2018 daemon.warn odhcpd[1396]: DHCPV6 CONFIRM IA_NA from 000100181e4723f200a0c6000000 on br-lan: not on-link 2001:14ba:801f:9f00::dbd/128 fd1b:7654:3210::dbd/128
Sat Apr 14 11:20:55 2018 daemon.warn odhcpd[1396]: DHCPV6 CONFIRM IA_NA from 000100181e4723f200a0c6000000 on br-lan: not on-link 2001:14ba:801f:9f00::dbd/128 fd1b:7654:3210::dbd/128
Sat Apr 14 11:20:56 2018 daemon.warn odhcpd[1396]: DHCPV6 CONFIRM IA_NA from 000100181e4723f200a0c6000000 on br-lan: not on-link 2001:14ba:801f:9f00::dbd/128 fd1b:7654:3210::dbd/128
Sat Apr 14 11:20:56 2018 daemon.warn odhcpd[1396]: DHCPV6 CONFIRM IA_NA from 000100181e4723f200a0c6000000 on br-lan: not on-link 2001:14ba:801f:9f00::dbd/128 fd1b:7654:3210::dbd/128
Sat Apr 14 11:20:56 2018 daemon.warn odhcpd[1396]: DHCPV6 SOLICIT IA_NA from 000100181e4723f200a0c6000000 on br-lan: ok 2001:14ba:801f:9f00::dbd/128 fd1b:7654:3210::dbd/128
Sat Apr 14 11:20:56 2018 user.notice odhcpd: **** ODHCPD event ****
Sat Apr 14 11:20:56 2018 daemon.info dnsmasq[3409]: read /etc/hosts - 4 addresses
Sat Apr 14 11:20:56 2018 daemon.info dnsmasq[3409]: read /tmp/hosts/odhcpd - 4 addresses
Sat Apr 14 11:20:56 2018 daemon.info dnsmasq[3409]: read /tmp/hosts/dhcp.cfg01411c - 2 addresses
Sat Apr 14 11:20:56 2018 daemon.info dnsmasq-dhcp[3409]: read /etc/ethers - 0 addresses
Sat Apr 14 11:20:56 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zztxdown.com
Sat Apr 14 11:20:56 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zzshw.net
Sat Apr 14 11:20:56 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zzpxw.cn
Sat Apr 14 11:20:56 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zyjyyy.com
Sat Apr 14 11:20:56 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zwgoca.com
Sat Apr 14 11:20:56 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zw52.ru
Sat Apr 14 11:20:56 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zumobi.com
Sat Apr 14 11:20:56 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zum.mudmaggot.com
Sat Apr 14 11:20:56 2018 daemon.info dnsmasq[3409]: using nameserver 62.241.198.246#53
Sat Apr 14 11:20:56 2018 daemon.info dnsmasq[3409]: using nameserver 62.241.198.245#53
Sat Apr 14 11:20:56 2018 daemon.info dnsmasq[3409]: using nameserver 2001:14b8:1000::1#53
Sat Apr 14 11:20:56 2018 daemon.info dnsmasq[3409]: using nameserver 2001:14b8:1000::2#53
Sat Apr 14 11:20:56 2018 daemon.info dnsmasq[3409]: using 4651 more local addresses
Sat Apr 14 11:20:57 2018 daemon.warn odhcpd[1396]: DHCPV6 REQUEST IA_NA from 000100181e4723f200a0c6000000 on br-lan: ok 2001:14ba:801f:9f00::dbd/128 fd1b:7654:3210::dbd/128
Sat Apr 14 11:20:57 2018 user.notice odhcpd: **** ODHCPD event ****
Sat Apr 14 11:20:57 2018 daemon.info dnsmasq[3409]: read /etc/hosts - 4 addresses
Sat Apr 14 11:20:57 2018 daemon.info dnsmasq[3409]: read /tmp/hosts/odhcpd - 6 addresses
Sat Apr 14 11:20:57 2018 daemon.info dnsmasq[3409]: read /tmp/hosts/dhcp.cfg01411c - 2 addresses
Sat Apr 14 11:20:57 2018 daemon.info dnsmasq-dhcp[3409]: read /etc/ethers - 0 addresses
Sat Apr 14 11:20:57 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zztxdown.com
Sat Apr 14 11:20:57 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zzshw.net
Sat Apr 14 11:20:57 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zzpxw.cn
Sat Apr 14 11:20:57 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zyjyyy.com
Sat Apr 14 11:20:57 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zwgoca.com
Sat Apr 14 11:20:57 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zw52.ru
Sat Apr 14 11:20:57 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zumobi.com
Sat Apr 14 11:20:57 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zum.mudmaggot.com
Sat Apr 14 11:20:57 2018 daemon.info dnsmasq[3409]: using nameserver 62.241.198.246#53
Sat Apr 14 11:20:57 2018 daemon.info dnsmasq[3409]: using nameserver 62.241.198.245#53
Sat Apr 14 11:20:57 2018 daemon.info dnsmasq[3409]: using nameserver 2001:14b8:1000::1#53
Sat Apr 14 11:20:57 2018 daemon.info dnsmasq[3409]: using nameserver 2001:14b8:1000::2#53
Sat Apr 14 11:20:57 2018 daemon.info dnsmasq[3409]: using 4651 more local addresses
Sat Apr 14 11:42:55 2018 daemon.info dnsmasq-dhcp[3409]: DHCPREQUEST(br-lan) 192.168.1.165 5c:ca:1a:2a:cd:c4
Sat Apr 14 11:42:55 2018 daemon.info dnsmasq-dhcp[3409]: DHCPACK(br-lan) 192.168.1.165 5c:ca:1a:2a:cd:c4 Hannu650
Sat Apr 14 11:42:56 2018 daemon.warn odhcpd[1396]: DHCPV6 CONFIRM IA_NA from 000100181e4723f200a0c6000000 on br-lan: not on-link 2001:14ba:801f:9f00::dbd/128 fd1b:7654:3210::dbd/128
Sat Apr 14 11:42:56 2018 daemon.warn odhcpd[1396]: DHCPV6 CONFIRM IA_NA from 000100181e4723f200a0c6000000 on br-lan: not on-link 2001:14ba:801f:9f00::dbd/128 fd1b:7654:3210::dbd/128
Sat Apr 14 11:42:57 2018 daemon.warn odhcpd[1396]: DHCPV6 CONFIRM IA_NA from 000100181e4723f200a0c6000000 on br-lan: not on-link 2001:14ba:801f:9f00::dbd/128 fd1b:7654:3210::dbd/128
Sat Apr 14 11:42:57 2018 daemon.warn odhcpd[1396]: DHCPV6 CONFIRM IA_NA from 000100181e4723f200a0c6000000 on br-lan: not on-link 2001:14ba:801f:9f00::dbd/128 fd1b:7654:3210::dbd/128
Sat Apr 14 11:42:58 2018 daemon.warn odhcpd[1396]: DHCPV6 SOLICIT IA_NA from 000100181e4723f200a0c6000000 on br-lan: ok 2001:14ba:801f:9f00::dbd/128 fd1b:7654:3210::dbd/128
Sat Apr 14 11:42:58 2018 user.notice odhcpd: **** ODHCPD event ****
Sat Apr 14 11:42:58 2018 daemon.info dnsmasq[3409]: read /etc/hosts - 4 addresses
Sat Apr 14 11:42:58 2018 daemon.info dnsmasq[3409]: read /tmp/hosts/odhcpd - 4 addresses
Sat Apr 14 11:42:58 2018 daemon.info dnsmasq[3409]: read /tmp/hosts/dhcp.cfg01411c - 2 addresses
Sat Apr 14 11:42:58 2018 daemon.info dnsmasq-dhcp[3409]: read /etc/ethers - 0 addresses
Sat Apr 14 11:42:58 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zztxdown.com
Sat Apr 14 11:42:58 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zzshw.net
Sat Apr 14 11:42:58 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zzpxw.cn
Sat Apr 14 11:42:58 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zyjyyy.com
Sat Apr 14 11:42:58 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zwgoca.com
Sat Apr 14 11:42:58 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zw52.ru
Sat Apr 14 11:42:58 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zumobi.com
Sat Apr 14 11:42:58 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zum.mudmaggot.com
Sat Apr 14 11:42:58 2018 daemon.info dnsmasq[3409]: using nameserver 62.241.198.246#53
Sat Apr 14 11:42:58 2018 daemon.info dnsmasq[3409]: using nameserver 62.241.198.245#53
Sat Apr 14 11:42:58 2018 daemon.info dnsmasq[3409]: using nameserver 2001:14b8:1000::1#53
Sat Apr 14 11:42:58 2018 daemon.info dnsmasq[3409]: using nameserver 2001:14b8:1000::2#53
Sat Apr 14 11:42:58 2018 daemon.info dnsmasq[3409]: using 4651 more local addresses
Sat Apr 14 11:42:59 2018 daemon.warn odhcpd[1396]: DHCPV6 REQUEST IA_NA from 000100181e4723f200a0c6000000 on br-lan: ok 2001:14ba:801f:9f00::dbd/128 fd1b:7654:3210::dbd/128
Sat Apr 14 11:42:59 2018 user.notice odhcpd: **** ODHCPD event ****
Sat Apr 14 11:42:59 2018 daemon.info dnsmasq[3409]: read /etc/hosts - 4 addresses
Sat Apr 14 11:42:59 2018 daemon.info dnsmasq[3409]: read /tmp/hosts/odhcpd - 6 addresses
Sat Apr 14 11:42:59 2018 daemon.info dnsmasq[3409]: read /tmp/hosts/dhcp.cfg01411c - 2 addresses
Sat Apr 14 11:42:59 2018 daemon.info dnsmasq-dhcp[3409]: read /etc/ethers - 0 addresses
Sat Apr 14 11:42:59 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zztxdown.com
Sat Apr 14 11:42:59 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zzshw.net
Sat Apr 14 11:42:59 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zzpxw.cn
Sat Apr 14 11:42:59 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zyjyyy.com
Sat Apr 14 11:42:59 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zwgoca.com
Sat Apr 14 11:42:59 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zw52.ru
Sat Apr 14 11:42:59 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zumobi.com
Sat Apr 14 11:42:59 2018 daemon.info dnsmasq[3409]: using local addresses only for domain zum.mudmaggot.com
Sat Apr 14 11:42:59 2018 daemon.info dnsmasq[3409]: using nameserver 62.241.198.246#53
Sat Apr 14 11:42:59 2018 daemon.info dnsmasq[3409]: using nameserver 62.241.198.245#53
Sat Apr 14 11:42:59 2018 daemon.info dnsmasq[3409]: using nameserver 2001:14b8:1000::1#53
Sat Apr 14 11:42:59 2018 daemon.info dnsmasq[3409]: using nameserver 2001:14b8:1000::2#53
Sat Apr 14 11:42:59 2018 daemon.info dnsmasq[3409]: using 4651 more local addresses
Sat Apr 14 11:49:32 2018 daemon.err uhttpd[4310]: luci: accepted login on / for root from 192.168.1.180

More information can be found at the following URL:
https://bugs.openwrt.org/index.php?do=details&task_id=1492