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.
2025-12-26 01:50:08 +01:00 · 2023-04-27 17:00:10 +02:00 · 2023-04-27 17:00:10 +02:00 · 87b46e1663
commit 87b46e1663
parent fc624b8de8
3 changed files with 110 additions and 62 deletions
--- 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);
--- 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)));
--- 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;
 }