core: refactoring logging in NMDevice to prefix each line with identifierth/logging

nm-device.c defines additional macros, to make their usage more
concise.

Signed-off-by: Thomas Haller <thaller@redhat.com>

1 files changed, 152 insertions, 167 deletions

diff --git a/src/devices/nm-device.c b/src/devices/nm-device.c
index 330b5adc00..b5156f5726 100644
--- a/src/devices/nm-device.c
+++ b/src/devices/nm-device.c
@@ -80,6 +80,18 @@ static void impl_device_disconnect (NMDevice *device, DBusGMethodInvocation *con
 
 #define DBUS_G_TYPE_UINT_STRUCT (dbus_g_type_get_struct ("GValueArray", G_TYPE_UINT, G_TYPE_UINT, G_TYPE_INVALID))
 
+#define __LOG(level, domain, fmt, ...) \
+	G_STMT_START { \
+		if (LOGL_##level <= LOGL_DEBUG) \
+			LOG(level, domain, self, "(%s): " fmt, self ? NN (nm_device_get_iface (self)) : "", __VA_ARGS__); \
+		else \
+			nm_log_##level (LOGD_##domain, "(%s): " fmt, self ? NN (nm_device_get_iface (self)) : "", __VA_ARGS__); \
+	} G_STMT_END
+#define _LOg(level, domain, text)       __LOG(level, domain, "%s", text)
+#define _LOG(level, domain, fmt, ...)   __LOG(level, domain, fmt, __VA_ARGS__)
+#define _LOGd(text)                     __LOG(debug, DEVICE, "%s", text)
+#define _LOGD(fmt, ...)                 __LOG(debug, DEVICE, fmt, __VA_ARGS__)
+
 /* default to installed helper, but can be modified for testing */
 const char *nm_device_autoipd_helper_path = LIBEXECDIR "/nm-avahi-autoipd.action";
 
@@ -447,9 +459,12 @@ device_get_driver_info (const char *iface, char **driver_version, char **firmwar
 	struct ifreq req;
 	int fd;
 
+	errno = 0;
 	fd = socket (PF_INET, SOCK_DGRAM, 0);
 	if (fd < 0) {
-		nm_log_warn (LOGD_HW, "couldn't open control socket.");
+		int e = errno;
+
+		nm_log_warn (LOGD_HW, "driver info: couldn't open control socket: %d (%s)", e, strerror (e));
 		return FALSE;
 	}
 
@@ -462,8 +477,10 @@ device_get_driver_info (const char *iface, char **driver_version, char **firmwar
 
 	errno = 0;
 	if (ioctl (fd, SIOCETHTOOL, &req) < 0) {
-		nm_log_dbg (LOGD_HW, "SIOCETHTOOL ioctl() failed: cmd=ETHTOOL_GDRVINFO, iface=%s, errno=%d",
-		            iface, errno);
+		int e = errno;
+
+		nm_log_dbg (LOGD_HW, "driver info: SIOCETHTOOL ioctl() failed: cmd=ETHTOOL_GDRVINFO, iface=%s, errno=%d (%s)",
+		            iface, e, strerror (e));
 		close (fd);
 		return FALSE;
 	}
@@ -488,7 +505,7 @@ constructor (GType type,
              GObjectConstructParam *construct_params)
 {
 	GObject *object;
-	NMDevice *dev;
+	NMDevice *dev, *self;
 	NMDevicePrivate *priv;
 	NMPlatform *platform;
 	int i;
@@ -501,10 +518,13 @@ constructor (GType type,
 		return NULL;
 
 	dev = NM_DEVICE (object);
+	self = dev;
 	priv = NM_DEVICE_GET_PRIVATE (dev);
 
+	_LOGD ("constructor ifindex #%d, '%s'", priv->ifindex, priv->iface ? priv->iface : "");
+
 	if (!priv->iface) {
-		nm_log_err (LOGD_DEVICE, "No device interface provided, ignoring");
+		_LOg (err, DEVICE, "No device interface provided, ignoring");
 		goto error;
 	}
 
@@ -544,6 +564,7 @@ static void
 constructed (GObject *object)
 {
 	NMDevice *dev = NM_DEVICE (object);
+	NMDevice *self = dev;
 	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (dev);
 
 	nm_device_update_hw_address (dev);
@@ -559,9 +580,8 @@ constructed (GObject *object)
 		priv->ignore_carrier = nm_config_get_ignore_carrier (nm_config_get (), NM_CONFIG_DEVICE (dev));
 
 		check_carrier (dev);
-		nm_log_info (LOGD_HW,
-		             "(%s): carrier is %s%s",
-		             nm_device_get_iface (NM_DEVICE (dev)),
+		_LOG (info, HW,
+		             "carrier is %s%s",
 		             priv->carrier ? "ON" : "OFF",
 		             priv->ignore_carrier ? " (but ignored)" : "");
 	} else {
@@ -720,7 +740,7 @@ nm_device_set_ip_iface (NMDevice *self, const char *iface)
 				nm_platform_link_set_up (priv->ip_ifindex);
 		} else {
 			/* Device IP interface must always be a kernel network interface */
-			nm_log_warn (LOGD_HW, "(%s): failed to look up interface index", iface);
+			_LOg (warn, HW, "failed to look up interface index");
 		}
 	}
 
@@ -1059,15 +1079,14 @@ nm_device_has_carrier (NMDevice *device)
 static gboolean
 link_disconnect_action_cb (gpointer user_data)
 {
-	NMDevice *device = NM_DEVICE (user_data);
-	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (device);
+	NMDevice *self = NM_DEVICE (user_data);
+	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (self);
 
 	priv->carrier_defer_id = 0;
 
-	nm_log_info (LOGD_DEVICE, "(%s): link disconnected (calling deferred action)",
-	             nm_device_get_iface (device));
+	_LOg (info, DEVICE, "link disconnected (calling deferred action)");
 
-	NM_DEVICE_GET_CLASS (device)->carrier_changed (device, FALSE);
+	NM_DEVICE_GET_CLASS (self)->carrier_changed (self, FALSE);
 
 	return FALSE;
 }
@@ -1075,10 +1094,10 @@ link_disconnect_action_cb (gpointer user_data)
 void
 nm_device_set_carrier (NMDevice *device, gboolean carrier)
 {
+	NMDevice *self = device;
 	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (device);
 	NMDeviceClass *klass = NM_DEVICE_GET_CLASS (device);
 	NMDeviceState state = nm_device_get_state (device);
-	const char *iface = nm_device_get_iface (device);
 
 	if (priv->carrier == carrier)
 		return;
@@ -1087,7 +1106,7 @@ nm_device_set_carrier (NMDevice *device, gboolean carrier)
 	g_object_notify (G_OBJECT (device), NM_DEVICE_CARRIER);
 
 	if (priv->carrier) {
-		nm_log_info (LOGD_DEVICE, "(%s): link connected", iface);
+		_LOg (info, DEVICE, "link connected");
 		if (priv->carrier_defer_id) {
 			g_source_remove (priv->carrier_defer_id);
 			priv->carrier_defer_id = 0;
@@ -1100,11 +1119,11 @@ nm_device_set_carrier (NMDevice *device, gboolean carrier)
 			nm_device_remove_pending_action (device, "carrier wait");
 		}
 	} else if (state <= NM_DEVICE_STATE_DISCONNECTED) {
-		nm_log_info (LOGD_DEVICE, "(%s): link disconnected", iface);
+		_LOg (info, DEVICE, "link disconnected");
 		klass->carrier_changed (device, FALSE);
 	} else {
-		nm_log_info (LOGD_DEVICE, "(%s): link disconnected (deferring action for %d seconds)",
-		             iface, LINK_DISCONNECT_DELAY);
+		_LOG (info, DEVICE, "link disconnected (deferring action for %d seconds)",
+		                    LINK_DISCONNECT_DELAY);
 		priv->carrier_defer_id = g_timeout_add_seconds (LINK_DISCONNECT_DELAY,
 		                                                link_disconnect_action_cb, device);
 	}
@@ -1213,13 +1232,12 @@ slave_state_changed (NMDevice *slave,
 	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (self);
 	gboolean release = FALSE;
 
-	nm_log_dbg (LOGD_DEVICE, "(%s): slave %s state change %d (%s) -> %d (%s)",
-	            nm_device_get_iface (self),
-	            nm_device_get_iface (slave),
-	            slave_old_state,
-	            state_to_string (slave_old_state),
-	            slave_new_state,
-	            state_to_string (slave_new_state));
+	_LOGD ("slave %s state change %d (%s) -> %d (%s)",
+	       nm_device_get_iface (slave),
+	       slave_old_state,
+	       state_to_string (slave_old_state),
+	       slave_new_state,
+	       state_to_string (slave_new_state));
 
 	g_assert (priv->state > NM_DEVICE_STATE_DISCONNECTED);
 
@@ -1240,10 +1258,8 @@ slave_state_changed (NMDevice *slave,
 	if (release) {
 		nm_device_release_one_slave (self, slave);
 		/* Bridge/bond/team interfaces are left up until manually deactivated */
-		if (priv->slaves == NULL && priv->state == NM_DEVICE_STATE_ACTIVATED) {
-			nm_log_dbg (LOGD_DEVICE, "(%s): last slave removed; remaining activated",
-			            nm_device_get_iface (self));
-		}
+		if (priv->slaves == NULL && priv->state == NM_DEVICE_STATE_ACTIVATED)
+			_LOGd ("last slave removed; remaining activated");
 	}
 }
 
@@ -1336,6 +1352,7 @@ void
 nm_device_master_check_slave_physical_port (NMDevice *dev, NMDevice *slave,
                                             guint64 log_domain)
 {
+	NMDevice *self = dev;
 	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (dev);
 	const char *slave_physical_port_id, *existing_physical_port_id;
 	SlaveInfo *info;
@@ -1352,10 +1369,10 @@ nm_device_master_check_slave_physical_port (NMDevice *dev, NMDevice *slave,
 
 		existing_physical_port_id = nm_device_get_physical_port_id (info->slave);
 		if (!g_strcmp0 (slave_physical_port_id, existing_physical_port_id)) {
-			nm_log_warn (log_domain, "(%s): slave %s shares a physical port with existing slave %s",
-			             nm_device_get_ip_iface (dev),
-			             nm_device_get_ip_iface (slave),
-			             nm_device_get_ip_iface (info->slave));
+			_LOG (warn, NONE|log_domain, "(ip_iface %s): slave %s shares a physical port with existing slave %s",
+			            nm_device_get_ip_iface (dev),
+			            nm_device_get_ip_iface (slave),
+			            nm_device_get_ip_iface (info->slave));
 			/* Since this function will get called for every slave, we only have
 			 * to warn about the first match we find; if there are other matches
 			 * later in the list, we will have already warned about them matching
@@ -1424,6 +1441,7 @@ nm_device_get_master (NMDevice *dev)
 static void
 nm_device_slave_notify_enslave (NMDevice *dev, gboolean success)
 {
+	NMDevice *self = dev;
 	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (dev);
 	NMConnection *connection = nm_device_get_connection (dev);
 
@@ -1432,18 +1450,16 @@ nm_device_slave_notify_enslave (NMDevice *dev, gboolean success)
 	g_warn_if_fail (priv->state == NM_DEVICE_STATE_IP_CONFIG);
 
 	if (success) {
-		nm_log_info (LOGD_DEVICE,
-				     "Activation (%s) connection '%s' enslaved, continuing activation",
-				     nm_device_get_iface (dev),
-				     nm_connection_get_id (connection));
+		_LOG (info, DEVICE,
+		      "Activation: connection '%s' enslaved, continuing activation",
+		      nm_connection_get_id (connection));
 
 		priv->enslaved = TRUE;
 		g_object_notify (G_OBJECT (dev), NM_DEVICE_MASTER);
 	} else {
-		nm_log_warn (LOGD_DEVICE,
-		             "Activation (%s) connection '%s' could not be enslaved",
-		             nm_device_get_iface (dev),
-		             nm_connection_get_id (connection));
+		_LOG (warn, DEVICE,
+		      "Activation: connection '%s' could not be enslaved",
+		      nm_connection_get_id (connection));
 	}
 
 	priv->ip4_state = IP_DONE;
@@ -1463,6 +1479,7 @@ nm_device_slave_notify_enslave (NMDevice *dev, gboolean success)
 static void
 nm_device_slave_notify_release (NMDevice *dev, NMDeviceStateReason reason)
 {
+	NMDevice *self = dev;
 	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (dev);
 	NMConnection *connection = nm_device_get_connection (dev);
 	NMDeviceState new_state;
@@ -1481,11 +1498,9 @@ nm_device_slave_notify_release (NMDevice *dev, NMDeviceStateReason reason)
 			master_status = "deactivated";
 		}
 
-		nm_log_dbg (LOGD_DEVICE,
-		            "Activation (%s) connection '%s' master %s",
-		            nm_device_get_iface (dev),
-		            nm_connection_get_id (connection),
-		            master_status);
+		_LOGD ("Activation: connection '%s' master %s",
+		       nm_connection_get_id (connection),
+		       master_status);
 
 		nm_device_queue_state (dev, new_state, reason);
 	}
@@ -1665,6 +1680,7 @@ device_has_config (NMDevice *device)
 NMConnection *
 nm_device_generate_connection (NMDevice *device)
 {
+	NMDevice *self = device;
 	NMDeviceClass *klass = NM_DEVICE_GET_CLASS (device);
 	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (device);
 	const char *ifname = nm_device_get_iface (device);
@@ -1684,7 +1700,7 @@ nm_device_generate_connection (NMDevice *device)
 
 	/* Return NULL if device is unconfigured. */
 	if (!device_has_config (device)) {
-		nm_log_dbg (LOGD_DEVICE, "(%s): device has no existing configuration", ifname);
+		_LOGd ("device has no existing configuration");
 		return NULL;
 	}
 
@@ -1767,7 +1783,7 @@ nm_device_generate_connection (NMDevice *device)
 	    && g_strcmp0 (ip6_method, NM_SETTING_IP6_CONFIG_METHOD_IGNORE) == 0
 	    && !nm_setting_connection_get_master (NM_SETTING_CONNECTION (s_con))
 	    && !nm_platform_link_supports_slaves (priv->ifindex)) {
-		nm_log_dbg (LOGD_DEVICE, "(%s): ignoring generated connection (no IP, not master, no slaves)", ifname);
+		_LOGd ("ignoring generated connection (no IP, not master, no slaves)");
 		g_object_unref (connection);
 		connection = NULL;
 	}
@@ -2036,9 +2052,8 @@ master_ready_cb (NMActiveConnection *active,
 	                            self,
 	                            nm_active_connection_get_assumed (active) ? FALSE : TRUE);
 
-	nm_log_dbg (LOGD_DEVICE, "(%s): master connection ready; master device %s",
-	            nm_device_get_iface (self),
-	            nm_device_get_iface (priv->master));
+	_LOGD ("master connection ready; master device %s",
+	       nm_device_get_iface (priv->master));
 
 	if (priv->master_ready_id) {
 		g_signal_handler_disconnect (active, priv->master_ready_id);
@@ -2065,7 +2080,6 @@ nm_device_activate_stage1_device_prepare (gpointer user_data)
 {
 	NMDevice *self = NM_DEVICE (user_data);
 	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (self);
-	const char *iface;
 	NMActStageReturn ret = NM_ACT_STAGE_RETURN_SUCCESS;
 	NMDeviceStateReason reason = NM_DEVICE_STATE_REASON_NONE;
 	NMActiveConnection *active = NM_ACTIVE_CONNECTION (priv->act_request);
@@ -2075,8 +2089,7 @@ nm_device_activate_stage1_device_prepare (gpointer user_data)
 
 	priv->ip4_state = priv->ip6_state = IP_NONE;
 
-	iface = nm_device_get_iface (self);
-	nm_log_info (LOGD_DEVICE, "Activation (%s) Stage 1 of 5 (Device Prepare) started...", iface);
+	_LOg (info, 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 */
@@ -2096,8 +2109,7 @@ nm_device_activate_stage1_device_prepare (gpointer user_data)
 		if (nm_active_connection_get_master_ready (active))
 			master_ready_cb (active, NULL, self);
 		else {
-			nm_log_dbg (LOGD_DEVICE, "(%s): waiting for master connection to become ready",
-			            nm_device_get_iface (self));
+			_LOGd ("waiting for master connection to become ready");
 
 			/* Attach a signal handler and wait for the master connection to begin activating */
 			g_assert (priv->master_ready_id == 0);
@@ -2111,7 +2123,7 @@ nm_device_activate_stage1_device_prepare (gpointer user_data)
 		nm_device_activate_schedule_stage2_device_config (self);
 
 out:
-	nm_log_info (LOGD_DEVICE, "Activation (%s) Stage 1 of 5 (Device Prepare) complete.", iface);
+	_LOg (info, DEVICE, "Activation: Stage 1 of 5 (Device Prepare) complete.");
 	return FALSE;
 }
 
@@ -2157,7 +2169,6 @@ nm_device_activate_stage2_device_config (gpointer user_data)
 {
 	NMDevice *self = NM_DEVICE (user_data);
 	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (self);
-	const char *iface;
 	NMActStageReturn ret;
 	NMDeviceStateReason reason = NM_DEVICE_STATE_REASON_NONE;
 	gboolean no_firmware = FALSE;
@@ -2167,8 +2178,7 @@ nm_device_activate_stage2_device_config (gpointer user_data)
 	/* Clear the activation source ID now that this stage has run */
 	activation_source_clear (self, FALSE, 0);
 
-	iface = nm_device_get_iface (self);
-	nm_log_info (LOGD_DEVICE, "Activation (%s) Stage 2 of 5 (Device Configure) starting...", iface);
+	_LOg (info, 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 */
@@ -2199,12 +2209,12 @@ nm_device_activate_stage2_device_config (gpointer user_data)
 			nm_device_enslave_slave (self, info->slave, nm_device_get_connection (info->slave));
 	}
 
-	nm_log_info (LOGD_DEVICE, "Activation (%s) Stage 2 of 5 (Device Configure) successful.", iface);
+	_LOg (info, DEVICE, "Activation: Stage 2 of 5 (Device Configure) successful.");
 
 	nm_device_activate_schedule_stage3_ip_config_start (self);
 
 out:
-	nm_log_info (LOGD_DEVICE, "Activation (%s) Stage 2 of 5 (Device Configure) complete.", iface);
+	_LOg (info, DEVICE, "Activation: Stage 2 of 5 (Device Configure) complete.");
 	return FALSE;
 }
 
@@ -2259,9 +2269,9 @@ aipd_cleanup (NMDevice *self)
 		kill (priv->aipd_pid, SIGKILL);
 
 		/* ensure the child is reaped */
-		nm_log_dbg (LOGD_AUTOIP4, "waiting for avahi-autoipd pid %d to exit", priv->aipd_pid);
+		_LOG (debug, AUTOIP4, "waiting for avahi-autoipd pid %d to exit", priv->aipd_pid);
 		waitpid (priv->aipd_pid, NULL, 0);
-		nm_log_dbg (LOGD_AUTOIP4, "avahi-autoip pid %d cleaned up", priv->aipd_pid);
+		_LOG (debug, AUTOIP4, "avahi-autoip pid %d cleaned up", priv->aipd_pid);
 
 		priv->aipd_pid = -1;
 	}
@@ -2305,7 +2315,7 @@ nm_device_handle_autoip4_event (NMDevice *self,
 {
 	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (self);
 	NMConnection *connection = NULL;
-	const char *iface, *method;
+	const char *method;
 	NMDeviceStateReason reason = NM_DEVICE_STATE_REASON_NONE;
 
 	g_return_if_fail (event != NULL);
@@ -2321,22 +2331,18 @@ nm_device_handle_autoip4_event (NMDevice *self,
 	if (g_strcmp0 (method, NM_SETTING_IP4_CONFIG_METHOD_LINK_LOCAL) != 0)
 		return;
 
-	iface = nm_device_get_iface (self);
-
 	if (strcmp (event, "BIND") == 0) {
 		guint32 lla;
 		NMIP4Config *config;
 
 		if (inet_pton (AF_INET, address, &lla) <= 0) {
-			nm_log_err (LOGD_AUTOIP4, "(%s): invalid address %s received from avahi-autoipd.",
-			            iface, address);
+			_LOG (err, AUTOIP4, "invalid address %s received from avahi-autoipd.", address);
 			nm_device_state_changed (self, NM_DEVICE_STATE_FAILED, NM_DEVICE_STATE_REASON_AUTOIP_ERROR);
 			return;
 		}
 
 		if ((lla & IPV4LL_NETMASK) != IPV4LL_NETWORK) {
-			nm_log_err (LOGD_AUTOIP4, "(%s): invalid address %s received from avahi-autoipd (not link-local).",
-			            iface, address);
+			_LOG (err, AUTOIP4, "invalid address %s received from avahi-autoipd (not link-local).", address);
 			nm_device_state_changed (self, NM_DEVICE_STATE_FAILED, NM_DEVICE_STATE_REASON_AUTOIP_ERROR);
 			return;
 		}
@@ -2362,8 +2368,7 @@ nm_device_handle_autoip4_event (NMDevice *self,
 
 		g_object_unref (config);
 	} else {
-		nm_log_warn (LOGD_AUTOIP4, "(%s): autoip address %s no longer valid because '%s'.",
-		            iface, address, event);
+		_LOG (warn, AUTOIP4, "autoip address %s no longer valid because '%s'.", address, event);
 
 		/* The address is gone; terminate the connection or fail activation */
 		nm_device_state_changed (self, NM_DEVICE_STATE_FAILED, NM_DEVICE_STATE_REASON_IP_CONFIG_EXPIRED);
@@ -2376,26 +2381,19 @@ aipd_watch_cb (GPid pid, gint status, gpointer user_data)
 	NMDevice *self = NM_DEVICE (user_data);
 	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (self);
 	NMDeviceState state;
-	const char *iface;
 
 	if (!priv->aipd_watch)
 		return;
 	priv->aipd_watch = 0;
 
-	iface = nm_device_get_iface (self);
-
-	if (WIFEXITED (status)) {
-		nm_log_dbg (LOGD_AUTOIP4, "(%s): avahi-autoipd exited with error code %d",
-		            iface, WEXITSTATUS (status));
-	} else if (WIFSTOPPED (status)) {
-		nm_log_warn (LOGD_AUTOIP4, "(%s): avahi-autoipd stopped unexpectedly with signal %d",
-		            iface, WSTOPSIG (status));
-	} else if (WIFSIGNALED (status)) {
-		nm_log_warn (LOGD_AUTOIP4, "(%s): avahi-autoipd died with signal %d",
-		             iface, WTERMSIG (status));
-	} else {
-		nm_log_warn (LOGD_AUTOIP4, "(%s): avahi-autoipd died from an unknown cause", iface);
-	}
+	if (WIFEXITED (status))
+		_LOG (debug, AUTOIP4, "avahi-autoipd exited with error code %d", WEXITSTATUS (status));
+	else if (WIFSTOPPED (status))
+		_LOG (warn, AUTOIP4, "avahi-autoipd stopped unexpectedly with signal %d", WSTOPSIG (status));
+	else if (WIFSIGNALED (status))
+		_LOG (warn, AUTOIP4, "avahi-autoipd died with signal %d", WTERMSIG (status));
+	else
+		_LOg (warn, AUTOIP4, "avahi-autoipd died from an unknown cause");
 
 	aipd_cleanup (self);
 
@@ -2411,7 +2409,7 @@ aipd_timeout_cb (gpointer user_data)
 	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (self);
 
 	if (priv->aipd_timeout) {
-		nm_log_info (LOGD_AUTOIP4, "(%s): avahi-autoipd timed out.", nm_device_get_iface (self));
+		_LOg (info, AUTOIP4, "avahi-autoipd timed out.");
 		priv->aipd_timeout = 0;
 		aipd_cleanup (self);
 
@@ -2443,7 +2441,6 @@ static NMActStageReturn
 aipd_start (NMDevice *self, NMDeviceStateReason *reason)
 {
 	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (self);
-	const char *iface = nm_device_get_iface (self);
 	char *argv[6], *cmdline;
 	const char **aipd_binary = NULL;
 	static const char *aipd_paths[] = {
@@ -2465,9 +2462,9 @@ aipd_start (NMDevice *self, NMDeviceStateReason *reason)
 	}
 
 	if (!*aipd_binary) {
-		nm_log_warn (LOGD_DEVICE | LOGD_AUTOIP4,
-		             "Activation (%s) Stage 3 of 5 (IP Configure Start) failed"
-		             " to start avahi-autoipd: not found", iface);
+		_LOg (warn, DEVICE | LOGD_AUTOIP4,
+		      "Activation: Stage 3 of 5 (IP Configure Start) failed"
+		      " to start avahi-autoipd: not found");
 		*reason = NM_DEVICE_STATE_REASON_AUTOIP_START_FAILED;
 		return NM_ACT_STAGE_RETURN_FAILURE;
 	}
@@ -2482,24 +2479,23 @@ aipd_start (NMDevice *self, NMDeviceStateReason *reason)
 	argv[i++] = NULL;
 
 	cmdline = g_strjoinv (" ", argv);
-	nm_log_dbg (LOGD_AUTOIP4, "running: %s", cmdline);
+	_LOG (debug, AUTOIP4, "running: %s", cmdline);
 	g_free (cmdline);
 
 	if (!g_spawn_async ("/", argv, NULL, G_SPAWN_DO_NOT_REAP_CHILD,
 	                    &aipd_child_setup, NULL, &(priv->aipd_pid), &error)) {
-		nm_log_warn (LOGD_DEVICE | LOGD_AUTOIP4,
-		             "Activation (%s) Stage 3 of 5 (IP Configure Start) failed"
-		             " to start avahi-autoipd: %s",
-		             iface,
-		             error && error->message ? error->message : "(unknown)");
+		_LOG (warn, DEVICE | LOGD_AUTOIP4,
+		      "Activation: Stage 3 of 5 (IP Configure Start) failed"
+		      " to start avahi-autoipd: %s",
+		      error && error->message ? error->message : "(unknown)");
 		g_clear_error (&error);
 		aipd_cleanup (self);
 		return NM_ACT_STAGE_RETURN_FAILURE;
 	}
 
-	nm_log_info (LOGD_DEVICE | LOGD_AUTOIP4,
-	             "Activation (%s) Stage 3 of 5 (IP Configure Start) started"
-	             " avahi-autoipd...", iface);
+	_LOg (info, DEVICE | LOGD_AUTOIP4,
+	      "Activation: Stage 3 of 5 (IP Configure Start) started"
+	      " avahi-autoipd...");
 
 	/* Monitor the child process so we know when it dies */
 	priv->aipd_watch = g_child_watch_add (priv->aipd_pid, aipd_watch_cb, self);
@@ -2602,13 +2598,13 @@ dhcp4_state_changed (NMDHCPClient *client,
                      gpointer user_data)
 {
 	NMDevice *device = NM_DEVICE (user_data);
+	NMDevice *self = device;
 	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (device);
 	NMIP4Config *config;
 
 	g_return_if_fail (nm_dhcp_client_get_ipv6 (client) == FALSE);
 
-	nm_log_dbg (LOGD_DHCP4, "(%s): new DHCPv4 client state %d",
-	            nm_device_get_iface (device), state);
+	_LOG (debug, DHCP4, "new DHCPv4 client state %d", state);
 
 	switch (state) {
 	case DHC_BOUND4:     /* lease obtained */
@@ -3014,12 +3010,12 @@ dhcp6_state_changed (NMDHCPClient *client,
                      gpointer user_data)
 {
 	NMDevice *device = NM_DEVICE (user_data);
+	NMDevice *self = device;
 	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (device);
 
 	g_return_if_fail (nm_dhcp_client_get_ipv6 (client) == TRUE);
 
-	nm_log_dbg (LOGD_DHCP6, "(%s): new DHCPv6 client state %d",
-	            nm_device_get_iface (device), state);
+	_LOG (debug, DHCP6, "new DHCPv6 client state %d", state);
 
 	switch (state) {
 	case DHC_BOUND6:
@@ -3200,8 +3196,7 @@ linklocal6_timeout_cb (gpointer user_data)
 
 	linklocal6_cleanup (self);
 
-	nm_log_dbg (LOGD_DEVICE, "[%s] linklocal6: waiting for link-local addresses failed due to timeout",
-	             nm_device_get_iface (self));
+	_LOGd ("linklocal6: waiting for link-local addresses failed due to timeout");
 
 	nm_device_activate_schedule_ip6_config_timeout (self);
 	return G_SOURCE_REMOVE;
@@ -3224,8 +3219,7 @@ linklocal6_complete (NMDevice *self)
 
 	method = nm_utils_get_ip_config_method (connection, NM_TYPE_SETTING_IP6_CONFIG);
 
-	nm_log_dbg (LOGD_DEVICE, "[%s] linklocal6: waiting for link-local addresses successful, continue with method %s",
-	             nm_device_get_iface (self), method);
+	_LOGD ("linklocal6: waiting for link-local addresses successful, continue with method %s", method);
 
 	if (strcmp (method, NM_SETTING_IP6_CONFIG_METHOD_AUTO) == 0)
 		addrconf6_start_with_link_ready (self);
@@ -3251,8 +3245,7 @@ linklocal6_start (NMDevice *self)
 	g_assert (connection);
 
 	method = nm_utils_get_ip_config_method (connection, NM_TYPE_SETTING_IP6_CONFIG);
-	nm_log_dbg (LOGD_DEVICE, "[%s] linklocal6: starting IPv6 with method '%s', but the device has no link-local addresses configured. Wait.",
-	            nm_device_get_iface (self), method);
+	_LOGD ("linklocal6: starting IPv6 with method '%s', but the device has no link-local addresses configured. Wait.", method);
 
 	priv->linklocal6_timeout_id = g_timeout_add_seconds (5, linklocal6_timeout_cb, self);
 
@@ -3922,8 +3915,7 @@ nm_device_activate_schedule_stage3_ip_config_start (NMDevice *self)
 	s_con = nm_connection_get_setting_connection (connection);
 
 	zone = nm_setting_connection_get_zone (s_con);
-	nm_log_dbg (LOGD_DEVICE, "Activation (%s) setting firewall zone '%s'",
-	            nm_device_get_iface (self), zone ? zone : "default");
+	_LOGD ("Activation: setting firewall zone '%s'", zone ? zone : "default");
 	priv->fw_call = nm_firewall_manager_add_or_change_zone (priv->fw_manager,
 	                                                        nm_device_get_ip_iface (self),
 	                                                        zone,
@@ -4562,8 +4554,7 @@ delete_on_deactivate_check_and_schedule (NMDevice *self, int ifindex)
 		return;
 	if (nm_device_get_state (self) == NM_DEVICE_STATE_UNAVAILABLE)
 		return;
-	nm_log_dbg (LOGD_DEVICE, "Schedule cleanup and delete virtual link #%d for [%s]",
-	                         ifindex, nm_device_get_iface (self));
+	_LOGD ("Schedule cleanup and delete virtual link #%d", ifindex);
 	priv = NM_DEVICE_GET_PRIVATE (self);
 	delete_on_deactivate_unschedule (priv); /* always cancel and reschedule */
 	priv->delete_on_deactivate_id = g_idle_add (delete_on_deactivate_link_delete, GINT_TO_POINTER (ifindex));
@@ -5500,6 +5491,8 @@ finalize (GObject *object)
 	NMDevice *self = NM_DEVICE (object);
 	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (self);
 
+	_LOGd ("finalize");
+
 	if (priv->dhcp_manager)
 		g_object_unref (priv->dhcp_manager);
 
@@ -5530,9 +5523,10 @@ set_property (GObject *object, guint prop_id,
 	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (object);
 	NMPlatformLink *platform_device;
 	const char *hw_addr;
- 
+
 	switch (prop_id) {
 	case PROP_PLATFORM_DEVICE:
+		/* construct-only */
 		platform_device = g_value_get_pointer (value);
 		if (platform_device) {
 			g_free (priv->udi);
@@ -5551,6 +5545,7 @@ set_property (GObject *object, guint prop_id,
 		}
 		break;
 	case PROP_IFACE:
+		/* construct-only */
 		if (g_value_get_string (value)) {
 			g_free (priv->iface);
 			priv->ifindex = 0;
@@ -6325,6 +6320,7 @@ nm_device_state_changed (NMDevice *device,
                          NMDeviceState state,
                          NMDeviceStateReason reason)
 {
+	NMDevice *self = device;
 	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (device);
 	NMDeviceState old_state;
 	NMActRequest *req;
@@ -6442,13 +6438,11 @@ nm_device_state_changed (NMDevice *device,
 		 * reasons.
 		 */
 		if (nm_device_is_available (device)) {
-			nm_log_dbg (LOGD_DEVICE, "(%s): device is available, will transition to DISCONNECTED",
-			            nm_device_get_iface (device));
+			_LOGd ("device is available, will transition to DISCONNECTED");
 			nm_device_queue_state (device, NM_DEVICE_STATE_DISCONNECTED, NM_DEVICE_STATE_REASON_NONE);
 		} else {
 			if (old_state == NM_DEVICE_STATE_UNMANAGED) {
-				nm_log_dbg (LOGD_DEVICE, "(%s): device not yet available for transition to DISCONNECTED",
-				            nm_device_get_iface (device));
+				_LOGd ("device not yet available for transition to DISCONNECTED");
 			} else if (old_state > NM_DEVICE_STATE_UNAVAILABLE && priv->default_unmanaged)
 				nm_device_queue_state (device, NM_DEVICE_STATE_UNMANAGED, NM_DEVICE_STATE_REASON_NONE);
 		}
@@ -6509,8 +6503,7 @@ nm_device_state_changed (NMDevice *device,
 		break;
 	case NM_DEVICE_STATE_SECONDARIES:
 		ip_check_gw_ping_cleanup (device);
-		nm_log_dbg (LOGD_DEVICE, "(%s): device entered SECONDARIES state",
-		            nm_device_get_iface (device));
+		_LOGd ("device entered SECONDARIES state");
 		break;
 	default:
 		break;
@@ -6544,10 +6537,9 @@ queued_set_state (gpointer user_data)
 	NMDeviceStateReason new_reason;
 
 	if (priv->queued_state.id) {
-		nm_log_dbg (LOGD_DEVICE, "(%s): running queued state change to %s (id %d)",
-			        nm_device_get_iface (self),
-			        state_to_string (priv->queued_state.state),
-			        priv->queued_state.id);
+		_LOGD ("running queued state change to %s (id %d)",
+		       state_to_string (priv->queued_state.state),
+		       priv->queued_state.id);
 
 		/* Clear queued state struct before triggering state change, since
 		 * the state change may queue another state.
@@ -6601,9 +6593,9 @@ nm_device_queue_state (NMDevice *self,
 
 	nm_device_remove_pending_action (self, "queued state lock");
 
-	nm_log_dbg (LOGD_DEVICE, "(%s): queued state change to %s due to %s (id %d)",
-	            nm_device_get_iface (self), state_to_string (state), reason_to_string (reason),
-	            priv->queued_state.id);
+	_LOGD ("queued state change to %s due to %s (id %d)",
+	       state_to_string (state), reason_to_string (reason),
+	       priv->queued_state.id);
 }
 
 NMDeviceState
@@ -6624,8 +6616,8 @@ nm_device_queued_state_clear (NMDevice *self)
 	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (self);
 
 	if (priv->queued_state.id) {
-		nm_log_dbg (LOGD_DEVICE, "(%s): clearing queued state transition (id %d)",
-		            nm_device_get_iface (self), priv->queued_state.id);
+		_LOGD ("clearing queued state transition (id %d)",
+		       priv->queued_state.id);
 		g_source_remove (priv->queued_state.id);
 		nm_device_remove_pending_action (self, queued_state_to_string (priv->queued_state.state));
 	}
@@ -6831,8 +6823,7 @@ device_ip_changed (NMPlatform *platform, int ifindex, gpointer platform_object,
 		if (!priv->queued_ip_config_id)
 			priv->queued_ip_config_id = g_idle_add (queued_ip_config_change, self);
 
-		nm_log_dbg (LOGD_DEVICE, "(%s): queued IP config change",
-		            nm_device_get_iface (self));
+		_LOGd ("queued IP config change");
 	}
 }
 
@@ -6842,8 +6833,7 @@ nm_device_queued_ip_config_change_clear (NMDevice *self)
 	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (self);
 
 	if (priv->queued_ip_config_id) {
-		nm_log_dbg (LOGD_DEVICE, "(%s): clearing queued IP config change",
-		            nm_device_get_iface (self));
+		_LOGd ("clearing queued IP config change");
 		g_source_remove (priv->queued_ip_config_id);
 		priv->queued_ip_config_id = 0;
 	}
@@ -6871,9 +6861,9 @@ nm_device_set_managed_internal (NMDevice *device,
                                 gboolean managed,
                                 NMDeviceStateReason reason)
 {
-	nm_log_dbg (LOGD_DEVICE, "(%s): now %s",
-	            nm_device_get_iface (device),
-	            managed ? "managed" : "unmanaged");
+	NMDevice *self = device;
+
+	_LOGD ("now %s", managed ? "managed" : "unmanaged");
 
 	g_object_notify (G_OBJECT (device), NM_DEVICE_MANAGED);
 
@@ -7284,7 +7274,7 @@ gboolean
 nm_device_set_hw_addr (NMDevice *device, const guint8 *addr,
                        const char *detail, guint64 hw_log_domain)
 {
-	const char *iface;
+	NMDevice *self = device;
 	char *mac_str = NULL;
 	gboolean success = FALSE;
 	guint len;
@@ -7292,11 +7282,9 @@ nm_device_set_hw_addr (NMDevice *device, const guint8 *addr,
 
 	g_return_val_if_fail (addr != NULL, FALSE);
 
-	iface = nm_device_get_iface (device);
-
 	/* Do nothing if current MAC is same */
 	if (cur_addr && !memcmp (cur_addr, addr, len)) {
-		nm_log_dbg (LOGD_DEVICE | hw_log_domain, "(%s): no MAC address change needed", iface);
+		_LOg (debug, DEVICE | hw_log_domain, "no MAC address change needed");
 		return TRUE;
 	}
 
@@ -7311,17 +7299,16 @@ nm_device_set_hw_addr (NMDevice *device, const guint8 *addr,
 		nm_device_update_hw_address (device);
 		cur_addr = nm_device_get_hw_address (device, NULL);
 		if (memcmp (cur_addr, addr, len) == 0) {
-			nm_log_info (LOGD_DEVICE | hw_log_domain, "(%s): %s MAC address to %s",
-			             iface, detail, mac_str);
+			_LOG (info, DEVICE | hw_log_domain, "%s MAC address to %s",
+			      detail, mac_str);
 		} else {
-			nm_log_warn (LOGD_DEVICE | hw_log_domain, "(%s): new MAC address %s "
-			             "not successfully set",
-			             iface, mac_str);
+			_LOG (warn, DEVICE | hw_log_domain, "new MAC address %s "
+			      "not successfully set", mac_str);
 			success = FALSE;
 		}
 	} else {
-		nm_log_warn (LOGD_DEVICE | hw_log_domain, "(%s): failed to %s MAC address to %s",
-		             iface, detail, mac_str);
+		_LOG (warn, DEVICE | hw_log_domain, "failed to %s MAC address to %s",
+		      detail, mac_str);
 	}
 	nm_device_bring_up (device, TRUE, NULL);
 	g_free (mac_str);
@@ -7339,6 +7326,7 @@ nm_device_set_hw_addr (NMDevice *device, const guint8 *addr,
 void
 nm_device_add_pending_action (NMDevice *device, const char *action)
 {
+	NMDevice *self = device;
 	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (device);
 	GSList *iter;
 	guint count;
@@ -7348,10 +7336,9 @@ nm_device_add_pending_action (NMDevice *device, const char *action)
 	/* Shouldn't ever add the same pending action twice */
 	for (iter = priv->pending_actions; iter; iter = iter->next) {
 		if (!strcmp (action, iter->data)) {
-			nm_log_warn (LOGD_DEVICE, "(%s): add_pending_action (%d): '%s' already added",
-			             nm_device_get_iface (device),
-			             g_slist_length (priv->pending_actions),
-			             action);
+			_LOG (warn, DEVICE, "add_pending_action (%d): '%s' already added",
+			      g_slist_length (priv->pending_actions),
+			      action);
 			g_return_if_reached ();
 		}
 	}
@@ -7359,10 +7346,9 @@ nm_device_add_pending_action (NMDevice *device, const char *action)
 	priv->pending_actions = g_slist_append (priv->pending_actions, g_strdup (action));
 	count = g_slist_length (priv->pending_actions);
 
-	nm_log_dbg (LOGD_DEVICE, "(%s): add_pending_action (%d): '%s'",
-	            nm_device_get_iface (device),
-	            count,
-	            action);
+	_LOGD ("add_pending_action (%d): '%s'",
+	       count,
+	       action);
 
 	if (count == 1)
 		g_object_notify (G_OBJECT (device), NM_DEVICE_HAS_PENDING_ACTION);
@@ -7378,6 +7364,7 @@ nm_device_add_pending_action (NMDevice *device, const char *action)
 void
 nm_device_remove_pending_action (NMDevice *device, const char *action)
 {
+	NMDevice *self = device;
 	NMDevicePrivate *priv = NM_DEVICE_GET_PRIVATE (device);
 	GSList *iter;
 
@@ -7388,10 +7375,9 @@ nm_device_remove_pending_action (NMDevice *device, const char *action)
 		if (!strcmp (action, iter->data)) {
 			g_free (iter->data);
 			priv->pending_actions = g_slist_delete_link (priv->pending_actions, iter);
-			nm_log_dbg (LOGD_DEVICE, "(%s): remove_pending_action (%d): '%s'",
-			            nm_device_get_iface (device),
-			            g_slist_length (priv->pending_actions),
-			            action);
+			_LOGD ("remove_pending_action (%d): '%s'",
+			       g_slist_length (priv->pending_actions),
+			       action);
 
 			if (priv->pending_actions == NULL)
 				g_object_notify (G_OBJECT (device), NM_DEVICE_HAS_PENDING_ACTION);
@@ -7399,10 +7385,9 @@ nm_device_remove_pending_action (NMDevice *device, const char *action)
 		}
 	}
 
-	nm_log_warn (LOGD_DEVICE, "(%s): remove_pending_action (%d): '%s' never added",
-	             nm_device_get_iface (device),
-	             g_slist_length (priv->pending_actions),
-	             action);
+	_LOG (warn, DEVICE, "remove_pending_action (%d): '%s' never added",
+	      g_slist_length (priv->pending_actions),
+	      action);
 	g_return_if_reached ();
 }