device/logging: refactor logging for activation-stageth/device-schedule-activation

Instead of hand-craft logging lines after each time we call activation_source_schedule(),
do it in activation_source_schedule(). This also gives us the exact same logging line
and provides more debugging-information (like the source-id that was scheduled).

1 files changed, 26 insertions, 72 deletions

diff --git a/src/devices/nm-device.c b/src/devices/nm-device.c
index a709380516..573a1d9d24 100644
--- a/src/devices/nm-device.c
+++ b/src/devices/nm-device.c
@@ -2833,8 +2833,7 @@ activation_source_clear (NMDevice *self, int family)
 static void
 activation_source_handle_cb (NMDevice *self, int family)
 {
-	ActivationHandleData *act_data;
-	ActivationHandleFunc func;
+	ActivationHandleData *act_data, a;
 
 	g_return_if_fail (NM_IS_DEVICE (self));
 
@@ -2843,13 +2842,16 @@ activation_source_handle_cb (NMDevice *self, int family)
 	g_return_if_fail (act_data->id);
 	g_return_if_fail (act_data->func);
 
-	func = act_data->func;
+	a = *act_data;
 
-	_LOGt (LOGD_DEVICE, "activation-stage: invoke %p/%d (id %u)", act_data->func, family, act_data->id);
 	act_data->func = NULL;
 	act_data->id = 0;
 
-	func (self);
+	_LOGD (LOGD_DEVICE, "activation-stage: invoke %p/%d (id %u)", a.func, family, a.id);
+
+	a.func (self);
+
+	_LOGD (LOGD_DEVICE, "activation-stage: complete %p/%d (id %u)", a.func, family, a.id);
 }
 
 static void
@@ -2870,9 +2872,9 @@ _activation_source_schedule (NMDevice *self, ActivationHandleFunc func, int fami
 		new_id = g_idle_add (source_func, self);
 
 	if (act_data->id)
-		_LOGE (LOGD_DEVICE, "activation stage already scheduled");
+		_LOGE (LOGD_DEVICE, "activation-stage: already scheduled (%s)", s_func);
 
-	_LOGt (LOGD_DEVICE, "activation-stage: schedule %s/%s (%p/%d) (id %u -> %u)",
+	_LOGD (LOGD_DEVICE, "activation-stage: schedule %s/%s (%p/%d) (id %u -> %u)",
 	       s_func, s_family, func, family, act_data->id, new_id);
 
 	if (new_id) {
@@ -2972,25 +2974,21 @@ nm_device_activate_stage1_device_prepare (NMDevice *self)
 	/* Notify the new ActiveConnection along with the state change */
 	g_object_notify (G_OBJECT (self), NM_DEVICE_ACTIVE_CONNECTION);
 
-	_LOGD (LOGD_DEVICE, "Activation: Stage 1 of 5 (Device Prepare) started...");
 	nm_device_state_changed (self, NM_DEVICE_STATE_PREPARE, NM_DEVICE_STATE_REASON_NONE);
 
 	/* Assumed connections were already set up outside NetworkManager */
 	if (!nm_active_connection_get_assumed (active)) {
 		ret = NM_DEVICE_GET_CLASS (self)->act_stage1_prepare (self, &reason);
 		if (ret == NM_ACT_STAGE_RETURN_POSTPONE) {
-			goto out;
+			return;
 		} else if (ret == NM_ACT_STAGE_RETURN_FAILURE) {
 			nm_device_state_changed (self, NM_DEVICE_STATE_FAILED, reason);
-			goto out;
+			return;
 		}
 		g_assert (ret == NM_ACT_STAGE_RETURN_SUCCESS);
 	}
 
 	nm_device_activate_schedule_stage2_device_config (self);
-
-out:
-	_LOGD (LOGD_DEVICE, "Activation: Stage 1 of 5 (Device Prepare) complete.");
 }
 
 
@@ -3011,8 +3009,6 @@ nm_device_activate_schedule_stage1_device_prepare (NMDevice *self)
 	g_return_if_fail (priv->act_request);
 
 	activation_source_schedule (self, nm_device_activate_stage1_device_prepare, AF_INET);
-
-	_LOGD (LOGD_DEVICE, "Activation: Stage 1 of 5 (Device Prepare) scheduled...");
 }
 
 static NMActStageReturn
@@ -3039,7 +3035,6 @@ nm_device_activate_stage2_device_config (NMDevice *self)
 	NMActiveConnection *active = NM_ACTIVE_CONNECTION (priv->act_request);
 	GSList *iter;
 
-	_LOGD (LOGD_DEVICE, "Activation: Stage 2 of 5 (Device Configure) starting...");
 	nm_device_state_changed (self, NM_DEVICE_STATE_CONFIG, NM_DEVICE_STATE_REASON_NONE);
 
 	/* Assumed connections were already set up outside NetworkManager */
@@ -3049,15 +3044,15 @@ nm_device_activate_stage2_device_config (NMDevice *self)
 				nm_device_state_changed (self, NM_DEVICE_STATE_FAILED, NM_DEVICE_STATE_REASON_FIRMWARE_MISSING);
 			else
 				nm_device_state_changed (self, NM_DEVICE_STATE_FAILED, NM_DEVICE_STATE_REASON_CONFIG_FAILED);
-			goto out;
+			return;
 		}
 
 		ret = NM_DEVICE_GET_CLASS (self)->act_stage2_config (self, &reason);
 		if (ret == NM_ACT_STAGE_RETURN_POSTPONE)
-			goto out;
+			return;
 		else if (ret == NM_ACT_STAGE_RETURN_FAILURE) {
 			nm_device_state_changed (self, NM_DEVICE_STATE_FAILED, reason);
-			goto out;
+			return;
 		}
 		g_assert (ret == NM_ACT_STAGE_RETURN_SUCCESS);
 	}
@@ -3074,12 +3069,7 @@ nm_device_activate_stage2_device_config (NMDevice *self)
 			nm_device_queue_recheck_assume (info->slave);
 	}
 
-	_LOGD (LOGD_DEVICE, "Activation: Stage 2 of 5 (Device Configure) successful.");
-
 	nm_device_activate_schedule_stage3_ip_config_start (self);
-
-out:
-	_LOGD (LOGD_DEVICE, "Activation: Stage 2 of 5 (Device Configure) complete.");
 }
 
 
@@ -3125,8 +3115,6 @@ nm_device_activate_schedule_stage2_device_config (NMDevice *self)
 	}
 
 	activation_source_schedule (self, nm_device_activate_stage2_device_config, AF_INET);
-
-	_LOGD (LOGD_DEVICE, "Activation: Stage 2 of 5 (Device Configure) scheduled...");
 }
 
 /*
@@ -5547,7 +5535,6 @@ nm_device_activate_stage3_ip_config_start (NMDevice *self)
 
 	priv->ip4_state = priv->ip6_state = IP_WAIT;
 
-	_LOGD (LOGD_DEVICE, "Activation: Stage 3 of 5 (IP Configure Start) started...");
 	nm_device_state_changed (self, NM_DEVICE_STATE_IP_CONFIG, NM_DEVICE_STATE_REASON_NONE);
 
 	/* Device should be up before we can do anything with it */
@@ -5571,21 +5558,18 @@ nm_device_activate_stage3_ip_config_start (NMDevice *self)
 			       nm_connection_get_id (nm_device_get_applied_connection (self)),
 			       master_device ? nm_device_get_iface (master_device) : "(unknown)");
 		}
-		goto out;
+		return;
 	}
 
 	/* IPv4 */
 	if (!nm_device_activate_stage3_ip4_start (self))
-		goto out;
+		return;
 
 	/* IPv6 */
 	if (!nm_device_activate_stage3_ip6_start (self))
-		goto out;
+		return;
 
 	nm_device_check_ip_failed (self, TRUE);
-
-out:
-	_LOGD (LOGD_DEVICE, "Activation: Stage 3 of 5 (IP Configure Start) complete.");
 }
 
 
@@ -5614,10 +5598,8 @@ fw_change_zone_cb (NMFirewallManager *firewall_manager,
 
 	if (priv->state == NM_DEVICE_STATE_IP_CHECK)
 		nm_device_start_ip_check (self);
-	else {
+	else
 		activation_source_schedule (self, nm_device_activate_stage3_ip_config_start, AF_INET);
-		_LOGD (LOGD_DEVICE, "Activation: Stage 3 of 5 (IP Configure Start) scheduled.");
-	}
 }
 
 /*
@@ -5650,7 +5632,6 @@ nm_device_activate_schedule_stage3_ip_config_start (NMDevice *self)
 	if (nm_device_uses_assumed_connection (self)) {
 		_LOGD (LOGD_DEVICE, "Activation: skip setting firewall zone '%s' for assumed device", zone ? zone : "default");
 		activation_source_schedule (self, nm_device_activate_stage3_ip_config_start, AF_INET);
-		_LOGD (LOGD_DEVICE, "Activation: Stage 3 of 5 (IP Configure Start) scheduled.");
 		return;
 	}
 
@@ -5687,23 +5668,18 @@ nm_device_activate_ip4_config_timeout (NMDevice *self)
 	NMActStageReturn ret = NM_ACT_STAGE_RETURN_FAILURE;
 	NMDeviceStateReason reason = NM_DEVICE_STATE_REASON_NONE;
 
-	_LOGD (LOGD_DEVICE | LOGD_IP4, "Activation: Stage 4 of 5 (IPv4 Configure Timeout) started...");
-
 	ret = NM_DEVICE_GET_CLASS (self)->act_stage4_ip4_config_timeout (self, &reason);
 	if (ret == NM_ACT_STAGE_RETURN_POSTPONE)
-		goto out;
+		return;
 	else if (ret == NM_ACT_STAGE_RETURN_FAILURE) {
 		nm_device_state_changed (self, NM_DEVICE_STATE_FAILED, reason);
-		goto out;
+		return;
 	}
-	g_assert (ret == NM_ACT_STAGE_RETURN_SUCCESS);	
+	g_assert (ret == NM_ACT_STAGE_RETURN_SUCCESS);
 
 	priv->ip4_state = IP_FAIL;
 
 	nm_device_check_ip_failed (self, FALSE);
-
-out:
-	_LOGD (LOGD_DEVICE | LOGD_IP4, "Activation: Stage 4 of 5 (IPv4 Configure Timeout) complete.");
 }
 
 
@@ -5724,8 +5700,6 @@ nm_device_activate_schedule_ip4_config_timeout (NMDevice *self)
 	g_return_if_fail (priv->act_request);
 
 	activation_source_schedule (self, nm_device_activate_ip4_config_timeout, AF_INET);
-
-	_LOGD (LOGD_DEVICE | LOGD_IP4, "Activation: Stage 4 of 5 (IPv4 Configure Timeout) scheduled...");
 }
 
 
@@ -5754,23 +5728,18 @@ nm_device_activate_ip6_config_timeout (NMDevice *self)
 	NMActStageReturn ret = NM_ACT_STAGE_RETURN_FAILURE;
 	NMDeviceStateReason reason = NM_DEVICE_STATE_REASON_NONE;
 
-	_LOGD (LOGD_DEVICE | LOGD_IP6, "Activation: Stage 4 of 5 (IPv6 Configure Timeout) started...");
-
 	ret = NM_DEVICE_GET_CLASS (self)->act_stage4_ip6_config_timeout (self, &reason);
 	if (ret == NM_ACT_STAGE_RETURN_POSTPONE)
-		goto out;
-	else if (ret == NM_ACT_STAGE_RETURN_FAILURE) {
+		return;
+	if (ret == NM_ACT_STAGE_RETURN_FAILURE) {
 		nm_device_state_changed (self, NM_DEVICE_STATE_FAILED, reason);
-		goto out;
+		return;
 	}
 	g_assert (ret == NM_ACT_STAGE_RETURN_SUCCESS);
 
 	priv->ip6_state = IP_FAIL;
 
 	nm_device_check_ip_failed (self, FALSE);
-
-out:
-	_LOGD (LOGD_DEVICE | LOGD_IP6, "Activation: Stage 4 of 5 (IPv6 Configure Timeout) complete.");
 }
 
 
@@ -5791,8 +5760,6 @@ nm_device_activate_schedule_ip6_config_timeout (NMDevice *self)
 	g_return_if_fail (priv->act_request);
 
 	activation_source_schedule (self, nm_device_activate_ip6_config_timeout, AF_INET6);
-
-	_LOGD (LOGD_DEVICE | LOGD_IP6, "Activation: Stage 4 of 5 (IPv6 Configure Timeout) scheduled...");
 }
 
 static gboolean
@@ -6008,8 +5975,6 @@ nm_device_activate_ip4_config_commit (NMDevice *self)
 	NMDeviceStateReason reason = NM_DEVICE_STATE_REASON_NONE;
 	int ip_ifindex;
 
-	_LOGD (LOGD_DEVICE, "Activation: Stage 5 of 5 (IPv4 Commit) started...");
-
 	req = nm_device_get_act_request (self);
 	g_assert (req);
 	connection = nm_act_request_get_applied_connection (req);
@@ -6027,7 +5992,7 @@ nm_device_activate_ip4_config_commit (NMDevice *self)
 	if (!ip4_config_merge_and_apply (self, NULL, TRUE, &reason)) {
 		_LOGD (LOGD_DEVICE | LOGD_IP4, "Activation: Stage 5 of 5 (IPv4 Commit) failed");
 		nm_device_state_changed (self, NM_DEVICE_STATE_FAILED, reason);
-		goto out;
+		return;
 	}
 
 	/* Start IPv4 sharing if we need it */
@@ -6037,7 +6002,7 @@ nm_device_activate_ip4_config_commit (NMDevice *self)
 		if (!start_sharing (self, priv->ip4_config)) {
 			_LOGW (LOGD_SHARING, "Activation: Stage 5 of 5 (IPv4 Commit) start sharing failed.");
 			nm_device_state_changed (self, NM_DEVICE_STATE_FAILED, NM_DEVICE_STATE_REASON_SHARED_START_FAILED);
-			goto out;
+			return;
 		}
 	}
 
@@ -6066,9 +6031,6 @@ nm_device_activate_ip4_config_commit (NMDevice *self)
 
 	if (nm_device_get_state (self) == NM_DEVICE_STATE_IP_CONFIG)
 		nm_device_state_changed (self, NM_DEVICE_STATE_IP_CHECK, NM_DEVICE_STATE_REASON_NONE);
-
-out:
-	_LOGD (LOGD_DEVICE, "Activation: Stage 5 of 5 (IPv4 Commit) complete.");
 }
 
 static void
@@ -6102,8 +6064,6 @@ nm_device_activate_schedule_ip4_config_result (NMDevice *self, NMIP4Config *conf
 
 	nm_device_queued_ip_config_change_clear (self);
 	activation_source_schedule (self, nm_device_activate_ip4_config_commit, AF_INET);
-
-	_LOGD (LOGD_DEVICE | LOGD_IP4, "Activation: Stage 5 of 5 (IPv4 Configure Commit) scheduled...");
 }
 
 gboolean
@@ -6129,8 +6089,6 @@ nm_device_activate_ip6_config_commit (NMDevice *self)
 	NMDeviceStateReason reason = NM_DEVICE_STATE_REASON_NONE;
 	int ip_ifindex;
 
-	_LOGD (LOGD_DEVICE, "Activation: Stage 5 of 5 (IPv6 Commit) started...");
-
 	req = nm_device_get_act_request (self);
 	g_assert (req);
 	connection = nm_act_request_get_applied_connection (req);
@@ -6173,8 +6131,6 @@ nm_device_activate_ip6_config_commit (NMDevice *self)
 		_LOGW (LOGD_DEVICE | LOGD_IP6, "Activation: Stage 5 of 5 (IPv6 Commit) failed");
 		nm_device_state_changed (self, NM_DEVICE_STATE_FAILED, reason);
 	}
-
-	_LOGD (LOGD_DEVICE, "Activation: Stage 5 of 5 (IPv6 Commit) complete.");
 }
 
 void
@@ -6191,8 +6147,6 @@ nm_device_activate_schedule_ip6_config_result (NMDevice *self)
 		priv->ip6_state = IP_CONF;
 
 	activation_source_schedule (self, nm_device_activate_ip6_config_commit, AF_INET6);
-
-	_LOGD (LOGD_DEVICE | LOGD_IP6, "Activation: Stage 5 of 5 (IPv6 Commit) scheduled...");
 }
 
 gboolean