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#1492 - odhcpd triggered dnsmasq reloads spam system log #6454

Open
openwrt-bot opened this issue Apr 14, 2018 · 1 comment
Open

FS#1492 - odhcpd triggered dnsmasq reloads spam system log #6454

openwrt-bot opened this issue Apr 14, 2018 · 1 comment
Labels

Comments

@openwrt-bot
Copy link

@openwrt-bot openwrt-bot commented Apr 14, 2018

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
@openwrt-bot
Copy link
Author

@openwrt-bot openwrt-bot commented Jun 18, 2019

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.

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

1 participant