IP lookup fails

Christoph · 11 February 2020 07:22

Yesterday I installed duplicacy-web 1.2.0 on my Linux server and I’m getting the following error when running a check job. I don’t know if this is related to the new version (on my windows PC I did not get the error with the new version), but I’d like to understand what it means:

2020-02-11 02:29:50.541 TRACE SNAPSHOT_LIST_REVISIONS Listing revisions for snapshot PC_D
2020-02-11 02:30:28.948 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/PC_D/319' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/PC_D/319: dial tcp: lookup webdav.pcloud.com on 127.0.0.53:53: read udp 127.0.0.1:33099->127.0.0.53:53: read: connection refused)
2020-02-11 02:32:03.135 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/PC_D/460' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/PC_D/460: dial tcp: lookup webdav.pcloud.com on 127.0.0.53:53: no such host)
2020-02-11 02:32:03.710 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/PC_D/460' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/PC_D/460: dial tcp: lookup webdav.pcloud.com on 127.0.0.53:53: no such host)
2020-02-11 02:32:04.824 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/PC_D/460' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/PC_D/460: dial tcp: lookup webdav.pcloud.com on 127.0.0.53:53: no such host)
2020-02-11 02:32:07.145 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/PC_D/460' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/PC_D/460: dial tcp: lookup webdav.pcloud.com on 127.0.0.53:53: no such host)
2020-02-11 02:32:11.188 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/PC_D/460' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/PC_D/460: dial tcp: lookup webdav.pcloud.com on 127.0.0.53:53: no such host)
2020-02-11 02:32:21.566 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/PC_D/460' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/PC_D/460: dial tcp: lookup webdav.pcloud.com on 127.0.0.53:53: no such host)
2020-02-11 02:32:47.208 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/PC_D/460' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/PC_D/460: dial tcp: lookup webdav.pcloud.com on 127.0.0.53:53: no such host)
2020-02-11 02:33:39.341 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/PC_D/460' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/PC_D/460: dial tcp: lookup webdav.pcloud.com on 127.0.0.53:53: no such host)
2020-02-11 02:35:21.714 ERROR SNAPSHOT_INFO Failed to get the information on the snapshot PC_D at revision 460: Maximum backoff reached
Failed to get the information on the snapshot PC_D at revision 460: Maximum backoff reached

Is duplicacy doing a DNS lookup on 127.0.0.53? Is that some kind of default DNS IP? It is not the IP of my DNS, obviously. Why is duplicacy checking that IP? And why is it doing a DNS look-up at all, given that it has already been in touch with the storage server for half an hour or so?

andrew.heberle · 11 February 2020 12:44

That address is the local caching DNS resolver provided by systemd (systemd-resolved to be exact). I know that depending on how its set up it will add itself (ie 127.0.0.53) to /etc/resolv.conf so it is used by the local system…it then forwards queries onto your real DNS servers…but unfortunately those defaults may be different depending on the distribution you are using.

It looks like this service has possibly died or has been disabled. I think it is enabled by default on Ubuntu.

Christoph · 11 February 2020 20:16

Thanks for explaining.

This is not something I ever configured manually. I’m using Ubuntu 18.04. And I have never had any DNS issues so far. And even duplicacy seems to have been using that service just minutes earlier. So I guess that means it suddenly crashed?

I ran the same check job again this morning and the same problem occurred again (I’m providing a bit more context this time):

2020-02-11 08:32:28.446 TRACE LIST_FILES Listing chunks/91/
2020-02-11 08:32:32.185 TRACE LIST_FILES Listing chunks/55/
2020-02-11 08:32:35.673 TRACE LIST_FILES Listing chunks/3e/
2020-02-11 08:32:39.107 TRACE LIST_FILES Listing chunks/0c/
2020-02-11 08:32:45.028 TRACE SNAPSHOT_LIST_IDS Listing all snapshot ids
2020-02-11 08:32:45.263 TRACE SNAPSHOT_LIST_REVISIONS Listing revisions for snapshot PC_C
2020-02-11 08:36:11.814 TRACE SNAPSHOT_LIST_REVISIONS Listing revisions for snapshot PC_D
2020-02-11 08:38:32.166 TRACE SNAPSHOT_LIST_REVISIONS Listing revisions for snapshot ALPHA_C
2020-02-11 08:41:48.208 TRACE SNAPSHOT_LIST_REVISIONS Listing revisions for snapshot ALPHA_D_COP
2020-02-11 08:41:50.451 TRACE SNAPSHOT_LIST_REVISIONS Listing revisions for snapshot NAS
2020-02-11 08:45:39.442 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/NAS/292' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/NAS/292: dial tcp: lookup webdav.pcloud.com on 127.0.0.53:53: no such host)
2020-02-11 08:45:40.347 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/NAS/292' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/NAS/292: dial tcp: lookup webdav.pcloud.com on 127.0.0.53:53: no such host)
2020-02-11 08:45:42.218 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/NAS/292' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/NAS/292: dial tcp: lookup webdav.pcloud.com on 127.0.0.53:53: no such host)
2020-02-11 08:45:45.781 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/NAS/292' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/NAS/292: dial tcp: lookup webdav.pcloud.com on 127.0.0.53:53: no such host)
2020-02-11 08:45:51.366 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/NAS/292' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/NAS/292: dial tcp: lookup webdav.pcloud.com on 127.0.0.53:53: no such host)
2020-02-11 08:46:04.247 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/NAS/292' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/NAS/292: dial tcp: lookup webdav.pcloud.com on 127.0.0.53:53: no such host)
2020-02-11 08:46:28.870 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/NAS/292' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/NAS/292: dial tcp: lookup webdav.pcloud.com on 127.0.0.53:53: no such host)
2020-02-11 08:47:14.145 TRACE WEBDAV_RETRY URL request 'PROPFIND snapshots/NAS/292' returned an error (Propfind https://webdav.pcloud.com/Backup/Duplicacy/snapshots/NAS/292: dial tcp: lookup webdav.pcloud.com on 127.0.0.53:53: no such host)
2020-02-11 08:49:00.877 ERROR SNAPSHOT_INFO Failed to get the information on the snapshot NAS at revision 292: Maximum backoff reached
Failed to get the information on the snapshot NAS at revision 292: Maximum backoff reached

andrew.heberle · 12 February 2020 01:02

OK, that makes it easier as I’ve got Ubuntu 18.04 running here too…

On my system /etc/resolv.conf looks like this:

$ cat /etc/resolv.conf
# Dynamic resolv.conf(5) file for glibc resolver(3) generated by resolvconf(8)
#     DO NOT EDIT THIS FILE BY HAND -- YOUR CHANGES WILL BE OVERWRITTEN
# 127.0.0.53 is the systemd-resolved stub resolver.
# run "systemd-resolve --status" to see details about the actual nameservers.

nameserver <my router ip>
nameserver 127.0.0.53
search <my internal domain>

Running the systemd-resolve --status command from the above gives me some sort of info but to be honest I’m not sure what it’s telling me

I’d suggest checking the status of systemd-resolved service using the following command:

$ systemctl status systemd-resolved
● systemd-resolved.service - Network Name Resolution
   Loaded: loaded (/lib/systemd/system/systemd-resolved.service; enabled; vendor preset: enabled)
   Active: active (running) since Thu 2020-02-06 06:19:07 AWST; 6 days ago
     Docs: man:systemd-resolved.service(8)
           https://www.freedesktop.org/wiki/Software/systemd/resolved
           https://www.freedesktop.org/wiki/Software/systemd/writing-network-configuration-managers
           https://www.freedesktop.org/wiki/Software/systemd/writing-resolver-clients
 Main PID: 28840 (systemd-resolve)
   Status: "Processing requests..."
    Tasks: 1 (limit: 4915)
   CGroup: /system.slice/systemd-resolved.service
           └─28840 /lib/systemd/systemd-resolved

If the Active line shows that the service is not running or has crashed you could attempt to restart it using:

$ sudo systemctl start systemd-resolved

Apart from that (or a reboot) I can’t offer too much more insight as I’m still getting my head around some of the deeper systemd integration in distributions now…back in the day you just had a list of DNS servers in /etc/resolv.conf and that was it…

Christoph · 12 February 2020 20:54

Mine only contains this (apart from comments)

nameserver 127.0.0.53
options edns0

While I don’t understand the output of systemd-resolve --status any more than you, I do see that it has the two DNS servers from my router at the beginning. So the first thing I’m wondering is where it got these from, given that, unlike yours, my /etc/resolv.conf doesn’t include my router IP.

But apart from that, I suspect that the reason for my failed lookups might be in the edns0 option. It seems to be a feature that not all DNS servers support.

When I do systemctl status systemd-resolved, the strange thing is that it says it is active since six minutes. But I didn’t start it…

$ systemctl status systemd-resolved
â systemd-resolved.service - Network Name Resolution
   Loaded: loaded (/lib/systemd/system/systemd-resolved.service; enabled; vendor
   Active: active (running) since Wed 2020-02-12 21:51:50 CET; 6min ago
     Docs: man:systemd-resolved.service(8)
           https://www.freedesktop.org/wiki/Software/systemd/resolved
           https://www.freedesktop.org/wiki/Software/systemd/writing-network-con
           https://www.freedesktop.org/wiki/Software/systemd/writing-resolver-cl
 Main PID: 24442 (systemd-resolve)
   Status: "Processing requests..."
    Tasks: 1 (limit: 4915)
   CGroup: /system.slice/systemd-resolved.service
           ââ24442 /lib/systemd/systemd-resolved

feb 12 21:51:50 server systemd[1]: Starting Network Name Resolution...
feb 12 21:51:50 server systemd-resolved[24442]: Positive Trust Anchors:
feb 12 21:51:50 server systemd-resolved[24442]: . IN DS 19036 8 2 49aac11d7b6f6446702e54a1607371607a1a41855200fd2ce1cdde32f24e8fb5
feb 12 21:51:50 server systemd-resolved[24442]: . IN DS 20326 8 2 e06d44b80b8f1d39a95c0b0d7c65d08458e880409bbc683457104237c7f8ec8d
feb 12 21:51:50 server systemd-resolved[24442]: Negative trust anchors: 10.in-addr.arpa 16.172.in-addr.arpa 17.172.in-addr.arpa 18.172.in-addr.arpa 19.172.in-addr.arpa 20.172.in-addr.arpa 21.172.in-addr.arpa 22. [**** snip ****}
feb 12 21:51:50 server systemd-resolved[24442]: Using system hostname 'server'.
feb 12 21:51:50 server systemd[1]: Started Network Name Resolution.

Update: It looks like my systend-resolved is constantly restarting and it might be related to this bug (although I did not upgrade from Xenial).