An issue with updating AdGuard Home when protection is disabled

[ameshkov]

Steps to reproduce

1. Disable protection
2. Apply auto-update

Expected behavior

AdGuard is started, everything is working as expected

Actual behavior

• /control/version.json returns 502
• Enable AdGuard Home button does not work: https://uploads.adguard.com/up04_pl3c6_AdGuard_Home.png (404 error0

Screenshot:

Your environment

Description	Value
Version of AdGuard Home server:	(e.g. v1.0)
How did you setup DNS configuration:	(System/Router/IoT)
If it's a router or IoT, please write device model:	(e.g. Raspberry Pi 3 Model B)
Operating system and version:	(e.g. Ubuntu 18.04.1)

[gdude2002]

This is still a problem, unfortunately. I'm working with the ARM version on a Raspberry Pi 2 - Clicked the "update" button in the AdGuard admin, and now nothing works. 502 on the version.json (JSON parse: EOF), 404 on /control/start. Solved by downloading the update manually, uninstalling the old service and installing the new one, and CTRL+F5ing the admin interface.

[szolin]

502 on the version.json

This means that the HTTP server is up but other modules are still starting up. How long did you wait after upgrade has finished? What's inside logs?

[gdude2002]

Not super long, ~10 mins or so.

There's nothing in the journal for the AdGuardHome service (aside from starts/stops). The logfiles in /var/log look normal to me, although perhaps a bit odd since AdGuard is currently running.

[alarm@alarmpi AdGuardHome]$ tail /var/log/AdGuardHome.err
2019/11/20 09:50:45 [info] Creating the TCP server socket
2019/11/20 09:50:45 [info] Listening to tcp://[::]:53
2019/11/20 09:50:45 [info] Entering the tcp listener loop on [::]:53
2019/11/20 09:50:45 [info] Entering the UDP listener loop on [::]:53
2019/11/20 09:52:14 [info] Stopping AdGuard Home
2019/11/20 09:52:14 [info] Stopping the DNS proxy server
2019/11/20 09:52:14 [info] tcpListen.Accept() returned because we're reading from a closed connection, exiting loop
2019/11/20 09:52:14 [info] udpListen.ReadFrom() returned because we're reading from a closed connection, exiting loop
2019/11/20 09:52:14 [info] Stopped the DNS proxy server
2019/11/20 09:52:14 [info] Stopped

Nothing in AdGuardHome.out.

[szolin]

Not super long, ~10 mins or so.

10 minutes is more than enough.

There are plenty of info-level log messages that AGH prints during an upgrade and I don't see any of them in your log. Please find the message Updating from in your log file and post here what was happening after it.

[ameshkov]

From what I read in the Telegram chat this is indeed an issue for some users.

Something is not okay with the timing, maybe we reload the page sooner than we should, and the update is not finished yet?

[gdude2002]

Shortened the lines to make this easier to read, but you can see the first and last timestamp in there.

2019/11/20 09:49:48
[info] Updating from v0.99.2 to v0.99.3.  URL:https://static.adguard.com/adguardhome/release/AdGuardHome_linux_arm.tar.gz  Package:/home/alarm/AdGuardHome/agh-update-v0.99.3/AdGuardHome_linux_arm.tar.gz

[info] Stopping all tasks
[info] Stopping AdGuard Home
[info] Stopping the DNS proxy server
[info] tcpListen.Accept() returned because we're reading from a closed connection, exiting loop
[info] udpListen.ReadFrom() returned because we're reading from a closed connection, exiting loop
[info] Stopped the DNS proxy server
[info] Stopped
[info] Restarting: [/home/alarm/AdGuardHome/AdGuardHome -s run]
[info] Service control action: run
[info] AdGuard Home, version v0.99.3, channel release
[info] AdGuard Home is running as a service
[info] AdGuard Home is available on the following addresses:
[info] Go to http://127.0.0.1:3000
[info] Go to http://192.168.1.100:3000
[info] Couldn't get version check json from https://static.adguard.com/adguardhome/release/version.json: *url.Error Get https://static.adguard.com/adguardhome/release/version.json: read udp 127.0.0.1:58643->127.0.0.1:53: read: connection refused
[info] Couldn't get version check json from https://static.adguard.com/adguardhome/release/version.json: *url.Error Get https://static.adguard.com/adguardhome/release/version.json: read udp 127.0.0.1:46270->127.0.0.1:53: read: connection refused
[info] Upstream 0: https://1.1.1.1:443/dns-query
[info] Upstream 1: https://1.0.0.1:443/dns-query
[info] Starting the DNS proxy server
[info] Ratelimit is enabled and set to 20 rps
[info] The server is configured to refuse ANY requests
[info] DNS cache is enabled
[info] Creating the UDP server socket
[info] Listening to udp://[::]:53
[info] Creating the TCP server socket
[info] Listening to tcp://[::]:53
[info] Entering the tcp listener loop on [::]:53
[info] Entering the UDP listener loop on [::]:53
[info] Stopping AdGuard Home
[info] Stopping the DNS proxy server
[info] tcpListen.Accept() returned because we're reading from a closed connection, exiting loop
[info] udpListen.ReadFrom() returned because we're reading from a closed connection, exiting loop
[info] Stopped the DNS proxy server

2019/11/20 09:52:14
[info] Stopped

I reinstalled it at ~09:55, so I guess that's less than 10 minutes, haha. Either way, logs look OK to me, I think.

[ameshkov]

Yeah, the timing is the problem indeed.

Here it tries to get the version info:

[info] Couldn't get version check json from https://static.adguard.com/adguardhome/release/version.json: *url.Error Get https://static.adguard.com/adguardhome/release/version.json: read udp 127.0.0.1:58643->127.0.0.1:53: read: connection refused
[info] Couldn't get version check json from https://static.adguard.com/adguardhome/release/version.json: *url.Error Get https://static.adguard.com/adguardhome/release/version.json: read udp 127.0.0.1:46270->127.0.0.1:53: read: connection refused

And the local DNS server is started after that:

[info] Upstream 0: https://1.1.1.1:443/dns-query
[info] Upstream 1: https://1.0.0.1:443/dns-query
[info] Starting the DNS proxy server

I bet it would have been enough to simply refresh the page.

I've filed a new bug report:
#1186

Thank you!