core: add better logging for autoconnect with a new log domainbg/log-autoconnect-1-20

Sometimes users report problems about profiles not autoconnecting and
with the current logging it's difficult to understand where the
problem is. Since all profiles must be evaluated when a device becomes
available for autoconnection, adding by default a log message for each
of them would be probably too verbose, even for TRACE level.

Add a new 'autoconnect' log domain that is disabled by default and is
useful to debug autoconnect problems, and use it to log why profiles
can't autoconnect.

(cherry picked from commit 2794093d18175f78439009c1b0b0b750e711b1b2)

10 files changed, 99 insertions, 31 deletions

diff --git a/clients/cli/general.c b/clients/cli/general.c
index e2ce639ece..2884da61e6 100644
--- a/clients/cli/general.c
+++ b/clients/cli/general.c
@@ -711,7 +711,7 @@ do_general_logging (NmCli *nmc, int argc, char **argv)
 					                             "AGENTS", "SETTINGS", "SUSPEND", "CORE", "DEVICE", "OLPC",
 					                             "INFINIBAND", "FIREWALL", "ADSL", "BOND", "VLAN", "BRIDGE",
 					                             "DBUS_PROPS", "TEAM", "CONCHECK", "DCB", "DISPATCH", "AUDIT",
-					                             "SYSTEMD", "VPN_PLUGIN", "PROXY", "TC", NULL);
+					                             "SYSTEMD", "VPN_PLUGIN", "PROXY", "TC", "AUTOCONNECT", NULL);
 				}
 				domains = *argv;
 			} else {
diff --git a/man/NetworkManager.conf.xml b/man/NetworkManager.conf.xml
index e56de21022..c9fbe6f1e1 100644
--- a/man/NetworkManager.conf.xml
+++ b/man/NetworkManager.conf.xml
@@ -543,7 +543,7 @@ unmanaged-devices=mac:00:22:68:1c:59:b1;mac:00:1E:65:30:D1:C4;interface-name:eth
           AGENTS, SETTINGS, SUSPEND, CORE, DEVICE, OLPC, WIMAX,
           INFINIBAND, FIREWALL, ADSL, BOND, VLAN, BRIDGE, DBUS_PROPS,
           TEAM, CONCHECK, DCB, DISPATCH, AUDIT, SYSTEMD, VPN_PLUGIN,
-          PROXY.</para>
+          PROXY, AUTOCONNECT.</para>
           <para>In addition, these special domains can be used: NONE,
           ALL, DEFAULT, DHCP, IP.</para>
           <para>You can specify per-domain log level overrides by
@@ -590,8 +590,9 @@ unmanaged-devices=mac:00:22:68:1c:59:b1;mac:00:1E:65:30:D1:C4;interface-name:eth
           <member>DISPATCH    : Dispatcher scripts</member>
           <member>AUDIT       : Audit records</member>
           <member>SYSTEMD     : Messages from internal libsystemd</member>
-          <member>VPN_PLUGIN  : logging messages from VPN plugins</member>
-          <member>PROXY       : logging messages for proxy handling</member>
+          <member>VPN_PLUGIN  : Messages from VPN plugins</member>
+          <member>PROXY       : Proxy handling</member>
+          <member>AUTOCONNECT : Autoconnect operations</member>
           <member> </member>
           <member>NONE        : when given by itself logging is disabled</member>
           <member>ALL         : all log domains</member>
diff --git a/shared/nm-glib-aux/nm-logging-fwd.h b/shared/nm-glib-aux/nm-logging-fwd.h
index c60a20b58b..51fbc99a9f 100644
--- a/shared/nm-glib-aux/nm-logging-fwd.h
+++ b/shared/nm-glib-aux/nm-logging-fwd.h
@@ -64,6 +64,7 @@ typedef enum  { /*< skip >*/
 	LOGD_SYSTEMD    = (1LL << 35),
 	LOGD_VPN_PLUGIN = (1LL << 36),
 	LOGD_PROXY      = (1LL << 37),
+	LOGD_AUTOCONNECT= (1LL << 38),
 
 	__LOGD_MAX,
 	LOGD_ALL       = (((__LOGD_MAX - 1LL) << 1) - 1LL),
@@ -71,6 +72,7 @@ typedef enum  { /*< skip >*/
 	                              LOGD_DBUS_PROPS |
 	                              LOGD_WIFI_SCAN |
 	                              LOGD_VPN_PLUGIN |
+	                              LOGD_AUTOCONNECT |
 	                              0),
 
 	/* aliases: */
diff --git a/src/devices/bluetooth/nm-device-bt.c b/src/devices/bluetooth/nm-device-bt.c
index 0853c926a7..eb37ce794c 100644
--- a/src/devices/bluetooth/nm-device-bt.c
+++ b/src/devices/bluetooth/nm-device-bt.c
@@ -140,20 +140,25 @@ get_generic_capabilities (NMDevice *device)
 static gboolean
 can_auto_connect (NMDevice *device,
                   NMSettingsConnection *sett_conn,
-                  char **specific_object)
+                  char **specific_object,
+                  GError **error)
 {
 	NMDeviceBtPrivate *priv = NM_DEVICE_BT_GET_PRIVATE ((NMDeviceBt *) device);
 	guint32 bt_type;
 
 	nm_assert (!specific_object || !*specific_object);
 
-	if (!NM_DEVICE_CLASS (nm_device_bt_parent_class)->can_auto_connect (device, sett_conn, NULL))
+	if (!NM_DEVICE_CLASS (nm_device_bt_parent_class)->can_auto_connect (device, sett_conn, NULL, error))
 		return FALSE;
 
 	/* Can't auto-activate a DUN connection without ModemManager */
 	bt_type = get_connection_bt_type (nm_settings_connection_get_connection (sett_conn));
-	if (bt_type == NM_BT_CAPABILITY_DUN && priv->mm_running == FALSE)
+	if (bt_type == NM_BT_CAPABILITY_DUN && priv->mm_running == FALSE) {
+		nm_utils_error_set_literal (error,
+		                            NM_UTILS_ERROR_CONNECTION_AVAILABLE_TEMPORARY,
+		                            "bluetooth DUN connection requires ModemManager");
 		return FALSE;
+	}
 
 	return TRUE;
 }
diff --git a/src/devices/nm-device.c b/src/devices/nm-device.c
index d31bc87e74..b9dec3900c 100644
--- a/src/devices/nm-device.c
+++ b/src/devices/nm-device.c
@@ -5476,7 +5476,8 @@ nm_device_autoconnect_allowed (NMDevice *self)
 static gboolean
 can_auto_connect (NMDevice *self,
                   NMSettingsConnection *sett_conn,
-                  char **specific_object)
+                  char **specific_object,
+                  GError **error)
 {
 	nm_assert (!specific_object || !*specific_object);
 	return TRUE;
@@ -5489,6 +5490,7 @@ can_auto_connect (NMDevice *self,
  * @specific_object: (out) (transfer full): on output, the path of an
  *   object associated with the returned connection, to be passed to
  *   nm_manager_activate_connection(), or %NULL.
+ * @error: location to store error, or %NULL
  *
  * Checks if @sett_conn can be auto-activated on @self right now.
  * This requires, at a minimum, that the connection be compatible with
@@ -5502,11 +5504,13 @@ can_auto_connect (NMDevice *self,
 gboolean
 nm_device_can_auto_connect (NMDevice *self,
                             NMSettingsConnection *sett_conn,
-                            char **specific_object)
+                            char **specific_object,
+                            GError **error)
 {
 	g_return_val_if_fail (NM_IS_DEVICE (self), FALSE);
 	g_return_val_if_fail (NM_IS_SETTINGS_CONNECTION (sett_conn), FALSE);
 	g_return_val_if_fail (!specific_object || !*specific_object, FALSE);
+	g_return_val_if_fail (!error || !*error, FALSE);
 
 	/* the caller must ensure that nm_device_autoconnect_allowed() returns
 	 * TRUE as well. This is done, because nm_device_can_auto_connect()
@@ -5521,10 +5525,10 @@ nm_device_can_auto_connect (NMDevice *self,
 	                                           nm_settings_connection_get_connection (sett_conn),
 	                                           NM_DEVICE_CHECK_CON_AVAILABLE_NONE,
 	                                           NULL,
-	                                           NULL))
+	                                           error))
 		return FALSE;
 
-	if (!NM_DEVICE_GET_CLASS (self)->can_auto_connect (self, sett_conn, specific_object))
+	if (!NM_DEVICE_GET_CLASS (self)->can_auto_connect (self, sett_conn, specific_object, error))
 		return FALSE;
 
 	return TRUE;
diff --git a/src/devices/nm-device.h b/src/devices/nm-device.h
index ae6aab392a..db28861846 100644
--- a/src/devices/nm-device.h
+++ b/src/devices/nm-device.h
@@ -333,7 +333,8 @@ typedef struct _NMDeviceClass {
 
 	gboolean    (* can_auto_connect) (NMDevice *self,
 	                                  NMSettingsConnection *sett_conn,
-	                                  char **specific_object);
+	                                  char **specific_object,
+	                                  GError **error);
 
 	guint32     (*get_configured_mtu) (NMDevice *self, NMDeviceMtuSource *out_source);
 
@@ -584,7 +585,8 @@ gboolean nm_device_master_update_slave_connection (NMDevice *master,
 
 gboolean nm_device_can_auto_connect (NMDevice *self,
                                      NMSettingsConnection *sett_conn,
-                                     char **specific_object);
+                                     char **specific_object,
+                                     GError **error);
 
 gboolean nm_device_complete_connection (NMDevice *device,
                                         NMConnection *connection,
diff --git a/src/devices/wifi/nm-device-iwd.c b/src/devices/wifi/nm-device-iwd.c
index 6ef9ef947c..fdcdcb1b65 100644
--- a/src/devices/wifi/nm-device-iwd.c
+++ b/src/devices/wifi/nm-device-iwd.c
@@ -937,7 +937,8 @@ get_autoconnect_allowed (NMDevice *device)
 static gboolean
 can_auto_connect (NMDevice *device,
                   NMSettingsConnection *sett_conn,
-                  char **specific_object)
+                  char **specific_object,
+                  GError **error)
 {
 	NMDeviceIwd *self = NM_DEVICE_IWD (device);
 	NMDeviceIwdPrivate *priv = NM_DEVICE_IWD_GET_PRIVATE (self);
@@ -949,7 +950,7 @@ can_auto_connect (NMDevice *device,
 
 	nm_assert (!specific_object || !*specific_object);
 
-	if (!NM_DEVICE_CLASS (nm_device_iwd_parent_class)->can_auto_connect (device, sett_conn, NULL))
+	if (!NM_DEVICE_CLASS (nm_device_iwd_parent_class)->can_auto_connect (device, sett_conn, NULL, error))
 		return FALSE;
 
 	connection = nm_settings_connection_get_connection (sett_conn);
@@ -961,16 +962,24 @@ can_auto_connect (NMDevice *device,
 	 * Note the wpa_supplicant backend has the opposite policy.
 	 */
 	mode = nm_setting_wireless_get_mode (s_wifi);
-	if (mode && g_strcmp0 (mode, NM_SETTING_WIRELESS_MODE_INFRA) != 0)
+	if (mode && g_strcmp0 (mode, NM_SETTING_WIRELESS_MODE_INFRA) != 0) {
+		nm_utils_error_set_literal (error,
+		                            NM_UTILS_ERROR_CONNECTION_AVAILABLE_INCOMPATIBLE,
+		                            "only infrastructure mode connections can autoconnect");
 		return FALSE;
+	}
 
 	/* Don't autoconnect to networks that have been tried at least once
 	 * but haven't been successful, since these are often accidental choices
 	 * from the menu and the user may not know the password.
 	 */
 	if (nm_settings_connection_get_timestamp (sett_conn, &timestamp)) {
-		if (timestamp == 0)
+		if (timestamp == 0) {
+			nm_utils_error_set_literal (error,
+			                            NM_UTILS_ERROR_CONNECTION_AVAILABLE_TEMPORARY,
+			                            "connection never activated successfully");
 			return FALSE;
+		}
 	}
 
 	ap = nm_wifi_aps_find_first_compatible (&priv->aps_lst_head, connection);
@@ -980,6 +989,9 @@ can_auto_connect (NMDevice *device,
 		return TRUE;
 	}
 
+	nm_utils_error_set_literal (error,
+	                            NM_UTILS_ERROR_CONNECTION_AVAILABLE_TEMPORARY,
+	                            "no compatible AP found");
 	return FALSE;
 }
 
diff --git a/src/devices/wifi/nm-device-wifi.c b/src/devices/wifi/nm-device-wifi.c
index 8c80b0aa54..5e3e082370 100644
--- a/src/devices/wifi/nm-device-wifi.c
+++ b/src/devices/wifi/nm-device-wifi.c
@@ -1016,7 +1016,8 @@ get_autoconnect_allowed (NMDevice *device)
 static gboolean
 can_auto_connect (NMDevice *device,
                   NMSettingsConnection *sett_conn,
-                  char **specific_object)
+                  char **specific_object,
+                  GError **error)
 {
 	NMDeviceWifi *self = NM_DEVICE_WIFI (device);
 	NMDeviceWifiPrivate *priv = NM_DEVICE_WIFI_GET_PRIVATE (self);
@@ -1029,7 +1030,7 @@ can_auto_connect (NMDevice *device,
 
 	nm_assert (!specific_object || !*specific_object);
 
-	if (!NM_DEVICE_CLASS (nm_device_wifi_parent_class)->can_auto_connect (device, sett_conn, NULL))
+	if (!NM_DEVICE_CLASS (nm_device_wifi_parent_class)->can_auto_connect (device, sett_conn, NULL, error))
 		return FALSE;
 
 	connection = nm_settings_connection_get_connection (sett_conn);
@@ -1058,8 +1059,12 @@ can_auto_connect (NMDevice *device,
 	 * from the menu and the user may not know the password.
 	 */
 	if (nm_settings_connection_get_timestamp (sett_conn, &timestamp)) {
-		if (timestamp == 0)
+		if (timestamp == 0) {
+			nm_utils_error_set_literal (error,
+			                            NM_UTILS_ERROR_CONNECTION_AVAILABLE_TEMPORARY,
+			                            "connection never activated successfully");
 			return FALSE;
+		}
 	}
 
 	ap = nm_wifi_aps_find_first_compatible (&priv->aps_lst_head, connection);
@@ -1069,6 +1074,9 @@ can_auto_connect (NMDevice *device,
 		return TRUE;
 	}
 
+	nm_utils_error_set_literal (error,
+	                            NM_UTILS_ERROR_CONNECTION_AVAILABLE_TEMPORARY,
+	                            "no compatible AP found");
 	return FALSE;
 }
 
diff --git a/src/nm-logging.c b/src/nm-logging.c
index ea505a81a6..c71c5c088c 100644
--- a/src/nm-logging.c
+++ b/src/nm-logging.c
@@ -221,6 +221,7 @@ static const LogDesc domain_desc[] = {
 	{ LOGD_SYSTEMD,   "SYSTEMD" },
 	{ LOGD_VPN_PLUGIN,"VPN_PLUGIN" },
 	{ LOGD_PROXY,     "PROXY" },
+	{ LOGD_AUTOCONNECT, "AUTOCONNECT" },
 	{ 0 },
 };
 
@@ -548,7 +549,7 @@ _domains_to_string (gboolean include_level_override,
 	return g_string_free (str, FALSE);
 }
 
-static char _all_logging_domains_to_str[273];
+static char _all_logging_domains_to_str[285];
 
 const char *
 nm_logging_all_domains_to_string (void)
diff --git a/src/nm-policy.c b/src/nm-policy.c
index 559babed3a..301646cff4 100644
--- a/src/nm-policy.c
+++ b/src/nm-policy.c
@@ -1254,12 +1254,20 @@ auto_activate_device (NMPolicy *self,
 	if (nm_device_get_act_request (device))
 		return;
 
-	if (!nm_device_autoconnect_allowed (device))
+	if (!nm_device_autoconnect_allowed (device)) {
+		_LOGT (LOGD_AUTOCONNECT,
+		       "autoconnect (%s): not allowed",
+		       nm_device_get_iface (device));
 		return;
+	}
 
 	connections = nm_manager_get_activatable_connections (priv->manager, TRUE, TRUE, &len);
-	if (!connections[0])
+	if (!connections[0]) {
+		_LOGT (LOGD_AUTOCONNECT,
+		       "autoconnect (%s): no activatable connections",
+		       nm_device_get_iface (device));
 		return;
+	}
 
 	/* Find the first connection that should be auto-activated */
 	best_connection = NULL;
@@ -1269,30 +1277,54 @@ auto_activate_device (NMPolicy *self,
 		NMSettingConnection *s_con;
 		const char *permission;
 
-		if (nm_settings_connection_autoconnect_is_blocked (candidate))
+		if (nm_settings_connection_autoconnect_is_blocked (candidate)) {
+			_LOGT (LOGD_AUTOCONNECT,
+			       "autoconnect (%s): connection %s is blocked",
+			       nm_device_get_iface (device),
+			       nm_settings_connection_get_uuid (candidate));
 			continue;
+		}
 
 		cand_conn = nm_settings_connection_get_connection (candidate);
 
 		s_con = nm_connection_get_setting_connection (cand_conn);
-		if (!nm_setting_connection_get_autoconnect (s_con))
+		if (!nm_setting_connection_get_autoconnect (s_con)) {
+			_LOGT (LOGD_AUTOCONNECT,
+			       "autoconnect (%s): connection %s has autoconnect=no",
+			       nm_device_get_iface (device),
+			       nm_settings_connection_get_uuid (candidate));
 			continue;
+		}
 
 		permission = nm_utils_get_shared_wifi_permission (cand_conn);
 		if (   permission
-		    && !nm_settings_connection_check_permission (candidate, permission))
+		    && !nm_settings_connection_check_permission (candidate, permission)) {
+			_LOGT (LOGD_AUTOCONNECT,
+			       "autoconnect (%s): connection %s has no permission",
+			       nm_device_get_iface (device),
+			       nm_settings_connection_get_uuid (candidate));
 			continue;
+		}
 
-		if (nm_device_can_auto_connect (device, candidate, &specific_object)) {
-			best_connection = candidate;
-			break;
+		if (!nm_device_can_auto_connect (device, candidate, &specific_object, &error)) {
+			_LOGT (LOGD_AUTOCONNECT,
+			       "autoconnect (%s): connection %s can't autoconnect: %s",
+			       nm_device_get_iface (device),
+			       nm_settings_connection_get_uuid (candidate),
+			       error->message);
+			g_clear_error (&error);
+			continue;
 		}
+
+		best_connection = candidate;
+		break;
 	}
 
 	if (!best_connection)
 		return;
 
-	_LOGI (LOGD_DEVICE, "auto-activating connection '%s' (%s)",
+	_LOGI (LOGD_DEVICE | LOGD_AUTOCONNECT,
+	       "autoconnect: auto-activating connection '%s' (%s)",
 	       nm_settings_connection_get_id (best_connection),
 	       nm_settings_connection_get_uuid (best_connection));
 
@@ -1308,7 +1340,8 @@ auto_activate_device (NMPolicy *self,
 	                                     NM_ACTIVATION_STATE_FLAG_LIFETIME_BOUND_TO_PROFILE_VISIBILITY,
 	                                     &error);
 	if (!ac) {
-		_LOGI (LOGD_DEVICE, "connection '%s' auto-activation failed: %s",
+		_LOGI (LOGD_DEVICE | LOGD_AUTOCONNECT,
+		       "autoconnect: '%s' auto-activation failed: %s",
 		       nm_settings_connection_get_id (best_connection),
 		       error->message);
 		nm_settings_connection_autoconnect_blocked_reason_set (best_connection,