Adguardhome: DHCP Server not run at first start

[TooYoungTooSimp]

Prerequisites

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

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

Issue Details

• Version of AdGuard Home server:
  
  
  
  • 0.104.1
  
  
• How did you setup DNS configuration:
  
  
  
  • System
  
  
• If it's a router or IoT, please write device model:
  
  
  
  
  
• Operating system and version:
  
  
  
  • Archlinux
  
  

Expected Behavior

dhcp listen at :67 after boot

Actual Behavior

dhcp doesn't listen 67. Unless I restart adguardhome

Screenshots

Screenshot:

Additional Information

I think maybe it's because it can not bind to specific nic at very early time.
So if there's a solution to let adguard home waiting the nic goes up to bind, it should be solved.

[ameshkov]

The problem is that we cannot solve this on our own as it's not caused by us.

AdGuard Home needs to be started when the network is available, and this is specified in the service configuration.

The question is why in your case the order is wrong.

[TooYoungTooSimp]

I've rechecked the boot sequence.


Seems agh boots AFTER nic link up.(I've set After=basic.target in agh .service file)
So in conclusion, I believe my order is correct.

[ameshkov]

@TooYoungTooSimp I guess the temporary solution would be to postpone the service startup so that the iface was actually initialized.

@ainar-g this is not the first time we're facing this issue. We could implement something simple, like waiting a couple more seconds if the interface is not found on the DHCP server startup.

[TooYoungTooSimp]

I added a ExecStartPre=sleep 3, as a temporary solution. It does work now. Thanks for your kindly advice.

[nhmarujo]

I think I'm facing the same issue. When I boot the system, the DHCP Server doesn't work properly. Devices are able to connect to the network, but hang obtaining an IP address.

If I restart the service (sudo service AdGuardHome restart) then everything starts working normally.

I'm running AdGuardHome on the following setup:

• RPi 1 Model B
• Raspbian GNU/Linux 10 (buster)
• AdguardHome v0.104.1

I have checked the service configuration file (/etc/systemd/system/AdGuardHome.service) and I can see the proper configuration to wait for the network: After=syslog.target network-online.target

I also tried to add the instruction ExecStartPre=sleep 3, like suggested by @TooYoungTooSimp as a workaround, but it doesn't seem to solve the issue (I still need to restart AdGuardHome after each boot).

[TooYoungTooSimp]

I think I'm facing the same issue. When I boot the system, the DHCP Server doesn't work properly. Devices are able to connect to the network, but hang obtaining an IP address.

If I restart the service (sudo service AdGuardHome restart) then everything starts working normally.

I'm running AdGuardHome on the following setup:

• RPi 1 Model B
• Raspbian GNU/Linux 10 (buster)
• AdguardHome v0.104.1

I have checked the service configuration file (/etc/systemd/system/AdGuardHome.service) and I can see the proper configuration to wait for the network: After=syslog.target network-online.target

I also tried to add the instruction ExecStartPre=sleep 3, like suggested by @TooYoungTooSimp as a workaround, but it doesn't seem to solve the issue (I still need to restart AdGuardHome after each boot).

well, you should type the full path of sleep, like /usr/bin/sleep (use which sleep to figure out). Maybe you could give it another try.

[nhmarujo]

Actually no, just like that was fine. I just had to increase the sleep a bit in order to make it work.

Here is the service definition (/etc/systemd/system/AdGuardHome.service):

[Unit]
Description=AdGuard Home: Network-level blocker
ConditionFileIsExecutable=/home/pi/AdGuardHome/AdGuardHome
After=syslog.target network-online.target

[Service]
StartLimitInterval=5
StartLimitBurst=10
ExecStartPre=sleep 5
ExecStart=/home/pi/AdGuardHome/AdGuardHome "-s" "run"

WorkingDirectory=/home/pi/AdGuardHome

StandardOutput=file:/var/log/AdGuardHome.out
StandardError=file:/var/log/AdGuardHome.err
Restart=always
RestartSec=10
EnvironmentFile=-/etc/sysconfig/AdGuardHome

[Install]
WantedBy=multi-user.target

If I try to put the full path it actually fail to start.

Right now, I got it booting up fine with this. My issue now is that the DHCP server stops working sometimes and I need to restart the service 😞

[ainar-g]

@TooYoungTooSimp, thanks for your report! Can you set verbose: true in your config and post the log (preferably in text, but a screenshot is fine too) of AGH starting up? Thanks again!

[TooYoungTooSimp]

log.txt
@ainar-g Here's my verbose log. Hope it is helpful for you!

[TooYoungTooSimp]

I can see a line likes not finding ip address of interface ens34, my nics are managed by systemd-networkd and have static ip configuration. Is there's a way just bind on specific interface regardless it's ipaddr (a whimsical suggestion)?

[ainar-g]

@TooYoungTooSimp, thanks for the logs, they're very helpful! We need to know the IP address of the interface we're binding to, because that's the address that we send to the DHCP clients as the address of the DNS server that they should use. We're currently thinking of ways to somehow wait for the interface to get an IP.

[ainar-g]

Should be fixed as of snapshot 60d72fb9. Can you please check if our solution fixes the issue for you?

[ainar-g]

I'll close this issue for now. Please feel free to reopen with more details if you think it should be reopened.

[TooYoungTooSimp]

fix confirmed in v0.105.0-beta.1. Sorry for late response and thank for your hard work!

[zadigre]

I have this issue on 0.105 beta 2.
I have to restart AdGuard home to get a working dhcp server...
I have a script in crontab running after reboot... sleep 15 and then restart AdGuard home.
it works fine with this command.

running on raspberry OS 64 bits.
I installed AdGuard home service with the -s install command.

Please let me know if you need logs to see what’s going on.

[ameshkov]

@zadigre

To troubleshoot this issue we need to see AdGuard Home logs.

1. Configure AdGuard Home to collect logs:
   
   
   
   • Specify log_file
   
   
   • Set verbose to True
   
   
2. Restart AdGuard Home and reproduce the issue
3. Post the log file here.

[zadigre]

here's the relevant parts... dhcpv4 cannot find IP address:
`
2021/01/25 09:19:35 470#49 [info] AdGuard Home, version 0.105.0-beta.2, channel beta, arch linux arm64
2021/01/25 09:19:35 470#49 [debug] Current working directory is /home/pi/AdGuardHome
2021/01/25 09:19:35 470#49 [info] AdGuard Home is running as a service
2021/01/25 09:19:35 470#49 [debug] github.com/AdguardTeam/AdGuardHome/internal/home.upgradeConfig(): got schema version 7
2021/01/25 09:19:35 470#49 [debug] Reading config file: /home/pi/AdGuardHome/AdGuardHome.yaml
2021/01/25 09:19:35 470#49 [debug] dhcpv4: added lease x.x.x.x <-> XX:XX:XX:XX:XX:XX

[... bunch of leases removed ...]

2021/01/25 09:19:35 470#49 [debug] dhcpv4: added lease x.x.x.x <-> XX:XX:XX:XX:XX:XX
2021/01/25 09:19:35 470#49 [info] DHCP: loaded leases v4:76 v6:0 total-read:76 from DB
2021/01/25 09:19:35 470#49 [debug] AutoHosts: loading hosts from file /etc/hosts
2021/01/25 09:19:35 470#49 [debug] AutoHosts: added 127.0.0.1 -> localhost
2021/01/25 09:19:35 470#49 [debug] AutoHosts: added reverse-address 127.0.0.1 -> localhost
2021/01/25 09:19:35 470#49 [debug] AutoHosts: added ::1 -> localhost
2021/01/25 09:19:35 470#49 [debug] AutoHosts: added reverse-address ::1 -> localhost
2021/01/25 09:19:35 470#49 [debug] AutoHosts: added ::1 -> ip6-localhost
2021/01/25 09:19:35 470#49 [debug] AutoHosts: added reverse-address ::1 -> ip6-localhost
2021/01/25 09:19:35 470#49 [debug] AutoHosts: added ::1 -> ip6-loopback
2021/01/25 09:19:35 470#49 [debug] AutoHosts: added reverse-address ::1 -> ip6-loopback
2021/01/25 09:19:35 470#49 [debug] AutoHosts: added ff02::1 -> ip6-allnodes
2021/01/25 09:19:35 470#49 [debug] AutoHosts: added reverse-address ff02::1 -> ip6-allnodes
2021/01/25 09:19:35 470#49 [debug] AutoHosts: added ff02::2 -> ip6-allrouters
2021/01/25 09:19:35 470#49 [debug] AutoHosts: added reverse-address ff02::2 -> ip6-allrouters
2021/01/25 09:19:35 470#49 [debug] AutoHosts: added 127.0.1.1 -> raspberrypi
2021/01/25 09:19:35 470#49 [debug] AutoHosts: added reverse-address 127.0.1.1 -> raspberrypi
2021/01/25 09:19:35 470#49 [debug] clients: removed 0 client aliases
2021/01/25 09:19:35 470#49 [debug] clients: added "x.x.x.x" -> "XXXXX" [1]

[... bunch of clients removed ...]

2021/01/25 09:19:35 470#49 [debug] clients: added "x.x.x.x" -> "XXXXX" [13]
2021/01/25 09:19:35 470#49 [debug] Clients: added 67 client aliases from DHCP
2021/01/25 09:19:35 470#49 [debug] Writing YAML file: /home/pi/AdGuardHome/AdGuardHome.yaml
2021/01/25 09:19:35 470#49 [info] Initializing auth module: /home/pi/AdGuardHome/data/sessions.db
2021/01/25 09:19:35 470#49 [debug] Auth: loaded 6 sessions from DB (removed 0 expired)
2021/01/25 09:19:35 470#49 [info] Auth: initialized. users:1 sessions:6
2021/01/25 09:19:35 470#49 [info] Initialize web module
2021/01/25 09:19:35 470#49 [debug] github.com/AdguardTeam/AdGuardHome/internal/stats.(statsCtx).dbOpen(): db.Open...
2021/01/25 09:19:35 470#49 [debug] github.com/AdguardTeam/AdGuardHome/internal/stats.(statsCtx).dbOpen(): db.Open
2021/01/25 09:19:35 470#49 [debug] github.com/AdguardTeam/AdGuardHome/internal/stats.(statsCtx).beginTxn(): db.Begin...
2021/01/25 09:19:35 470#49 [debug] github.com/AdguardTeam/AdGuardHome/internal/stats.(statsCtx).beginTxn(): db.Begin
2021/01/25 09:19:35 470#49 [debug] github.com/AdguardTeam/AdGuardHome/internal/stats.createObject(): Deleting old units...
2021/01/25 09:19:35 470#49 [debug] Stats: initialized
2021/01/25 09:19:35 470#49 [debug] DNS: skipping invalid hostname Meross Smart Switch from DHCP
2021/01/25 09:19:35 470#49 [debug] DNS: skipping invalid hostname Meross Smart Switch from DHCP
2021/01/25 09:19:35 470#49 [debug] DNS: skipping invalid hostname blink_sync_module from DHCP
2021/01/25 09:19:35 470#49 [debug] DNS: skipping invalid hostname Meross Smart Switch from DHCP
2021/01/25 09:19:35 470#49 [debug] DNS: skipping invalid hostname Meross Smart Switch from DHCP
2021/01/25 09:19:35 470#49 [debug] DNS: skipping invalid hostname Meross Smart Switch from DHCP
2021/01/25 09:19:35 470#49 [debug] DNS: skipping invalid hostname Meross Smart Switch from DHCP
2021/01/25 09:19:35 470#49 [debug] DNS: skipping invalid hostname Meross Smart Switch from DHCP
2021/01/25 09:19:35 470#49 [debug] DNS: added 59 A/PTR entries from DHCP
2021/01/25 09:19:35 470#49 [debug] IPSET: added 0 hosts
2021/01/25 09:19:35 470#49 [debug] Bootstraps: [9.9.9.11 149.112.112.11 2620:fe::11 2620:fe::fe:11]
2021/01/25 09:19:35 470#49 [debug] Upstream 0: 207.164.234.129:53
2021/01/25 09:19:35 470#49 [debug] Upstream 1: 207.164.234.193:53
2021/01/25 09:19:35 470#49 [debug] github.com/AdguardTeam/AdGuardHome/internal/home.(Filtering).load(): Loading filter 1609598775 contents to: /home/pi/AdGuardHome/data/filters/1609598775.txt
2021/01/25 09:19:35 470#49 [debug] github.com/AdguardTeam/AdGuardHome/internal/home.(Filtering).load(): File /home/pi/AdGuardHome/data/filters/1609598775.txt, id 1609598775, length 10780572
2021/01/25 09:19:35 470#49 [debug] Web: applying new TLS configuration
2021/01/25 09:19:35 470#49 [debug] Start AutoHosts module
2021/01/25 09:19:35 470#27 [debug] AutoHosts: loading hosts from file /etc/hosts
2021/01/25 09:19:35 470#27 [debug] AutoHosts: loading hosts from file /etc/hosts
2021/01/25 09:19:35 470#27 [debug] AutoHosts: added 127.0.0.1 -> localhost
2021/01/25 09:19:35 470#27 [debug] AutoHosts: added reverse-address 127.0.0.1 -> localhost
2021/01/25 09:19:35 470#27 [debug] AutoHosts: added ::1 -> localhost
2021/01/25 09:19:35 470#27 [debug] AutoHosts: added reverse-address ::1 -> localhost
2021/01/25 09:19:35 470#27 [debug] AutoHosts: added ::1 -> ip6-localhost
2021/01/25 09:19:35 470#27 [debug] AutoHosts: added reverse-address ::1 -> ip6-localhost
2021/01/25 09:19:35 470#27 [debug] AutoHosts: added ::1 -> ip6-loopback
2021/01/25 09:19:35 470#27 [debug] AutoHosts: added reverse-address ::1 -> ip6-loopback
2021/01/25 09:19:35 470#27 [debug] AutoHosts: added ff02::1 -> ip6-allnodes
2021/01/25 09:19:35 470#27 [debug] AutoHosts: added reverse-address ff02::1 -> ip6-allnodes
2021/01/25 09:19:35 470#27 [debug] AutoHosts: added ff02::2 -> ip6-allrouters
2021/01/25 09:19:35 470#27 [debug] AutoHosts: added reverse-address ff02::2 -> ip6-allrouters
2021/01/25 09:19:35 470#27 [debug] AutoHosts: added 127.0.1.1 -> raspberrypi
2021/01/25 09:19:35 470#27 [debug] AutoHosts: added reverse-address 127.0.1.1 -> raspberrypi
2021/01/25 09:19:35 470#27 [debug] clients: removed 0 client aliases
2021/01/25 09:19:35 470#27 [debug] clients: added "ff02::1" -> "ip6-allnodes" [68]
2021/01/25 09:19:35 470#27 [debug] clients: added "ff02::2" -> "ip6-allrouters" [69]
2021/01/25 09:19:35 470#27 [debug] clients: added "127.0.1.1" -> "raspberrypi" [70]
2021/01/25 09:19:35 470#27 [debug] clients: added "127.0.0.1" -> "localhost" [71]
2021/01/25 09:19:35 470#27 [debug] clients: added "::1" -> "localhost" [72]
2021/01/25 09:19:35 470#27 [debug] clients: added "::1" -> "ip6-localhost" [72]
2021/01/25 09:19:35 470#27 [debug] clients: added "::1" -> "ip6-loopback" [72]
2021/01/25 09:19:35 470#27 [debug] Clients: added 7 client aliases from system hosts-file
2021/01/25 09:19:35 470#49 [debug] dhcpv4: starting...
2021/01/25 09:19:35 470#49 [debug] dhcpv4: attempt 1: no ip addresses
2021/01/25 09:19:36 470#49 [debug] dhcpv4: attempt 2: no ip addresses
2021/01/25 09:19:36 470#49 [debug] dhcpv4: attempt 3: no ip addresses
2021/01/25 09:19:37 470#49 [debug] dhcpv4: attempt 4: no ip addresses
2021/01/25 09:19:37 470#49 [debug] dhcpv4: attempt 5: no ip addresses
2021/01/25 09:19:38 470#49 [debug] dhcpv4: attempt 6: no ip addresses
2021/01/25 09:19:38 470#49 [debug] dhcpv4: attempt 7: no ip addresses
2021/01/25 09:19:39 470#49 [debug] dhcpv4: attempt 8: no ip addresses
2021/01/25 09:19:39 470#49 [debug] dhcpv4: attempt 9: no ip addresses
2021/01/25 09:19:40 470#49 [debug] dhcpv4: attempt 10: no ip addresses
2021/01/25 09:19:40 470#49 [error] dhcpv4: no ip address for interface after 11 attempts and 5.5s
2021/01/25 09:19:40 470#49 [info] AdGuard Home is available on the following addresses:
2021/01/25 09:19:40 470#49 [info] Go to http://127.0.0.1:80
2021/01/25 09:19:40 470#49 [info] Go to http://[::1]:80
2021/01/25 09:19:44 470#29 [debug] initialized filtering engine
2021/01/25 09:19:44 470#29 [info] Starting the DNS proxy server
2021/01/25 09:19:44 470#29 [info] Cache TTL override is enabled. Min=300, Max=86400
2021/01/25 09:19:44 470#29 [info] Ratelimit is enabled and set to 100 rps
2021/01/25 09:19:44 470#29 [info] The server is configured to refuse ANY requests
2021/01/25 09:19:44 470#29 [info] DNS cache is enabled
2021/01/25 09:19:44 470#29 [info] MaxGoroutines is set to 300
2021/01/25 09:19:44 470#29 [info] Creating the UDP server socket
2021/01/25 09:19:44 470#29 [info] Listening to udp://[::]:53
2021/01/25 09:19:44 470#29 [info] Creating a TCP server socket
2021/01/25 09:19:44 470#29 [info] Listening to tcp://[::]:53
2021/01/25 09:19:44 470#31 [info] Entering the UDP listener loop on [::]:53
2021/01/25 09:19:44 470#30 [debug] github.com/AdguardTeam/AdGuardHome/internal/home.(clientsContainer).addFromSystemARP(): executing /usr/sbin/arp [arp -a]
2021/01/25 09:19:44 470#29 [debug] github.com/AdguardTeam/AdGuardHome/internal/stats.(statsCtx).beginTxn(): db.Begin...
2021/01/25 09:19:44 470#29 [debug] github.com/AdguardTeam/AdGuardHome/internal/stats.(statsCtx).beginTxn(): db.Begin
2021/01/25 09:19:44 470#66 [debug] Filters: updating...
2021/01/25 09:19:44 470#66 [debug] Filters: update finished
2021/01/25 09:19:44 470#32 [info] Entering the tcp listener loop on [::]:53
2021/01/25 09:19:44 470#30 [debug] github.com/AdguardTeam/AdGuardHome/internal/home.(clientsContainer).addFromSystemARP(): executing /usr/sbin/arp [arp -a]
2021/01/25 09:19:44 470#29 [debug] github.com/AdguardTeam/AdGuardHome/internal/stats.(statsCtx).beginTxn(): db.Begin...
2021/01/25 09:19:44 470#29 [debug] github.com/AdguardTeam/AdGuardHome/internal/stats.(statsCtx).beginTxn(): db.Begin
2021/01/25 09:19:44 470#66 [debug] Filters: updating...
2021/01/25 09:19:44 470#66 [debug] Filters: update finished
2021/01/25 09:19:44 470#32 [info] Entering the tcp listener loop on [::]:53
2021/01/25 09:19:44 470#68 [debug] querylog: the oldest log entry: 2021-01-24T09:32:52.766932726-05:00
2021/01/25 09:19:44 470#30 [debug] clients: removed 0 client aliases
2021/01/25 09:19:44 470#30 [debug] Clients: added 0 client aliases from 'arp -a' command output
2021/01/25 09:19:44 470#29 [debug] github.com/AdguardTeam/AdGuardHome/internal/home.(RDNS).Begin(): rDNS: adding 192.168.25.71
2021/01/25 09:19:44 470#29 [debug] github.com/AdguardTeam/AdGuardHome/internal/home.(RDNS).Begin(): rDNS: adding 192.168.25.49
2021/01/25 09:19:44 470#29 [debug] github.com/AdguardTeam/AdGuardHome/internal/home.(RDNS).Begin(): rDNS: adding 192.168.25.72
2021/01/25 09:19:44 470#25 [debug] github.com/AdguardTeam/AdGuardHome/internal/home.(RDNS).resolve(): Resolving host for 192.168.25.71
2021/01/25 09:19:44 470#29 [debug] github.com/AdguardTeam/AdGuardHome/internal/home.(RDNS).Begin(): rDNS: adding 192.168.25.3
2021/01/25 09:19:44 470#29 [debug] github.com/AdguardTeam/AdGuardHome/internal/home.(RDNS).Begin(): rDNS: adding 192.168.25.13
2021/01/25 09:19:44 470#29 [debug] github.com/AdguardTeam/AdGuardHome/internal/home.(RDNS).Begin(): rDNS: adding 192.168.25.69
2021/01/25 09:19:44 470#29 [debug] github.com/AdguardTeam/AdGuardHome/internal/home.(RDNS).Begin(): rDNS: adding 169.254.115.200
2021/01/25 09:19:44 470#29 [debug] github.com/AdguardTeam/AdGuardHome/internal/home.(RDNS).Begin(): rDNS: adding 169.254.96.195
2021/01/25 09:19:44 470#29 [debug] github.com/AdguardTeam/AdGuardHome/internal/home.(RDNS).Begin(): rDNS: adding 169.254.216.143
2021/01/25 09:19:44 470#25 [debug] 207.164.234.129:53: sending request PTR 71.25.168.192.in-addr.arpa.
2021/01/25 09:19:46 470#9 [debug] github.com/AdguardTeam/dnsproxy/proxy.(Proxy).udpHandlePacket(): Start handling new UDP packet from 127.0.0.1:41656
2021/01/25 09:19:46 470#8 [debug] github.com/AdguardTeam/dnsproxy/proxy.(Proxy).udpHandlePacket(): Start handling new UDP packet from 127.0.0.1:41656
`

DNS works fine.
DHCP works fine as soon as I restart AdGuardHome (either in crontab 15 secs after reboot or manually on the command line).

IP address is static... configured through the dhcpcd.conf file.
I have two interface (ethernet and wireless) connected to the same network.
wireless IP address also static.
DHCP in AdGuardHome is configured to listen to the ethernet interface.