Unbound could not open autotrust file for writing

[_me_myself_and_i_]

Hi, @Martineau

After a very long stretch of flawless uptime, unbound died on me, today. It seemed to have happened just after the cron job to update adblock sites completed, and error was:

Could not open autotrust file for writing /root.key.31931-0-21f5b430

The only way I could get it working, again, was to remove unbound, reboot, re-install via amtm. (I retained my config files.)

Any idea what might have happened?

 

[SomeWhereOverTheRainBow]

Hi, @Martineau

After a very long stretch of flawless uptime, unbound died on me, today. It seemed to have happened just after the cron job to update adblock sites completed, and error was:

Could not open autotrust file for writing /root.key.31931-0-21f5b430

The only way I could get it working, again, was to remove unbound, reboot, re-install via amtm. (I retained my config files.)

Any idea what might have happened?

Those router trolls did it again!.

Some how it looks like the root key did not properly get downloaded for whatever reason thus resulting in unbound not being able to start or stop. The appropriate solution would have been to redownload it. Maybe a better check needs to be put in place to assure the root key has been properly downloaded.

 

[_me_myself_and_i_]

The appropriate solution would have been to redownload it.

Can you elaborate? How would one do this?

 

[SomeWhereOverTheRainBow]

Can you elaborate? How would one do this?

No because I have not studied the specifics of @Martineau script for such matters, I was just providing the at a glance analysis of what happen. I could be wrong but, a possible reason for why such might have occured was because maybe your internet/dns services were down at the time it attempted to download or do the adblock cron job update, the results led to the download of a corrupt or otherwise incomplete root.key. The only person(s) who can resolve such an issue from happening again is @Martineau or @juched the unbound-manager writer, or unbound-adblock writer respectively. It would have been prudent to incorporate an internet detection mechanism that would bail out of performing the updates if no connection were found. This ultimately would have prevented your unbound instance from suffering from a corrupt or incomplete file download.

 

[_me_myself_and_i_]

occured was because maybe your internet/dns services were down at the time it attempted to download

This was not the case, and multiple restarts of unbound (and even the router) did not resolve.

I don't think adblock had anything to do with it -it's just the last thing I saw in the log before the error.

Anyway, let's see if Martineu has a chance to reply... no urgency, as it's all working again.

Once enhancement I may add on my own is a monitoring script that will alert me if "unbound is not running!" appears in the log. I spend most of my days on my workplace VPN and so DNS is not handled by my setup... the only way I discovered this in a timely way is because my kids started complaining.

 

[Deleted member 62525]

This error is related to permissions, ,but not directly to the root.key. Rather its permission to directory where root.key is stored.

 

[SomeWhereOverTheRainBow]

This error is related to permissions, ,but not directly to the root.key. Rather its permission to directory where root.key is stored.

Figures, those blasted permission trolls.

 

[Martineau]

Anyway, let's see if Martineu has a chance to reply... no urgency, as it's all working again.

Once enhancement I may add on my own is a monitoring script that will alert me if "unbound is not running!" appears in the log. I spend most of my days on my workplace VPN and so DNS is not handled by my setup... the only way I discovered this in a timely way is because my kids started complaining.

I don't believe I have experienced the error; unbound can easily go for weeks.......even months

+======================================================================+
|  Welcome to the unbound Manager/Installation script (Asuswrt-Merlin) |
|                                                                      |
|                      Version 3.23bD by Martineau                     |
|                                                                      |
+======================================================================+
unbound (pid 19782) is running... uptime: 58 days 17:35:13 version: 1.13.2 # Version=v1.13 Martineau update (Date Loaded by unbound_manager Mon Dec 6 15:07:48 GMT 2021)

i  = Update unbound and configuration ('/opt/var/lib/unbound/')        l  = Show unbound log entries (lo=Enable FULL Logging [log_level])
z  = Remove unbound/unbound_manager                                    v  = View ('/opt/var/lib/unbound/') unbound Configuration (vx=Edit;vh=help)
3  = Advanced Tools                                                    rl = Reload Configuration (Doesn't halt unbound) e.g. 'rl test1[.conf]' (Recovery use 'rl reset/user')
?  = About Configuration                                               oq = Query unbound Configuration option e.g 'oq verbosity' (ox=Set) e.g. 'ox log-queries yes'

rs = Restart (or Start) unbound (use 'rs nocache' to flush cache)      s  = Show unbound Extended statistics (s=Summary Totals; sa=All; http://10.88.8.1:80/user3.asp)

e  = Exit Script [?]

A:Option ==>

Checking the files etc.

ls -l /opt/var/lib/

drwxr-xr-x    3 nobody   root          4096 Feb  3 08:45 unbound

ls -l /opt/var/lib/unbound

drwxrwxrwx    2 admin    root          4096 Oct  6 11:47 adblock
-rw-rw-rw-    1 admin    root          3313 Feb  3 04:12 root.hints
-rw-rw-rw-    1 nobody   nobody         759 Feb  3 01:41 root.key
-rw-rw-rw-    1 nobody   nobody     2257327 Feb  3 07:14 root.zone
-rw-rw-rw-    1 admin    root        151359 Feb  3 07:15 rpz.urlhaus.abuse.ch.zone
-rw-rw-rw-    1 admin    root         11141 Dec  6 15:07 unbound.conf
-rw-rw-rw-    1 admin    root         36230 Feb  3 06:57 unbound.log
-rw-r-----    1 admin    root          2455 Oct  6 11:36 unbound_control.key
-rw-r-----    1 admin    root          1399 Oct  6 11:36 unbound_control.pem
-rw-r--r--    1 admin    root          7168 Dec  6 17:06 unbound_log.db
-rw-r-----    1 admin    root          2459 Oct  6 11:35 unbound_server.key
-rw-r-----    1 admin    root          1521 Oct  6 11:35 unbound_server.pem
-rw-r--r--    1 admin    root         40960 Feb  3 06:59 unbound_stats.db

Q. Did your error message actually contain 'Permission denied'? - as per this similar 'sudden' NL Labs bug track

fatal error: could not open autotrust file for writing, /var/lib/unbound/root.key.2602864-1-560c3a7457d0: Permission denied · Issue #447 · NLnetLabs/unbound

Any reason why this started to happen? fatal error: could not open autotrust file for writing, /var/lib/unbound/root.key.2602864-1-560c3a7457d0: Permission denied unbound-libs-1.13.1-1.fc33.x86_64 ...

github.com

I'm not sure how frequently the update (no download involved) to 'root.key' should occur, suffice to say I don't know if it is every day?, but clearly 'root.key' was successfully updated this morning on my system (with the permissions shown above), but this is all there is in my scant unbound log, so no explicit reference (logging level not high enough?)

e  = Exit Script [?]

A:Option ==> l

/opt/var/lib/unbound/unbound.log        Press CTRL-C to stop

Jan 30 03:11:07 unbound[19782:0] info: validation failure <fwupdate.asuswrt-merlin.net. AAAA IN>: no signatures from 173.245.58.130
Jan 30 03:12:08 unbound[19782:0] info: validation failure <fwupdate.asuswrt-merlin.net. AAAA IN>: no signatures from 172.64.32.130
Feb 01 03:11:13 unbound[19782:0] info: validation failure <fwupdate.asuswrt-merlin.net. AAAA IN>: no signatures from 173.245.59.80
Feb 01 03:12:15 unbound[19782:0] info: validation failure <fwupdate.asuswrt-merlin.net. AAAA IN>: no signatures from 108.162.193.80
Feb 01 06:26:00 unbound[19782:0] error: SERVFAIL <www.internic.net. A IN>: all servers for this domain failed, at zone vip.icann.org. upstream server timeout
Feb 01 06:26:00 unbound[19782:0] error: .: failed lookup, cannot transfer from master www.internic.net
Feb 01 09:46:08 unbound[19782:0] info: validation failure <fwupdate.asuswrt-merlin.net. AAAA IN>: no signatures from 108.162.193.80
Feb 01 10:07:26 unbound[19782:0] info: validation failure <fwupdate.asuswrt-merlin.net. AAAA IN>: no signatures from 108.162.192.130
Feb 03 03:11:35 unbound[19782:0] info: validation failure <fwupdate.asuswrt-merlin.net. AAAA IN>: no signatures from 108.162.193.80
Feb 03 03:12:37 unbound[19782:0] info: validation failure <fwupdate.asuswrt-merlin.net. AAAA IN>: no signatures from 173.245.59.80

If the permissions were incorrect, then they have presumably always been incorrect if unbound_manager is used to install unbound, and there are not (to my knowledge) numerous reports of similar failures using unbound_manager

However, if there was an issue with the disk, then perhaps a new flash drive together with a fresh install of Entware/unbound may be the cure, rather than implement the unbound watch-dog; although it may be prudent.

Obviously should the issue reoccur, you should check the permissions, then either manually regenerate the 'root.key' in isolation using the NL Labs utility, or simply use unbound_manager menu option 1.

 

[_me_myself_and_i_]

Thanks for the reply, @Martineau !

I don't believe I have experienced the error; unbound can easily go for weeks.......even months

Q. Did your error message actually contain 'Permission denied'? - as per this similar 'sudden' NL Labs bug track

Yes, the actual error was "permission denied." I'm kicking myself for not backing up the log file, as it got overwritten after uninstall/reinstall.

As a result of this debacle, my drive is only a month old and fsck says it's healthy.

fatal error: could not open autotrust file for writing, /var/lib/unbound/root.key.2602864-1-560c3a7457d0: Permission denied · Issue #447 · NLnetLabs/unbound

Any reason why this started to happen? fatal error: could not open autotrust file for writing, /var/lib/unbound/root.key.2602864-1-560c3a7457d0: Permission denied unbound-libs-1.13.1-1.fc33.x86_64 ...

github.com

I'm not sure how frequently the update (no download involved) to 'root.key' should occur, suffice to say I don't know if it is every day?, but clearly 'root.key' was successfully updated this morning on my system (with the permissions shown above), but this is all there is in my scant unbound log, so no explicit reference (logging level not high enough?)

This bug report takes a left turn at Albuquerque, but the original symptom reported by the poster is *exactly* the issue I hit!

So, now we have learned:

Unbound periodically writes to the root.key file, to process the updates for RFC5011 updates. That is what you have configured.

The error is that unbound wants to create a temporary file to write the new contents of the /var/lib/unbound/root.key into. After that unbound is going to remove the old root.key file and rename this file to the root.key file.

Interesting that the temp file is being created in / instead of /tmp or even /opt/var/lib/unbound. I did check permissions on /, but not /opt/var/lib/unbound.

Obviously should the issue reoccur, you should check the permissions, then either manually regenerate the 'root.key' in isolation using the NL Labs utility, or simply use unbound_manager menu option 1.

Yes, if there is a next time (like I said, I have gone many moons with no interruption), I now know how to better debug. In the heat of the moment I just wanted to get back running as quickly as possible.

I will surely report back here if this should reoccur, hopefully with a better workaround than uninstall/reinstall.

I have a cron job that rsyncs my USB drive every 8 hours. If there is a next time, I can compare /opt/var/lib/unbound on USB to the backup to see if anything stands out (including permissions).

Many thanks for your time, and for this wonderful implementation of unbound. It's simple to manage and I prefer it to other adblocking solutions. Adding new block sources is so easy, as is whitelisting others. I've added these with great success and reliability:

https://block.energized.pro/porn/formats/hosts
https://effinthing.com/~dfelicia/blocklist/SmartTV

 

[Deleted member 62525]

You can always run unbound-anchor -vvv to force root.key to be re-generated and permissions fixed.
Its best if run with users that owns unbound process.