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

[LinuxPersonEC]

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
python3-unbound-1.13.1-1.fc33.x86_64
unbound-1.13.1-1.fc33.x86_64

[wcawijngaards]

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. But unbound gets permission denied when it attempts to write there. Perhaps the directory has no write permissions (for the unbound user), or you have selinux or apparmor or freebsd capabilities configured to deny write access from unbound to this directory?

[LinuxPersonEC]

I try to chown unbound:unbound but after restarting the unbound process it goes back to root;

ls -l /var/lib/unbound/root.key
-rw-r--r-- 1 root root 759 Mar 19 10:24 /var/lib/unbound/root.key

No SELinux, no AppArmor, and you can see from my rpm command it's Fedora 33.

Now I see:

fatal error: could not open autotrust file for writing, /var/lib/unbound/root.key.2653680-3-56517c61b7d0: Permission denied

[LinuxPersonEC]

Not sure if this is the long term fix but I ran chown -R unbound:unbound /var/lib/unbound and restarted unbound but I get these error: read (in tcp s): Connection refused as mentioned in issue 360.

Mar 19 12:15:52 ourserver unbound[2660803]: [2660803:3] error: read (in tcp s): Connection refused for 199.180.182.53 port 53
Mar 19 12:15:52 ourserver unbound[2660803]: [2660803:3] error: read (in tcp s): Connection refused for 199.180.182.53 port 53
Mar 19 12:15:52 ourserver unbound[2660803]: [2660803:3] error: read (in tcp s): Connection refused for 193.0.9.1 port 53
Mar 19 12:15:52 ourserver unbound[2660803]: [2660803:3] error: read (in tcp s): Connection refused for 193.0.9.1 port 53
Mar 19 12:15:52 ourserver unbound[2660803]: [2660803:3] error: read (in tcp s): Connection refused for 196.216.169.10 port 53
Mar 19 12:15:52 ourserver unbound[2660803]: [2660803:3] error: read (in tcp s): Connection refused for 196.216.169.10 port 53
Mar 19 12:15:52 ourserver unbound[2660803]: [2660803:3] error: read (in tcp s): Connection refused for 193.0.9.1 port 53
Mar 19 12:15:52 ourserver unbound[2660803]: [2660803:3] error: read (in tcp s): Connection refused for 193.0.9.1 port 53
Mar 19 12:15:52 ourserver unbound[2660803]: [2660803:3] error: read (in tcp s): Connection refused for 200.10.60.53 port 53
Mar 19 12:15:52 ourserver unbound[2660803]: [2660803:3] error: read (in tcp s): Connection refused for 200.10.60.53 port 53

TCP Fast Open is disabled. How can I debug this?

dig +tcp @193.0.9.1
;; Connection to 193.0.9.1#53(193.0.9.1) for . failed: connection refused.

Edit I see a user having this with Netgate.

[wcawijngaards]

The chown of the directory worked, and that fixed your permission denied failure that you had.

The connection refused, is a spammy message that says unbound cannot make tcp connections. I have made it less visible, by only making it print when verbosity is high. This is committed to the repository.

It seems you cannot make TCP connections, and dig also cannot make tcp connections to those IP addresses from the commandline. I also do not know why the connections are refused by your upstream. Perhaps your firewall is refusing to allow tcp connections there, or another firewall is refusing tcp connections. This is a separate issue from your permission denied issue.

[LinuxPersonEC]

Once I removed the -d option from /usr/lib/systemd/system/unbound.service in ExecStart the TCP timeout issues also disappeared from the logs. Perhaps this was already done upstream?

unbound-libs-1.13.1-1.fc33.x86_64
python3-unbound-1.13.1-1.fc33.x86_64
unbound-1.13.1-1.fc33.x86_64

Anyways, as for the original issue, yes it's fixed. I haven't tried a reboot but I'm assuming it should be persistent. But I don't see this documented anywhere to change the permission in the/var/lib/unbounddirectory. Should that be part of the installation process?

[wcawijngaards]

Not sure how the removal of the -d option fixes your issue, perhaps what happened was you reloaded your new config file in the process with fixed options in it? Or it fixed it somehow, the unbound.service file is part of the unbound rpm that you are using.

Also the var/lib/unbound directory is created by the rpm and also the configuration that unbound uses that directory to store files is part of the rpm configure script (or default configuration shipped with the package). But we do not do the package scripts, that is handled by the distro that you are using. A look at the unbound.spec file shows that it performs a chown for the user unbound on install %dir %attr(0755,unbound,unbound) %{_sharedstatedir}/%{name}, so I do not know what is wrong with that.

[LinuxPersonEC]

Not sure how the removal of the -d option fixes your issue, perhaps what happened was you reloaded your new config file in the process with fixed options in it? Or it fixed it somehow, the unbound.service file is part of the unbound rpm that you are using.

I can confirm that on a second server running unbound, that when I removed the -d option from the /usr/lib/systemd/system/unbound.service all of those error: read (in tcp s): Connection refused errors disappeared.

[wcawijngaards]

The -d option, documented with -d do not fork into the background., makes unbound not fork into a new process. So with -d it stays attached to the console on which it was started. This is what systemd wants because systemd is monitoring that console.

Systemd may also have set other permissions on that console, did it? Would that have caused the different results for tcp connections for the program? Without the -d option unbound forks into a process, but I do not really see what difference that could have made to the tcp connections, so that it gives no connection refused.

[LinuxPersonEC]

Systemd may also have set other permissions on that console, did it?

Can you clarify what you are looking for? Here is what is in the /usr/lib/systemd/system/unbound.service file.

[Unit]
Description=Unbound recursive Domain Name Server
After=network.target
After=unbound-keygen.service
Wants=unbound-keygen.service
Wants=unbound-anchor.timer
Before=nss-lookup.target
Wants=nss-lookup.target

[Service]
Type=simple
EnvironmentFile=-/etc/sysconfig/unbound
ExecStartPre=/usr/sbin/unbound-checkconf
ExecStartPre=-/usr/sbin/unbound-anchor -a /var/lib/unbound/root.key -c /etc/unbound/icannbundle.pem -f /etc/resolv.conf -R
ExecStart=/usr/sbin/unbound  $UNBOUND_OPTIONS
ExecReload=/usr/sbin/unbound-control reload

[Install]
WantedBy=multi-user.target

 /etc/sysconfig/unbound
# for extra debug, add "-v -v" or change verbosity: in unbound.conf

UNBOUND_OPTIONS=""

[wcawijngaards]

From this I see no reason why -d would have made a difference to TCP connections.

[LinuxPersonEC]

After I removed our DNS servers in /etc/resolv.conf unbound stops working:

unbound-checkconf
unbound-checkconf: no errors in /etc/unbound/unbound.conf
# unbound-control dump_cache
[1617035678] unbound-control[3348867:0] error: connect: Connection refused for 127.0.0.1 port 8953

# systemctl status unbound
● unbound.service - Unbound recursive Domain Name Server
     Loaded: loaded (/usr/lib/systemd/system/unbound.service; enabled; vendor preset: disabled)
     Active: inactive (dead) since Mon 2021-03-29 12:31:33 EDT; 3min 12s ago
    Process: 3348322 ExecStartPre=/usr/sbin/unbound-checkconf (code=exited, status=0/SUCCESS)
    Process: 3348323 ExecStartPre=/usr/sbin/unbound-anchor -a /var/lib/unbound/root.key -c /etc/unbound/icannbundle.pem -f /etc/resolv.conf -R (code=exited, status=0/SUCCESS)
    Process: 3348373 ExecStart=/usr/sbin/unbound $UNBOUND_OPTIONS (code=exited, status=0/SUCCESS)
   Main PID: 3348373 (code=exited, status=0/SUCCESS)
        CPU: 148ms

Mar 29 12:31:33 ourserver unbound[3348374]: [3348374:0] info: service stopped (unbound 1.13.1).
Mar 29 12:31:33 ourserver unbound[3348374]: [3348374:0] info: server stats for thread 0: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Mar 29 12:31:33 ourserver unbound[3348374]: [3348374:0] info: server stats for thread 0: requestlist max 0 avg 0 exceeded 0 jostled 0
Mar 29 12:31:33 ourserver unbound[3348374]: [3348374:0] info: server stats for thread 1: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Mar 29 12:31:33 ourserver unbound[3348374]: [3348374:0] info: server stats for thread 1: requestlist max 0 avg 0 exceeded 0 jostled 0
Mar 29 12:31:33 ourserver unbound[3348374]: [3348374:0] info: server stats for thread 2: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Mar 29 12:31:33 ourserver unbound[3348374]: [3348374:0] info: server stats for thread 2: requestlist max 0 avg 0 exceeded 0 jostled 0
Mar 29 12:31:33 ourserver unbound[3348374]: [3348374:0] info: server stats for thread 3: 0 queries, 0 answers from cache, 0 recursions, 0 prefetch, 0 rejected by ip ratelimiting
Mar 29 12:31:33 ourserver unbound[3348374]: [3348374:0] info: server

netstat -nltup | grep 'Proto\|:8953 '
Proto Recv-Q Send-Q Local Address           Foreign Address         State       PID/Program name

unbound-control status
[1617035844] unbound-control[3349422:0] error: connect: Connection refused for 127.0.0.1 port 8953
unbound is stopped

Port 8953 is open. What else is wrong?

[LinuxPersonEC]

OK a little embarrassing here. The -d option is definitely needed. interface-automatic was set to the default, no.

        # NOTE: Enable this option when specifying interface 0.0.0.0 or ::0
        # NOTE: Disabled per Fedora policy not to listen to * on default install
        # NOTE: If deploying on non-default port, eg 80/443, this needs to be disabled
        interface-automatic: yes

I'm still getting the error: read (in tcp s): Connection refused for errors but at least unbound is working.

dig +tcp @193.0.9.1
;; Connection to 193.0.9.1#53(193.0.9.1) for . failed: connection refused.

[wcawijngaards]

So dig fails to make a tcp connection. Unbound also fails to make that tcp connection. Your system does not make tcp connections.

Perhaps a firewall issue, on this device or on another device?

[LinuxPersonEC]

So dig fails to make a tcp connection. Unbound also fails to make that tcp connection. Your system does not make tcp connections.

Perhaps a firewall issue, on this device or on another device?

Indeed our IT group confirmed they started blocking all non-UDP requests to DNS. They are looking at allowing it back just for our department.

You previously mentioned TCP Fast Open. Does unbound take advantage of it and any place I can share documentation for it?

Also if TCP is blocked for IPs outside of our subnet, would that cause dnf update to fail with the following?

Error: Error downloading packages:
  Curl error (6): Couldn't resolve host name for https://mirrors.fedoraproject.org/metalink?repo=updates-released-f33&arch=x86_64 [Could not resolve host: mirrors.fedoraproject.org]