DHCP options of DHCP server return bogus content, breaking network

[alexpovel]

Prerequisites

Please answer the following questions for yourself before submitting an issue. YOU MAY DELETE THE PREREQUISITES SECTION.

• I am running the latest version
• I checked the documentation and found no answer
• I checked to make sure that this issue has not already been filed

Issue Details

• Version of AdGuard Home server:
  • v0.105.1
• How did you install AdGuard Home:
  • Docker
• How did you setup DNS configuration:
• If it's a router or IoT, please write device model:
  • Raspberry Pi 4
• CPU architecture:
  • ARM
• Operating system and version:
  • Raspbian

Expected Behavior

The following DHCP config, part of AdGuardHome.yaml, worked in v0.104.3:

dhcp:
  enabled: true
  # The container will run in `network_mode = host`, so the interfaces have to agree:
  interface_name: eth0
  dhcpv4:
    gateway_ip: 192.168.0.1
    subnet_mask: 255.255.255.0
    range_start: 192.168.0.50
    range_end: 192.168.0.250
    lease_duration: 86400 # default: 86400 (24h)
    icmp_timeout_msec: 1000
    options:
      # https://github.com/AdguardTeam/AdGuardHome/wiki/DHCP#the-dhcpdhcpv4options-array-field
      # Options and numbers here:
      # https://www.iana.org/assignments/bootp-dhcp-parameters/bootp-dhcp-parameters.xhtml#options
      # Option #4 sets time server (NTP):
      - "4 ip 192.168.0.1"
      # Option #6 broadcasts the IP as the DNS server for DHCP clients to use:
      - "6 ip 192.168.0.2"
  dhcpv6:
    range_start: ""
    lease_duration: 86400
    ra_slaac_only: false
    ra_allow_slaac: false

where 192.168.0.2 is the AdGuardHome server's IP. Used to work like a charm! On DHCP clients, the following output used to be observable (this example is Debian 10):

# (Some irrelevant lines removed). 
$ cat /var/lib/dhcp/dhclient*.leases
lease {
  interface "eno1";
  fixed-address 192.168.0.4;
  option subnet-mask 255.255.255.0;
  option dhcp-lease-time 86400;
  option routers 192.168.0.1;
  option time-servers 192.168.0.1;
  option dhcp-message-type 5;
  option dhcp-server-identifier 192.168.0.2;
  option domain-name-servers 192.168.0.2;
  option fqdn.server-update true;
  option fqdn.rcode1 255;
  option fqdn.rcode2 255;
  renew 2 2021/02/16 08:06:23;
  rebind 2 2021/02/16 17:44:31;
  expire 2 2021/02/16 20:44:31;
}

and

$ cat /etc/resolv.conf
# Dynamic resolv.conf(5) file for glibc resolver(3) generated by resolvconf(8)
#     DO NOT EDIT THIS FILE BY HAND -- YOUR CHANGES WILL BE OVERWRITTEN
nameserver 192.168.0.2

Actual Behavior

Example Client 1 (Debian 10 NUC)

Now, the output on a Debian 10 DHCP client is the following. This is what DHCP clients get told by AdGuardHome's DHCP server, as part of the DHCP options 4 and 6, see config above:

# (Most lines removed). 
$ cat /var/lib/dhcp/dhclient*.leases
lease {
  option time-servers 0.0.0.0,0.0.0.0,0.0.255.255,192.168.0.1;
  option domain-name-servers 0.0.0.0,0.0.0.0,0.0.255.255,192.168.0.2;
}

and

$ cat /etc/resolv.conf
# Dynamic resolv.conf(5) file for glibc resolver(3) generated by resolvconf(8)
#     DO NOT EDIT THIS FILE BY HAND -- YOUR CHANGES WILL BE OVERWRITTEN
nameserver 0.0.0.0
nameserver 0.0.255.255
nameserver 192.168.0.2

How did 0.0.0.0 (twice) and 0.0.255.255 get in there? As a consequence of this, one of the errors I got was along the lines of

bash[1024]: ../../../../lib/isc/unix/socket.c:2173: internal_send: 0.0.255.255#53: Invalid argument

in journalctl of a service that tried to start up but couldn't. It tried to run DNS queries against 0.0.255.255 and obviously failed. Other services failed because they tried against 0.0.0.0.

Example Client 2 (Synology NAS)

Similar behaviour on this machine:

$ cat /etc/dhclient/ipv4/dhcpcd-eth0.info
IPADDR=192.168.0.3
NETMASK=255.255.255.0
NETWORK=192.168.0.0
BROADCAST=192.168.0.255
GATEWAY=192.168.0.1
DOMAIN=
DNS=0.0.0.0 0.0.0.0 0.0.255.255 192.168.0.2  # <----
DHCPSID=192.168.0.2
DHCPGIADDR=
DHCPSIADDR=

This causes the entire machine to fall on its face pretty hard.

---

I've rolled back to v0.104.3. The above is an issue that breaks my entire home network.

[ainar-g]

Hello, and thank you for the report. I wasn't able to reproduce the issue on my machine. Do you happen to have a verbose log of your installation starting? In particular, lines like:

2021/02/16 11:11:16 1#1 [debug] dhcpv4: starting...
2021/02/16 11:11:16 1#1 [debug] dhcpv4: got addresses [172.17.0.1 172.17.0.1] after 1 attempts

Also, since you're using Docker, could you also provide the docker command you're using to run it? Thanks!

[alexpovel]

Thanks for the super quick reply!

The logs are verbose and give this output:

$ docker logs adguard 2>&1 | head -n 500 | rg "dhcp"
2021/02/15 20:41:12 1#1 [debug] dhcpv4: added lease 192.168.0.4 <-> 1c:69:7a:03:1f:3b
2021/02/15 20:41:12 1#1 [debug] dhcpv4: added lease 192.168.0.3 <-> 00:11:32:89:ba:f0
2021/02/15 20:41:12 1#1 [debug] dhcpv4: added lease 192.168.0.66 <-> fc:65:de:e0:b0:bb
2021/02/15 20:41:12 1#1 [debug] dhcpv4: added lease 192.168.0.50 <-> dc:a6:32:5f:b9:99
2021/02/15 20:41:12 1#1 [debug] dhcpv4: added lease 192.168.0.65 <-> d4:12:43:dd:4c:58
2021/02/15 20:41:12 1#1 [debug] dhcpv4: added lease 192.168.0.52 <-> 68:ec:c5:62:4f:7b
2021/02/15 20:41:12 1#1 [debug] dhcpv4: added lease 192.168.0.64 <-> 98:fa:9b:c0:ac:1f
2021/02/15 20:41:12 1#1 [debug] dhcpv4: added lease 192.168.0.54 <-> 22:a6:2f:47:5e:ff
2021/02/15 20:41:12 1#1 [debug] dhcpv4: added lease 192.168.0.55 <-> fc:01:7c:aa:74:c4
2021/02/15 20:41:12 1#1 [debug] dhcpv4: added lease 192.168.0.56 <-> e8:e8:b7:9e:f6:6d
2021/02/15 20:41:12 1#1 [debug] dhcpv4: added lease 192.168.0.57 <-> 90:60:f1:66:50:ec
2021/02/15 20:41:12 1#1 [debug] dhcpv4: added lease 192.168.0.58 <-> b0:fc:0d:3a:b2:91
2021/02/15 20:41:12 1#1 [debug] dhcpv4: added lease 192.168.0.59 <-> c0:ee:fb:fa:4d:9a
2021/02/15 20:41:12 1#1 [debug] dhcpv4: added lease 192.168.0.60 <-> a0:02:dc:6d:f2:e4
2021/02/15 20:41:12 1#1 [debug] dhcpv4: added lease 192.168.0.61 <-> 32:91:ab:35:0c:de
2021/02/15 20:41:12 1#1 [debug] dhcpv4: added lease 192.168.0.62 <-> a4:83:e7:1c:6a:da
2021/02/15 20:41:12 1#1 [debug] dhcpv4: added lease 192.168.0.63 <-> 50:e0:85:08:0b:29
2021/02/15 20:41:12 1#1 [debug] dhcpv4: added lease 192.168.0.51 <-> 4c:32:75:93:15:3b
2021/02/15 20:41:12 1#1 [debug] dhcpv4: added lease 192.168.0.53 <-> 8c:16:45:e5:58:64
2021/02/15 20:41:15 1#1 [debug] dhcpv4: starting...
2021/02/15 20:41:15 1#1 [debug] dhcpv4: setting secondary dns ip to iself for interface eth0
2021/02/15 20:41:15 1#1 [info] dhcpv4: listening
[dhcpv4] 2021/02/15 20:41:15 Server listening on 0.0.0.0:67
[dhcpv4] 2021/02/15 20:41:15 Ready to handle requests

There is no line mentioning dhcpv4: got addresses [172.17.0.1 172.17.0.1] after 1 attempts or similiar, even removing head -n 500.

The container is configured via docker-compose, it's pretty simple:

version: "3.2"

volumes:
  work:

services:
  main:
    image: adguard/adguardhome
    container_name: adguard
    network_mode: host  # Required for DHCP server
    volumes:
      - ./conf:/opt/adguardhome/conf
      - work:/opt/adguardhome/work
    restart: unless-stopped

The dhcp part of AdGuardHome.yaml I posted above, let me know if you need more of that file.

Cheers

[ainar-g]

Are you sure that that is the log from the latest version? That line should definitely be there in v0.105.0 and v0.105.1.

The network_mode is an important detail though, so thanks. We'll investigate further.

[alexpovel]

Yep, you are right, sorry. These logs are definitely from v0.105.1:

$ docker logs adguard 2>&1 | rg "dhcp"
...
2021/02/16 13:15:44 1#1 [debug] dhcpv4: starting...
2021/02/16 13:15:44 1#1 [debug] dhcpv4: setting secondary dns ip to itself
2021/02/16 13:15:44 1#1 [debug] dhcpv4: got addresses [192.168.0.2 192.168.0.2] after 1 attempts
2021/02/16 13:15:44 1#1 [info] dhcpv4: listening
[dhcpv4] 2021/02/16 13:15:44 Server listening on 0.0.0.0:67
[dhcpv4] 2021/02/16 13:15:44 Ready to handle requests
...

So that's right, thanks. This piece:

AdGuardHome/internal/dhcpd/v46.go

Lines 80 to 123 in f68f6c9

	func ifaceDNSIPAddrs(
	iface netIface,
	ipv ipVersion,
	maxAttempts int,
	backoff time.Duration,
	) (addrs []net.IP, err error) {
	var n int
	waitForIP:
	for n = 1; n <= maxAttempts; n++ {
	addrs, err = ifaceIPAddrs(iface, ipv)
	if err != nil {
	return nil, fmt.Errorf("getting ip addrs: %w", err)
	}
	switch len(addrs) {
	case 0:
	log.Debug("dhcpv%d: attempt %d: no ip addresses", ipv, n)
	time.Sleep(backoff)
	case 1:
	// Some Android devices use 8.8.8.8 if there is not
	// a secondary DNS server. Fix that by setting the
	// secondary DNS address to the same address.
	//
	// See https://github.com/AdguardTeam/AdGuardHome/issues/1708.
	log.Debug("dhcpv%d: setting secondary dns ip to itself", ipv)
	addrs = append(addrs, addrs[0])
	fallthrough
	default:
	break waitForIP
	}
	}
	if len(addrs) == 0 {
	// Don't return errors in case the users want to try and enable
	// the DHCP server later.
	log.Error("dhcpv%d: no ip address for interface after %d attempts and %s", ipv, n, time.Duration(n)*backoff)
	} else {
	log.Debug("dhcpv%d: got addresses %s after %d attempts", ipv, addrs, n)
	}
	return addrs, nil
	}

seems to work correctly then, it got the correct interface address. Does it collide with the "6 ip 192.168.0.2" option from the config somehow?

[ainar-g]

We've found the bug, and it should be patched on the edge channel, including in Docker. Can you please check if the fresh edge docker image works?