core: improve handling for blocking autoconnect

Cleanup logging to always print a "block-autoconnect:" prefix to related
lines. Also, make sure that everywhere where the state changes, a line
gets logged. Also, for devconf data print both the interface and the
profile.

3 files changed, 110 insertions, 62 deletions

diff --git a/src/core/nm-manager.c b/src/core/nm-manager.c
index 8773ce47fe..46adfd356b 100644
--- a/src/core/nm-manager.c
+++ b/src/core/nm-manager.c
@@ -89,6 +89,16 @@ typedef struct {
 
 } DevConData;
 
+#define DEV_CON_DATA_LOG_FMT \
+    "device[" NM_HASH_OBFUSCATE_PTR_FMT ",%s]-profile[" NM_HASH_OBFUSCATE_PTR_FMT ",%s]"
+
+/* This is an unsafe macro (it evaluates the macro arguments multiple times and is non-function-like). */
+#define DEV_CON_DATA_LOG_ARGS(device, sett_conn)                                                  \
+    NM_HASH_OBFUSCATE_PTR(device), nm_device_get_iface(device), NM_HASH_OBFUSCATE_PTR(sett_conn), \
+        nm_settings_connection_get_id(sett_conn)
+
+#define DEV_CON_DATA_LOG_ARGS_DATA(data) DEV_CON_DATA_LOG_ARGS((data)->device, (data)->sett_conn)
+
 typedef enum {
     ASYNC_OP_TYPE_AC_AUTH_ACTIVATE_INTERNAL,
     ASYNC_OP_TYPE_AC_AUTH_ACTIVATE_USER,
@@ -440,7 +450,8 @@ static void _rfkill_update(NMManager *self, NMRfkillType rtype);
 static DevConData *_devcon_lookup_data(NMManager            *self,
                                        NMDevice             *device,
                                        NMSettingsConnection *sett_conn,
-                                       gboolean              create);
+                                       gboolean              create,
+                                       gboolean              log_creation);
 
 /*****************************************************************************/
 
@@ -1262,38 +1273,45 @@ _autoconnect_retries_initial(NMSettingsConnection *sett_conn)
 static void
 _autoconnect_retries_set(NMManager *self, DevConData *data, guint32 retries, gboolean is_reset)
 {
+    gboolean changed = FALSE;
+    gint32   blocked_until_sec;
+
     nm_assert(data);
 
-    if (data->autoconnect.retries != retries || !data->autoconnect.initialized) {
-        _LOGT(LOGD_SETTINGS,
-              "autoconnect: device[%p] (%s): retries set %d%s",
-              data->device,
-              nm_device_get_ip_iface(data->device),
-              retries,
-              is_reset ? " (reset)" : "");
+    if (!data->autoconnect.initialized || data->autoconnect.retries != retries) {
         data->autoconnect.initialized = TRUE;
         data->autoconnect.retries     = retries;
+        changed                       = TRUE;
     }
 
     if (retries != 0) {
-        _LOGT(LOGD_SETTINGS,
-              "autoconnect: device[%p] (%s): no longer block autoconnect (due to retry count) %s",
-              data->device,
-              nm_device_get_ip_iface(data->device),
-              is_reset ? " (reset)" : "");
-        data->autoconnect.blocked_until_sec = 0;
+        blocked_until_sec = 0;
     } else {
         /* NOTE: the blocked time must be identical for all connections, otherwise
          * the tracking of resetting the retry count in NMPolicy needs adjustment
          * in _connection_autoconnect_retries_set() (as it would need to re-evaluate
          * the next-timeout every time a connection gets blocked). */
-        data->autoconnect.blocked_until_sec =
+        blocked_until_sec =
             nm_utils_get_monotonic_timestamp_sec() + AUTOCONNECT_RESET_RETRIES_TIMER_SEC;
+    }
+
+    if (data->autoconnect.blocked_until_sec != blocked_until_sec) {
+        data->autoconnect.blocked_until_sec = blocked_until_sec;
+        changed                             = TRUE;
+    }
+
+    if (changed) {
+        char sbuf[200];
+
         _LOGT(LOGD_SETTINGS,
-              "autoconnect: device[%p] (%s): block autoconnect due to retry count for %d seconds",
-              data->device,
-              nm_device_get_ip_iface(data->device),
-              AUTOCONNECT_RESET_RETRIES_TIMER_SEC);
+              "block-autoconnect: " DEV_CON_DATA_LOG_FMT ": retries set %u%s%s",
+              DEV_CON_DATA_LOG_ARGS_DATA(data),
+              retries,
+              is_reset ? " (is-reset)" : "",
+              blocked_until_sec == 0 ? ""
+                                     : nm_sprintf_buf(sbuf,
+                                                      " (blocked for %d sec)",
+                                                      AUTOCONNECT_RESET_RETRIES_TIMER_SEC));
     }
 }
 
@@ -1320,11 +1338,10 @@ nm_manager_devcon_autoconnect_retries_get(NMManager            *self,
     nm_assert(self == nm_device_get_manager(device));
     nm_assert(self == nm_settings_connection_get_manager(sett_conn));
 
-    data = _devcon_lookup_data(self, device, sett_conn, TRUE);
+    data = _devcon_lookup_data(self, device, sett_conn, TRUE, FALSE);
 
-    if (G_UNLIKELY(!data->autoconnect.initialized)) {
+    if (G_UNLIKELY(!data->autoconnect.initialized))
         _autoconnect_retries_set(self, data, _autoconnect_retries_initial(sett_conn), FALSE);
-    }
 
     return data->autoconnect.retries;
 }
@@ -1336,7 +1353,7 @@ nm_manager_devcon_autoconnect_retries_set(NMManager            *self,
                                           guint32               retries)
 {
     _autoconnect_retries_set(self,
-                             _devcon_lookup_data(self, device, sett_conn, TRUE),
+                             _devcon_lookup_data(self, device, sett_conn, TRUE, FALSE),
                              retries,
                              FALSE);
 }
@@ -1347,18 +1364,22 @@ nm_manager_devcon_autoconnect_retries_reset(NMManager            *self,
                                             NMSettingsConnection *sett_conn)
 {
     DevConData *data;
+    guint32     retries_initial;
 
     nm_assert(NM_IS_SETTINGS_CONNECTION(sett_conn));
 
-    if (device)
+    retries_initial = _autoconnect_retries_initial(sett_conn);
+
+    if (device) {
         _autoconnect_retries_set(self,
-                                 _devcon_lookup_data(self, device, sett_conn, TRUE),
-                                 _autoconnect_retries_initial(sett_conn),
+                                 _devcon_lookup_data(self, device, sett_conn, TRUE, FALSE),
+                                 retries_initial,
                                  TRUE);
-    else {
-        c_list_for_each_entry (data, &sett_conn->devcon_con_lst_head, con_lst)
-            _autoconnect_retries_set(self, data, _autoconnect_retries_initial(sett_conn), TRUE);
+        return;
     }
+
+    c_list_for_each_entry (data, &sett_conn->devcon_con_lst_head, con_lst)
+        _autoconnect_retries_set(self, data, retries_initial, TRUE);
 }
 
 /**
@@ -1398,7 +1419,8 @@ nm_manager_devcon_autoconnect_reset_reconnect_all(NMManager            *self,
         return changed;
     }
 
-    /* we reset the tries-count and any blocked-reason */
+    /* we reset the tries-count and any blocked-reason... */
+
     nm_manager_devcon_autoconnect_retries_reset(self, NULL, sett_conn);
 
     if (device) {
@@ -1434,18 +1456,19 @@ nm_manager_devcon_autoconnect_retries_blocked_until(NMManager            *self,
     nm_assert(NM_IS_SETTINGS_CONNECTION(sett_conn));
 
     if (device) {
-        data = _devcon_lookup_data(self, device, sett_conn, TRUE);
+        data = _devcon_lookup_data(self, device, sett_conn, TRUE, TRUE);
         return data->autoconnect.blocked_until_sec;
-    } else {
-        min_stamp = 0;
-        c_list_for_each_entry (data, &sett_conn->devcon_con_lst_head, con_lst) {
-            gint32 condev_stamp = data->autoconnect.blocked_until_sec;
-            if (condev_stamp == 0)
-                continue;
+    }
 
-            if (min_stamp == 0 || min_stamp > condev_stamp)
-                min_stamp = condev_stamp;
-        }
+    min_stamp = 0;
+    c_list_for_each_entry (data, &sett_conn->devcon_con_lst_head, con_lst) {
+        gint32 condev_stamp = data->autoconnect.blocked_until_sec;
+
+        if (condev_stamp == 0)
+            continue;
+
+        if (min_stamp == 0 || min_stamp > condev_stamp)
+            min_stamp = condev_stamp;
     }
 
     return min_stamp;
@@ -1464,11 +1487,12 @@ nm_manager_devcon_autoconnect_is_blocked(NMManager            *self,
     if (nm_settings_connection_autoconnect_is_blocked(sett_conn))
         return TRUE;
 
-    data = _devcon_lookup_data(self, device, sett_conn, TRUE);
+    data = _devcon_lookup_data(self, device, sett_conn, TRUE, TRUE);
+
     if (data->autoconnect.blocked_reason != NM_SETTINGS_AUTOCONNECT_BLOCKED_REASON_NONE)
         return TRUE;
 
-    if (data->autoconnect.retries == 0 && data->autoconnect.initialized)
+    if (data->autoconnect.initialized && data->autoconnect.retries == 0)
         return TRUE;
 
     return FALSE;
@@ -1491,18 +1515,18 @@ nm_manager_devcon_autoconnect_blocked_reason_set(NMManager
     nm_assert(!NM_FLAGS_ANY(value, ~(NM_SETTINGS_AUTOCONNECT_BLOCKED_REASON_FAILED)));
 
     if (device) {
-        data = _devcon_lookup_data(self, device, sett_conn, TRUE);
+        data = _devcon_lookup_data(self, device, sett_conn, TRUE, TRUE);
         v    = data->autoconnect.blocked_reason;
         v    = NM_FLAGS_ASSIGN(v, value, set);
 
         if (data->autoconnect.blocked_reason == v)
             return FALSE;
 
-        _LOGT(LOGD_SETTINGS,
-              "autoconnect: blocked reason: %s for device %s",
-              nm_settings_autoconnect_blocked_reason_to_string(v, buf, sizeof(buf)),
-              nm_device_get_ip_iface(device));
         data->autoconnect.blocked_reason = v;
+        _LOGT(LOGD_SETTINGS,
+              "block-autoconnect: " DEV_CON_DATA_LOG_FMT ": set blocked reason %s",
+              DEV_CON_DATA_LOG_ARGS_DATA(data),
+              nm_settings_autoconnect_blocked_reason_to_string(v, buf, sizeof(buf)));
         return TRUE;
     }
 
@@ -1512,10 +1536,11 @@ nm_manager_devcon_autoconnect_blocked_reason_set(NMManager
 
         if (data->autoconnect.blocked_reason == v)
             continue;
+
         _LOGT(LOGD_SETTINGS,
-              "autoconnect: blocked reason: %s for device %s",
-              nm_settings_autoconnect_blocked_reason_to_string(v, buf, sizeof(buf)),
-              nm_device_get_ip_iface(data->device));
+              "block-autoconnect: " DEV_CON_DATA_LOG_FMT ": set blocked reason %s",
+              DEV_CON_DATA_LOG_ARGS_DATA(data),
+              nm_settings_autoconnect_blocked_reason_to_string(v, buf, sizeof(buf)));
         data->autoconnect.blocked_reason = v;
         changed                          = TRUE;
     }
@@ -1554,7 +1579,8 @@ static DevConData *
 _devcon_lookup_data(NMManager            *self,
                     NMDevice             *device,
                     NMSettingsConnection *sett_conn,
-                    gboolean              create)
+                    gboolean              create,
+                    gboolean              log_creation)
 {
     NMManagerPrivate *priv = NM_MANAGER_GET_PRIVATE(self);
     DevConData       *data;
@@ -1581,7 +1607,10 @@ _devcon_lookup_data(NMManager            *self,
         .sett_conn = sett_conn,
         .autoconnect =
             {
-                .initialized = FALSE,
+                .initialized       = FALSE,
+                .retries           = 0,
+                .blocked_until_sec = 0,
+                .blocked_reason    = NM_SETTINGS_AUTOCONNECT_BLOCKED_REASON_NONE,
             },
     };
     c_list_link_tail(&device->devcon_dev_lst_head, &data->dev_lst);
@@ -1589,6 +1618,12 @@ _devcon_lookup_data(NMManager            *self,
 
     g_hash_table_add(priv->devcon_data_dict, data);
 
+    if (log_creation) {
+        _LOGT(LOGD_SETTINGS,
+              "block-autoconnect: " DEV_CON_DATA_LOG_FMT ": entry created (not initialized)",
+              DEV_CON_DATA_LOG_ARGS_DATA(data));
+    }
+
     return data;
 }
 
@@ -1600,7 +1635,7 @@ _devcon_remove_data(NMManager *self, DevConData *data)
     nm_assert(data);
     nm_assert(NM_IS_DEVICE(data->device));
     nm_assert(NM_IS_SETTINGS_CONNECTION(data->sett_conn));
-    nm_assert(data == _devcon_lookup_data(self, data->device, data->sett_conn, FALSE));
+    nm_assert(data == _devcon_lookup_data(self, data->device, data->sett_conn, FALSE, FALSE));
 
     c_list_unlink_stale(&data->dev_lst);
     c_list_unlink_stale(&data->con_lst);
diff --git a/src/core/nm-policy.c b/src/core/nm-policy.c
index 2e7f9c605b..ae2c15f22a 100644
--- a/src/core/nm-policy.c
+++ b/src/core/nm-policy.c
@@ -1998,7 +1998,8 @@ device_state_changed(NMDevice           *device,
                 con_v = nm_settings_connection_get_last_secret_agent_version_id(sett_conn);
                 if (con_v == 0 || con_v == nm_agent_manager_get_agent_version_id(priv->agent_mgr)) {
                     _LOGD(LOGD_DEVICE,
-                          "connection '%s' now blocked from autoconnect due to no secrets",
+                          "block-autoconnect: connection '%s' now blocked from autoconnect due to "
+                          "no secrets",
                           nm_settings_connection_get_id(sett_conn));
                     nm_settings_connection_autoconnect_blocked_reason_set(
                         sett_conn,
@@ -2017,7 +2018,8 @@ device_state_changed(NMDevice           *device,
                  * dependency-failed.
                  */
                 _LOGD(LOGD_DEVICE,
-                      "autoconnect: connection[%p] (%s) now blocked from autoconnect due to failed "
+                      "block-autoconnect: connection[%p] (%s) now blocked from autoconnect due to "
+                      "failed "
                       "dependency",
                       sett_conn,
                       nm_settings_connection_get_id(sett_conn));
@@ -2102,7 +2104,7 @@ device_state_changed(NMDevice           *device,
             }
             if (blocked_reason != NM_SETTINGS_AUTOCONNECT_BLOCKED_REASON_NONE) {
                 _LOGD(LOGD_DEVICE,
-                      "blocking autoconnect of connection '%s': %s",
+                      "block-autoconnect: blocking autoconnect of connection '%s': %s",
                       nm_settings_connection_get_id(sett_conn),
                       NM_UTILS_LOOKUP_STR_A(nm_device_state_reason_to_string,
                                             nm_device_state_reason_check(reason)));
diff --git a/src/core/settings/nm-settings-connection.c b/src/core/settings/nm-settings-connection.c
index 8b18812255..da0f272872 100644
--- a/src/core/settings/nm-settings-connection.c
+++ b/src/core/settings/nm-settings-connection.c
@@ -2523,8 +2523,8 @@ nm_settings_connection_autoconnect_blocked_reason_set(NMSettingsConnection
 {
     NMSettingsAutoconnectBlockedReason v;
     NMSettingsConnectionPrivate       *priv = NM_SETTINGS_CONNECTION_GET_PRIVATE(self);
-    char                               buf1[100];
-    char                               buf2[100];
+    char                               buf1[200];
+    char                               buf2[200];
 
     nm_assert(reason != NM_SETTINGS_AUTOCONNECT_BLOCKED_REASON_NONE);
     nm_assert(!NM_FLAGS_ANY(reason,
@@ -2537,10 +2537,21 @@ nm_settings_connection_autoconnect_blocked_reason_set(NMSettingsConnection
     if (priv->autoconnect_blocked_reason == v)
         return FALSE;
 
-    _LOGD("autoconnect: %s blocked reason: %s (now %s)",
-          set ? "set" : "unset",
-          nm_settings_autoconnect_blocked_reason_to_string(reason, buf1, sizeof(buf1)),
-          nm_settings_autoconnect_blocked_reason_to_string(v, buf2, sizeof(buf2)));
+    if (set) {
+        _LOGT("block-autoconnect: profile: blocked with reason %s (%s %s)",
+              nm_settings_autoconnect_blocked_reason_to_string(v, buf1, sizeof(buf1)),
+              "just blocked",
+              nm_settings_autoconnect_blocked_reason_to_string(reason, buf2, sizeof(buf2)));
+    } else if (v != NM_SETTINGS_AUTOCONNECT_BLOCKED_REASON_NONE) {
+        _LOGT("block-autoconnect: profile: blocked with reason %s (%s %s)",
+              nm_settings_autoconnect_blocked_reason_to_string(v, buf1, sizeof(buf1)),
+              "just unblocked",
+              nm_settings_autoconnect_blocked_reason_to_string(reason, buf2, sizeof(buf2)));
+    } else {
+        _LOGT("block-autoconnect: profile: not blocked (unblocked %s)",
+              nm_settings_autoconnect_blocked_reason_to_string(reason, buf1, sizeof(buf1)));
+    }
+
     priv->autoconnect_blocked_reason = v;
     return TRUE;
 }