AdGuardHome AdGuard Home fails to start after reboot

[SomeWhereOverTheRainBow]

Not really.
I have another AX86U that behaves as it should and AdGuard correctly starts everytime.
Both of them are configured similarly.

Except from nsrum which runs only on the "adguard failing" router, these are the active scripts I use on both of them:

5  open     scribe                    v2.4.3
j1 open     connmon                   v3.0.2
j2 open     ntpMerlin                 v3.4.5
j3 open     scMerlin                  v2.4.0
j6 open     uiScribe                  v1.4.5
j7 open     YazDHCP                   v1.0.4
ag open     AdGuardHome               v1.5.3
rs manage   Reboot scheduler * @ 4:0

Maybe there's some misconfiguration somewhere, but I really could not find it.

do you have nsrum actually performing task during reboots? if so, what /jffs scripts do you have entries in for such runs?

 

[Markfree]

It was only there for an old nvram backup.
I already removed nsrum but it was not running any particular script.

 

[SomeWhereOverTheRainBow]

It was only there for an old nvram backup.
I already removed nsrum but it was not running any particular script.

Are you by chance running a VPN client at boot? or any personalized scripts that spawn from the scripts in /jffs/scripts/*.

 

[Markfree]

Are you by chance running a VPN client at boot? or any personalized scripts that spawn from the scripts in /jffs/scripts/*.

No VPN or scripts

 

[SomeWhereOverTheRainBow]

No VPN or scripts

okay so in your /jffs/scripts/init-start

modify this line

[ -x /jffs/addons/AdGuardHome.d/AdGuardHome.sh ] && /jffs/addons/AdGuardHome.d/AdGuardHome.sh init-start

to be

[ -x /jffs/addons/AdGuardHome.d/AdGuardHome.sh ] && /jffs/addons/AdGuardHome.d/AdGuardHome.sh init-start &>/tmp/AGHManager.log &

On days that the script fails to start run the command:

awk '{ print }' /tmp/AGHManager.log

in the terminal, before starting AdGuardHome.

Report its output.

 

[Markfree]

Today AdGuard started correctly, but when checking its logs I noticed that the new /tmp/AGHManager.log had some errors.

Mon Jun 6 07:00:02 UTC 2022
/jffs/addons/AdGuardHome.d/AdGuardHome.sh: trap: line 195: ERR: invalid signal specification
/jffs/addons/AdGuardHome.d/AdGuardHome.sh: trap: line 195: ERR: invalid signal specification
Mon Jun 6 07:01:05 UTC 2022
awk: /proc/3471/cmdline: No such file or directory

The error is referring to this line:

if [ "$1" = "init-start" ] && [ ! -f "$UPPER_SCRIPT" ]; then timezone; trap '' HUP INT QUIT ABRT TERM; trap 'exec $MID_SCRIPT "$@"; exit $?' EXIT ERR; while [ ! -f "$UPPER_SCRIPT" ]; do sleep 1; { if [ -f "$UPPER_SCRIPT" ]; then break; fi; }; done; trap - HUP INT QUIT ABRT TERM EXIT ERR; fi

 

[SomeWhereOverTheRainBow]

Today AdGuard started correctly, but when checking its logs I noticed that the new /tmp/AGHManager.log had some errors.


The error is referring to this line:

if [ "$1" = "init-start" ] && [ ! -f "$UPPER_SCRIPT" ]; then timezone; trap '' HUP INT QUIT ABRT TERM; trap 'exec $MID_SCRIPT "$@"; exit $?' EXIT ERR; while [ ! -f "$UPPER_SCRIPT" ]; do sleep 1; { if [ -f "$UPPER_SCRIPT" ]; then break; fi; }; done; trap - HUP INT QUIT ABRT TERM EXIT ERR; fi

that is just one of the lines.

 

[SomeWhereOverTheRainBow]

Today AdGuard started correctly, but when checking its logs I noticed that the new /tmp/AGHManager.log had some errors.


The error is referring to this line:

if [ "$1" = "init-start" ] && [ ! -f "$UPPER_SCRIPT" ]; then timezone; trap '' HUP INT QUIT ABRT TERM; trap 'exec $MID_SCRIPT "$@"; exit $?' EXIT ERR; while [ ! -f "$UPPER_SCRIPT" ]; do sleep 1; { if [ -f "$UPPER_SCRIPT" ]; then break; fi; }; done; trap - HUP INT QUIT ABRT TERM EXIT ERR; fi

But that wont cause the script not to start. The other lines are not errors, but general statements that are usually silent in the terminal. The ERR is an actual error though. The timestamps are normal.

 

[SomeWhereOverTheRainBow]

@Markfree now you have observation of what you might find in this log. keep an eye out for when it fails to start. It may provide some clue of what is happening. Right now I have a dev branch open I am making improvements. I will be using your feedback as well to add additional improvements.

 

[SomeWhereOverTheRainBow]

A good way for any script to be informed of NTP being synced is to hook into service-event-end for $1=restart $2=diskmon. It can be better than waiting and looping for something that might never happen.

I am considering this practice a bit more. while this is going off topic of the post, have you ran into an instance where this event occurs before ntp has actually sync?

 

[SomeWhereOverTheRainBow]

@Markfree Have you discovered any recurrences as of yet?

 

[Markfree]

It took quite a while to fail again, but it did. (actually it failed twice and I forgot to collect the logs )

AdGuard only started after 5 minutes when my script started it.

Jun 23 04:00:01 [HOSTNAME] rc_service: service 2577:notify_rc stop_AdGuardHome
Jun 23 04:05:55 [HOSTNAME] rc_service: service 6967:notify_rc start_AdGuardHome
Jun 23 04:05:55 [HOSTNAME] custom_script: Running /jffs/scripts/service-event (args: start AdGuardHome)
Jun 23 04:05:55 [HOSTNAME] custom_script: Running /jffs/scripts/service-event-end (args: start AdGuardHome)
Jun 23 04:05:58 [HOSTNAME] S99AdGuardHome[7104]: Starting Monitor!
Jun 23 04:05:58 [HOSTNAME] S99AdGuardHome[7104]: Started AdGuardHome from S99AdGuardHome[7104].
Jun 23 04:05:58 [HOSTNAME] S99AdGuardHome[7104]: start_AdGuardHome took 0 second(s) to complete.
Jun 23 04:05:58 [HOSTNAME] AdGuardHome[7248]: 2022/06/23 04:05:58.821821 [info] AdGuard Home, version v0.107.7
Jun 23 04:05:58 [HOSTNAME] AdGuardHome[7248]: 2022/06/23 04:05:58.821899 [info] AdGuard Home is running as a service
Jun 23 04:05:58 [HOSTNAME] AdGuardHome[7248]: 2022/06/23 04:05:58.878975 [info] Initializing auth module: /tmp/mnt/entware/entware/etc/AdGuardHome/data/sessions.db
Jun 23 04:05:58 [HOSTNAME] AdGuardHome[7248]: 2022/06/23 04:05:58.882785 [info] auth: initialized.  users:1  sessions:3
Jun 23 04:05:58 [HOSTNAME] AdGuardHome[7248]: 2022/06/23 04:05:58.882900 [info] Initialize web module
Jun 23 04:05:59 [HOSTNAME] AdGuardHome[7248]: 2022/06/23 04:05:59.588428 [info] AdGuard Home is available at the following addresses:
Jun 23 04:05:59 [HOSTNAME] AdGuardHome[7248]: 2022/06/23 04:05:59.613593 [info] Go to http://127.0.0.1:14711

When checking AdGuard Manager log, I found nothing was there, only the UTC time.

# cat /tmp/AGHManager.log
Thu Jun 23 07:00:02 UTC 2022

So, I'm not sure what happened.

 

[SomeWhereOverTheRainBow]

It took quite a while to fail again, but it did. (actually it failed twice and I forgot to collect the logs )

AdGuard only started after 5 minutes when my script started it.

Jun 23 04:00:01 [HOSTNAME] rc_service: service 2577:notify_rc stop_AdGuardHome
Jun 23 04:05:55 [HOSTNAME] rc_service: service 6967:notify_rc start_AdGuardHome
Jun 23 04:05:55 [HOSTNAME] custom_script: Running /jffs/scripts/service-event (args: start AdGuardHome)
Jun 23 04:05:55 [HOSTNAME] custom_script: Running /jffs/scripts/service-event-end (args: start AdGuardHome)
Jun 23 04:05:58 [HOSTNAME] S99AdGuardHome[7104]: Starting Monitor!
Jun 23 04:05:58 [HOSTNAME] S99AdGuardHome[7104]: Started AdGuardHome from S99AdGuardHome[7104].
Jun 23 04:05:58 [HOSTNAME] S99AdGuardHome[7104]: start_AdGuardHome took 0 second(s) to complete.
Jun 23 04:05:58 [HOSTNAME] AdGuardHome[7248]: 2022/06/23 04:05:58.821821 [info] AdGuard Home, version v0.107.7
Jun 23 04:05:58 [HOSTNAME] AdGuardHome[7248]: 2022/06/23 04:05:58.821899 [info] AdGuard Home is running as a service
Jun 23 04:05:58 [HOSTNAME] AdGuardHome[7248]: 2022/06/23 04:05:58.878975 [info] Initializing auth module: /tmp/mnt/entware/entware/etc/AdGuardHome/data/sessions.db
Jun 23 04:05:58 [HOSTNAME] AdGuardHome[7248]: 2022/06/23 04:05:58.882785 [info] auth: initialized.  users:1  sessions:3
Jun 23 04:05:58 [HOSTNAME] AdGuardHome[7248]: 2022/06/23 04:05:58.882900 [info] Initialize web module
Jun 23 04:05:59 [HOSTNAME] AdGuardHome[7248]: 2022/06/23 04:05:59.588428 [info] AdGuard Home is available at the following addresses:
Jun 23 04:05:59 [HOSTNAME] AdGuardHome[7248]: 2022/06/23 04:05:59.613593 [info] Go to http://127.0.0.1:14711

When checking AdGuard Manager log, I found nothing was there, only the UTC time.

# cat /tmp/AGHManager.log
Thu Jun 23 07:00:02 UTC 2022

So, I'm not sure what happened.

The only thing I can think is that somehow AdGuardHome "itself" is occasionally hanging instead of starting. It is very hard to actually diagnosis since there are no logs indicating it actually starting. I am only assuming it is the AdGuardHome process hanging on start simply because we see my script that starts it is actually running. This tells me the script is not getting past the point where the AdGuardHome start command hangs at. What model router are you using again? The only thing I can recommend trying now is to see if there are any hung process's running when the occurances of AdGuardHome not starting happens. Disable whatever side script you are using to start adguardhome with, just check the running process's with something like htop the next time you experience a hang.

 

[Markfree]

I'm using a RT-AX86U.
And there's no script to start AdGuard. I happen to use Zabbix on this router and it checks if the service is alive. If it is not, then it issues a start command.
I'm not really using any customized script besides those from AMTM.

I'll keep an eye out for odd processes next time AdGuard fails to start.

Thank you @SomeWhereOverTheRainBow

 

[Markfree]

After all AdGuard updates that followed this discussion, I can say that AdGuard is now starting correctly.
I even went as far as to monitor the NTP synchronization time using @Maverickcdn's great script.

We can see that in the last 30 days my router's NTP took about 38s on average to syncronize on a daily basis.

Also, there were 2 times when it took more time (up to 2m51s).
I'm not sure why that happened, though.

Fortunately, I have had no more fails since my last post.

 

[SomeWhereOverTheRainBow]

After all AdGuard updates that followed this discussion, I can say that AdGuard is now starting correctly.
I even went as far as to monitor the NTP synchronization time using @Maverickcdn's great script.

We can see that in the last 30 days my router's NTP took about 38s on average to syncronize on a daily basis.
View attachment 43489
Also, there were 2 times when it took more time (up to 2m51s).
I'm not sure why that happened, though.

Fortunately, I have had no more fails since my last post.

You could try making sure your ntp servers are not waiting for encryption to sync the time by ensuring they are only using plain dns to resolve the hostnames

## eg. place something similar that matches your respected setup inside your upstream section on adguardhome.

[/pool.ntp.org/]1.1.1.1
[/pool.ntp.org/]1.0.0.1
[/pool.ntp.org/]2606:4700:4700::1111
[/pool.ntp.org/]2606:4700:4700::1001

By the way, the latest revision of the installer allows adguardhome to start even if the clock isn't synced as long as there is internet connectivity. So making such an addition may now be required in your case if you are using adguardhome encryption. Otherwise, the overall delay in the encryption process could stall your NTP sync.

 

[SomeWhereOverTheRainBow]

@Markfree

Here is purportedly an example of what happens in some instances with adguardhome and ntp not set correctly.

AdGuardHome will not start if system time is wrong, because the certificate check is invalid, and since the DNS server is not yet enabled, obtaining pool.ntp.org to set time is impossible. · Issue #4880 · AdguardTeam/AdGuardHome

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 Operating system type Li...

github.com