Query log entries disappear after a service restart

[don-dolarson]

Prerequisites

• I have checked the Wiki and Discussions and found no answer

• I have searched other issues and found no duplicates

• I want to report a bug and not ask a question or ask for help

• I have set up AdGuard Home correctly and configured clients to use it. (Use the Discussions for help with installing and configuring clients.)

Platform (OS and CPU architecture)

Linux, AMD64 (aka x86_64)

Installation

GitHub releases or script from README

Setup

On a router, DHCP is handled by the router

AdGuard Home version

0.107.36

Action

As the title say, after a machine restart / AGH service restart, entries in query log disappear. Sometimes 2 hours, sometimes 6 hours, sometimes a day or two, it vary. Restarted the service 3 times now, in a period of 30-40 minutes and all logs disappeared to the same time and the same entry log at 17:03.
The problem showed up after updating to .36 build. Couldn't see it on previously running .34 (skipped .35) or any other build since .21 when my journey with AGH started. No setting changed between these builds other than increased rate limit from 20 to 40 queries/second and possibly increasing both the cache size to 32MB and TTL.

Expected result

Complete query log.

Actual result

Not complete log.

Additional information and/or screenshots

OpenWrt 22.03.3 x86 Intel, kernel 5.10.161. Not using the opkg package but stable script from AGH repo.

[ainar-g]

AdGuard Home keeps an in-memory buffer of records, configurable through the querylog.size_memory parameter in the configuration file. If the service is shut down properly, AGH flushes the records to disk before shutting down. Have you written your own service file or have you used the one AdGuard Home installs itself?

In any case, enabling verbose logs and seeing if there are any errors during the shutdown should help. You can also set querylog.size_memory to a lesser value to reduce the number of lost records in these scenarios.

[fernvenue]

Same here, reproduced, and I found just a little bit differnces in verbose log:

[debug] stats: opening database
[debug] stats: database opened
[debug] stats: deleting old units until id *****
[debug] github.com/AdguardTeam/AdGuardHome/internal/stats.loadUnitFromDB(): Loading unit *****
[debug] stats: initialized

And here's another server which works perfectly normal:

[debug] stats: opening database
[debug] stats: database opened
[debug] stats: deleting old units until id *****
[debug] stats: initialized
[debug] github.com/AdguardTeam/AdGuardHome/internal/stats.loadUnitFromDB(): Loading unit *****
[debug] github.com/AdguardTeam/AdGuardHome/internal/stats.loadUnitFromDB(): Loading unit *****

I tried over and over again, they always do these works like that, and first one always lost it's query log and stats, second one always works great. Anything else should I provide?

By the way, I do tried to set querylog.size_memory to 0, 100, 1000 and 10000, not working :(

[ainar-g]

@fernvenue, thanks for the effort! The question remains still, how do you stop AGH? When it's shut down properly, the following lines indicate that the stats and the query log have been correctly flushed to disk:

[info] Received signal "interrupt"
[…]
[debug] stats: flushing unit with id 470219 and total of 10
[debug] stats: database closed
[debug] 10 elements serialized via json in 1.593432ms: 3 kB, 311/entry, 159.343µs/entry
[debug] querylog: ok "/path/to/data/querylog.json": 3110 bytes written

We haven't been able to find bugs in the start-up procedure, so the shutdown is the main suspect for now.

[fernvenue]

Hi @ainar-g, this will happen when I use systemctl restart AdGuardHome, and here's my AdGuardHome systemd service configuration:

[Unit]
Description=AdGuard Home: Network-level blocker
ConditionFileIsExecutable=/opt/AdGuardHome/AdGuardHome

After=syslog.target network-online.target 

[Service]
StartLimitInterval=5
StartLimitBurst=10
ExecStartPre=/bin/mkdir -p /var/log/
ExecStart=/opt/AdGuardHome/AdGuardHome "-s" "run"

WorkingDirectory=/opt/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

AdGuardHome installed by:

curl -s -S -L https://raw.githubusercontent.com/AdguardTeam/AdGuardHome/master/scripts/install.sh | sh -s -- -v

I got nothing when I try cat /tmp/aghlog.txt | grep "written" this, and I don't found any thing like database closed in verbose log, in the end it likes this:

[info] service: action run has been done successfully on linux-systemd

If any other information needed or I can help with, feel free to tell me :)

[ainar-g]

Ah, so this is mostly seen when running as a service. We'll investigate.

[schzhn]

We've pushed the edge release containing the fix.

[fernvenue]

Hi @schzhn, I just tested edge release, that works for me :)