device: improve logging for hostname-from-dns events

Improve logging:
 - log only when something changes
 - print the new resolver state, instead of the old one
 - rename state "in-progress" to "started"
 - log when the resolver state is reset due to DNS changes

(cherry picked from commit 7037aa66c6fce01d3e33e1fae32c35fb1f25b363)

3 files changed, 51 insertions, 39 deletions

diff --git a/src/core/devices/nm-device.c b/src/core/devices/nm-device.c
index 040bc276ab..291fb279fc 100644
--- a/src/core/devices/nm-device.c
+++ b/src/core/devices/nm-device.c
@@ -312,7 +312,7 @@ typedef struct {
 
 typedef enum {
     RESOLVER_WAIT_ADDRESS = 0,
-    RESOLVER_IN_PROGRESS,
+    RESOLVER_STARTED,
     RESOLVER_DONE,
 } ResolverState;
 
@@ -17107,6 +17107,21 @@ nm_device_auth_retries_try_next(NMDevice *self)
     return TRUE;
 }
 
+static const char *
+_resolver_state_to_string(ResolverState state)
+{
+    switch (state) {
+    case RESOLVER_WAIT_ADDRESS:
+        return "WAIT-ADDRESS";
+    case RESOLVER_STARTED:
+        return "STARTED";
+    case RESOLVER_DONE:
+        return "DONE";
+    }
+    nm_assert_not_reached();
+    return "UNKNOWN";
+}
+
 static void
 hostname_dns_lookup_callback(GObject *source, GAsyncResult *result, gpointer user_data)
 {
@@ -17126,7 +17141,9 @@ hostname_dns_lookup_callback(GObject *source, GAsyncResult *result, gpointer use
 
     if (error) {
         _LOGD(LOGD_DNS,
-              "hostname-from-dns: lookup error for %s: %s",
+              "hostname-from-dns: ipv%c resolver %s: lookup error for %s: %s",
+              nm_utils_addr_family_to_char(resolver->addr_family),
+              _resolver_state_to_string(RESOLVER_DONE),
               (addr_str = g_inet_address_to_string(resolver->address)),
               error->message);
     } else {
@@ -17136,7 +17153,9 @@ hostname_dns_lookup_callback(GObject *source, GAsyncResult *result, gpointer use
         valid              = nm_utils_validate_hostname(resolver->hostname);
 
         _LOGD(LOGD_DNS,
-              "hostname-from-dns: lookup done for %s, result %s%s%s%s",
+              "hostname-from-dns: ipv%c resolver %s: lookup successful for %s, result %s%s%s%s",
+              nm_utils_addr_family_to_char(resolver->addr_family),
+              _resolver_state_to_string(RESOLVER_DONE),
               (addr_str = g_inet_address_to_string(resolver->address)),
               NM_PRINT_FMT_QUOTE_STRING(resolver->hostname),
               valid ? "" : " (invalid)");
@@ -17162,8 +17181,9 @@ hostname_dns_address_timeout(gpointer user_data)
     nm_assert(!resolver->cancellable);
 
     _LOGT(LOGD_DNS,
-          "hostname-from-dns: timed out while waiting IPv%c address",
-          nm_utils_addr_family_to_char(resolver->addr_family));
+          "hostname-from-dns: ipv%c state %s: timed out while waiting for address",
+          nm_utils_addr_family_to_char(resolver->addr_family),
+          _resolver_state_to_string(RESOLVER_DONE));
 
     resolver->timeout_id = 0;
     resolver->state      = RESOLVER_DONE;
@@ -17172,30 +17192,16 @@ hostname_dns_address_timeout(gpointer user_data)
     return G_SOURCE_REMOVE;
 }
 
-static const char *
-_resolver_state_to_string(ResolverState state)
-{
-    switch (state) {
-    case RESOLVER_WAIT_ADDRESS:
-        return "wait-address";
-    case RESOLVER_IN_PROGRESS:
-        return "in-progress";
-    case RESOLVER_DONE:
-        return "done";
-    default:
-        nm_assert_not_reached();
-        return "unknown";
-    }
-}
-
 void
-nm_device_clear_dns_lookup_data(NMDevice *self)
+nm_device_clear_dns_lookup_data(NMDevice *self, const char *reason)
 {
     NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE(self);
-    guint            i;
 
-    for (i = 0; i < 2; i++)
-        nm_clear_pointer(&priv->hostname_resolver_x[i], _hostname_resolver_free);
+    if (priv->hostname_resolver_4 || priv->hostname_resolver_6) {
+        _LOGT(LOGD_DNS, "hostname-from-dns: resetting (%s)", reason);
+        nm_clear_pointer(&priv->hostname_resolver_4, _hostname_resolver_free);
+        nm_clear_pointer(&priv->hostname_resolver_6, _hostname_resolver_free);
+    }
 }
 
 gboolean
@@ -17329,29 +17335,35 @@ nm_device_get_hostname_from_dns_lookup(NMDevice *self, int addr_family, gboolean
     } else if (new_address != resolver->address)
         address_changed = TRUE;
 
+    if (address_changed) {
+        /* set new state before logging */
+        if (new_address)
+            resolver->state = RESOLVER_STARTED;
+        else
+            resolver->state = RESOLVER_WAIT_ADDRESS;
+    }
+
     {
         gs_free char *old_str = NULL;
         gs_free char *new_str = NULL;
 
-        _LOGT(LOGD_DNS,
-              "hostname-from-dns: ipv%c resolver state %s, old address %s, new address %s",
-              nm_utils_addr_family_to_char(resolver->addr_family),
-              _resolver_state_to_string(resolver->state),
-              resolver->address ? (old_str = g_inet_address_to_string(resolver->address))
-                                : "(null)",
-              new_address ? (new_str = g_inet_address_to_string(new_address)) : "(null)");
+        if (address_changed) {
+            _LOGT(LOGD_DNS,
+                  "hostname-from-dns: ipv%c resolver %s, address changed from %s to %s",
+                  nm_utils_addr_family_to_char(resolver->addr_family),
+                  _resolver_state_to_string(resolver->state),
+                  resolver->address ? (old_str = g_inet_address_to_string(resolver->address))
+                                    : "(null)",
+                  new_address ? (new_str = g_inet_address_to_string(new_address)) : "(null)");
+        }
     }
 
-    /* In every state, if the address changed, we restart
-     * the resolution with the new address */
     if (address_changed) {
         nm_clear_g_cancellable(&resolver->cancellable);
         g_clear_object(&resolver->address);
-        resolver->state = RESOLVER_WAIT_ADDRESS;
     }
 
     if (address_changed && new_address) {
-        resolver->state       = RESOLVER_IN_PROGRESS;
         resolver->cancellable = g_cancellable_new();
         resolver->address     = g_steal_pointer(&new_address);
 
@@ -17369,7 +17381,7 @@ nm_device_get_hostname_from_dns_lookup(NMDevice *self, int addr_family, gboolean
             resolver->timeout_id = g_timeout_add(30000, hostname_dns_address_timeout, resolver);
         NM_SET_OUT(out_wait, TRUE);
         return NULL;
-    case RESOLVER_IN_PROGRESS:
+    case RESOLVER_STARTED:
         NM_SET_OUT(out_wait, TRUE);
         return NULL;
     case RESOLVER_DONE:
diff --git a/src/core/devices/nm-device.h b/src/core/devices/nm-device.h
index f54457d12e..bcf4d7b991 100644
--- a/src/core/devices/nm-device.h
+++ b/src/core/devices/nm-device.h
@@ -817,7 +817,7 @@ gboolean nm_device_is_vpn(NMDevice *self);
 const char *
 nm_device_get_hostname_from_dns_lookup(NMDevice *self, int addr_family, gboolean *out_pending);
 
-void nm_device_clear_dns_lookup_data(NMDevice *self);
+void nm_device_clear_dns_lookup_data(NMDevice *self, const char *reason);
 
 gboolean nm_device_get_allow_autoconnect_on_external(NMDevice *self);
 
diff --git a/src/core/nm-policy.c b/src/core/nm-policy.c
index 4192808a7b..d7e05b7b5b 100644
--- a/src/core/nm-policy.c
+++ b/src/core/nm-policy.c
@@ -2581,7 +2581,7 @@ dns_config_changed(NMDnsManager *dns_manager, gpointer user_data)
         return;
 
     nm_manager_for_each_device (priv->manager, device, tmp_lst) {
-        nm_device_clear_dns_lookup_data(device);
+        nm_device_clear_dns_lookup_data(device, "DNS configuration changed");
     }
 
     update_system_hostname(self, "DNS configuration changed");