Merge pull request #974 from teg/resolved-fixes-2

resolved: debugging improvements

4 files changed, 85 insertions, 12 deletions

diff --git a/src/resolve-host/resolve-host.c b/src/resolve-host/resolve-host.c
index 4d557bdf02..7525d7c32f 100644
--- a/src/resolve-host/resolve-host.c
+++ b/src/resolve-host/resolve-host.c
@@ -41,7 +41,8 @@ static uint16_t arg_class = 0;
 static bool arg_legend = true;
 static uint64_t arg_flags = 0;
 
-static void print_source(int ifindex, uint64_t flags) {
+static void print_source(int ifindex, uint64_t flags, usec_t rtt) {
+        char rtt_str[FORMAT_TIMESTAMP_MAX];
 
         if (!arg_legend)
                 return;
@@ -62,6 +63,10 @@ static void print_source(int ifindex, uint64_t flags) {
                 printf(" interface %s", strna(if_indextoname(ifindex, ifname)));
         }
 
+        assert_se(format_timespan(rtt_str, sizeof(rtt_str), rtt, 100));
+
+        printf(" in %s", rtt_str);
+
         fputc('.', stdout);
         fputc('\n', stdout);
 }
@@ -74,6 +79,7 @@ static int resolve_host(sd_bus *bus, const char *name) {
         unsigned c = 0;
         int r, ifindex;
         uint64_t flags;
+        usec_t ts;
 
         assert(name);
 
@@ -93,12 +99,16 @@ static int resolve_host(sd_bus *bus, const char *name) {
         if (r < 0)
                 return bus_log_create_error(r);
 
+        ts = now(CLOCK_MONOTONIC);
+
         r = sd_bus_call(bus, req, DNS_CALL_TIMEOUT_USEC, &error, &reply);
         if (r < 0) {
                 log_error("%s: resolve call failed: %s", name, bus_error_message(&error, r));
                 return r;
         }
 
+        ts = now(CLOCK_MONOTONIC) - ts;
+
         r = sd_bus_message_read(reply, "i", &ifindex);
         if (r < 0)
                 return bus_log_parse_error(r);
@@ -182,7 +192,7 @@ static int resolve_host(sd_bus *bus, const char *name) {
                 return -ESRCH;
         }
 
-        print_source(ifindex, flags);
+        print_source(ifindex, flags, ts);
 
         return 0;
 }
@@ -195,6 +205,7 @@ static int resolve_address(sd_bus *bus, int family, const union in_addr_union *a
         uint64_t flags;
         unsigned c = 0;
         const char *n;
+        usec_t ts;
         int r;
 
         assert(bus);
@@ -243,12 +254,16 @@ static int resolve_address(sd_bus *bus, int family, const union in_addr_union *a
         if (r < 0)
                 return bus_log_create_error(r);
 
+        ts = now(CLOCK_MONOTONIC);
+
         r = sd_bus_call(bus, req, DNS_CALL_TIMEOUT_USEC, &error, &reply);
         if (r < 0) {
                 log_error("%s: resolve call failed: %s", pretty, bus_error_message(&error, r));
                 return r;
         }
 
+        ts = now(CLOCK_MONOTONIC) - ts;
+
         r = sd_bus_message_read(reply, "i", &ifindex);
         if (r < 0)
                 return bus_log_parse_error(r);
@@ -283,7 +298,7 @@ static int resolve_address(sd_bus *bus, int family, const union in_addr_union *a
                 return -ESRCH;
         }
 
-        print_source(ifindex, flags);
+        print_source(ifindex, flags, ts);
 
         return 0;
 }
@@ -321,6 +336,7 @@ static int resolve_record(sd_bus *bus, const char *name) {
         unsigned n = 0;
         uint64_t flags;
         int r, ifindex;
+        usec_t ts;
 
         assert(name);
 
@@ -341,12 +357,16 @@ static int resolve_record(sd_bus *bus, const char *name) {
         if (r < 0)
                 return bus_log_create_error(r);
 
+        ts = now(CLOCK_MONOTONIC);
+
         r = sd_bus_call(bus, req, DNS_CALL_TIMEOUT_USEC, &error, &reply);
         if (r < 0) {
                 log_error("%s: resolve call failed: %s", name, bus_error_message(&error, r));
                 return r;
         }
 
+        ts = now(CLOCK_MONOTONIC) - ts;
+
         r = sd_bus_message_read(reply, "i", &ifindex);
         if (r < 0)
                 return bus_log_parse_error(r);
@@ -414,7 +434,7 @@ static int resolve_record(sd_bus *bus, const char *name) {
                 return -ESRCH;
         }
 
-        print_source(ifindex, flags);
+        print_source(ifindex, flags, ts);
 
         return 0;
 }
diff --git a/src/resolve/resolved-dns-cache.c b/src/resolve/resolved-dns-cache.c
index 9ffaf4b19f..81ea1cafcb 100644
--- a/src/resolve/resolved-dns-cache.c
+++ b/src/resolve/resolved-dns-cache.c
@@ -95,14 +95,19 @@ void dns_cache_flush(DnsCache *c) {
         c->by_expiry = prioq_free(c->by_expiry);
 }
 
-static void dns_cache_remove(DnsCache *c, DnsResourceKey *key) {
+static bool dns_cache_remove(DnsCache *c, DnsResourceKey *key) {
         DnsCacheItem *i;
+        bool exist = false;
 
         assert(c);
         assert(key);
 
-        while ((i = hashmap_get(c->by_key, key)))
+        while ((i = hashmap_get(c->by_key, key))) {
                 dns_cache_item_remove_and_free(c, i);
+                exist = true;
+        }
+
+        return exist;
 }
 
 static void dns_cache_make_space(DnsCache *c, unsigned add) {
@@ -263,6 +268,7 @@ static int dns_cache_put_positive(
                 const union in_addr_union *owner_address) {
 
         _cleanup_(dns_cache_item_freep) DnsCacheItem *i = NULL;
+        _cleanup_free_ char *key_str = NULL;
         DnsCacheItem *existing;
         int r;
 
@@ -272,7 +278,14 @@ static int dns_cache_put_positive(
 
         /* New TTL is 0? Delete the entry... */
         if (rr->ttl <= 0) {
-                dns_cache_remove(c, rr->key);
+                if (dns_cache_remove(c, rr->key)) {
+                        r = dns_resource_key_to_string(rr->key, &key_str);
+                        if (r < 0)
+                                return r;
+
+                        log_debug("Removed zero TTL entry from cache: %s", key_str);
+                }
+
                 return 0;
         }
 
@@ -311,6 +324,12 @@ static int dns_cache_put_positive(
         if (r < 0)
                 return r;
 
+        r = dns_resource_key_to_string(i->key, &key_str);
+        if (r < 0)
+                return r;
+
+        log_debug("Added cache entry for %s", key_str);
+
         i = NULL;
         return 0;
 }
@@ -325,6 +344,7 @@ static int dns_cache_put_negative(
                 const union in_addr_union *owner_address) {
 
         _cleanup_(dns_cache_item_freep) DnsCacheItem *i = NULL;
+        _cleanup_free_ char *key_str = NULL;
         int r;
 
         assert(c);
@@ -337,8 +357,15 @@ static int dns_cache_put_negative(
                 return 0;
         if (key->type == DNS_TYPE_ANY)
                 return 0;
-        if (soa_ttl <= 0)
+        if (soa_ttl <= 0) {
+                r = dns_resource_key_to_string(key, &key_str);
+                if (r < 0)
+                        return r;
+
+                log_debug("Ignored negative cache entry with zero SOA TTL: %s", key_str);
+
                 return 0;
+        }
 
         if (!IN_SET(rcode, DNS_RCODE_SUCCESS, DNS_RCODE_NXDOMAIN))
                 return 0;
@@ -364,6 +391,12 @@ static int dns_cache_put_negative(
         if (r < 0)
                 return r;
 
+        r = dns_resource_key_to_string(i->key, &key_str);
+        if (r < 0)
+                return r;
+
+        log_debug("Added %s cache entry for %s", i->type == DNS_CACHE_NODATA ? "NODATA" : "NXDOMAIN", key_str);
+
         i = NULL;
         return 0;
 }
@@ -468,11 +501,19 @@ int dns_cache_lookup(DnsCache *c, DnsQuestion *q, int *rcode, DnsAnswer **ret) {
         }
 
         for (i = 0; i < q->n_keys; i++) {
+                _cleanup_free_ char *key_str = NULL;
                 DnsCacheItem *j;
 
                 if (q->keys[i]->type == DNS_TYPE_ANY ||
                     q->keys[i]->class == DNS_CLASS_ANY) {
                         /* If we have ANY lookups we simply refresh */
+
+                        r = dns_resource_key_to_string(q->keys[i], &key_str);
+                        if (r < 0)
+                                return r;
+
+                        log_debug("Ignoring cache for ANY lookup: %s", key_str);
+
                         *ret = NULL;
                         *rcode = 0;
                         return 0;
@@ -481,9 +522,24 @@ int dns_cache_lookup(DnsCache *c, DnsQuestion *q, int *rcode, DnsAnswer **ret) {
                 j = hashmap_get(c->by_key, q->keys[i]);
                 if (!j) {
                         /* If one question cannot be answered we need to refresh */
+
+                        r = dns_resource_key_to_string(q->keys[i], &key_str);
+                        if (r < 0)
+                                return r;
+
+                        log_debug("Cache miss for %s", key_str);
+
                         *ret = NULL;
                         *rcode = 0;
                         return 0;
+                } else {
+                        r = dns_resource_key_to_string(j->key, &key_str);
+                        if (r < 0)
+                                return r;
+
+                        log_debug("%s cache hit for %s",
+                                   j->type == DNS_CACHE_POSITIVE ? "Positive" :
+                                                                  (j->type == DNS_CACHE_NODATA ? "NODATA" : "NXDOMAIN"), key_str);
                 }
 
                 LIST_FOREACH(by_key, j, j) {
diff --git a/src/resolve/resolved-dns-packet.c b/src/resolve/resolved-dns-packet.c
index 39951a362c..35ad899544 100644
--- a/src/resolve/resolved-dns-packet.c
+++ b/src/resolve/resolved-dns-packet.c
@@ -1712,7 +1712,7 @@ int dns_packet_read_rr(DnsPacket *p, DnsResourceRecord **ret, size_t *start) {
                 if (r < 0)
                         goto fail;
 
-                r = dns_packet_read_type_windows(p, &rr->nsec.types, offset + rdlength - p->rindex, NULL);
+                r = dns_packet_read_type_windows(p, &rr->nsec3.types, offset + rdlength - p->rindex, NULL);
                 if (r < 0)
                         goto fail;
 
diff --git a/src/resolve/resolved-dns-transaction.c b/src/resolve/resolved-dns-transaction.c
index 53779f3372..2d9d1a47ee 100644
--- a/src/resolve/resolved-dns-transaction.c
+++ b/src/resolve/resolved-dns-transaction.c
@@ -624,7 +624,6 @@ int dns_transaction_go(DnsTransaction *t) {
                 if (r < 0)
                         return r;
                 if (r > 0) {
-                        log_debug("Cache hit!");
                         if (t->cached_rcode == DNS_RCODE_SUCCESS)
                                 dns_transaction_complete(t, DNS_TRANSACTION_SUCCESS);
                         else
@@ -661,8 +660,6 @@ int dns_transaction_go(DnsTransaction *t) {
                 return 0;
         }
 
-        log_debug("Cache miss!");
-
         /* Otherwise, we need to ask the network */
         r = dns_transaction_make_packet(t);
         if (r == -EDOM) {