TEST: add debug logging (TODO)th/queue_act_request_no_carrier_rh1079353

reproducer:
 - start NM with cable unplugged.
 - NM will be waiting indefinitely for carrier
 - `nmcli connection up C` hangs
 - in another terminal: `nmcli connection up C`, see
   that now both hang.
 - in another termina: `nmcli connection up C`, see
   that the first invokation returns.

It seems that libnm's 'active-connection-removed' signal
is broken. And what is with 'active-connection-added'? Is it
wired up correctly?

6 files changed, 26 insertions, 1 deletions

diff --git a/clients/cli/connections.c b/clients/cli/connections.c
index 75ad308518..10b031aea5 100644
--- a/clients/cli/connections.c
+++ b/clients/cli/connections.c
@@ -2043,7 +2043,9 @@ activate_connection_cb (GObject *client, GAsyncResult *result, gpointer user_dat
 	const GPtrArray *ac_devs;
 	GError *error = NULL;
 
+	g_print (">>> nm_client_activate_connection_finish() xxx\n");
 	active = nm_client_activate_connection_finish (NM_CLIENT (client), result, &error);
+	g_print (">>> nm_client_activate_connection_finish() returned: %p, %s\n", active, error ? error->message : "-");
 
 	if (error) {
 		g_string_printf (nmc->return_text, _("Error: Connection activation failed: %s"),
@@ -2081,6 +2083,7 @@ activate_connection_cb (GObject *client, GAsyncResult *result, gpointer user_dat
 					progress_id = g_timeout_add (120, progress_vpn_cb, NM_VPN_CONNECTION (active));
 				}
 			} else {
+				g_print (">> wait for notify:state\n");
 				g_signal_connect (active, "notify::state", G_CALLBACK (active_connection_state_cb), nmc);
 				active_connection_state_cb (active, NULL, nmc);
 
@@ -2253,6 +2256,7 @@ nmc_activate_connection (NmCli *nmc,
 	info->nmc = nmc;
 	info->device = device;
 
+	g_print (">>> nm_client_activate_connection_finish() callxxxxx\n");
 	nm_client_activate_connection_async (nmc->client,
 	                                     connection,
 	                                     device,
@@ -2368,6 +2372,7 @@ do_connection_up (NmCli *nmc, int argc, char **argv)
 	nmc->nowait_flag = (nmc->timeout == 0);
 	nmc->should_wait = TRUE;
 
+	g_print (">>> nm_client_activate_connection_finish() call\n");
 	if (!nmc_activate_connection (nmc, connection, ifname, ap, nsp, pwds, activate_connection_cb, &error)) {
 		g_string_printf (nmc->return_text, _("Error: %s."),
 		                 error ? error->message : _("unknown error"));
diff --git a/libnm/nm-client.c b/libnm/nm-client.c
index ef73e329b2..5d0a04ea30 100644
--- a/libnm/nm-client.c
+++ b/libnm/nm-client.c
@@ -831,6 +831,8 @@ activate_cb (GObject *object,
 	NMActiveConnection *ac;
 	GError *error = NULL;
 
+	g_print (">>> call nm_manager_activate_connection_async() returned\n");
+
 	ac = nm_manager_activate_connection_finish (NM_MANAGER (object), result, &error);
 	if (ac)
 		g_simple_async_result_set_op_res_gpointer (simple, ac, g_object_unref);
@@ -899,6 +901,7 @@ nm_client_activate_connection_async (NMClient *client,
 
 	simple = g_simple_async_result_new (G_OBJECT (client), callback, user_data,
 	                                    nm_client_activate_connection_async);
+	g_print (">>> call nm_manager_activate_connection_async()\n");
 	nm_manager_activate_connection_async (NM_CLIENT_GET_PRIVATE (client)->manager,
 	                                      connection, device, specific_object,
 	                                      cancellable, activate_cb, simple);
diff --git a/libnm/nm-manager.c b/libnm/nm-manager.c
index 1abb513021..8a64458e89 100644
--- a/libnm/nm-manager.c
+++ b/libnm/nm-manager.c
@@ -850,6 +850,7 @@ active_removed (NMObject *object, NMActiveConnection *active, gpointer user_data
 	ActivateInfo *info = user_data;
 	GError *error = NULL;
 
+	g_print (">>> RETURN %p - %s\n", info, nm_object_get_path (NM_OBJECT (active)));
 	if (strcmp (info->active_path, nm_object_get_path (NM_OBJECT (active))))
 		return;
 
@@ -868,6 +869,7 @@ activate_cb (GObject *object,
 	ActivateInfo *info = user_data;
 	GError *error = NULL;
 
+	g_print (">>> call nmdbus_manager_call_activate_connection() return\n");
 	if (nmdbus_manager_call_activate_connection_finish (NMDBUS_MANAGER (object),
 	                                                    &info->active_path,
 	                                                    result, &error)) {
@@ -876,6 +878,7 @@ activate_cb (GObject *object,
 			                                       G_CALLBACK (activation_cancelled), info);
 		}
 
+		g_print (">>> WAIT %p, %s\n", info, info->active_path);
 		g_signal_connect (info->manager, "active-connection-removed",
 		                  G_CALLBACK (active_removed), info);
 
@@ -914,6 +917,7 @@ nm_manager_activate_connection_async (NMManager *manager,
 	priv = NM_MANAGER_GET_PRIVATE (manager);
 	priv->pending_activations = g_slist_prepend (priv->pending_activations, info);
 
+	g_print (">>> call nmdbus_manager_call_activate_connection()\n");
 	nmdbus_manager_call_activate_connection (priv->manager_proxy,
 	                                         connection ? nm_connection_get_path (connection) : "/",
 	                                         device ? nm_object_get_path (NM_OBJECT (device)) : "/",
@@ -1027,6 +1031,7 @@ device_ac_changed (GObject *object, GParamSpec *pspec, gpointer user_data)
 {
 	NMManager *self = user_data;
 
+	g_print (">>> call %s()\n", __PRETTY_FUNCTION__);
 	recheck_pending_activations (self);
 }
 
@@ -1048,12 +1053,14 @@ ac_devices_changed (GObject *object, GParamSpec *pspec, gpointer user_data)
 {
 	NMManager *self = user_data;
 
+	g_print (">>> call %s()\n", __PRETTY_FUNCTION__);
 	recheck_pending_activations (self);
 }
 
 static void
 active_connection_added (NMManager *self, NMActiveConnection *ac)
 {
+	g_print (">>> call %s()\n", __PRETTY_FUNCTION__);
 	g_signal_connect (ac, "notify::" NM_ACTIVE_CONNECTION_DEVICES,
 	                  G_CALLBACK (ac_devices_changed), self);
 	recheck_pending_activations (self);
diff --git a/src/devices/nm-device.c b/src/devices/nm-device.c
index 5b3e3c4eed..25c3b1045c 100644
--- a/src/devices/nm-device.c
+++ b/src/devices/nm-device.c
@@ -5822,6 +5822,8 @@ nm_device_queue_activation (NMDevice *self, NMActRequest *req)
 		return;
 	}
 
+	nm_log_dbg (LOGD_CORE, ">>> queue reuest: is %p (%d), new: %p (%d)", priv->queued_act_request, priv->queued_act_request ? (int) nm_active_connection_get_state ((NMActiveConnection *) priv->queued_act_request) : -1, req, nm_active_connection_get_state ((NMActiveConnection *)req));
+
 	/* supercede any already-queued request */
 	_clear_queued_act_request (priv);
 	priv->queued_act_request = g_object_ref (req);
@@ -6448,7 +6450,7 @@ nm_device_bring_up (NMDevice *self, gboolean block, gboolean *no_firmware)
 			g_source_remove (priv->carrier_wait_id);
 		else
 			nm_device_add_pending_action (self, "carrier wait", TRUE);
-		priv->carrier_wait_id = g_timeout_add_seconds (5, carrier_wait_timeout, self);
+		priv->carrier_wait_id = g_timeout_add_seconds (300000, carrier_wait_timeout, self);
 	}
 
 	/* Can only get HW address of some devices when they are up */
diff --git a/src/nm-active-connection.c b/src/nm-active-connection.c
index d0b5b8753f..f82d11dabb 100644
--- a/src/nm-active-connection.c
+++ b/src/nm-active-connection.c
@@ -853,6 +853,8 @@ dispose (GObject *object)
 	NMActiveConnection *self = NM_ACTIVE_CONNECTION (object);
 	NMActiveConnectionPrivate *priv = NM_ACTIVE_CONNECTION_GET_PRIVATE (self);
 
+	nm_log_dbg (LOGD_CORE, ">>> DISPOSE NMActiveConnection %p, %s", object, priv->path);
+
 	if (priv->chain) {
 		nm_auth_chain_unref (priv->chain);
 		priv->chain = NULL;
diff --git a/src/nm-manager.c b/src/nm-manager.c
index a42f89e5d3..85b1f4dc70 100644
--- a/src/nm-manager.c
+++ b/src/nm-manager.c
@@ -267,12 +267,15 @@ active_connection_remove (NMManager *self, NMActiveConnection *active)
 	gboolean notify = !!nm_active_connection_get_path (active);
 	GSList *found;
 
+	nm_log_dbg (LOGD_CORE, ">>> active_connection_remove(): %p, %s", active, nm_active_connection_get_path (active));
+
 	/* FIXME: switch to a GList for faster removal */
 	found = g_slist_find (priv->active_connections, active);
 	if (found) {
 		NMConnection *connection;
 
 		priv->active_connections = g_slist_remove (priv->active_connections, active);
+		nm_log_dbg (LOGD_CORE, ">>> active_connection_remove(): %p raise", active);
 		g_signal_emit (self, signals[ACTIVE_CONNECTION_REMOVED], 0, active);
 		g_signal_handlers_disconnect_by_func (active, active_connection_state_changed, self);
 		g_signal_handlers_disconnect_by_func (active, active_connection_default_changed, self);
@@ -3154,11 +3157,14 @@ _activation_auth_done (NMActiveConnection *active,
 	GError *error = NULL;
 
 	if (success) {
+		nm_log_dbg (LOGD_CORE, ">>> start activating");
 		if (_internal_activate_generic (self, active, &error)) {
+			nm_log_dbg (LOGD_CORE, ">>> activating success %s", nm_active_connection_get_path (active));
 			dbus_g_method_return (context, nm_active_connection_get_path (active));
 			g_object_unref (active);
 			return;
 		}
+		nm_log_dbg (LOGD_CORE, ">>> activating failure: %s", error->message);
 	} else {
 		error = g_error_new_literal (NM_MANAGER_ERROR,
 			                         NM_MANAGER_ERROR_PERMISSION_DENIED,