DHCP options of DHCP server return bogus content, breaking network #2688

alexpovel · 2021-02-15T21:25:11Z

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.

The text was updated successfully, but these errors were encountered:

ainar-g · 2021-02-16T11:15:22Z

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 · 2021-02-16T12:09:41Z

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 · 2021-02-16T13:09:15Z

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 · 2021-02-16T13:21:20Z

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?

Merge in DNS/adguard-home from 2688-dhcp-opt-ip to master Updates #2688. Squashed commit of the following: commit e17e003 Author: Ainar Garipov <A.Garipov@AdGuard.COM> Date: Tue Feb 16 17:10:32 2021 +0300 dhcpd: fix ip option parsing

ainar-g · 2021-02-16T15:35:12Z

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?

alexpovel · 2021-02-16T16:16:08Z

Yep looking good, edge image tag allows it to work:

$ 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

on example client 1, etc, so results as before.

Thanks a ton for the quick fix, keep up the good work!

alexpovel · 2021-02-16T19:07:30Z

Just as an addendum, I ended up not using any DHCP options for now:

options: []

I wasn't aware of this functionality

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 
        
           }

and it works really well, broadcasting the AGH server's IP address as the first two (and only) DNS servers to use. This saves me from having to set DHCP option number 6 in the first place. Thanks for that functionality, takes a lot of annoying trial-and-error out of the setup. This also means I am back on latest aka v0.105.1 right now, and it works again.

Merge in DNS/adguard-home from 2688-dhcp-opt-ip to master Updates AdguardTeam#2688. Squashed commit of the following: commit e17e003 Author: Ainar Garipov <A.Garipov@AdGuard.COM> Date: Tue Feb 16 17:10:32 2021 +0300 dhcpd: fix ip option parsing

alexpovel changed the title ~~DHCP options of DHCP server return bogus content~~ DHCP options of DHCP server return bogus content, breaking network Feb 16, 2021

ameshkov added this to the v0.105.2 milestone Feb 16, 2021

ameshkov assigned ainar-g Feb 16, 2021

ainar-g added docker Docker-related issues waiting for data Waiting for users to provide more data. labels Feb 16, 2021

ainar-g assigned EugeneOne1 Feb 16, 2021

ainar-g added bug P3: Medium and removed waiting for data Waiting for users to provide more data. labels Feb 16, 2021

ainar-g closed this as completed Feb 16, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

DHCP options of DHCP server return bogus content, breaking network #2688

DHCP options of DHCP server return bogus content, breaking network #2688

alexpovel commented Feb 15, 2021 •

edited

Loading

ainar-g commented Feb 16, 2021

alexpovel commented Feb 16, 2021

ainar-g commented Feb 16, 2021

alexpovel commented Feb 16, 2021

ainar-g commented Feb 16, 2021

alexpovel commented Feb 16, 2021

alexpovel commented Feb 16, 2021 •

edited

Loading

DHCP options of DHCP server return bogus content, breaking network #2688

DHCP options of DHCP server return bogus content, breaking network #2688

Comments

alexpovel commented Feb 15, 2021 • edited Loading

Prerequisites

Issue Details

Expected Behavior

Actual Behavior

Example Client 1 (Debian 10 NUC)

Example Client 2 (Synology NAS)

ainar-g commented Feb 16, 2021

alexpovel commented Feb 16, 2021

ainar-g commented Feb 16, 2021

alexpovel commented Feb 16, 2021

ainar-g commented Feb 16, 2021

alexpovel commented Feb 16, 2021

alexpovel commented Feb 16, 2021 • edited Loading

alexpovel commented Feb 15, 2021 •

edited

Loading

alexpovel commented Feb 16, 2021 •

edited

Loading