FS#1492 - odhcpd triggered dnsmasq reloads spam system log

[aparcar]

hnyman:

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

[aparcar]

supersebbo:

I can confirm this bug.

Some effort needs to be put into this to determine whether this might be exploitable in terms of DoS due to the ability to programmatically remotely trigger dnsmasq reloads with DHCPv6 requests (which are routinely not filtered).

If it is normal and benign behaviour, then OpenWRT should be updated to suppress the logging of this action with the UCI 'quietdhcp' flag.

Having multiple IPv6 clients on a network serviced by odhcp creates so much log chatter that tracing real problems is very difficult.