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

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.

10 files changed, 100 insertions, 32 deletions

diff --git a/clients/cli/general.c b/clients/cli/general.c
index e246d2828d..144c97dc22 100644
--- a/clients/cli/general.c
+++ b/clients/cli/general.c
@@ -793,7 +793,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 eecba8bead..3363989563 100644
--- a/shared/nm-glib-aux/nm-logging-fwd.h
+++ b/shared/nm-glib-aux/nm-logging-fwd.h
@@ -49,6 +49,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),
@@ -56,6 +57,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 497810c36f..a58a522570 100644
--- a/src/devices/bluetooth/nm-device-bt.c
+++ b/src/devices/bluetooth/nm-device-bt.c
@@ -166,7 +166,8 @@ get_generic_capabilities (NMDevice *device)
 static gboolean
 can_auto_connect (NMDevice *device,
                   NMSettingsConnection *sett_conn,
-                  char **specific_object)
+                  char **specific_object,
+                  GError **error)
 {
 	NMDeviceBt *self = NM_DEVICE_BT (device);
 	NMDeviceBtPrivate *priv = NM_DEVICE_BT_GET_PRIVATE (self);
@@ -174,19 +175,23 @@ can_auto_connect (NMDevice *device,
 
 	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;
 
 	if (!get_connection_bt_type_check (self,
 	                                   nm_settings_connection_get_connection (sett_conn),
 	                                   &bt_type,
-	                                   NULL))
+	                                   error))
 		return FALSE;
 
 	/* Can't auto-activate a DUN connection without ModemManager */
 	if (   bt_type == NM_BT_CAPABILITY_DUN
-	    && priv->mm_running == FALSE)
+	    && 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 bd6a84ee0e..8f41c73a7f 100644
--- a/src/devices/nm-device.c
+++ b/src/devices/nm-device.c
@@ -5502,7 +5502,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;
@@ -5515,6 +5516,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
@@ -5528,11 +5530,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()
@@ -5547,10 +5551,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 df8777b720..ce15ad95dc 100644
--- a/src/devices/nm-device.h
+++ b/src/devices/nm-device.h
@@ -319,7 +319,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);
 
@@ -558,7 +559,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 8e3aafda12..9a94cd613c 100644
--- a/src/devices/wifi/nm-device-iwd.c
+++ b/src/devices/wifi/nm-device-iwd.c
@@ -923,7 +923,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);
@@ -935,7 +936,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);
@@ -947,16 +948,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);
@@ -966,6 +975,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 04c90058a1..21d74cddc6 100644
--- a/src/devices/wifi/nm-device-wifi.c
+++ b/src/devices/wifi/nm-device-wifi.c
@@ -955,7 +955,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);
@@ -968,7 +969,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);
@@ -997,8 +998,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);
@@ -1008,6 +1013,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 add57e4726..636848f870 100644
--- a/src/nm-logging.c
+++ b/src/nm-logging.c
@@ -207,6 +207,7 @@ static const LogDesc domain_desc[] = {
 	{ LOGD_SYSTEMD,   "SYSTEMD" },
 	{ LOGD_VPN_PLUGIN,"VPN_PLUGIN" },
 	{ LOGD_PROXY,     "PROXY" },
+	{ LOGD_AUTOCONNECT, "AUTOCONNECT" },
 	{ 0 },
 };
 
@@ -534,7 +535,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 d322b2efea..a7fe6d0f6b 100644
--- a/src/nm-policy.c
+++ b/src/nm-policy.c
@@ -1240,12 +1240,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;
@@ -1255,30 +1263,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));
 
@@ -1294,7 +1326,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,